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.
- Wait on a semaphore to get access to the journal.
- Write to the journal buffer (possibly waiting for I/O if exceeding the 512k buffer)
- Send the frame to replica forests
- Send the frame to journal archive/database replica forests
- Release the semaphore so other threads can access the journal
- Wait for everything above to complete, if needed.
- If it's a synchronous op (e.g. prepare, commit, fast query timestamp), we wait for disk I/O
- If there are replica forests, we wait for them to acknowledge that they have journaled and replayed.
- 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 | % | Cumulative | Cumulative % |
---|
0..9 |
280 |
99.64 |
280 |
99.64 |
50..59 |
1 |
0.36 |
281 |
100.00 |
Semaphore
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
816 |
100.00 |
816 |
100.00 |
Disk
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
204 |
99.51 |
204 |
99.51 |
10..19 |
1 |
0.49 |
205 |
100.00 |
Local-Disk Replication
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
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 | % | Cumulative | Cumulative % |
---|
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 | % | Cumulative | Cumulative % |
---|
0..9 |
811 |
100.00 |
811 |
100.00 |
Disk
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
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 | % | Cumulative | Cumulative % |
---|
0..9 |
809 |
99.75 |
809 |
99.75 |
10..59 |
2 |
0.25 |
811 |
100.00 |
Journal Replay
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
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.
- Wait on a semaphore to get access to the in-memory stand.
- Wait on the insert throttle (e.g. if there are too may stands)
- Wait for the stand's journal semaphore, to serialize with the previous insert if needed.
- Release the stand insert semaphore.
- Journal the insert.
- Release the stand journal semaphore.
- 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 | % | Cumulative | Cumulative % |
---|
0..9 |
606 |
100.00 |
606 |
100.00 |
Insert Sem
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
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 | % | Cumulative | Cumulative % |
---|
0..9 |
606 |
100.00 |
606 |
100.00 |
Stand Insert
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
605 |
99.84 |
605 |
99.84 |
100..109 |
1 |
0.17 |
606 |
100.00 |
Journal Sem
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
604 |
99.67 |
604 |
99.67 |
10..119 |
2 |
0.33 |
606 |
100.00 |
Journal
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
603 |
99.50 |
603 |
99.50 |
10..119 |
3 |
0.50 |
606 |
100.00 |
Total
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
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 | % | Cumulative | Cumulative % |
---|
0..9 |
606 |
100.00 |
606 |
100.00 |
Filled IPD
No Information
Stand Throttle
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
606 |
100.00 |
606 |
100.00 |
Stand Insert
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
605 |
99.84 |
605 |
99.84 |
110..119 |
1 |
0.17 |
606 |
100.00 |
Journal Sem
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
0..9 |
606 |
100.00 |
606 |
100.00 |
Journal
No Information
Total
Bucket (ms) | Count | % | Cumulative | Cumulative % |
---|
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: