Jira Indexing Queue
JIRA 8.16 SERVER DC
JRASERVER-72045 - Getting issue details... STATUS
In Jira every local index update is done by a single thread doing all the adds, updates and deletes on a given index.
Lucene documents are built in user request threads. Re-indexing tasks (like Jira background indexing, SLA recalculations, DVCS indexing, index synchronisation in Jira DC) are triggered in non request threads.
Before JIRA 8.16 there was a single queue (with indexing operations and Lucene documents) for communication between threads requesting updates to a given index and the thread responsible for updating this index.
This approach may have caused some issues where background indexing tasks could overflow the indexing queue with lots of indexing operations requested at once. This resulted in user actions being seriously affected by asynchronous indexing tasks and might have left Jira in an inconsistent state where DB data (like added or updated issues) were not indexed.
Priority Queues
In JIRA 8.16 we are introducing 2 priority queues to the single threaded index updater (per index):
the primary indexing queue - accepts only indexing requests created by user requests (HTTP threads)
the secondary indexing queue - accepts all other indexing requests (created by non-request threads)
Indexing operations from the secondary queue are only consumed when the primary queue is empty. With this change user actions (triggering re-indexing) should not be affected by background indexing tasks.
Both queues may have internal priority, however currently this is an internal API and only core Jira indexing background processes (node index replay and DBR in Jira DC) have higher priority then all other indexing tasks. In the future we may expose the priority API as a public API. For now plugins triggering any re-indexing in user requests or in background threads are not required to change anything.
We have also significantly improved the performance of all conditional updates (since Jira 8.10 this refers to all index updates except foreground re-index) by decreasing the frequency of requesting a fresh searcher (this operation triggers an index flush) on the index. This will speed up background indexing. By how much? This depends on many factors:
traffic shape - how many concurrent updates are done when any background indexing task is running
I/O performance - index flush triggers a disk operation, so with this change indexing performance should be less affected by slower I/O
Queuing Index Stats
With the changes above we introduced some new log stats which describe the state of both queues in an aggregated form. This new log is following the snapshot/total pattern and can be found in the standard atlassian-jira.log.
Log prefix: [INDEXING-QUEUE]
Log format: INFO - [JIRA-STATS] [INDEXING-QUEUE] index:[index-name], [total/snapshot] [primary/secondary] queue stats:[data]
The most interesting data:
timeInQueueMillis- this is the time spent in the queuetimeToUpdateIndexMillis- this is the time the time the indexing thread has spent updating the local index; this part has dedicated stats[index-writer-stats](see: Jira stats logs).totalTimeMillis- this is the total time the thread has been waiting for the indexing operation to affect the local index (time spent in queue + time spent updating the index + consuming the result); note that "consuming the result" depends on when the result is consumed by the requesting thread so may be greater than "time spent in queue + time spent updating the index", for example background indexing consumes the result in batches;
Example log: primary queue total from the issue indexer
[JIRA-STATS] [INDEXING-QUEUE] index:ISSUE, total primary queue stats:
{
"maxQueueSize": 4, // biggest queue size we have seen
"putCounter": 19326, // number of puts
"queueFullOnPut": 0, // number of puts which had to wait because the queue was full
"getCounter": 19326, // number of consumed index operations
"timeInQueueMillis": { // time of index operation spent in queue, here 1millisecond on average
"count": 19326,
"min": 0,
"max": 85,
"sum": 23604,
"avg": 1, // timeInQueueMillis: 1 millisecond on average
"distributionCounter": {
"0": 15602,
"1": 1371,
"10": 1680,
"100": 673,
"1000": 0,
"10000": 0,
"20000": 0,
"30000": 0
}
},
"timeToUpdateIndexMillis": { // time of index operation being applied to index
"count": 19326,
"min": 0,
"max": 609,
"sum": 32828,
"avg": 1, // timeToUpdateIndexMillis: 1 millisecond on average
"distributionCounter": {
"0": 12848,
"1": 4319,
"10": 1324,
"50": 714,
"100": 117,
"500": 1,
"1000": 3
}
},
"totalTimeMillis": { // total time: from putting to queue until getting result
"count": 19326,
"min": 0,
"max": 612,
"sum": 83290,
"avg": 4, // totalTimeMillis: 4 milliseconds on average
"distributionCounter": {
"0": 10,
"1": 4537,
"10": 12889,
"100": 1886,
"1000": 4,
"10000": 0,
"20000": 0,
"30000": 0
}
},
"totalTimeFailedMillis": { // total time: from putting to queue until failed result
"count": 0,
"min": 0,
"max": 0,
"sum": 0,
"avg": 0,
"distributionCounter": {}
},
"totalTimeTimedOutMillis": { // total time: from putting to queue until timeout result
"count": 0,
"min": 0,
"max": 0,
"sum": 0,
"avg": 0,
"distributionCounter": {}
},
"putCounterByThreadTopN": { // top N threads sorted by number of puts descending, primary queue so these are all HTTP threads
"http-nio-8080-exec-14 url: /rest/api/2/issue; user: admin": 256,
"http-nio-8080-exec-3 url: /rest/api/2/issue; user: admin": 248,
"http-nio-8080-exec-15 url: /rest/api/2/issue; user: admin": 242,
"http-nio-8080-exec-19 url: /rest/api/2/issue; user: admin": 234,
"http-nio-8080-exec-9 url: /secure/QuickCreateIssue.jspa; user: admin": 234,
"http-nio-8080-exec-1 url: /secure/QuickCreateIssue.jspa; user: admin": 230,
"http-nio-8080-exec-11 url: /rest/api/2/issue; user: admin": 228,
"http-nio-8080-exec-19 url: /secure/QuickCreateIssue.jspa; user: admin": 228,
"http-nio-8080-exec-2 url: /secure/QuickCreateIssue.jspa; user: admin": 228,
"http-nio-8080-exec-24 url: /rest/api/2/issue; user: admin": 227
},
"indexerNotRunningCounter": 0
}Example log: secondary queue total from the issue indexer
[JIRA-STATS] [INDEXING-QUEUE] index:ISSUE, total secondary queue stats:
{
"maxQueueSize": 61,
"putCounter": 138565,
"queueFullOnPut": 0,
"getCounter": 138564,
"timeInQueueMillis": {
"count": 138564,
"min": 0,
"max": 638,
"sum": 376014,
"avg": 2,
"distributionCounter": {
"0": 101336,
"1": 9278,
"10": 14857,
"100": 13076,
"1000": 17,
"10000": 0,
"20000": 0,
"30000": 0
}
},
"timeToUpdateIndexMillis": {
"count": 138563,
"min": 0,
"max": 2228,
"sum": 204177,
"avg": 1,
"distributionCounter": {
"0": 100538,
"1": 23558,
"10": 8793,
"50": 5019,
"100": 644,
"500": 0,
"1000": 10,
"9223372036854775807": 1
}
},
"totalTimeMillis": {
"count": 138563,
"min": 0,
"max": 2229,
"sum": 661863,
"avg": 4,
"distributionCounter": {
"0": 22111,
"1": 65967,
"10": 29831,
"100": 20624,
"1000": 29,
"10000": 1,
"20000": 0,
"30000": 0
}
},
"totalTimeFailedMillis": {
"count": 0,
"min": 0,
"max": 0,
"sum": 0,
"avg": 0,
"distributionCounter": {}
},
"totalTimeTimedOutMillis": {
"count": 0,
"min": 0,
"max": 0,
"sum": 0,
"avg": 0,
"distributionCounter": {}
},
"putCounterByThreadTopN": { // top N threads sorted by number of puts descending, secondary queue so these are all non-HTTP threads, here DBR replication threads;
"RMI TCP Connection(614)-10.0.0.93": 1195,
"RMI TCP Connection(1383)-10.0.0.93": 1024,
"RMI TCP Connection(529)-10.0.0.61": 978,
"RMI TCP Connection(879)-10.0.0.106": 942,
"RMI TCP Connection(1285)-10.0.0.61": 937,
"RMI TCP Connection(957)-10.0.0.158": 892,
"RMI TCP Connection(531)-10.0.0.61": 863,
"RMI TCP Connection(708)-10.0.0.93": 777,
"RMI TCP Connection(1141)-10.0.0.158": 766,
"RMI TCP Connection(1385)-10.0.0.153": 762
},
"indexerNotRunningCounter": 0
}