JIRA may become unresponsive when creating too many concurrent create requests due to transaction in OfBizCustomFieldValuePersister

Summary

Summary

Jira can become unresponsive when too many concurrent "Create Issue" requests happen.
While the problem is similar to JRASERVER-30528, it has some specific conditions:

• The threads create new Issue and each would create a transaction as part of updateValues (and request a connection from the pool), not all would get a connection and some would be waiting.
  • We will call those that acquired a connection threads 'A' to 'H'. Threads 'I' and 'J' would be waiting.
• At some point one thread would cause the sequence generator to require new block of sequences
• The sequence generator would request a new connection from the pool. Assume this is Thread 'A'.
• Thread 'A' would then require a sequence number calling SequenceUtil.SequenceBank.getNextSeqId() and need to get a new block of ids would then request a connection from the DB pool to do so
  • It needs a new connection to do this so it is not in the transaction of the calling thread
• Thread 'A' is waiting for the connection from the DB pool. DB pool is full.
• The remaining threads would block at SequenceUtil.SequenceBank.getNextSeqId(), which is a synchronised method
• Threads 'B' to 'H" are all now waiting on the synchronization lock of SequenceUtil.SequenceBank.getNextSeqId() which is held by thread 'A' and so will never release a connection for thread 'A' to use.
• Jira becomes unresponsive
  • Afterwards, the threads are in state similar to deadlocks while waiting for connection pool. After a DB pool timeout expires, connections will timeout, opening up new connections to eventually then complete the requests. During this period of time, Jira would be unresponsive.

Steps to Reproduce

• Create many global fields with default values
  • Example from local testing: created 50 select fields with default values configured.
• Initiate a constant stream of concurrent requests creating issues in Jira, a number of concurrent requests needs to be larger than the maximum DB pool size in dbconfig.xml.

Expected Results

Jira creates all issues successfully

Actual Results

Jira becomes unresponsive; and in large production instances, may require a restart. Depending on the scenario, Jira may also recover after a period of time.

Diagnosis

• Threads blocked at getNextSeqId

  "http-nio-8080-exec-61" #221 daemon prio=5 os_prio=31 tid=0x00007ff18bdf7800 nid=0x1f803 waiting for monitor entry [0x000070001654e000]
     java.lang.Thread.State: BLOCKED (on object monitor)
          at org.ofbiz.core.entity.SequenceUtil$SequenceBank.getNextSeqId(SequenceUtil.java:141)
          - waiting to lock <0x00000007af46e2c0> (a org.ofbiz.core.entity.SequenceUtil$SequenceBank)
          at org.ofbiz.core.entity.SequenceUtil.getNextSeqId(SequenceUtil.java:97)
          at org.ofbiz.core.entity.GenericDelegator.getNextSeqId(GenericDelegator.java:2474)
          at org.ofbiz.core.entity.DelegatorInterface.getNextSeqId(DelegatorInterface.java:266)
          at com.atlassian.jira.ofbiz.DefaultOfBizDelegator.createValue(DefaultOfBizDelegator.java:291)
          at com.atlassian.jira.ofbiz.WrappingOfBizDelegator.createValue(WrappingOfBizDelegator.java:172)
          at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.createValuesInt(OfBizCustomFieldValuePersister.java:129)
          at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.updateValues(OfBizCustomFieldValuePersister.java:154)
          at com.atlassian.jira.issue.customfields.persistence.EagerLoadingOfBizCustomFieldPersister.updateValues(EagerLoadingOfBizCustomFieldPersister.java:54)
          at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.createValues(OfBizCustomFieldValuePersister.java:109)
          at com.atlassian.jira.issue.customfields.persistence.EagerLoadingOfBizCustomFieldPersister.createValues(EagerLoadingOfBizCustomFieldPersister.java:42)
          at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.createValues(OfBizCustomFieldValuePersister.java:102)
          at com.atlassian.jira.issue.customfields.persistence.EagerLoadingOfBizCustomFieldPersister.createValues(EagerLoadingOfBizCustomFieldPersister.java:36)
          at com.atlassian.jira.issue.customfields.impl.AbstractSingleFieldType.createValue(AbstractSingleFieldType.java:143)
          at com.atlassian.jira.issue.fields.ImmutableCustomField.createValue(ImmutableCustomField.java:693)
          at com.atlassian.jira.workflow.function.issue.IssueCreateFunction.execute(IssueCreateFunction.java:81)
          at com.opensymphony.workflow.AbstractWorkflow.executeFunction(AbstractWorkflow.java:1014)
          at com.opensymphony.workflow.AbstractWorkflow.transitionWorkflow(AbstractWorkflow.java:1407)
          at com.opensymphony.workflow.AbstractWorkflow.initialize(AbstractWorkflow.java:606)
          at com.atlassian.jira.workflow.OSWorkflowManager.createIssue(OSWorkflowManager.java:742)
          at com.atlassian.jira.issue.managers.DefaultIssueManager.createIssue(DefaultIssueManager.java:580)
          at com.atlassian.jira.issue.managers.DefaultIssueManager.createIssue(DefaultIssueManager.java:494)
          at com.atlassian.jira.issue.managers.RequestCachingIssueManager.createIssue(RequestCachingIssueManager.java:192)
          at com.atlassian.jira.bc.issue.DefaultIssueService.create(DefaultIssueService.java:238)
          at com.atlassian.jira.bc.issue.DefaultIssueService.create(DefaultIssueService.java:207)
          at sun.reflect.GeneratedMethodAccessor840.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
          at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
          at com.sun.proxy.$Proxy319.create(Unknown Source)
  		...
  		...
          at com.atlassian.jira.rest.v2.issue.CreateIssueResource.createIssue(CreateIssueResource.java:166)
          at com.atlassian.jira.rest.v2.issue.CreateIssueResource.createIssue(CreateIssueResource.java:57)
          at com.atlassian.jira.rest.v2.issue.IssueResource.createIssue(IssueResource.java:594)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
  

• thread trying to get connection as part of updateValues, needs DB connection:

  "http-nio-8080-exec-45" #206 daemon prio=5 os_prio=31 tid=0x00007ff18488d800 nid=0x701f waiting on condition [0x00007000146f4000]
     java.lang.Thread.State: TIMED_WAITING (parking)
          at sun.misc.Unsafe.park(Native Method)
          - parking to wait for  <0x0000000771d73f68> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
          at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
          at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
          at org.apache.commons.pool2.impl.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:631)
          at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:444)
          at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
          at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
          at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
          at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:285)
          at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:283)
          at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:48)
          at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.trackConnection(DBCPConnectionFactory.java:283)
          at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.getConnection(DBCPConnectionFactory.java:80)
          at org.ofbiz.core.entity.ConnectionFactory.tryGenericConnectionSources(ConnectionFactory.java:69)
          at org.ofbiz.core.entity.transaction.JNDIFactory.getConnection(JNDIFactory.java:173)
          at org.ofbiz.core.entity.TransactionFactory.getConnection(TransactionFactory.java:114)
          at org.ofbiz.core.entity.ConnectionFactory.getConnection(ConnectionFactory.java:59)
          at org.ofbiz.core.entity.TransactionUtil.beginLocalTransaction(TransactionUtil.java:287)
          at com.atlassian.core.ofbiz.util.CoreTransactionUtil.begin(CoreTransactionUtil.java:50)
          at com.atlassian.jira.transaction.TransactionSupportImpl.beginTxn(TransactionSupportImpl.java:52)
          at com.atlassian.jira.transaction.TransactionSupportImpl.startedTransaction(TransactionSupportImpl.java:46)
          at com.atlassian.jira.transaction.TransactionSupportImpl.begin(TransactionSupportImpl.java:31)
          at com.atlassian.jira.transaction.Txn.begin(Txn.java:17)
          at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.updateValues(OfBizCustomFieldValuePersister.java:150)
          at com.atlassian.jira.issue.customfields.persistence.EagerLoadingOfBizCustomFieldPersister.updateValues(EagerLoadingOfBizCustomFieldPersister.java:54)
          at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.createValues(OfBizCustomFieldValuePersister.java:109)
          at com.atlassian.jira.issue.customfields.persistence.EagerLoadingOfBizCustomFieldPersister.createValues(EagerLoadingOfBizCustomFieldPersister.java:42)
          at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.createValues(OfBizCustomFieldValuePersister.java:102)
          at com.atlassian.jira.issue.customfields.persistence.EagerLoadingOfBizCustomFieldPersister.createValues(EagerLoadingOfBizCustomFieldPersister.java:36)
          at com.atlassian.jira.issue.customfields.impl.AbstractSingleFieldType.createValue(AbstractSingleFieldType.java:143)
          at com.atlassian.jira.issue.fields.ImmutableCustomField.createValue(ImmutableCustomField.java:693)
          at com.atlassian.jira.workflow.function.issue.IssueCreateFunction.execute(IssueCreateFunction.java:81)
          at com.opensymphony.workflow.AbstractWorkflow.executeFunction(AbstractWorkflow.java:1014)
          at com.opensymphony.workflow.AbstractWorkflow.transitionWorkflow(AbstractWorkflow.java:1407)
          at com.opensymphony.workflow.AbstractWorkflow.initialize(AbstractWorkflow.java:606)
          at com.atlassian.jira.workflow.OSWorkflowManager.createIssue(OSWorkflowManager.java:742)
          at com.atlassian.jira.issue.managers.DefaultIssueManager.createIssue(DefaultIssueManager.java:580)
          at com.atlassian.jira.issue.managers.DefaultIssueManager.createIssue(DefaultIssueManager.java:494)
          at com.atlassian.jira.issue.managers.RequestCachingIssueManager.createIssue(RequestCachingIssueManager.java:192)
          at com.atlassian.jira.bc.issue.DefaultIssueService.create(DefaultIssueService.java:238)
          at com.atlassian.jira.bc.issue.DefaultIssueService.create(DefaultIssueService.java:207)
  		...
  		...
          at com.atlassian.jira.rest.v2.issue.CreateIssueResource.createIssue(CreateIssueResource.java:166)
          at com.atlassian.jira.rest.v2.issue.CreateIssueResource.createIssue(CreateIssueResource.java:57)
          at com.atlassian.jira.rest.v2.issue.IssueResource.createIssue(IssueResource.java:594)
          at sun.reflect.GeneratedMethodAccessor603.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
  

• thread holding the lock, executing getNextSeqId, needs DB connection (thread 'A' in previous terminlogy):

  "http-nio-8280-exec-244" #690 daemon prio=5 tid=0x00007fd028082000 nid=0x5a68 waiting on condition [0x00007fd09c233000]
     java.lang.Thread.State: TIMED_WAITING (parking)
  	at sun.misc.Unsafe.park(Native Method)
  	- parking to wait for  <0x0000000081139058> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
  	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
  	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
  	at org.apache.commons.pool2.impl.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:631)
  	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:444)
  	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
  	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
  	at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
  	at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:285)
  	at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:283)
  	at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:48)
  	at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.trackConnection(DBCPConnectionFactory.java:283)
  	at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.getConnection(DBCPConnectionFactory.java:80)
  	at org.ofbiz.core.entity.ConnectionFactory.tryGenericConnectionSources(ConnectionFactory.java:69)
  	at org.ofbiz.core.entity.transaction.JNDIFactory.getConnection(JNDIFactory.java:173)
  	at org.ofbiz.core.entity.TransactionFactory.getConnection(TransactionFactory.java:114)
  	at org.ofbiz.core.entity.ConnectionFactory.getConnection(ConnectionFactory.java:59)
  	at org.ofbiz.core.entity.SequenceUtil$SequenceBank.fillBank(SequenceUtil.java:195)
  	- locked <0x00000000ddb51140> (a org.ofbiz.core.entity.SequenceUtil$SequenceBank)
  	at org.ofbiz.core.entity.SequenceUtil$SequenceBank.getNextSeqId(SequenceUtil.java:147)
  	- locked <0x00000000ddb51140> (a org.ofbiz.core.entity.SequenceUtil$SequenceBank)
  	at org.ofbiz.core.entity.SequenceUtil.getNextSeqId(SequenceUtil.java:97)
  	at org.ofbiz.core.entity.GenericDelegator.getNextSeqId(GenericDelegator.java:2474)
  	at org.ofbiz.core.entity.DelegatorInterface.getNextSeqId(DelegatorInterface.java:266)
  	at com.atlassian.jira.ofbiz.DefaultOfBizDelegator.createValue(DefaultOfBizDelegator.java:291)
  	at com.atlassian.jira.ofbiz.WrappingOfBizDelegator.createValue(WrappingOfBizDelegator.java:172)
  	at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.createValuesInt(OfBizCustomFieldValuePersister.java:129)
  	at com.atlassian.jira.issue.customfields.persistence.OfBizCustomFieldValuePersister.updateValues(OfBizCustomFieldValuePersister.java:154)
  	at com.atlassian.jira.issue.customfields.persistence.EagerLoadingOfBizCustomFieldPersister.updateValues(EagerLoadingOfBizCustomFieldPersister.java:54)
  	...
  

• There are no connections available in the pool.
• Notice that most threads are holding onto a db connection, yet BLOCKED, causing deadlock.

  grep -c 'OfBizCustomFieldValuePersister.java:154' jira_threads.*
  jira_threads.1534536906.txt:20
  jira_threads.1534536924.txt:20
  jira_threads.1534536942.txt:20
  
  grep -c 'waiting to lock <0x00000000cc3d4340' ./jira_threads.*
  ./jira_threads.1534536906.txt:19
  ./jira_threads.1534536924.txt:19
  ./jira_threads.1534536942.txt:19
  
  "http-nio-8280-exec-16  java.lang.Thread.State: TIMED_WAITING (parking)
  	- parking to wait for  <0x00000000810da1d8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
  	- locked <0x00000000cc3d4340> (a org.ofbiz.core.entity.SequenceUtil$SequenceBank)
  	- locked <0x00000000cc3d4340> (a org.ofbiz.core.entity.SequenceUtil$SequenceBank)
  

Workaround

• Increasing the database pool size (in $jira-home/dbconfig.xml) can help to alleviate this problem. Increasing the pool size will reduce the impact this bug has (as there will be more connections available for other threads to complete during peak periods).
• Decrease pool timeout value "<pool-max-wait>5000</pool-max-wait>" (in $jira-home/dbconfig.xml)
• When increasing the database pool size in Jira, be sure to take into account the hardware of your database server, the workload it might be performing for other applications, as well as how many connections it can support - for example, MySQL has a maximum of 150 connections + 1 super user; and Postgres typically has a default of 100 connections. Make small, incremental changes, testing and verifying as you go.