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)
    

• 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