Uploaded image for project: 'Jira Data Center'
  1. Jira Data Center
  2. JRASERVER-65845

Possible deadlock in MS SQL and MySQL on CachingOfBizPropertyEntryStore

XMLWordPrintable

      Summary

      Under somewhat heavy concurrent load, some operations that rely on specific methods that interact with the propertyentry table will fail to complete due to a deadlock.

      Expected Behavior

      Have more robust locking mechanisms in place to prevent deadlocks from occurring.

      Actual Behavior

      Miscellaneous operations will fail and register a deadlock in the logs. See example below.

      MySQL
      2016-11-29 14:38:07,228 http-nio-8080-exec-22 ERROR admin 878x2525x9 18u7hc0 172.30.254.2 /rest/quickedit/1.0/userpreferences/create [c.a.p.r.c.error.jersey.ThrowableExceptionMapper] Uncaught exception thrown by REST service: Failed operation: SetOperation[entityName=ApplicationUser,entityId=10000,propertyKey=jira.quick.edit.show.welcome.screen,newType=1,newMapper=TypeMapper[handler=NumberPropertyHandler,valueEntity=OSPropertyNumber]]
com.opensymphony.module.propertyset.PropertyImplementationException: Failed operation: SetOperation[entityName=ApplicationUser,entityId=10000,propertyKey=jira.quick.edit.show.welcome.screen,newType=1,newMapper=TypeMapper[handler=NumberPropertyHandler,valueEntity=OSPropertyNumber]]
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.propEx(CachingOfBizPropertyEntryStore.java:324)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.retry(CachingOfBizPropertyEntryStore.java:310)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.setEntry(CachingOfBizPropertyEntryStore.java:148)
	at com.atlassian.jira.propertyset.CachingOfBizPropertySet.setImpl(CachingOfBizPropertySet.java:183)
	at com.opensymphony.module.propertyset.AbstractPropertySet.set(AbstractPropertySet.java:502)
	at com.opensymphony.module.propertyset.AbstractPropertySet.setBoolean(AbstractPropertySet.java:147)
	at com.atlassian.jira.quickedit.user.UserPreferencesStoreImpl.storeCreateUserPreferences(UserPreferencesStoreImpl.java:112)
	at com.atlassian.jira.quickedit.rest.UserPreferenceResource.setCreatePreferences(UserPreferenceResource.java:102)
	... 3 filtered
	at java.lang.reflect.Method.invoke(Method.java:497)
	... 19 filtered
	at com.atlassian.plugins.rest.module.RestDelegatingServletFilter$JerseyOsgiServletContainer.doFilter(RestDelegatingServletFilter.java:154)
	... 1 filtered
	at com.atlassian.plugins.rest.module.RestDelegatingServletFilter.doFilter(RestDelegatingServletFilter.java:68)
	... 36 filtered
	at com.atlassian.web.servlet.plugin.request.RedirectInterceptingFilter.doFilter(RedirectInterceptingFilter.java:21)
	... 53 filtered
	at com.atlassian.jira.security.JiraSecurityFilter.lambda$doFilter$0(JiraSecurityFilter.java:76)
	at com.atlassian.jira.security.JiraSecurityFilter$$Lambda$595/392679220.doFilter(Unknown Source)
	... 1 filtered
	at com.atlassian.jira.security.JiraSecurityFilter.doFilter(JiraSecurityFilter.java:74)
	... 16 filtered
	at com.atlassian.plugins.rest.module.servlet.RestSeraphFilter.doFilter(RestSeraphFilter.java:37)
	... 20 filtered
	at com.atlassian.jira.servermetrics.CorrelationIdPopulatorFilter.doFilter(CorrelationIdPopulatorFilter.java:30)
	... 20 filtered
	at com.atlassian.web.servlet.plugin.request.RedirectInterceptingFilter.doFilter(RedirectInterceptingFilter.java:21)
	... 4 filtered
	at com.atlassian.web.servlet.plugin.LocationCleanerFilter.doFilter(LocationCleanerFilter.java:36)
	... 29 filtered
	at com.atlassian.jira.servermetrics.MetricsCollectorFilter.doFilter(MetricsCollectorFilter.java:25)
	... 28 filtered
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Caused by: com.querydsl.core.QueryException: Caught MySQLTransactionRollbackException for insert into propertyentry (entity_name, entity_id, property_key, propertytype, id)
values (?, ?, ?, ?, ?)
	at com.querydsl.sql.DefaultSQLExceptionTranslator.translate(DefaultSQLExceptionTranslator.java:50)
	at com.querydsl.sql.Configuration.translate(Configuration.java:453)
	at com.querydsl.sql.dml.SQLInsertClause.execute(SQLInsertClause.java:396)
	at com.atlassian.jira.database.IdGeneratingSQLInsertClause.executeWithId(IdGeneratingSQLInsertClause.java:71)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore$SetOperation.upsert(CachingOfBizPropertyEntryStore.java:605)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore$SetOperation$$Lambda$317/1172449917.runQuery(Unknown Source)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.lambda$tx$6(CachingOfBizPropertyEntryStore.java:295)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore$$Lambda$313/1911659418.runQuery(Unknown Source)
	at com.atlassian.jira.database.DefaultQueryDslAccessor$1.lambda$executeQuery$0(DefaultQueryDslAccessor.java:83)
	at com.atlassian.jira.database.DefaultQueryDslAccessor$1$$Lambda$55/1269275298.run(Unknown Source)
	at com.atlassian.jira.database.DatabaseAccessorImpl.executeQuery(DatabaseAccessorImpl.java:67)
	at com.atlassian.jira.database.DefaultQueryDslAccessor$1.executeQuery(DefaultQueryDslAccessor.java:82)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.query(CachingOfBizPropertyEntryStore.java:285)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.tx(CachingOfBizPropertyEntryStore.java:293)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.access$300(CachingOfBizPropertyEntryStore.java:72)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore$SetOperation.perform(CachingOfBizPropertyEntryStore.java:592)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.retry(CachingOfBizPropertyEntryStore.java:304)
	... 252 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:408)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1074)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4226)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4158)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2615)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2776)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2840)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2082)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2334)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2262)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2246)
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:98)
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:98)
	at com.querydsl.sql.dml.SQLInsertClause.execute(SQLInsertClause.java:382)
	... 267 more
      MSSQL
      2017-08-14 14:39:39,375 http-nio-8080-exec-60 ERROR admin 878x3231x33 euiwg9 127.0.0.1 /secure/QuickCreateIssue.jspa [c.a.j.quickedit.action.QuickCreateIssue] com.opensymphony.module.propertyset.PropertyImplementationException: Failed operation: SetOperation[entityName=ApplicationUser,entityId=34711,propertyKey=user.last.issue.type.id,newType=5,newMapper=TypeMapper[handler=StringPropertyHandler,valueEntity=OSPropertyString]]
com.opensymphony.module.propertyset.PropertyImplementationException: Failed operation: SetOperation[entityName=ApplicationUser,entityId=34711,propertyKey=user.last.issue.type.id,newType=5,newMapper=TypeMapper[handler=StringPropertyHandler,valueEntity=OSPropertyString]]
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.propEx(CachingOfBizPropertyEntryStore.java:324)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.retry(CachingOfBizPropertyEntryStore.java:310)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.setEntry(CachingOfBizPropertyEntryStore.java:148)
	at com.atlassian.jira.propertyset.CachingOfBizPropertySet.setImpl(CachingOfBizPropertySet.java:183)
	at com.opensymphony.module.propertyset.AbstractPropertySet.set(AbstractPropertySet.java:502)
	at com.opensymphony.module.propertyset.AbstractPropertySet.setString(AbstractPropertySet.java:300)
	at com.atlassian.jira.user.preferences.JiraUserPreferences.setString(JiraUserPreferences.java:109)
	at com.atlassian.jira.user.UserIssueTypeManagerImpl.setIssueType(UserIssueTypeManagerImpl.java:66)
	at com.atlassian.jira.user.UserIssueTypeManagerImpl.setLastUsedIssueTypeId(UserIssueTypeManagerImpl.java:32)
	... 2 filtered
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
	at com.sun.proxy.$Proxy471.setLastUsedIssueTypeId(Unknown Source)
	... 2 filtered
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean$DynamicServiceInvocationHandler.invoke(HostComponentFactoryBean.java:136)
	at com.sun.proxy.$Proxy471.setLastUsedIssueTypeId(Unknown Source)
	at com.atlassian.jira.quickedit.action.QuickCreateIssue.doDefault(QuickCreateIssue.java:224)
	at com.atlassian.jira.quickedit.action.QuickCreateIssue.doExecute(QuickCreateIssue.java:356)
	... 1 filtered
	at com.atlassian.jira.action.JiraActionSupport.execute(JiraActionSupport.java:63)
	... 7 filtered
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
	... 52 filtered
	at com.atlassian.greenhopper.jira.filters.ClassicBoardRouter.doFilter(ClassicBoardRouter.java:62)
	... 7 filtered
	at com.atlassian.web.servlet.plugin.request.RedirectInterceptingFilter.doFilter(RedirectInterceptingFilter.java:21)
	... 20 filtered
	at com.intenso.jira.contentinjection.filter.ContentInjectionFilter.doFilter(ContentInjectionFilter.java:71)
	... 41 filtered
	at com.atlassian.jira.security.JiraSecurityFilter.lambda$doFilter$0(JiraSecurityFilter.java:76)
	... 1 filtered
	at com.atlassian.jira.security.JiraSecurityFilter.doFilter(JiraSecurityFilter.java:74)
	... 36 filtered
	at com.atlassian.jira.servermetrics.CorrelationIdPopulatorFilter.doFilter(CorrelationIdPopulatorFilter.java:30)
	... 5 filtered
	at com.valiantys.jira.plugins.sql.service.servicedesk.ContextListenerServletFilter.doFilter(ContextListenerServletFilter.java:24)
	... 8 filtered
	at com.atlassian.web.servlet.plugin.request.RedirectInterceptingFilter.doFilter(RedirectInterceptingFilter.java:21)
	... 4 filtered
	at com.atlassian.web.servlet.plugin.LocationCleanerFilter.doFilter(LocationCleanerFilter.java:36)
	... 29 filtered
	at com.atlassian.jira.servermetrics.MetricsCollectorFilter.doFilter(MetricsCollectorFilter.java:25)
	... 27 filtered
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Caused by: com.querydsl.core.QueryException: Caught SQLException for select O_S_PROPERTY_ENTRY.id, O_S_PROPERTY_ENTRY.propertytype
from propertyentry O_S_PROPERTY_ENTRY
with (updlock)
where O_S_PROPERTY_ENTRY.entity_name = ? and O_S_PROPERTY_ENTRY.entity_id = ? and O_S_PROPERTY_ENTRY.property_key = ?
order by O_S_PROPERTY_ENTRY.id desc
	at com.querydsl.sql.DefaultSQLExceptionTranslator.translate(DefaultSQLExceptionTranslator.java:50)
	at com.querydsl.sql.AbstractSQLQuery.fetch(AbstractSQLQuery.java:502)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore$SetOperation.upsert(CachingOfBizPropertyEntryStore.java:604)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.lambda$tx$6(CachingOfBizPropertyEntryStore.java:295)
	at com.atlassian.jira.database.DefaultQueryDslAccessor$1.lambda$executeQuery$0(DefaultQueryDslAccessor.java:83)
	at com.atlassian.jira.database.DatabaseAccessorImpl.executeQuery(DatabaseAccessorImpl.java:67)
	at com.atlassian.jira.database.DefaultQueryDslAccessor$1.executeQuery(DefaultQueryDslAccessor.java:82)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.query(CachingOfBizPropertyEntryStore.java:285)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.tx(CachingOfBizPropertyEntryStore.java:293)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.access$300(CachingOfBizPropertyEntryStore.java:72)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore$SetOperation.perform(CachingOfBizPropertyEntryStore.java:592)
	at com.atlassian.jira.propertyset.CachingOfBizPropertyEntryStore.retry(CachingOfBizPropertyEntryStore.java:304)
	... 273 more
Caused by: java.sql.SQLException: Transaction (Process ID 188) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
	at net.sourceforge.jtds.jdbc.SQLDiagnostic.addDiagnostic(SQLDiagnostic.java:372)
	at net.sourceforge.jtds.jdbc.TdsCore.tdsErrorToken(TdsCore.java:2988)
	at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2421)
	at net.sourceforge.jtds.jdbc.TdsCore.isDataInResultSet(TdsCore.java:838)
	at net.sourceforge.jtds.jdbc.JtdsResultSet.<init>(JtdsResultSet.java:149)
	at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeQuery(JtdsPreparedStatement.java:1029)
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
	at com.querydsl.sql.AbstractSQLQuery.fetch(AbstractSQLQuery.java:446)
	... 283 more

      Steps to Reproduce

      The bug is not easily reproducible, but it might happen, for example, when a user opens multiple issues in separate tabs.

      Workaround

              Unassigned Unassigned
              jpalharini Joao Palharini (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: