SonarQube

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. Text File
    large_project_log.txt
    11/Feb/11 8:44 AM
    17 kB
    Christian Loroff
  2. Text File
    small_project_log.txt
    11/Feb/11 8:44 AM
    10 kB
    Christian Loroff

Issue Links

depends upon

New Feature - A new feature of the product, which has yet to be developed. SONAR-2757 Refactor the purge mechanisms to prevent any fullscan SQL requests on snapshots table

  • Major - Major loss of function.
  • Closed - The issue is considered finished, the resolution is correct. Issues which are not closed can be reopened.
is depended upon by

Improvement - An improvement or enhancement to an existing feature or task. SONAR-2961 Fail silently when deadlock happens during a purge

  • Critical - Crashes, loss of data, severe memory leak.
  • Closed - The issue is considered finished, the resolution is correct. Issues which are not closed can be reopened.
is related to

New Feature - A new feature of the product, which has yet to be developed. SONAR-3043 Do not purge snapshots systematically

  • Major - Major loss of function.
  • Closed - The issue is considered finished, the resolution is correct. Issues which are not closed can be reopened.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Vote (10)
Watch (9)

Dates

  • Created:
    Updated:
    Resolved: