Commit issue in batches instead of individual operation

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