Knowledgebase:
IO Statistics: New performance trace events
04 October 2016 05:39 AM

Introduction

We are always looking for ways to understand and address performance issues within the product and we are addressing this by adding the following new diagnostic features to the product.

New Trace Events in MarkLogic Server

Some new diagnostic trace events have been added to MarkLogic Server:

  • Background Time Statistics - Background thread period and further processing timings are added to xdmp:host-status() output if this trace event is set.
  • Journal Lag 30 - A forest will now log a warning message if a frame takes more than 30 seconds to journal.
    • Please note that this limit can be adjusted down by setting the Journal Lag # trace event (where # is {1, 2, 5 or 10} seconds).
  • Canary Thread 10 - A new "canary thread" that does nothing but sleep for a second and check how long is was since it went to sleep.
    • It will log messages if the interval between sleeping has exceeded 10 seconds.
    • This can be adjusted down by setting the Canary Thread # trace event (where # is {1, 2, 5 or 10} seconds).
  • Canary Thread Histogram - Adding this trace event will cause MarkLogic to write to the ErrorLog a histogram of timings once every 10 minutes.
  • Forest Fast Query Lag 10 - By default, a forest will now warn if the fast query timestamp is lagging by more than 30 seconds.
    • This can be adjusted down by setting the Forest Fast Query Lag # (where # is {1, 2, 5, or 10} seconds).
    • Note that Warning level messages will be repeatedly logged at intervals while the lag limit is exceeded, with the time between logged messages doubling until it reaches 60 seconds.
    • There will be a final warning when the lag drops below the limit again as a way to bracket the period of lag.

Examples of some of new statistics can be viewed in the Admin UI by going to the following URL in a browser (replacing hostname with the name of a node in your cluster and replacing TheDatabase with the name of the database that you would like to monitor):

You can clear the forest insert and journal statistics by adding clear=true to your request; executing the following in a browser:

These changes now feature in the current releases of both MarkLogic 7 and MarkLogic 8 and are available for download from our developer website:

Hints for interpreting new diagnostic pages

Here's some further detail on what the numbers mean.

First, a note about how bucketing is performed on these diagnostic pages:

For each operation category (e.g. Timestamp Wait, Semaphore, Disk), the wait time will fall into a range of values, which need to be bucketed.

The bucketing algorithm starts with 1000 buckets to cover the whole range, but then collapses them into a small set of buckets that cover the whole span of values. The algorithm aims to

1. End up with a small number of buckets

2. Include extreme (out-liers) values

3. Spread out multiple values so that they are not too "bunched-up" and are therefore easier to interpret.

Forest Journal Statistics (http://hostname:8001/forest-journal-statistics.xqy?database=TheDatabase)

When we journal a frame, there are a sequence of operations.

  1. Wait on a semaphore to get access to the journal.
  2. Write to the journal buffer (possibly waiting for I/O if exceeding the 512k buffer)
  3. Send the frame to replica forests
  4. Send the frame to journal archive/database replica forests
  5. Release the semaphore so other threads can access the journal
  6. Wait for everything above to complete, if needed.
    1. If it's a synchronous op (e.g. prepare, commit, fast query timestamp), we wait for disk I/O
    2. If there are replica forests, we wait for them to acknowledge that they have journaled and replayed.
    3. If the journal archive or database replica is lagged, wait for it to no longer be lagged.

We note the wall clock time before/after these various options, so we can track how long they're taking.

On the replica side, we also measure the "Journal Replay" time which would be inserting into the in-memory stand, committing, etc.

Here's an example for a master and its replica.

Forest F-1-1

Timestamp Wait
Bucket (ms)Count%CumulativeCumulative %
0..9 280 99.64 280 99.64
50..59 1 0.36 281 100.00
Semaphore
Bucket (ms)Count%CumulativeCumulative %
0..9 816 100.00 816 100.00
Disk
Bucket (ms)Count%CumulativeCumulative %
0..9 204 99.51 204 99.51
10..19 1 0.49 205 100.00
Local-Disk Replication
Bucket (ms)Count%CumulativeCumulative %
0..9 804 99.26 804 99.26
10..119 6 0.74 810 100.00
Journal Archive

No Information

Database Replication

No Information

Journal Total
Bucket (ms)Count%CumulativeCumulative %
0..9 810 99.26 810 99.26
10..119 6 0.74 816 100.00
Journal Replay

No Information

Forest F-1-1-R

Timestamp Wait

No Information

Semaphore
Bucket (ms)Count%CumulativeCumulative %
0..9 811 100.00 811 100.00
Disk
Bucket (ms)Count%CumulativeCumulative %
0..9 203 99.02 203 99.02
10..59 2 0.98 205 100.00
Local-Disk Replication

No Information

Journal Archive

No Information

Database Replication

No Information

Journal Total
Bucket (ms)Count%CumulativeCumulative %
0..9 809 99.75 809 99.75
10..59 2 0.25 811 100.00
Journal Replay
Bucket (ms)Count%CumulativeCumulative %
0..9 807 99.63 807 99.63
10..119 3 0.37 810 100.00

Forest Insert Statistics (http://hostname:8001/forest-insert-statistics.xqy?database=TheDatabase)

When we're inserting a fragment into an in-memory stand, we also have a sequence of operations.

  1. Wait on a semaphore to get access to the in-memory stand.
  2. Wait on the insert throttle (e.g. if there are too may stands)
  3. Wait for the stand's journal semaphore, to serialize with the previous insert if needed.
  4. Release the stand insert semaphore.
  5. Journal the insert.
  6. Release the stand journal semaphore.
  7. Start the checkpoint task if the stand is full.

As with the journal statistics, we note the wall clock time between these operations so we can track how long they're taking.

On the replica side, the behavior is similar, although the journal and insert are in reverse order (we journal before inserting into the in-memory stand). If it's a database replica forest, we also have to regenerate the index information (Filled IPD).

Here is a example for a master and its replica.

Forest F-1-1

Journal Throttle
Bucket (ms)Count%CumulativeCumulative %
0..9 606 100.00 606 100.00
Insert Sem
Bucket (ms)Count%CumulativeCumulative %
0..9 604 99.67 604 99.67
80..199 2 0.33 606 100.00
Filled IPD

No Information

Stand Throttle
Bucket (ms)Count%CumulativeCumulative %
0..9 606 100.00 606 100.00
Stand Insert
Bucket (ms)Count%CumulativeCumulative %
0..9 605 99.84 605 99.84
100..109 1 0.17 606 100.00
Journal Sem
Bucket (ms)Count%CumulativeCumulative %
0..9 604 99.67 604 99.67
10..119 2 0.33 606 100.00
Journal
Bucket (ms)Count%CumulativeCumulative %
0..9 603 99.50 603 99.50
10..119 3 0.50 606 100.00
Total
Bucket (ms)Count%CumulativeCumulative %
0..9 597 98.51 597 98.51
10..19 6 0.99 603 99.50
200..229 3 0.50 606 100.00

Forest F-1-1-R

Journal Throttle

No Information

Insert Sem
Bucket (ms)Count%CumulativeCumulative %
0..9 606 100.00 606 100.00
Filled IPD

No Information

Stand Throttle
Bucket (ms)Count%CumulativeCumulative %
0..9 606 100.00 606 100.00
Stand Insert
Bucket (ms)Count%CumulativeCumulative %
0..9 605 99.84 605 99.84
110..119 1 0.17 606 100.00
Journal Sem
Bucket (ms)Count%CumulativeCumulative %
0..9 606 100.00 606 100.00
Journal

No Information

Total
Bucket (ms)Count%CumulativeCumulative %
0..9 605 99.84 605 99.84
110..119 1 0.17 606 100.00

Further reading

To learn more about diagnostic trace events, please refer to our documentation and Knowledgebase articles and note that some trace events may only log information if logging is set to debug:

(3 vote(s))
Helpful
Not helpful

Comments (0)