SonarQube
  1. SonarQube
  2. SONAR-2190

Database Locks when two projects are built simultaneously

    Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.5
    • Fix Version/s: 2.14
    • Component/s: Database, DB Cleaner
    • Labels:
      None
    • Environment:
      Sonar triggered from Hudson builds, running on Linux server
    • Number of attachments :
      2

      Description

      Since version 2.5 of Sonar, in our Hudson/Sonar continuous integration build environment the following problem occurs:

      When two or more builds are created simultaneously and also the Sonar parts of the builds are running in parallel, then these builds regularly lock each other.

      For example, if we have a large project being built, which takes a long time, before all the Sonar checks are finished, and we then start the build of a small project, then this build will block in the PurgeDependencies step of the Sonar run, until it gets a timeout or the large build is killed.

      See the attached log excerpts for details. A heap dump was triggered for the large project build to be able to see, which threads are locked.

      1. large_project_log.txt
        17 kB
        Christian Loroff
      2. small_project_log.txt
        10 kB
        Christian Loroff

        Issue Links

          Activity

          Hide
          Olivier Gaudin added a comment -

          I looked at your 2 logs and could not see a database lock there, I only saw a timeout to acquire a lock. Are the analysis running on the same machine as the Sonar server and the database ? In that case, as the analysis is resource intensive it could explain why the database is not able to answer.

          Show
          Olivier Gaudin added a comment - I looked at your 2 logs and could not see a database lock there, I only saw a timeout to acquire a lock. Are the analysis running on the same machine as the Sonar server and the database ? In that case, as the analysis is resource intensive it could explain why the database is not able to answer.
          Hide
          Olivier Gaudin added a comment -

          Feel free to reopen the issue if you have more info to provide

          Show
          Olivier Gaudin added a comment - Feel free to reopen the issue if you have more info to provide
          Hide
          Andreas Mandel added a comment -

          Im working together with Christian, I've some details to add.

          The build in which the analysis is running is on a different machine than the Sonar server. Nevertheless both builds run on the same machine. At the moment when I 'kill' the project that is in the Package design analysis... phase the purge continues and finishes successfully short moment after that. I would guess it is a lock on the database side - held during the Package design analysis... that causes the purge to hang. I hope the following thread dump (kill -3) of the Purge process can give more detail:

          09:18:40  [INFO]  Purge org.sonar.plugins.dbcleaner.period.PeriodPurge done: 14 ms
          09:18:40  [INFO]  Purge org.sonar.plugins.dbcleaner.purges.PurgeDependencies...
          09:23:57  2011-02-18 09:24:02
          09:23:57  Full thread dump Java HotSpot(TM) Client VM (16.3-b01 mixed mode, sharing):
          09:23:57  
          09:23:57  "pool-1-thread-5" prio=10 tid=0x082ca000 nid=0x7327 in Object.wait() [0xb413c000]
          09:23:57     java.lang.Thread.State: WAITING (on object monitor)
          09:23:57        at java.lang.Object.wait(Native Method)
          09:23:57        - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at java.lang.Object.wait(Object.java:485)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316)
          09:23:57        - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
          09:23:57        at java.lang.Thread.run(Thread.java:619)
          09:23:57  
          09:23:57  "pool-1-thread-4" prio=10 tid=0x082d0800 nid=0x7326 in Object.wait() [0xb418d000]
          09:23:57     java.lang.Thread.State: WAITING (on object monitor)
          09:23:57        at java.lang.Object.wait(Native Method)
          09:23:57        - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at java.lang.Object.wait(Object.java:485)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316)
          09:23:57        - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
          09:23:57        at java.lang.Thread.run(Thread.java:619)
          09:23:57  
          09:23:57  "pool-1-thread-3" prio=10 tid=0x0829ac00 nid=0x7324 in Object.wait() [0xb42a8000]
          09:23:57     java.lang.Thread.State: WAITING (on object monitor)
          09:23:57        at java.lang.Object.wait(Native Method)
          09:23:57        - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at java.lang.Object.wait(Object.java:485)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316)
          09:23:57        - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
          09:23:57        at java.lang.Thread.run(Thread.java:619)
          09:23:57  
          09:23:57  "pool-1-thread-2" prio=10 tid=0x08299000 nid=0x7323 in Object.wait() [0xb42f9000]
          09:23:57     java.lang.Thread.State: WAITING (on object monitor)
          09:23:57        at java.lang.Object.wait(Native Method)
          09:23:57        - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at java.lang.Object.wait(Object.java:485)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316)
          09:23:57        - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
          09:23:57        at java.lang.Thread.run(Thread.java:619)
          09:23:57  
          09:23:57  "pool-1-thread-1" prio=10 tid=0x08298800 nid=0x7322 in Object.wait() [0xb434a000]
          09:23:57     java.lang.Thread.State: WAITING (on object monitor)
          09:23:57        at java.lang.Object.wait(Native Method)
          09:23:57        - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at java.lang.Object.wait(Object.java:485)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316)
          09:23:57        - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054)
          09:23:57        at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
          09:23:57        at java.lang.Thread.run(Thread.java:619)
          09:23:57  
          09:23:57  "Low Memory Detector" daemon prio=10 tid=0x0808d000 nid=0x731c runnable [0x00000000]
          09:23:57     java.lang.Thread.State: RUNNABLE
          09:23:57  
          09:23:57  "CompilerThread0" daemon prio=10 tid=0x08089c00 nid=0x731b waiting on condition [0x00000000]
          09:23:57     java.lang.Thread.State: RUNNABLE
          09:23:57  
          09:23:57  "Signal Dispatcher" daemon prio=10 tid=0x08088400 nid=0x731a waiting on condition [0x00000000]
          09:23:57     java.lang.Thread.State: RUNNABLE
          09:23:57  
          09:23:57  "Finalizer" daemon prio=10 tid=0x0807f400 nid=0x7319 in Object.wait() [0xb4781000]
          09:23:57     java.lang.Thread.State: WAITING (on object monitor)
          09:23:57        at java.lang.Object.wait(Native Method)
          09:23:57        - waiting on <0x64300238> (a java.lang.ref.ReferenceQueue$Lock)
          09:23:57        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
          09:23:57        - locked <0x64300238> (a java.lang.ref.ReferenceQueue$Lock)
          09:23:57        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
          09:23:57        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
          09:23:57  
          09:23:57  "Reference Handler" daemon prio=10 tid=0x0807dc00 nid=0x7318 in Object.wait() [0xb47d1000]
          09:23:57     java.lang.Thread.State: WAITING (on object monitor)
          09:23:57        at java.lang.Object.wait(Native Method)
          09:23:57        - waiting on <0x643002c0> (a java.lang.ref.Reference$Lock)
          09:23:57        at java.lang.Object.wait(Object.java:485)
          09:23:57        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
          09:23:57        - locked <0x643002c0> (a java.lang.ref.Reference$Lock)
          09:23:57  
          09:23:57  "main" prio=10 tid=0x08059400 nid=0x7314 runnable [0xb6d63000]
          09:23:57     java.lang.Thread.State: RUNNABLE
          09:23:57        at java.net.SocketInputStream.socketRead0(Native Method)
          09:23:57        at java.net.SocketInputStream.read(SocketInputStream.java:129)
          09:23:57        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
          09:23:57        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
          09:23:57        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
          09:23:57        - locked <0x64df24f8> (a com.mysql.jdbc.util.ReadAheadInputStream)
          09:23:57        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499)
          09:23:57        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
          09:23:57        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941)
          09:23:57        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489)
          09:23:57        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
          09:23:57        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
          09:23:57        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
          09:23:57        - locked <0x64ded230> (a java.lang.Object)
          09:23:57        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113)
          09:23:57        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2409)
          09:23:57        - locked <0x64ded230> (a java.lang.Object)
          09:23:57        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2327)
          09:23:57        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2312)
          09:23:57        at org.hibernate.hql.ast.exec.BasicExecutor.execute(BasicExecutor.java:101)
          09:23:57        at org.hibernate.hql.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:421)
          09:23:57        at org.hibernate.engine.query.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:283)
          09:23:57        at org.hibernate.impl.SessionImpl.executeUpdate(SessionImpl.java:1169)
          09:23:57        at org.hibernate.impl.QueryImpl.executeUpdate(QueryImpl.java:117)
          09:23:57        at org.hibernate.ejb.QueryImpl.executeUpdate(QueryImpl.java:51)
          09:23:57        at org.sonar.plugins.dbcleaner.api.PurgeUtils.executeQuery(PurgeUtils.java:121)
          09:23:57        at org.sonar.plugins.dbcleaner.purges.PurgeDependencies.purge(PurgeDependencies.java:43)
          09:23:57        at org.sonar.plugins.dbcleaner.runner.PurgeRunner.executePurges(PurgeRunner.java:91)
          09:23:57        at org.sonar.plugins.dbcleaner.runner.PurgeRunner.purge(PurgeRunner.java:74)
          09:23:57        at org.sonar.plugins.dbcleaner.runner.PurgeRunner.executeOn(PurgeRunner.java:61)
          09:23:57        at org.sonar.batch.phases.PostJobsExecutor.execute(PostJobsExecutor.java:58)
          09:23:57        at org.sonar.batch.phases.Phases.execute(Phases.java:79)
          09:23:57        at org.sonar.batch.ProjectBatch.execute(ProjectBatch.java:61)
          09:23:57        at org.sonar.batch.Batch.analyzeModule(Batch.java:149)
          09:23:57        at org.sonar.batch.Batch.analyzeModules(Batch.java:106)
          09:23:57        at org.sonar.batch.Batch.execute(Batch.java:66)
          09:23:57        at org.sonar.maven.SonarMojo.executeBatch(SonarMojo.java:142)
          09:23:57        at org.sonar.maven.SonarMojo.execute(SonarMojo.java:133)
          09:23:57        at org.apache.maven.plugin.DefaultPluginManager.executeMojo(DefaultPluginManager.java:490)
          09:23:57        at org.codehaus.mojo.sonar.Bootstraper.executeMojo(Bootstraper.java:98)
          09:23:57        at org.codehaus.mojo.sonar.Bootstraper.start(Bootstraper.java:79)
          09:23:57        at org.codehaus.mojo.sonar.SonarMojo.execute(SonarMojo.java:88)
          09:23:57        at org.apache.maven.plugin.DefaultPluginManager.executeMojo(DefaultPluginManager.java:490)
          09:23:57        at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoals(DefaultLifecycleExecutor.java:694)
          09:23:57        at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeStandaloneGoal(DefaultLifecycleExecutor.java:569)
          09:23:57        at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoal(DefaultLifecycleExecutor.java:539)
          09:23:57        at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalAndHandleFailures(DefaultLifecycleExecutor.java:387)
          09:23:57        at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeTaskSegments(DefaultLifecycleExecutor.java:284)
          09:23:57        at org.apache.maven.lifecycle.DefaultLifecycleExecutor.execute(DefaultLifecycleExecutor.java:180)
          09:23:57        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:328)
          09:23:57        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:138)
          09:23:57        at org.apache.maven.cli.MavenCli.main(MavenCli.java:362)
          09:23:57        at org.apache.maven.cli.compat.CompatibleMain.main(CompatibleMain.java:60)
          09:23:57        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          09:23:57        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
          09:23:57        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
          09:23:57        at java.lang.reflect.Method.invoke(Method.java:597)
          09:23:57        at org.codehaus.classworlds.Launcher.launchEnhanced(Launcher.java:315)
          09:23:57        at org.codehaus.classworlds.Launcher.launch(Launcher.java:255)
          09:23:57        at org.codehaus.classworlds.Launcher.mainWithExitCode(Launcher.java:430)
          09:23:57        at org.codehaus.classworlds.Launcher.main(Launcher.java:375)
          09:23:57  
          09:23:57  "VM Thread" prio=10 tid=0x0807c400 nid=0x7316 runnable 
          09:23:57  
          09:23:57  "VM Periodic Task Thread" prio=10 tid=0x080a0400 nid=0x731d waiting on condition 
          09:23:57  
          09:23:57  JNI global references: 948
          09:23:57  
          09:23:57  Heap
          09:23:57   def new generation   total 247744K, used 167546K [0x4edb0000, 0x5fa80000, 0x64300000)
          09:23:57    eden space 220224K,  75% used [0x4edb0000, 0x58f3d100, 0x5c4c0000)
          09:23:57    from space 27520K,   7% used [0x5dfa0000, 0x5e1b1820, 0x5fa80000)
          09:23:57    to   space 27520K,   0% used [0x5c4c0000, 0x5c4c0000, 0x5dfa0000)
          09:23:57   tenured generation   total 550436K, used 259537K [0x64300000, 0x85c89000, 0x8edb0000)
          09:23:57     the space 550436K,  47% used [0x64300000, 0x740745a8, 0x74074600, 0x85c89000)
          09:23:57   compacting perm gen  total 32512K, used 32485K [0x8edb0000, 0x90d70000, 0x92db0000)
          09:23:57     the space 32512K,  99% used [0x8edb0000, 0x90d697e0, 0x90d69800, 0x90d70000)
          09:23:57      ro space 10240K,  61% used [0x92db0000, 0x933d6298, 0x933d6400, 0x937b0000)
          09:23:57      rw space 12288K,  60% used [0x937b0000, 0x93ee6cb8, 0x93ee6e00, 0x943b0000)
          09:23:57  
          
          Show
          Andreas Mandel added a comment - Im working together with Christian, I've some details to add. The build in which the analysis is running is on a different machine than the Sonar server. Nevertheless both builds run on the same machine. At the moment when I 'kill' the project that is in the Package design analysis... phase the purge continues and finishes successfully short moment after that. I would guess it is a lock on the database side - held during the Package design analysis... that causes the purge to hang. I hope the following thread dump (kill -3) of the Purge process can give more detail: 09:18:40 [INFO] Purge org.sonar.plugins.dbcleaner.period.PeriodPurge done: 14 ms 09:18:40 [INFO] Purge org.sonar.plugins.dbcleaner.purges.PurgeDependencies... 09:23:57 2011-02-18 09:24:02 09:23:57 Full thread dump Java HotSpot(TM) Client VM (16.3-b01 mixed mode, sharing): 09:23:57 09:23:57 "pool-1-thread-5" prio=10 tid=0x082ca000 nid=0x7327 in Object .wait() [0xb413c000] 09:23:57 java.lang. Thread .State: WAITING (on object monitor) 09:23:57 at java.lang. Object .wait(Native Method) 09:23:57 - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at java.lang. Object .wait( Object .java:485) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316) 09:23:57 - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575) 09:23:57 at java.lang. Thread .run( Thread .java:619) 09:23:57 09:23:57 "pool-1-thread-4" prio=10 tid=0x082d0800 nid=0x7326 in Object .wait() [0xb418d000] 09:23:57 java.lang. Thread .State: WAITING (on object monitor) 09:23:57 at java.lang. Object .wait(Native Method) 09:23:57 - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at java.lang. Object .wait( Object .java:485) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316) 09:23:57 - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575) 09:23:57 at java.lang. Thread .run( Thread .java:619) 09:23:57 09:23:57 "pool-1-thread-3" prio=10 tid=0x0829ac00 nid=0x7324 in Object .wait() [0xb42a8000] 09:23:57 java.lang. Thread .State: WAITING (on object monitor) 09:23:57 at java.lang. Object .wait(Native Method) 09:23:57 - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at java.lang. Object .wait( Object .java:485) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316) 09:23:57 - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575) 09:23:57 at java.lang. Thread .run( Thread .java:619) 09:23:57 09:23:57 "pool-1-thread-2" prio=10 tid=0x08299000 nid=0x7323 in Object .wait() [0xb42f9000] 09:23:57 java.lang. Thread .State: WAITING (on object monitor) 09:23:57 at java.lang. Object .wait(Native Method) 09:23:57 - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at java.lang. Object .wait( Object .java:485) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316) 09:23:57 - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575) 09:23:57 at java.lang. Thread .run( Thread .java:619) 09:23:57 09:23:57 "pool-1-thread-1" prio=10 tid=0x08298800 nid=0x7322 in Object .wait() [0xb434a000] 09:23:57 java.lang. Thread .State: WAITING (on object monitor) 09:23:57 at java.lang. Object .wait(Native Method) 09:23:57 - waiting on <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at java.lang. Object .wait( Object .java:485) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316) 09:23:57 - locked <0x64422dc0> (a hidden.edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:994) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1054) 09:23:57 at hidden.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575) 09:23:57 at java.lang. Thread .run( Thread .java:619) 09:23:57 09:23:57 "Low Memory Detector" daemon prio=10 tid=0x0808d000 nid=0x731c runnable [0x00000000] 09:23:57 java.lang. Thread .State: RUNNABLE 09:23:57 09:23:57 "CompilerThread0" daemon prio=10 tid=0x08089c00 nid=0x731b waiting on condition [0x00000000] 09:23:57 java.lang. Thread .State: RUNNABLE 09:23:57 09:23:57 "Signal Dispatcher" daemon prio=10 tid=0x08088400 nid=0x731a waiting on condition [0x00000000] 09:23:57 java.lang. Thread .State: RUNNABLE 09:23:57 09:23:57 "Finalizer" daemon prio=10 tid=0x0807f400 nid=0x7319 in Object .wait() [0xb4781000] 09:23:57 java.lang. Thread .State: WAITING (on object monitor) 09:23:57 at java.lang. Object .wait(Native Method) 09:23:57 - waiting on <0x64300238> (a java.lang.ref.ReferenceQueue$Lock) 09:23:57 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) 09:23:57 - locked <0x64300238> (a java.lang.ref.ReferenceQueue$Lock) 09:23:57 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134) 09:23:57 at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) 09:23:57 09:23:57 "Reference Handler" daemon prio=10 tid=0x0807dc00 nid=0x7318 in Object .wait() [0xb47d1000] 09:23:57 java.lang. Thread .State: WAITING (on object monitor) 09:23:57 at java.lang. Object .wait(Native Method) 09:23:57 - waiting on <0x643002c0> (a java.lang.ref.Reference$Lock) 09:23:57 at java.lang. Object .wait( Object .java:485) 09:23:57 at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) 09:23:57 - locked <0x643002c0> (a java.lang.ref.Reference$Lock) 09:23:57 09:23:57 "main" prio=10 tid=0x08059400 nid=0x7314 runnable [0xb6d63000] 09:23:57 java.lang. Thread .State: RUNNABLE 09:23:57 at java.net.SocketInputStream.socketRead0(Native Method) 09:23:57 at java.net.SocketInputStream.read(SocketInputStream.java:129) 09:23:57 at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) 09:23:57 at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) 09:23:57 at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) 09:23:57 - locked <0x64df24f8> (a com.mysql.jdbc.util.ReadAheadInputStream) 09:23:57 at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499) 09:23:57 at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952) 09:23:57 at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941) 09:23:57 at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489) 09:23:57 at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959) 09:23:57 at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113) 09:23:57 at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568) 09:23:57 - locked <0x64ded230> (a java.lang. Object ) 09:23:57 at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113) 09:23:57 at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2409) 09:23:57 - locked <0x64ded230> (a java.lang. Object ) 09:23:57 at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2327) 09:23:57 at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2312) 09:23:57 at org.hibernate.hql.ast.exec.BasicExecutor.execute(BasicExecutor.java:101) 09:23:57 at org.hibernate.hql.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:421) 09:23:57 at org.hibernate.engine.query.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:283) 09:23:57 at org.hibernate.impl.SessionImpl.executeUpdate(SessionImpl.java:1169) 09:23:57 at org.hibernate.impl.QueryImpl.executeUpdate(QueryImpl.java:117) 09:23:57 at org.hibernate.ejb.QueryImpl.executeUpdate(QueryImpl.java:51) 09:23:57 at org.sonar.plugins.dbcleaner.api.PurgeUtils.executeQuery(PurgeUtils.java:121) 09:23:57 at org.sonar.plugins.dbcleaner.purges.PurgeDependencies.purge(PurgeDependencies.java:43) 09:23:57 at org.sonar.plugins.dbcleaner.runner.PurgeRunner.executePurges(PurgeRunner.java:91) 09:23:57 at org.sonar.plugins.dbcleaner.runner.PurgeRunner.purge(PurgeRunner.java:74) 09:23:57 at org.sonar.plugins.dbcleaner.runner.PurgeRunner.executeOn(PurgeRunner.java:61) 09:23:57 at org.sonar.batch.phases.PostJobsExecutor.execute(PostJobsExecutor.java:58) 09:23:57 at org.sonar.batch.phases.Phases.execute(Phases.java:79) 09:23:57 at org.sonar.batch.ProjectBatch.execute(ProjectBatch.java:61) 09:23:57 at org.sonar.batch.Batch.analyzeModule(Batch.java:149) 09:23:57 at org.sonar.batch.Batch.analyzeModules(Batch.java:106) 09:23:57 at org.sonar.batch.Batch.execute(Batch.java:66) 09:23:57 at org.sonar.maven.SonarMojo.executeBatch(SonarMojo.java:142) 09:23:57 at org.sonar.maven.SonarMojo.execute(SonarMojo.java:133) 09:23:57 at org.apache.maven.plugin.DefaultPluginManager.executeMojo(DefaultPluginManager.java:490) 09:23:57 at org.codehaus.mojo.sonar.Bootstraper.executeMojo(Bootstraper.java:98) 09:23:57 at org.codehaus.mojo.sonar.Bootstraper.start(Bootstraper.java:79) 09:23:57 at org.codehaus.mojo.sonar.SonarMojo.execute(SonarMojo.java:88) 09:23:57 at org.apache.maven.plugin.DefaultPluginManager.executeMojo(DefaultPluginManager.java:490) 09:23:57 at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoals(DefaultLifecycleExecutor.java:694) 09:23:57 at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeStandaloneGoal(DefaultLifecycleExecutor.java:569) 09:23:57 at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoal(DefaultLifecycleExecutor.java:539) 09:23:57 at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalAndHandleFailures(DefaultLifecycleExecutor.java:387) 09:23:57 at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeTaskSegments(DefaultLifecycleExecutor.java:284) 09:23:57 at org.apache.maven.lifecycle.DefaultLifecycleExecutor.execute(DefaultLifecycleExecutor.java:180) 09:23:57 at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:328) 09:23:57 at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:138) 09:23:57 at org.apache.maven.cli.MavenCli.main(MavenCli.java:362) 09:23:57 at org.apache.maven.cli.compat.CompatibleMain.main(CompatibleMain.java:60) 09:23:57 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 09:23:57 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 09:23:57 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 09:23:57 at java.lang.reflect.Method.invoke(Method.java:597) 09:23:57 at org.codehaus.classworlds.Launcher.launchEnhanced(Launcher.java:315) 09:23:57 at org.codehaus.classworlds.Launcher.launch(Launcher.java:255) 09:23:57 at org.codehaus.classworlds.Launcher.mainWithExitCode(Launcher.java:430) 09:23:57 at org.codehaus.classworlds.Launcher.main(Launcher.java:375) 09:23:57 09:23:57 "VM Thread " prio=10 tid=0x0807c400 nid=0x7316 runnable 09:23:57 09:23:57 "VM Periodic Task Thread " prio=10 tid=0x080a0400 nid=0x731d waiting on condition 09:23:57 09:23:57 JNI global references: 948 09:23:57 09:23:57 Heap 09:23:57 def new generation total 247744K, used 167546K [0x4edb0000, 0x5fa80000, 0x64300000) 09:23:57 eden space 220224K, 75% used [0x4edb0000, 0x58f3d100, 0x5c4c0000) 09:23:57 from space 27520K, 7% used [0x5dfa0000, 0x5e1b1820, 0x5fa80000) 09:23:57 to space 27520K, 0% used [0x5c4c0000, 0x5c4c0000, 0x5dfa0000) 09:23:57 tenured generation total 550436K, used 259537K [0x64300000, 0x85c89000, 0x8edb0000) 09:23:57 the space 550436K, 47% used [0x64300000, 0x740745a8, 0x74074600, 0x85c89000) 09:23:57 compacting perm gen total 32512K, used 32485K [0x8edb0000, 0x90d70000, 0x92db0000) 09:23:57 the space 32512K, 99% used [0x8edb0000, 0x90d697e0, 0x90d69800, 0x90d70000) 09:23:57 ro space 10240K, 61% used [0x92db0000, 0x933d6298, 0x933d6400, 0x937b0000) 09:23:57 rw space 12288K, 60% used [0x937b0000, 0x93ee6cb8, 0x93ee6e00, 0x943b0000) 09:23:57
          Hide
          Christian Loroff added a comment -

          The database and the Sonar server are running on one machine and the builds (with the analysis) are running on a different machine. So the load of the analysis should not affect the responsiveness of the database.

          Show
          Christian Loroff added a comment - The database and the Sonar server are running on one machine and the builds (with the analysis) are running on a different machine. So the load of the analysis should not affect the responsiveness of the database.
          Hide
          Christian Loroff added a comment -

          The problem is reproducible. If a large build with a long Sonar analysis phase runs and a small build is started during this analysis phase, the small build will get a timeout while trying to acquire a lock for the PurgeDependencies step.

          Show
          Christian Loroff added a comment - The problem is reproducible. If a large build with a long Sonar analysis phase runs and a small build is started during this analysis phase, the small build will get a timeout while trying to acquire a lock for the PurgeDependencies step.
          Hide
          Christian Loroff added a comment -

          See our previous comments for additional information about this issue.

          Show
          Christian Loroff added a comment - See our previous comments for additional information about this issue.
          Hide
          Andreas Mandel added a comment -

          Might be a straight solution or workaround could be the following:

          1. Set a smaller timeout for the purge operation, or check for existing locks in advance if possible
          2. Do not let the build fail if one of the purge operations fails, just skip them silently
          Show
          Andreas Mandel added a comment - Might be a straight solution or workaround could be the following: Set a smaller timeout for the purge operation, or check for existing locks in advance if possible Do not let the build fail if one of the purge operations fails, just skip them silently
          Hide
          Andreas Mandel added a comment -

          Olivier, could you find something about this?

          One process is working on Package design analysis... and the other times out in Purge org.sonar.plugins.dbcleaner.purges.PurgeDependencies.... Just looking at the name of the 2 tasks it seems not unlikely to me, that both work on the same database table?

          The Package design analysis... takes more than one hour for the 'large_project' mentioned above. (see also SONAR-2164)

          Show
          Andreas Mandel added a comment - Olivier, could you find something about this? One process is working on Package design analysis... and the other times out in Purge org.sonar.plugins.dbcleaner.purges.PurgeDependencies... . Just looking at the name of the 2 tasks it seems not unlikely to me, that both work on the same database table? The Package design analysis... takes more than one hour for the 'large_project' mentioned above. (see also SONAR-2164 )
          Hide
          Benjamin Schmid added a comment -

          We seem to share the same problem here: We have around 25 projects in Sonar. Sonar runs are triggered by our CI system Bamboo at night and take between 10 up to 45 minutes per project. So collisions are likely and chances are increasing with further progress in our Sonar deployment in our projects.

          IMHO this issue will cause problems in every no-longer-playground sized installation of Sonar due to increased collision likeness.

          I'd expect that locks are held only during a very short timespan. Does purging take so long?

          Show
          Benjamin Schmid added a comment - We seem to share the same problem here: We have around 25 projects in Sonar. Sonar runs are triggered by our CI system Bamboo at night and take between 10 up to 45 minutes per project. So collisions are likely and chances are increasing with further progress in our Sonar deployment in our projects. IMHO this issue will cause problems in every no-longer-playground sized installation of Sonar due to increased collision likeness. I'd expect that locks are held only during a very short timespan. Does purging take so long?
          Hide
          B M added a comment -

          Is there any updates to this issue. Even we are getting the same error.

          Show
          B M added a comment - Is there any updates to this issue. Even we are getting the same error.
          Hide
          Andrea Aime added a comment -

          Had the same problem trying to analyze in parallel GeoTools and GeoServer (with the base + findbugs profile). Both are open source projects if you want to try on your machine (warning, they are large, the Sonar build takes forever).
          I'm running with the embedded database (would running with a separate mysql db work better?)

          Show
          Andrea Aime added a comment - Had the same problem trying to analyze in parallel GeoTools and GeoServer (with the base + findbugs profile). Both are open source projects if you want to try on your machine (warning, they are large, the Sonar build takes forever). I'm running with the embedded database (would running with a separate mysql db work better?)
          Hide
          Andrea Aime added a comment -

          Btw, switching to PostgreSQL seems to have solved the issue. The sonar:sonar maven build appears to be significantly faster, too

          Show
          Andrea Aime added a comment - Btw, switching to PostgreSQL seems to have solved the issue. The sonar:sonar maven build appears to be significantly faster, too
          Hide
          Benjamin Schmid added a comment -

          We use sonar in around 24 Projects with sizes up to 250.000 Lines of Code (LOC).

          Though we increased the timeout up to 10 minutes, we experience increasing problem with this issue. Any progress and advices regarding this problem?

          @Andrea: How large is your installation just as a possible last resort if no cure is in sight?

          Show
          Benjamin Schmid added a comment - We use sonar in around 24 Projects with sizes up to 250.000 Lines of Code (LOC). Though we increased the timeout up to 10 minutes , we experience increasing problem with this issue. Any progress and advices regarding this problem? @Andrea: How large is your installation just as a possible last resort if no cure is in sight?
          Hide
          Michael Rumpf added a comment -

          This seems to be related to SONAR-1945.

          Show
          Michael Rumpf added a comment - This seems to be related to SONAR-1945 .
          Hide
          Andreas Mandel added a comment -

          Sorry to repeat myself. Can't the following be a solution for the issue:

          1. Set a smaller timeout for the purge operation, or better check for existing locks in advance if possible
          2. Do not let the build fail if one of the purge operations fails, just skip them silently
          Show
          Andreas Mandel added a comment - Sorry to repeat myself. Can't the following be a solution for the issue: Set a smaller timeout for the purge operation, or better check for existing locks in advance if possible Do not let the build fail if one of the purge operations fails, just skip them silently
          Hide
          Freddy Mallet added a comment -

          You're right Andreas, at least not failing the Sonar analysis could be a useful workaround while waiting for the purge mechanism refactoring.

          Show
          Freddy Mallet added a comment - You're right Andreas, at least not failing the Sonar analysis could be a useful workaround while waiting for the purge mechanism refactoring.

            People

            • Assignee:
              Simon Brandhof
              Reporter:
              Christian Loroff
            • Votes:
              10 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: