Uploaded image for project: 'Bamboo Data Center'
  1. Bamboo Data Center
  2. BAM-16459

Build deletion has bad performance when running on MySQL

    XMLWordPrintable

Details

    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.

      Attachments

        Issue Links

          Activity

            People

              kbrazulewicz Krystian Brazulewicz
              pkoczan Peter Koczan (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: