Details
-
Bug
-
Resolution: Fixed
-
Medium
-
5.9.4
Description
Problem
When running on MySQL, automatic build plan deletion is slow, possibly resulting in new builds failing to start with:
org.springframework.jdbc.UncategorizedSQLException: Hibernate flushing: Could not execute JDBC batch update; uncategorized SQLException for SQL [insert into REPOSITORY_CHANGESET (BUILDRESULTSUMMARY_ID, VCS_LOCATION_ID, CHANGESET_ID, SKIPPED_COMMITS_COUNT, LIST_POSITION, BUILD_TRIGGER, REPOSITORY_CHANGESET_ID) values (?, ?, ?, ?, ?, ?, ?)]; SQL state [41000]; error code [1205]; Lock wait timeout exceeded; try restarting transaction; nested exception is java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:84) at org.springframework.orm.hibernate3.HibernateTransactionManager.convertJdbcAccessException(HibernateTransactionManager.java:811) at org.springframework.orm.hibernate3.HibernateTransactionManager.convertHibernateAccessException(HibernateTransactionManager.java:797) at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:669) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:757) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:726) at sun.reflect.GeneratedMethodAccessor130.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:201) at com.sun.proxy.$Proxy27.commit(Unknown Source) at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:478) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:272) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:95) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) at com.sun.proxy.$Proxy61.updateResultSummaryWithBuildChanges(Unknown Source) at com.atlassian.bamboo.chains.ChainExecutionManagerImpl$2.getChainState(ChainExecutionManagerImpl.java:235) at com.atlassian.bamboo.chains.ChainExecutionManagerImpl.tryStartChainState(ChainExecutionManagerImpl.java:278) at com.atlassian.bamboo.chains.ChainExecutionManagerImpl.delayedStart(ChainExecutionManagerImpl.java:214) 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:497) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) at com.sun.proxy.$Proxy146.delayedStart(Unknown Source) at com.atlassian.bamboo.plan.PlanExecutionManagerImpl$2$1$1$1.run(PlanExecutionManagerImpl.java:430) at com.atlassian.bamboo.util.CacheAwareness$2.call(CacheAwareness.java:83) at com.atlassian.bamboo.util.CacheAwareness$2.call(CacheAwareness.java:79) at com.atlassian.bamboo.util.CacheAwareness.whileReadingThroughCaches(CacheAwareness.java:101) at com.atlassian.bamboo.util.CacheAwareness.whileReadingThroughCaches(CacheAwareness.java:78) at com.atlassian.bamboo.util.CacheAwareness.whileReadingThroughCaches(CacheAwareness.java:118) at com.atlassian.bamboo.plan.PlanExecutionManagerImpl$2$1$1.call(PlanExecutionManagerImpl.java:425) at com.atlassian.bamboo.plan.PlanExecutionManagerImpl$2$1$1.call(PlanExecutionManagerImpl.java:417) at com.atlassian.util.concurrent.ManagedLocks$ManagedLockImpl.withLock(ManagedLocks.java:312) at com.atlassian.bamboo.plan.PlanExecutionLockServiceImpl.lock(PlanExecutionLockServiceImpl.java:85) at com.atlassian.bamboo.plan.PlanExecutionManagerImpl.doWithProcessLock(PlanExecutionManagerImpl.java:800) at com.atlassian.bamboo.plan.PlanExecutionManagerImpl.access$300(PlanExecutionManagerImpl.java:129) at com.atlassian.bamboo.plan.PlanExecutionManagerImpl$2$1.run(PlanExecutionManagerImpl.java:411) at com.atlassian.bamboo.utils.BambooRunnables$1.run(BambooRunnables.java:49) at com.atlassian.bamboo.security.ImpersonationHelper.runWith(ImpersonationHelper.java:31) at com.atlassian.bamboo.security.ImpersonationHelper.runWithSystemAuthority(ImpersonationHelper.java:20) at com.atlassian.bamboo.security.ImpersonationHelper$1.run(ImpersonationHelper.java:52) at java.lang.Thread.run(Thread.java:745) Caused by: java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2054) at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1467) at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723) at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70) at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:268) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:184) at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51) at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216) at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:383) at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:133) at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:661) ... 46 more Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1078) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4120) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4052) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2503) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2664) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2815) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2458) at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2006) ... 58 more
Diagnosis
To diagnose the problem, start Bamboo with -Datlassian.profile.activate=true and enable DEBUG logging for the class: com.atlassian.util.profiling.UtilTimerStack. The logs for build deletion then will show the progress like:
2015-10-14 19:22:00,639 DEBUG [AtlassianEvent::0-BAM::EVENTS:pool-3-thread-8] [UtilTimerStack] [143344ms] - DeletionServiceImpl.removePlan(XXXXXXXXXXXXX) [143236ms] - Remove result summaries [16866ms] - Remove test results [61256ms] - delete from COMMIT_FILES where COMMIT_ID in (select COMMIT_ID from USER_COMMIT where REPOSITORY_CHANGESET_ID in (select REPOSITORY_CHANGESET_ID from REPOSITORY_CHANGESET where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) ) [7749ms] - delete from USER_COMMIT where REPOSITORY_CHANGESET_ID in (select REPOSITORY_CHANGESET_ID from REPOSITORY_CHANGESET where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) [355ms] - delete from BRS_CONSUMED_SUBSCRIPTION where ARTIFACT_LINK_ID in (select ARTIFACT_LINK_ID from BRS_ARTIFACT_LINK where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) OR PRODUCERJOBRESULT_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) OR CONSUMER_RESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) [206ms] - delete from BRS_ARTIFACT_LINK where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) or PRODUCERJOBRESULT_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) [1011ms] - delete from RELEVANT_CHANGESETS where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [1022ms] - delete from REPOSITORY_CHANGESET where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [1ms] - delete from BUILDRESULTSUMMARY_LABEL where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [51274ms] - delete from BUILDRESULTSUMMARY_CUSTOMDATA where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [516ms] - delete from BRS_LINKEDJIRAISSUES where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [426ms] - delete from VARIABLE_CONTEXT where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [1655ms] - delete from VARIABLE_SUBSTITUTION where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [10ms] - delete from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ? and BUILD_TYPE <> 'CHAIN' [3ms] - delete from STAGE_VARIABLE_CONTEXT where STAGERESULT_ID IN (select STAGERESULT_ID from CHAIN_STAGE_RESULT where CHAINRESULT_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) [763ms] - delete from CHAIN_STAGE_RESULT where CHAINRESULT_ID IN (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) [1ms] - delete from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ? and BUILD_TYPE = 'CHAIN' [10ms] - De-indexing build "XXXXXXXXXXXXX" [15ms] - Remove plan particles and dependencies [18ms] - Remove plan variables [13ms] - Remove repositories and plan vcs history [7ms] - Remove Bandana Data [10ms] - Remove agent assignments [0ms] - delete Buildable [0ms] - DeletionServiceImpl.clearBuildDirectories() 2015-10-14 19:22:00,759 WARN [AtlassianEvent::0-BAM::EVENTS:pool-3-thread-8] [S3ArtifactHandlerConfigurator] S3 artifact handler was used, but AWS credentials are missing 2015-10-14 19:22:00,760 WARN [AtlassianEvent::0-BAM::EVENTS:pool-3-thread-8] [S3ArtifactHandler] S3 artifact handling won't work: bucket name is invalid: [null] 2015-10-14 19:22:00,762 INFO [AtlassianEvent::0-BAM::EVENTS:pool-3-thread-8] [DeletionServiceImpl] Deleting XXXXXXXXXXXXX 2015-10-14 19:24:20,420 DEBUG [14-IndexerService.indexer:pool-30-thread-1] [UtilTimerStack] [1ms] - com.atlassian.bonnie.LoggingReentrantLock.indexWriteLock [1ms] - com.atlassian.bonnie.LoggingReentrantLock.searcherRefreshLock 2015-10-14 19:24:20,437 DEBUG [AtlassianEvent::0-BAM::EVENTS:pool-3-thread-8] [UtilTimerStack] [139674ms] - DeletionServiceImpl.removePlan(XXXXXXXXXXXXX) [139656ms] - Remove result summaries [16079ms] - Remove test results [58804ms] - delete from COMMIT_FILES where COMMIT_ID in (select COMMIT_ID from USER_COMMIT where REPOSITORY_CHANGESET_ID in (select REPOSITORY_CHANGESET_ID from REPOSITORY_CHANGESET where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) ) [8064ms] - delete from USER_COMMIT where REPOSITORY_CHANGESET_ID in (select REPOSITORY_CHANGESET_ID from REPOSITORY_CHANGESET where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) [358ms] - delete from BRS_CONSUMED_SUBSCRIPTION where ARTIFACT_LINK_ID in (select ARTIFACT_LINK_ID from BRS_ARTIFACT_LINK where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) OR PRODUCERJOBRESULT_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) OR CONSUMER_RESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) [200ms] - delete from BRS_ARTIFACT_LINK where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) or PRODUCERJOBRESULT_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) [1014ms] - delete from RELEVANT_CHANGESETS where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [1011ms] - delete from REPOSITORY_CHANGESET where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [1ms] - delete from BUILDRESULTSUMMARY_LABEL where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [50600ms] - delete from BUILDRESULTSUMMARY_CUSTOMDATA where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [529ms] - delete from BRS_LINKEDJIRAISSUES where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [416ms] - delete from VARIABLE_CONTEXT where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [1681ms] - delete from VARIABLE_SUBSTITUTION where BUILDRESULTSUMMARY_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ?) [7ms] - delete from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ? and BUILD_TYPE <> 'CHAIN' [1ms] - delete from STAGE_VARIABLE_CONTEXT where STAGERESULT_ID IN (select STAGERESULT_ID from CHAIN_STAGE_RESULT where CHAINRESULT_ID in (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) ) [771ms] - delete from CHAIN_STAGE_RESULT where CHAINRESULT_ID IN (select BUILDRESULTSUMMARY_ID from BUILDRESULTSUMMARY where BUILD_KEY = ?) [1ms] - delete from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY.BUILD_KEY = ? and BUILD_TYPE = 'CHAIN' [1ms] - De-indexing build "XXXXXXXXXXXXX" [3ms] - Remove plan particles and dependencies [1ms] - Remove plan variables [7ms] - Remove repositories and plan vcs history [1ms] - Remove Bandana Data [0ms] - Remove agent assignments [0ms] - delete Buildable [0ms] - DeletionServiceImpl.clearBuildDirectories()
As seen, the delete statements take up most of the time. The statements will run long, regardless if they actually delete any rows.