Sonarqube 5.6 much slower than 4.5.2

maa...@gmail.com

unread,

Jun 17, 2016, 4:18:19 PM6/17/16

to SonarQube

i am currently looking into migrating our existing 4.5.2 sonarqube install to the new LTS version 5.6. I am currently experiencing several issues i will work through later, but the primary issue I'm seeing is a "publish" scan takes an order of magnitude longer than 4.5.2. It can spend up to 10-20 minutes per java file being scanned. This is the java plugin scan.

In 4.5.2 it took about 45 minutes for a scan. in 5.6 it looks like it is going to take closer to 6:10 hours (still running).

a snippet from log

[sonar:sonar] 15:53:11.667 INFO - 75/227 files analyzed, current file: C:\xxxxx\xxx.java

[sonar:sonar] 15:53:21.682 INFO - 75/227 files analyzed, current file:C:\xxxxx\xxx.java

.....

[sonar:sonar] 16:14:52.731 INFO - 75/227 files analyzed, current file: C:\xxxxx\xxx.java

[sonar:sonar] 16:15:02.746 INFO - 75/227 files analyzed, current file: C:\xxxxx\xxx.java

[sonar:sonar] 16:15:12.762 INFO - 75/227 files analyzed, current file: C:\xxxxx\xxx.java

[sonar:sonar] 16:15:22.777 INFO - 75/227 files analyzed, current file: C:\xxxxx\xxx.java

The file in question is about 300 lines long.

Is there any way to speed this up?

I am using the sonar-runner ant task to perform the scan. I am also using an unmodified generated sonar-project.properties file from 4.5.2

Nicolas Peru

unread,

Jun 20, 2016, 3:05:33 AM6/20/16

to maa...@gmail.com, SonarQube

Hi,

Can you precise which version of the java plugin you are using ?

Would you be able to share the incriminated file where the analysis is stuck ?

I suspect this is linked to the issue mentioned in this thread but I lack information to confirm it.

Thanks

Cheers,

--
You received this message because you are subscribed to the Google Groups "SonarQube" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sonarqube+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/sonarqube/3e380e8d-a1a9-44dd-acb4-359a673545c5%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Nicolas PERU | SonarSource

Senior Developer
http://sonarsource.com

https://twitter.com/benzonico

Maaltan Naatlam

unread,

Jun 20, 2016, 9:56:12 AM6/20/16

to SonarQube

i am using java 3.14. The scan eventually completed in 6 hours. this is up from 45 minutes. Unfortunately, I am not allowed to share any of our code.

Also, we have been having this issue for a long time (i reported it on the old mailing list). On the sonar 4.5 LTS, We were forced to downgrade to the 2.7 version of the java plugin for this specific reason as well as the infinite loops mentioned in other thread. I am only doing a pilot setup to see if we can upgrade.

Is there any way to profile a run by rule? Maybe our problem is one or two rules we dont really care about.

Thanks

Nicolas Peru

unread,

Jun 20, 2016, 9:59:40 AM6/20/16

to Maaltan Naatlam, SonarQube

Hi,

Without the source file or more information it will be very hard to help you out.

Are you using some instances of the ArchitecturalConstraint check with some regexps ?

Cheers,

To view this discussion on the web visit https://groups.google.com/d/msgid/sonarqube/CAGwUve_uT2atAeZXH%3DY2KNk8-%2BDQEkAQx26rLvFsyfwwh6%2Bucw%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

maa...@gmail.com

unread,

Jun 21, 2016, 9:53:40 AM6/21/16

to SonarQube, maa...@gmail.com

i patched together something that seems to work. I am currently running a visualvm profile against the standalone sonar-runner against the 5.6 converted environment.

core.sonar.projectBaseDir=D\:/sonar/sonarqubesrc/server/sonar-server

core.sonar.sources=src/main/java

core.sonar.projectName=core

sonar.modules=core

sonar.projectKey=sonar

sonar.projectName=sonar

sonar.projectVersion=5.6

sonar.sourceEncoding=UTF-8

sonar.analysis.mode=publish

sonar.findbugs.timeout=4294967290

sonar.language=java

sonar.analysis.mode=publish

sonar.issuesReport.console.enable=true

sonar.issuesReport.html.enable=true

sonar.login=admin

sonar.password=admin

sonar.host.url=xxxxxxxxxxxxxxxxxx

Scanning sonar-server with various configurations gave me the following. In summary, our production configuration with sonarqube 4.5.2 and java 2.4 gives us a scan time of about 11 seconds. The timings have steadily increased to 35 seconds in our converted 5.6 environment. all of the 4.5 tests were run against the default "sonar way". the 5.6 test is run against "our way" which is a subset of the 4.5.2 "sonar way" minus any rules that were disabled by the migration process.

sonarqube 4.5.2/ java 2.4

15:03:24.007 INFO - Sensor JavaSquidSensor...

15:03:24.070 INFO - Java Main Files AST scan...

15:03:24.070 INFO - 1222 source files to be analyzed

15:03:34.085 INFO - 1026/1222 files analyzed, current is D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\rule\ws\DeleteAction.java

15:03:35.614 INFO - 1222/1222 source files analyzed

15:03:35.676 INFO - Java Main Files AST scan done: 11606 ms

15:03:35.676 WARN - Java bytecode has not been made available to the analyzer. The deperecated dependencies metrics, S1160 rule, UnusedPrivateMethod rule, RedundantThrowsDeclarationCheck rule, S1217 rule are disabled.

15:03:35.676 INFO - Java Test Files AST scan...

15:03:35.676 INFO - 0 source files to be analyzed

15:03:35.676 INFO - Java Test Files AST scan done: 0 ms

15:03:35.676 INFO - 0/0 source files analyzed

15:03:36.878 INFO - Sensor JavaSquidSensor done: 12871 ms

4.5.2/3.1

15:09:28.822 INFO - Java Main Files AST scan...

15:09:28.822 INFO - 1222 source files to be analyzed

15:09:38.837 INFO - 529/1222 files analyzed, current is D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\duplication\ws\DuplicationsParser.java

15:09:48.852 INFO - 1020/1222 files analyzed, current is D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\rule\index\RuleResultSetIterator.java

15:09:52.284 INFO - Java Main Files AST scan done: 23462 ms

15:09:52.284 INFO - 1222/1222 source files analyzed

15:09:52.284 WARN - Java bytecode has not been made available to the analyzer. The org.sonar.java.bytecode.visitor.DependenciesVisitor@41a6e293, org.sonar.java.checks.UnusedPrivateMethodCheck@620c558e, org.sonar.java.checks.RedundantThrowsDeclarationCheck@6295be36 are disabled.

15:09:52.284 INFO - Java Test Files AST scan...

15:09:52.284 INFO - 0 source files to be analyzed

15:09:52.284 INFO - Java Test Files AST scan done: 0 ms

15:09:52.284 INFO - 0/0 source files analyzed

15:09:52.362 INFO - Sensor JavaSquidSensor done: 23930 ms

4.5.7/3.14

15:16:11.470 INFO - Sensor JavaSquidSensor...

15:16:11.907 INFO - Java Main Files AST scan...

15:16:11.907 INFO - 1222 source files to be analyzed

15:16:21.920 INFO - 417/1222 files analyzed, current is D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\computation\step\ExtractReportStep.java

15:16:31.907 INFO - 822/1222 files analyzed, current is D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\platform\TempFolderProvider.java

15:16:41.291 INFO - 1222/1222 source files analyzed

15:16:41.291 INFO - Java Main Files AST scan done: 29384 ms

15:16:41.291 WARN - Java bytecode has not been made available to the analyzer. The org.sonar.java.bytecode.visitor.DependenciesVisitor@451a7647, org.sonar.java.checks.UnusedPrivateMethodCheck@4a114a53, org.sonar.java.checks.RedundantThrowsDeclarationCheck@7d8e1e59 are disabled.

15:16:41.291 INFO - Java Test Files AST scan...

15:16:41.291 INFO - 0 source files to be analyzed

15:16:41.291 INFO - Java Test Files AST scan done: 0 ms

15:16:41.291 INFO - 0/0 source files analyzed

15:16:41.353 INFO - Sensor JavaSquidSensor done: 29883 ms

5.6/3.14

14:52:14.365 INFO - 1222 source files to be analyzed

14:52:24.380 INFO - 353/1222 files analyzed, current file: D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\computation\qualitygate\QualityGateStatus.java

14:52:34.396 INFO - 695/1222 files analyzed, current file: D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\measure\custom\ws\CustomMeasureValueDescription.java

14:52:44.411 INFO - 1030/1222 files analyzed, current file: D:\sonar\sonarqubesrc\server\sonar-server\src\main\java\org\sonar\server\rule\ws\RuleQueryFactory.java

14:52:49.247 INFO - Java Main Files AST scan done: 34882 ms

14:52:49.247 INFO - 1222/1222 source files have been analyzed

maa...@gmail.com

unread,

Jun 21, 2016, 4:23:40 PM6/21/16

to SonarQube

I am having a hard time getting a profiler to complete without crashing. It looks like org.sonar.java.ast.subcriptionvendor.visitchildren is the top hotspot from what i can tell.

Nicolas Peru

unread,

Jun 28, 2016, 4:43:14 AM6/28/16

to maa...@gmail.com, SonarQube

Hi,

Can you share your quality profile ? which rules are activated ? Your problem can be related to this issue of the java plugin https://jira.sonarsource.com/browse/SONARJAVA-1682

The hotspot you mention is somehow expected. (But we still need to work on it).

Cheers,

To view this discussion on the web visit https://groups.google.com/d/msgid/sonarqube/456227e0-0b9d-4b26-869d-38779b2181d4%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

maa...@gmail.com

unread,

Jun 28, 2016, 5:04:36 PM6/28/16

to SonarQube

it is the standard "Sonar way" that comes with 5.x

Nicolas Peru

unread,

Jun 29, 2016, 2:28:59 AM6/29/16

to maa...@gmail.com, SonarQube

Hi,

it is the standard "Sonar way" that comes with 5.x

Please note that this does not really make sense. SonarQube does not provide rules, the analyzers do. So my guess is that you are using the default quality profiles provided by the version of the sonar java analyzer.

I assume you reset the quality profile when you are upgrading the version of the sonar java analyzer on a given SQ instance.

Now, unless you can provide more information (ie : do a dichotomy tests on activated rules to determine wether or not this is due to a particular rule) for me, your problem is related to this one : https://jira.sonarsource.com/browse/SONARJAVA-1756

Note : this is (again) a wild guess, I don't have enough information to be sure of this.

Cheers,

To view this discussion on the web visit https://groups.google.com/d/msgid/sonarqube/c9fa3df1-4cba-4d93-b084-0a84c9b7d0d2%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

maa...@gmail.com

unread,

Jul 11, 2016, 2:49:33 PM7/11/16

to SonarQube, maa...@gmail.com

I have upgraded to 4.0 and the initial issue seems to be fixed. Also, I reset the "sonarway" profile to default before retesting.

Unfortunately, i have a new set of hotspots. Sorry, export capabilities are limited becase of out-of-memory condition in my profiler. the 3 integers are from left "total time in MS", "own time in ms" and call count.

com.persistit.BufferPool.selectDirtyBuffers(int[], BufferPool$BufferHolder[]) BufferPool.java 498351 498345 1

org.sonar.squidbridge.ProgressReport.run() ProgressReport.java 490633 490533 1

com.persistit.MediatedFileChannel.size() MediatedFileChannel.java 396491 396474 1

com.persistit.MediatedFileChannel.read(ByteBuffer, long) MediatedFileChannel.java 389402 389400 1

org.sonar.java.resolve.Resolve.findMethod(Resolve$Env, JavaType, JavaType, String, List, List, boolean) Resolve.java 486336 357280 205953377

java.lang.ref.Finalizer$FinalizerThread.run() Finalizer.java 340208 340208 1

org.sonar.java.resolve.Resolve.findMethod(Resolve$Env, JavaType, JavaType, String, List, List) Resolve.java 485231 129048 102977532

It seems our code is either creating very deep recursion on findMethod, or something is not unwinding correctly. Unfortunately, this is still crashing my profiler quickly (even when dedicating 32gb of ram to it)

I question that may be relevant. Right now the sonar-project has about 30 sub-projects. Right now all libraries are being dumped in a single huge sonar.java.libraries (about 20k characters). Would it improve performance any to provide a more targeted list to the sub-projects?

Nicolas Peru

unread,

Jul 12, 2016, 2:20:52 AM7/12/16

to maa...@gmail.com, SonarQube

Hi,

Without any more information this is very hard to answer : yes, maybe. It could improve performance to reduce the classpath to its submodule.

Cheers,

To view this discussion on the web visit https://groups.google.com/d/msgid/sonarqube/f4b47369-43ae-47cb-a7bc-a32b2baa9fe9%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

maa...@gmail.com

unread,

Jul 21, 2016, 2:16:17 PM7/21/16

to SonarQube, maa...@gmail.com

here is a stack trace dump for the active scan. it has been stuck on one file (with about 30 lines of code) for about 2 hours now.

Also, my company has just purchased an Ultimate license with premium support. Unfortunately, no one has been able to find out how to CONTACT this support(even the sonar sales rep) Can you assist with this? I would like to move this issue into a corporate support ticket.

2016-07-21 13:58:29

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.51-b03 mixed mode):

"Attach Listener" #263 daemon prio=9 os_prio=0 tid=0x00007fda34001000 nid=0x24c waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

"Report about progress of Java AST analyzer" #262 daemon prio=5 os_prio=0 tid=0x00007fda64c81800 nid=0x5a95 waiting on condition [0x00007fda295d6000]

java.lang.Thread.State: TIMED_WAITING (sleeping)

at java.lang.Thread.sleep(Native Method)

at org.sonar.squidbridge.ProgressReport.run(ProgressReport.java:62)

at java.lang.Thread.run(Thread.java:745)

"CLEANUP_MANAGER" #19 prio=5 os_prio=0 tid=0x00007fda6522c000 nid=0x5078 in Object.wait() [0x00007fda4c88c000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:173)

- locked <0x00000000e2854a80> (a com.persistit.CleanupManager)

at java.lang.Thread.run(Thread.java:745)

"CHECKPOINT_WRITER" #18 prio=5 os_prio=0 tid=0x00007fda65064800 nid=0x5077 in Object.wait() [0x00007fda4c98d000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:173)

- locked <0x00000000e2854c50> (a com.persistit.CheckpointManager)

at java.lang.Thread.run(Thread.java:745)

"TXN_UPDATE" #17 prio=5 os_prio=0 tid=0x00007fda6518c000 nid=0x5076 in Object.wait() [0x00007fda4ca8e000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:173)

- locked <0x00000000e2854e18> (a com.persistit.TransactionIndex$ActiveTransactionCachePollTask)

at java.lang.Thread.run(Thread.java:745)

"PAGE_WRITER:8192" #16 prio=5 os_prio=0 tid=0x00007fda650a5800 nid=0x5075 in Object.wait() [0x00007fda4cb8f000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:173)

- locked <0x00000000e27b5b88> (a com.persistit.BufferPool$PageWriter)

at java.lang.Thread.run(Thread.java:745)

"JOURNAL_FLUSHER" #15 prio=5 os_prio=0 tid=0x00007fda6509a000 nid=0x5074 in Object.wait() [0x00007fda4cc90000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:173)

- locked <0x00000000e2854fc0> (a com.persistit.JournalManager$JournalFlusher)

at java.lang.Thread.run(Thread.java:745)

"JOURNAL_COPIER" #14 prio=5 os_prio=0 tid=0x00007fda65098800 nid=0x5073 in Object.wait() [0x00007fda4cd91000]

java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at com.persistit.IOTaskRunnable.run(IOTaskRunnable.java:173)

- locked <0x00000000e28551a0> (a com.persistit.JournalManager$JournalCopier)

at java.lang.Thread.run(Thread.java:745)

"LOG_FLUSHER" #13 daemon prio=5 os_prio=0 tid=0x00007fda64fb6800 nid=0x5072 waiting on condition [0x00007fda4ce92000]

java.lang.Thread.State: TIMED_WAITING (sleeping)

at java.lang.Thread.sleep(Native Method)

at com.persistit.util.Util.sleep(Util.java:558)

at com.persistit.Persistit$LogFlusher.run(Persistit.java:188)

"Okio Watchdog" #11 daemon prio=5 os_prio=0 tid=0x00007fda64b72000 nid=0x5070 in Object.wait() [0x00007fda4d755000]

java.lang.Thread.State: WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at java.lang.Object.wait(Object.java:502)

at okio.AsyncTimeout.awaitTimeout(AsyncTimeout.java:311)

- locked <0x00000000e2878b40> (a java.lang.Class for okio.AsyncTimeout)

at okio.AsyncTimeout.access$000(AsyncTimeout.java:40)

at okio.AsyncTimeout$Watchdog.run(AsyncTimeout.java:286)

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007fda640c2000 nid=0x506d runnable [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007fda640b2800 nid=0x506c waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fda640b0800 nid=0x506b waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fda640ae000 nid=0x506a waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fda640ab800 nid=0x5069 runnable [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fda6407e000 nid=0x5068 in Object.wait() [0x00007fda4f5f4000]

java.lang.Thread.State: WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)

- locked <0x00000000e007e5e0> (a java.lang.ref.ReferenceQueue$Lock)

at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)

at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fda6407c000 nid=0x5067 in Object.wait() [0x00007fda4f6f5000]

java.lang.Thread.State: WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

at java.lang.Object.wait(Object.java:502)

at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)

- locked <0x00000000e007e7f8> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0x00007fda64008800 nid=0x5061 runnable [0x00007fda6c62a000]

java.lang.Thread.State: RUNNABLE

at com.google.common.collect.ImmutableSet.chooseTableSize(ImmutableSet.java:210)

at com.google.common.collect.ImmutableSet.construct(ImmutableSet.java:173)

at com.google.common.collect.ImmutableSet.access$000(ImmutableSet.java:44)

at com.google.common.collect.ImmutableSet$Builder.build(ImmutableSet.java:495)

at org.sonar.java.resolve.JavaSymbol$TypeJavaSymbol.interfacesOfType(JavaSymbol.java:401)

at org.sonar.java.resolve.JavaSymbol$TypeJavaSymbol.interfacesOfType(JavaSymbol.java:399)

at org.sonar.java.resolve.JavaSymbol$TypeJavaSymbol.superTypes(JavaSymbol.java:384)

at org.sonar.java.resolve.ClassJavaType.superTypeIsSubTypeOf(ClassJavaType.java:72)