Details
-
Suggestion
-
Resolution: Won't Fix
Description
NOTE: This suggestion is for JIRA Cloud. Using JIRA Server? See the corresponding suggestion.
Due to the way JIRA commit to index on every index operation, we start seeing large instances that Lucene write operations (e.g create/edit issue) are slow waiting for QueueingIndex implementation (waiting for the writer thread to complete other running process one by one)
- Lets say we have ~100 issues in a queue (expected for instance with many creates/updated/deletes)
- Let's say each Lucene commit takes 10 ms
- Then 100 issues are forced to wait ~1s ( 100 issues * 10 ms), and if they are not lucky, then they have to wait for a previous batch to be finished first (total time spent in a queue: 1-2s)
In some cases the create issue can be as slow as 19s with the following breakdown
23:21:54 - action not started.
23:21:56 - reindexing issue after issue created/transitioned. || Indexing thread waiting for merging thread
23:21:58 - reindexing issue after issue created/transitioned || Indexing thread is working
23:22:01 - reindexing issue after issue Created event. || Indexing thread is working
23:22:04 - Service desk setStringPropertyToIssue and reindex issue || Indexing thread is working
23:22:06 - Service desk updates SLA value, and reindex issue. Waiting for reindexing to be finished. || Index thread is working
23:22:08 - Service desk updates SLA value, and reindex issue. Waiting for reindexing to be finished. || Index thread is working
23:22:11 - processing webhooks - reading from the index
23:22:13 - processing webhooks - reading from the index
23:22:15 - processing webhooks - reading from the index
23:22:16 - End of issue create action
Summary:
- issue create took ~19 seconds
- 4x reindexed the issue ( ~14 seconds)
- processing webhook (~ 5 seconds)
Environment
- JIRA 7.2.7
- 1.5M issues + 2k custom fields + 2.5M comments and 396 projects
- ServiceDesk with (100) automation rule
Verification
- Create/edit issue is slow (eg. 20s)
- Large number of threads waiting for re-index
grep -B 3 -A 10 'java.util.concurrent.CountDownLatch' threads/jira_threads.1489620113.txt | awk '/http-nio-8080/{print $1}' | sort -u | wc -l 150
- Example of the thread waiting for reindex:
"http-nio-8080-exec-374 uri:/secure/QuickCreateIssue.jspa username:admin" #8603445 daemon prio=5 os_prio=0 tid=0x00007f24b40d5800 nid=0x2f47 waiting on condition [0x00007f2346ff0000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000645800218> (a java.util.concurrent.CountDownLatch$Sync) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037) at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328) at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277) at com.atlassian.util.concurrent.SettableFuture.get(SettableFuture.java:83) at com.atlassian.jira.index.FutureResult.await(FutureResult.java:38) at com.atlassian.jira.index.AccumulatingResultBuilder$CompositeResult.await(AccumulatingResultBuilder.java:175) at com.atlassian.jira.issue.index.DefaultIndexManager$$Lambda$2043/398130608.await(Unknown Source) at com.atlassian.jira.issue.index.DefaultIndexManager.obtain(DefaultIndexManager.java:815) at com.atlassian.jira.issue.index.DefaultIndexManager.await(DefaultIndexManager.java:791) at com.atlassian.jira.issue.index.DefaultIndexManager.reIndexIssues(DefaultIndexManager.java:571) at com.atlassian.jira.issue.index.DefaultIndexManager.reIndexIssueObjects(DefaultIndexManager.java:468) at com.atlassian.jira.issue.index.DefaultIndexManager.reIndex(DefaultIndexManager.java:489) at com.atlassian.jira.issue.index.DefaultIndexManager.reIndex(DefaultIndexManager.java:473) at sun.reflect.GeneratedMethodAccessor1800.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.atlassian.jira.config.component.SwitchingInvocationHandler.invoke(SwitchingInvocationHandler.java:22) at com.sun.proxy.$Proxy16.reIndex(Unknown Source) at com.atlassian.jira.issue.index.IssueIndexManager$reIndex.call(Unknown Source)
- Example of the thread waiting for reindex:
- Issue reindex done in batches by ISSUE-indexQueue:thread-1
"ISSUE-indexQueue:thread-1" #431 prio=5 os_prio=0 tid=0x00007f22341ea000 nid=0x4f28 runnable [0x00007f18748f9000] java.lang.Thread.State: RUNNABLE at java.lang.String.intern(Native Method) at org.apache.lucene.util.SimpleStringInterner.intern(SimpleStringInterner.java:77) at org.apache.lucene.util.StringHelper.intern(StringHelper.java:39) at org.apache.lucene.index.FieldInfos.read(FieldInfos.java:362) at org.apache.lucene.index.FieldInfos.<init>(FieldInfos.java:71) at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:72) at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:114) at org.apache.lucene.index.IndexWriter$ReaderPool.get(IndexWriter.java:702) - locked <0x00000001d5ef7018> (a org.apache.lucene.index.IndexWriter$ReaderPool) at org.apache.lucene.index.IndexWriter$ReaderPool.get(IndexWriter.java:677) - locked <0x00000001d5ef7018> (a org.apache.lucene.index.IndexWriter$ReaderPool) at org.apache.lucene.index.BufferedDeletesStream.applyDeletes(BufferedDeletesStream.java:249) - locked <0x000000021a1b79b8> (a org.apache.lucene.index.BufferedDeletesStream) at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3571) - locked <0x00000001e1bd7430> (a org.apache.lucene.index.IndexWriter) at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3508) at org.apache.lucene.index.IndexWriter.prepareCommit(IndexWriter.java:3371) at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3444) - locked <0x00000001deb47cf0> (a java.lang.Object) at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3426) at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3410) at com.atlassian.jira.index.WriterWrapper.commit(WriterWrapper.java:115) at com.atlassian.jira.index.DefaultIndexEngine$WriterReference.commit(DefaultIndexEngine.java:239) at com.atlassian.jira.index.DefaultIndexEngine$FlushPolicy$2.commit(DefaultIndexEngine.java:69) at com.atlassian.jira.index.DefaultIndexEngine$FlushPolicy.perform(DefaultIndexEngine.java:124) at com.atlassian.jira.index.DefaultIndexEngine.write(DefaultIndexEngine.java:184) at com.atlassian.jira.index.DefaultIndex.perform(DefaultIndex.java:29) at com.atlassian.jira.index.QueueingIndex$Task.perform(QueueingIndex.java:132) - locked <0x00000001d5ef7048> (a com.atlassian.jira.index.QueueingIndex$Task) at com.atlassian.jira.index.QueueingIndex$Task.index(QueueingIndex.java:144) at com.atlassian.jira.index.QueueingIndex$Task.run(QueueingIndex.java:111) at java.lang.Thread.run(Thread.java:745)
Expected Results
Issue creation should be fast
Actual Results
Issue creation is as slow as 20s with many thread waiting on QueueingIndex
Workaround
None
Attachments
Issue Links
- is related to
-
JRASERVER-64900 Commit issue in batches instead of individual operation
- Closed