all JIRA threads are blocked waiting for cache UsersSecurityLevels

Summary

JIRA is very slow or inaccessible. Almost all incoming http threads are blocked waiting for cache getUsersSecurityLevels to be populated.
Problem could be caused by two factors:

• Too frequent cache flush
• Slow cache population

Environment

• Large number of issue: 1M+
• Large number of users: 50k+
• High concurrent load: 300 request/min

Steps to Reproduce

1. TBD

Expected Results

JIRA can handle high load

Actual Results

JIRA is very slow.
Thread-dump will show that there are a lot of threads in java.lang.Thread.State: WAITING state waiting for cache.

Notes

Please note that doAddUserToGroup() or addActorsToProjectRole() will cause flush of the projectAndUserToSecurityLevelCache cache.

More detailed break-down from thread dump

• Number of threads and state: based on Future 0000001303b43078

  find ./ -name '*.td' | xargs -n 1 -I %  sh -c '/bin/echo -n %; grep -B 3 -A 20 0000001303b43078 % | grep -e java.lang.Thread.State | sed 's/prio.*//' |sort | uniq -c '
  .//jira_threads.1484815453.txt1.td 214    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815466.txt1.td 208    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815479.txt1.td 212    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815492.txt1.td 
     1    java.lang.Thread.State: RUNNABLE
     211    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815505.txt1.td 191    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815518.txt1.td 178    java.lang.Thread.State: WAITING (parking)
  

• Number of threads and state with getUsersSecurityLevels method, majority of the thread doing getUsersSecurityLevels are waiting for cache.

  find ./ -name '*.td' | xargs -n 1 -I %  sh -c '/bin/echo -n %; grep -B 20 com.atlassian.jira.issue.security.IssueSecurityLevelManagerImpl.getUsersSecurityLevels % | grep -e java.lang.Thread.State | sort | uniq -c '
  .//jira_threads.1484815453.txt1.td 295    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815466.txt1.td 295    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815479.txt1.td   1    java.lang.Thread.State: RUNNABLE
   307    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815492.txt1.td   1    java.lang.Thread.State: RUNNABLE
   302    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815505.txt1.td 266    java.lang.Thread.State: WAITING (parking)
  .//jira_threads.1484815518.txt1.td 257    java.lang.Thread.State: WAITING (parking)
  

• Overall getUsersSecurityLevels in thread dumps (quick check):

  grep -c 'com.atlassian.jira.issue.security.IssueSecurityLevelManagerImpl.getUsersSecurityLevels' *.td
  
  jira_threads.1484815453.txt1.td:590
  jira_threads.1484815466.txt1.td:590
  jira_threads.1484815479.txt1.td:616
  jira_threads.1484815492.txt1.td:606
  jira_threads.1484815505.txt1.td:534
  jira_threads.1484815518.txt1.td:516
  

Example of the thread:

"ajp-nio-8009-exec-1654" #794541 daemon prio=5 tid=0x00007f563d925000 nid=0xd431  waiting on condition   
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(ZJ)V(Native Method)
	- parking to wait for  <0x0000001303b43078> (a java.util.concurrent.locks.ReentrantReadWriteLock$FairSync)
	at java.util.concurrent.locks.LockSupport.park(Ljava/lang/Object;)V(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt()Z(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(I)V(AbstractQueuedSynchronizer.java:967)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(I)V(AbstractQueuedSynchronizer.java:1283)
	at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock()V(ReentrantReadWriteLock.java:751)
	at com.atlassian.cache.memory.BlockingCacheLoader.load(Ljava/lang/Object;)Ljava/lang/Object;(BlockingCacheLoader.java:50)
	at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(Ljava/lang/Object;Lcom/google/common/cache/CacheLoader;)Lcom/google/common/util/concurrent/ListenableFuture;(LocalCache.java:3573)
	at com.google.common.cache.LocalCache$Segment.loadSync(Ljava/lang/Object;ILcom/google/common/cache/LocalCache$LoadingValueReference;Lcom/google/common/cache/CacheLoader;)Ljava/lang/Object;(LocalCache.java:2350)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(Ljava/lang/Object;ILcom/google/common/cache/CacheLoader;)Ljava/lang/Object;(LocalCache.java:2313)
	- locked <0x0000001085e4a360> (a com.google.common.cache.LocalCache$StrongAccessEntry)
	at com.google.common.cache.LocalCache$Segment.get(Ljava/lang/Object;ILcom/google/common/cache/CacheLoader;)Ljava/lang/Object;(LocalCache.java:2228)
	at com.google.common.cache.LocalCache.get(Ljava/lang/Object;Lcom/google/common/cache/CacheLoader;)Ljava/lang/Object;(LocalCache.java:3970)
	at com.google.common.cache.LocalCache.getOrLoad(Ljava/lang/Object;)Ljava/lang/Object;(LocalCache.java:3974)
	at com.google.common.cache.LocalCache$LocalManualCache.get(Ljava/lang/Object;)Ljava/lang/Object;(LocalCache.java:4834)
	at com.atlassian.cache.memory.DelegatingCache$DelegatingLoadingCache.get(Ljava/lang/Object;)Ljava/lang/Object;(DelegatingCache.java:324)
	at com.atlassian.jira.issue.security.IssueSecurityLevelManagerImpl.getUsersSecurityLevels(Lorg/ofbiz/core/entity/GenericValue;Lcom/atlassian/crowd/embedded/api/User;)Ljava/util/List;(IssueSecurityLevelManagerImpl.java:225)
	at com.atlassian.jira.issue.security.IssueSecurityLevelManagerImpl.getUsersSecurityLevels(Lcom/atlassian/jira/project/Project;Lcom/atlassian/crowd/embedded/api/User;)Ljava/util/List;(IssueSecurityLevelManagerImpl.java:272)
...

Workaround

• While working on support case we identified that problem was caused by too frequent cache flush events.
  • Large amount of cache flush events were triggered by SOAP calls to JIRA from integration framework.