Sonar branch analysis takes a lot more time after upgrade to 8.6

Hello,
We have been lately trying to upgrade SonarQube from 7.6 version to 8.5 (8.6) version, going through 7.9 LTS version.

We have done that on a staging instance, on which we have also conducted tests as part of the upgrade process. It appears that after the upgrade, the Sonar branch analysis now takes a lot more time (e.g. for a component it now takes around 45 mins, as opposed to a few seconds, with the old 7.6 version).

We’ve tried to investigate why this would take so much more time now, and we found some issues with the 8.5 version, that is why we have also upgraded to 8.6 version, but it seems that it is taking the same amount of time, even after the 8.5-8.6 upgrade.

Context for previous 7.6 version:
Enterprise Edition - Version 7.6 (build 21501)
SonarQube plugins:

  • License for SonarLint 7.6 (license)
  • SonarJava 5.12.1.17771 (java)
    Project server settings:
  • sonar.issue.ignore.block=1
  • sonar.leak.period=14
    Project scanner properties:
  • sonar.branch.name=task/*
  • sonar.branch.target=develop
  • sonar.scanner.app=ScannerGradle
  • sonar.scanner.appVersion=3.0/6.3
  • sonar.sourceEncoding=UTF-8

Previous output:

Sensor JaCoCo XML Report Importer [jacoco]
Sensor JaCoCo XML Report Importer [jacoco] (done) | time=69ms
Sensor Zero Coverage Sensor
Sensor Zero Coverage Sensor (done) | time=30ms
------------- Run sensors on project
Sensor Java CPD Block Indexer
Sensor Java CPD Block Indexer (done) | time=82ms
No SCM system was detected. You can use the ‘sonar.scm.provider’ property to explicitly specify it.
79 files had no CPD blocks
Calculating CPD for 74 files
Analysis report generated in 227ms, dir size=785 KB
Analysis report compressed in 209ms, zip size=451 KB
Analysis report uploaded in 75ms
ANALYSIS SUCCESSFUL

Last analysis time before upgrade of staging instance:

12s

Context for current 8.6 version:
Enterprise Edition - Version 8.6 (build 39681)
SonarQube plugins:

Project scanner properties:

  • sonar.branch.name=task/*
  • New Code - Reference branch: develop
  • sonar.scanner.app=ScannerGradle
  • sonar.scanner.appVersion=3.0/6.3
  • sonar.sourceEncoding=UTF-8

Current output:

Sensor JaCoCo XML Report Importer [jacoco] (done) | time=62ms
Sensor ThymeLeaf template sensor [securityjavafrontend]
Sensor ThymeLeaf template sensor [securityjavafrontend] (done) | time=2ms
Sensor JavaSecuritySensor [security]
Reading type hierarchy from: […]/build/sonar/ucfg2/java
Read 294 type definitions
Reading UCFGs from: […]/build/sonar/ucfg2/java
17:17:54.056 Building Runtime Type propagation graph
17:17:54.068 Running Tarjan on 406 nodes
17:17:54.07 Tarjan found 404 components
17:17:54.073 Variable type analysis: done
17:17:54.079 Building Runtime Type propagation graph
17:17:54.085 Running Tarjan on 406 nodes
17:17:54.086 Tarjan found 404 components
17:17:54.087 Variable type analysis: done
Analyzing 149 ucfgs to detect vulnerabilities.
All rules entrypoints : 0 Retained UCFGs : 0
rule: S5131, entrypoints: 0
rule: S5131 done
rule: S3649, entrypoints: 0
rule: S3649 done
rule: S2076, entrypoints: 0
rule: S2076 done
rule: S2091, entrypoints: 0
rule: S2091 done
rule: S2078, entrypoints: 0
rule: S2078 done
rule: S2631, entrypoints: 0
rule: S2631 done
rule: S5135, entrypoints: 0
rule: S5135 done
rule: S2083, entrypoints: 0
rule: S2083 done
rule: S5167, entrypoints: 0
rule: S5167 done
rule: S5144, entrypoints: 0
rule: S5144 done
rule: S5145, entrypoints: 0
rule: S5145 done
rule: S5146, entrypoints: 0
rule: S5146 done
rule: S5334, entrypoints: 0
rule: S5334 done
Sensor JavaSecuritySensor [security] (done) | time=507ms
Sensor CSharpSecuritySensor [security/]
Reading type hierarchy from: […]/ucfg_cs2
Read 0 type definitions
Reading UCFGs from: […]/build/ucfg_cs2
No UCFGs have been included for analysis.
Sensor CSharpSecuritySensor [security] (done) | time=0ms
Sensor PhpSecuritySensor [security]
Reading type hierarchy from: […]/build/sonar/ucfg2/php
Read 0 type definitions
Reading UCFGs from: […]/build/sonar/ucfg2/php
No UCFGs have been included for analysis.
Sensor PhpSecuritySensor [security] (done) | time=0ms
Sensor PythonSecuritySensor [security]
Reading type hierarchy from: […]/build/sonar/ucfg2/python
Read 0 type definitions
Reading UCFGs from: […]/build/sonar/ucfg2/python
No UCFGs have been included for analysis.
Sensor PythonSecuritySensor [security] (done) | time=0ms
Sensor JsSecuritySensor [security]
Reading type hierarchy from: […]/build/sonar/ucfg2/js
Read 0 type definitions
Reading UCFGs from: […]/build/sonar/ucfg2/js
No UCFGs have been included for analysis.
Sensor JsSecuritySensor [security] (done) | time=0ms
------------- Run sensors on project
Sensor Zero Coverage Sensor
Sensor Zero Coverage Sensor (done) | time=0ms
Sensor Java CPD Block Indexer
Sensor Java CPD Block Indexer (done) | time=94ms
SCM Publisher SCM provider for this project is: git
SCM Publisher 8 source files to be analyzed
CPD Executor 79 files had no CPD blocks
CPD Executor Calculating CPD for 74 files
Load New Code definition
Load New Code definition (done) | time=18ms
Computing New Code since fork with ‘develop’
Analysis report generated in 172ms, dir size=912 KB
Analysis report compressed in 223ms, zip size=479 KB
Analysis report uploaded in 337ms
ANALYSIS SUCCESSFUL

Current analysis time:

0h 45min

Do you have any ideas as to why the analysis would take so much more time now?

Thank you,
Iuliana

1 Like

Hello,

Any ideas, please? Are there any extra information needed?

Thank you!

Hi @iarama,

Welcome to SonarSource community! :wave:

Can you post the Sonar analysis logs with debug flag enabled? Just add -d to your Gradle command to get debug logs and post the logs here, or to make the logs shorter, just post the relevant part of the Sonar analysis logs.

Joe

Hi, @Joe! Thank you for your reply.
I have run it again with the debug option and there are thousands of lines of output, hopefully I chose relevant part of the logs, but please let me know if you would need some other information.

I would also like to point out the following, since there are quite some differences between the two versions (7.6 Enterprise edition which we currently have and 8.6 Enterprise edition to which we are trying to upgrade). We are now tackling new code in a different way - with 7.6 we were using sonar.branch.target, which was set to ‘develop’ branches by default, but we also had a mechanism to set it to a different one per run, whereas now we are using reference branches - by default set to ‘develop’ branches, and for develop branches, we have set it to create a delta between current and previous version.
I have noticed that for first time runs for develop branches, the analyses per component take around 1 hour each, and since we are analysing multiple components per run, we have to keep rerunning it until all components’ analyses are done, which takes a lot of time. Is it normal for an analysis to take so much time? For example, one component which has 2.2k lines of code, took exactly 1h 0min to finish its analysis. A second analysis took 5 seconds as opposed to a few ms with the previous Sonar version. Is it possible that it is now taking more time than before, even for second analyses, due to extra rules being parsed? I am most concerned here for the first time ‘develop’ branches analyses.

Sonar analysis logs with debug flag enabled:

2021-01-05T08:25:52.556+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Quality profile for java: Sonar way
2021-01-05T08:25:52.556+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] ------------- Run sensors on module xxx
2021-01-05T08:25:52.718+0000 [DEBUG] [okhttp3.internal.http2.Http2] >> 0x00000049    66 HEADERS       END_STREAM|END_HEADERS
2021-01-05T08:25:52.738+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] GET 200 sonarxxx/api/metrics/search?f=name,description,direction,qualitative,custom&ps=500&p=1 | time=21ms
2021-01-05T08:25:52.743+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 scheduled after   0 µs: OkHttp ConnectionPool
2021-01-05T08:25:52.746+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Load metrics repository (done) | time=28ms
2021-01-05T08:25:54.191+0000 [LIFECYCLE] [org.gradle.cache.internal.DefaultFileLockManager] 
2021-01-05T08:25:54.191+0000 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
[...]
2021-01-05T08:25:52.919+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] 
2021-01-05T08:25:52.919+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] > Task :xxx:sonarqube
2021-01-05T08:25:54.719+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Adding rules for repository 'jssecurity', language: JAVASCRIPT, [class A.A.A.A.A.A.B, class A.A.A.A.A.A.A, class A.A.A.A.A.A.C] from A.A.A.A.A.F
[...]
2021-01-05T08:25:55.280+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Sensors : JavaSquidSensor -> HTL -> CSS Rules -> C# Properties -> SurefireSensor -> Removed properties sensor -> JavaXmlSensor -> HTML -> VB.NET Properties -> JaCoCo XML Report Importer -> ThymeLeaf template sensor -> JavaSecuritySensor -> CSharpSecuritySensor -> PhpSecuritySensor -> PythonSecuritySensor -> JsSecuritySensor
2021-01-05T08:25:55.281+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor JavaSquidSensor [java]
[...]
2021-01-05T08:25:55.450+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Found 0 JSP files.
2021-01-05T08:25:55.463+0000 [DEBUG] [okhttp3.internal.http2.Http2] >> 0x0000004b    67 HEADERS       END_STREAM|END_HEADERS
2021-01-05T08:25:55.509+0000 [LIFECYCLE] [okhttp3.internal.http2.Http2] 
2021-01-05T08:25:55.509+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004b   195 HEADERS       END_HEADERS
2021-01-05T08:25:55.509+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004b   963 DATA          
2021-01-05T08:25:55.509+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004b     0 DATA          END_STREAM
2021-01-05T08:25:55.511+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 starting              : OkHttp ConnectionPool
2021-01-05T08:25:55.511+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 run again after 300 s : OkHttp ConnectionPool
2021-01-05T08:25:55.511+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 finished run in 100 µs: OkHttp ConnectionPool
2021-01-05T08:25:57.146+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 5/5 source files have been analyzed
2021-01-05T08:25:57.283+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 1/1 source files have been analyzed
2021-01-05T08:25:57.287+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 0/0 source files have been analyzed
2021-01-05T08:25:57.294+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 0/0 source files have been analyzed
2021-01-05T08:25:55.419+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] 
2021-01-05T08:25:55.419+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] > Task :xxx:sonarqube
2021-01-05T08:25:55.509+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] GET 200 sonarxxx/batch/project.protobuf?key=xxx&branch=xxx | time=48ms
2021-01-05T08:25:55.511+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 scheduled after   0 µs: OkHttp ConnectionPool
2021-01-05T08:25:55.518+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Load project repositories (done) | time=56ms
2021-01-05T08:25:55.518+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'xxx' generated metadata with charset 'UTF-8'
2021-01-05T08:25:56.360+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] [SE] Loaded 174 hardcoded method behaviors.
2021-01-05T08:25:57.147+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Java Main Files AST scan (done) | time=1696ms
2021-01-05T08:25:57.147+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Java Test Files AST scan
2021-01-05T08:25:57.147+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 1 source files to be analyzed
2021-01-05T08:25:57.148+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'xxx' generated metadata as test  with charset 'UTF-8'
[...]
2021-01-05T08:25:57.296+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Project 'xxx': No Roslyn issues reports have been found.
[...]
2021-01-05T08:25:57.371+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Project 'xxx': No Roslyn issues reports have been found.
2021-01-05T08:25:57.371+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor VB.NET Properties [vbnet] (done) | time=1ms
2021-01-05T08:25:57.371+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor JaCoCo XML Report Importer [jacoco]
2021-01-05T08:25:57.376+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Importing 1 report(s). Turn your logs in debug mode in order to see the exhaustive list.
2021-01-05T08:25:57.376+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Reading report 'xxx'
2021-01-05T08:25:57.387+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor JaCoCo XML Report Importer [jacoco] (done) | time=16ms
2021-01-05T08:25:57.388+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor ThymeLeaf template sensor [securityjavafrontend]
2021-01-05T08:25:57.388+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor ThymeLeaf template sensor [securityjavafrontend] (done) | time=0ms
2021-01-05T08:25:57.388+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor JavaSecuritySensor [security]
2021-01-05T08:25:57.389+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading type hierarchy from: xxx
2021-01-05T08:25:57.476+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Read 25 type definitions
2021-01-05T08:25:57.479+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading UCFGs from: xxx
2021-01-05T08:25:57.525+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.525 Building Runtime Type propagation graph
2021-01-05T08:25:57.529+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.53 Running Tarjan on 6 nodes
2021-01-05T08:25:57.531+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.531 Tarjan found 6 components
2021-01-05T08:25:57.535+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.535 Variable type analysis: done
2021-01-05T08:25:57.535+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.536 Building Runtime Type propagation graph
2021-01-05T08:25:57.536+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.536 Running Tarjan on 6 nodes
2021-01-05T08:25:57.536+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.536 Tarjan found 6 components
2021-01-05T08:25:57.536+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] 08:25:57.536 Variable type analysis: done
2021-01-05T08:25:57.538+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analyzing 7 ucfgs to detect vulnerabilities.
2021-01-05T08:25:57.592+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sources/S5131.json was not read
2021-01-05T08:25:57.594+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 303 sources for rule S5131
2021-01-05T08:25:57.604+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sinks/common.json was not read
2021-01-05T08:25:57.606+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 31 sinks for rule S5131
2021-01-05T08:25:57.610+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sources/S3649.json was not read
2021-01-05T08:25:57.610+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 303 sources for rule S3649
2021-01-05T08:25:57.611+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sinks/common.json was not read
2021-01-05T08:25:57.614+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 273 sinks for rule S3649
2021-01-05T08:25:57.620+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sources/S2076.json was not read
2021-01-05T08:25:57.620+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 303 sources for rule S2076
2021-01-05T08:25:57.621+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sinks/common.json was not read
2021-01-05T08:25:57.622+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 15 sinks for rule S2076
2021-01-05T08:25:57.623+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sources/S2091.json was not read
2021-01-05T08:25:57.624+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 303 sources for rule S2091
2021-01-05T08:25:57.624+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sinks/common.json was not read
2021-01-05T08:25:57.625+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 23 sinks for rule S2091
2021-01-05T08:25:57.627+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sources/S2078.json was not read
2021-01-05T08:25:57.628+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 303 sources for rule S2078
[...]
2021-01-05T08:25:57.647+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 303 sources for rule S5146
2021-01-05T08:25:57.647+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sinks/common.json was not read
2021-01-05T08:25:57.648+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 21 sinks for rule S5146
2021-01-05T08:25:57.649+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sources/S5334.json was not read
2021-01-05T08:25:57.649+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 303 sources for rule S5334
2021-01-05T08:25:57.649+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Resource file javasecurity/sinks/common.json was not read
2021-01-05T08:25:57.650+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] loaded 91 sinks for rule S5334
2021-01-05T08:25:57.651+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] All rules entrypoints : 0 Retained UCFGs : 0
2021-01-05T08:25:57.653+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] rule: S5131, entrypoints: 0
2021-01-05T08:25:57.653+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] rule: S5131 done
[...]
2021-01-05T08:25:57.653+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] rule: S5146 done
2021-01-05T08:25:57.653+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] rule: S5334, entrypoints: 0
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] rule: S5334 done
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor JavaSecuritySensor [security] (done) | time=266ms
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor CSharpSecuritySensor [security]
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading type hierarchy from: /xxx/ucfg_cs2
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Read 0 type definitions
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading UCFGs from: /xxx/ucfg_cs2
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] No UCFGs have been included for analysis.
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor CSharpSecuritySensor [security] (done) | time=0ms
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor PhpSecuritySensor [security]
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading type hierarchy from: /xxx/sonar/ucfg2/php
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Read 0 type definitions
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading UCFGs from: /xxx/ucfg2/php
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] No UCFGs have been included for analysis.
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor PhpSecuritySensor [security] (done) | time=0ms
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor PythonSecuritySensor [security]
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading type hierarchy from: /xxx/sonar/ucfg2/python
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Read 0 type definitions
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading UCFGs from: /xxx/sonar/ucfg2/python
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] No UCFGs have been included for analysis.
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor PythonSecuritySensor [security] (done) | time=0ms
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor JsSecuritySensor [security]
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading type hierarchy from: /xxx/sonar/ucfg2/js
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Read 0 type definitions
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Reading UCFGs from: /xxx/sonar/ucfg2/js
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] No UCFGs have been included for analysis.
2021-01-05T08:25:57.654+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor JsSecuritySensor [security] (done) | time=1ms
2021-01-05T08:25:57.658+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] ------------- Run sensors on project
2021-01-05T08:25:57.669+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'Generic Coverage Report' skipped because one of the required properties is missing
2021-01-05T08:25:57.669+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'C#' skipped because there is no related file in current project
2021-01-05T08:25:57.669+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'C# Tests Coverage Report Import' skipped because there is no related file in current project
2021-01-05T08:25:57.669+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] '[Deprecated] C# Integration Tests Coverage Report Import' skipped because there is no related file in current project
2021-01-05T08:25:57.669+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'C# Unit Test Results Import' skipped because there is no related file in current project
2021-01-05T08:25:57.670+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'VB.NET' skipped because there is no related file in current project
2021-01-05T08:25:57.670+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'VB.NET Tests Coverage Report Import' skipped because there is no related file in current project
2021-01-05T08:25:57.670+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] '[Deprecated] VB.NET Integration Tests Coverage Report Import' skipped because there is no related file in current project
2021-01-05T08:25:57.670+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] 'VB.NET Unit Test Results Import' skipped because there is no related file in current project
2021-01-05T08:25:57.670+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Sensors : Zero Coverage Sensor -> Java CPD Block Indexer
2021-01-05T08:25:57.671+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor Zero Coverage Sensor
2021-01-05T08:25:57.671+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor Zero Coverage Sensor (done) | time=0ms
2021-01-05T08:25:57.671+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor Java CPD Block Indexer
[...]
2021-01-05T08:25:57.694+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Not enough content in 'xxx' to have CPD blocks, it will not be part of the duplication detection
2021-01-05T08:25:57.694+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Sensor Java CPD Block Indexer (done) | time=23ms
2021-01-05T08:25:57.706+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] CPD Executor 4 files had no CPD blocks
2021-01-05T08:25:57.706+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] CPD Executor Calculating CPD for 1 file
2021-01-05T08:25:57.706+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Detection of duplications for xxx
2021-01-05T08:25:57.718+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] CPD Executor CPD calculation finished (done) | time=12ms
2021-01-05T08:25:57.742+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004d   194 HEADERS       END_HEADERS
2021-01-05T08:25:57.742+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004d    58 DATA          
2021-01-05T08:25:57.742+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004d     0 DATA          END_STREAM
2021-01-05T08:25:57.744+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 starting              : OkHttp ConnectionPool
2021-01-05T08:25:57.744+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 run again after 300 s : OkHttp ConnectionPool
2021-01-05T08:25:57.744+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 finished run in 109 µs: OkHttp ConnectionPool
2021-01-05T08:25:57.997+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004f     4 WINDOW_UPDATE 
2021-01-05T08:25:57.997+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004f     4 WINDOW_UPDATE 
2021-01-05T08:25:57.999+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004f     4 WINDOW_UPDATE 
2021-01-05T08:25:59.223+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004f   194 HEADERS       END_HEADERS
2021-01-05T08:25:59.223+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004f    44 DATA          
2021-01-05T08:25:59.224+0000 [DEBUG] [okhttp3.internal.http2.Http2] << 0x0000004f     0 DATA          END_STREAM
2021-01-05T08:25:59.226+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 starting              : OkHttp ConnectionPool
2021-01-05T08:25:59.226+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 run again after 300 s : OkHttp ConnectionPool
2021-01-05T08:25:59.226+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 finished run in 121 µs: OkHttp ConnectionPool
2021-01-05T08:25:57.619+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] 
2021-01-05T08:25:57.619+0000 [LIFECYCLE] [class org.gradle.internal.buildevents.TaskExecutionLogger] > Task :xxx:sonarqube
2021-01-05T08:25:57.728+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] SCM revision ID 'xxx'
2021-01-05T08:25:57.728+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Load New Code definition
2021-01-05T08:25:57.729+0000 [DEBUG] [okhttp3.internal.http2.Http2] >> 0x0000004d    79 HEADERS       END_STREAM|END_HEADERS
2021-01-05T08:25:57.743+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] GET 200 sonarxxx/api/new_code_periods/show.protobuf?project=xxx&branch=xxx | time=15ms
2021-01-05T08:25:57.744+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 scheduled after   0 µs: OkHttp ConnectionPool
2021-01-05T08:25:57.744+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Load New Code definition (done) | time=16ms
2021-01-05T08:25:57.745+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Computing New Code since fork with 'develop'
2021-01-05T08:25:57.745+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, create new FileSnapshot: lastRead=2021-01-05 08:25:57.745000000, lastModified=2021-01-05 08:01:41.000000000, size=208, fileKey=(dev=10301,ino=95420544)
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, isRacyClean=false, read=2021-01-05 08:25:52.386000000, lastModified=1970-01-01 01:00:00.000000000, delta=1609835152386000000 ns, racy<=2500000000 ns
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, is unmodified
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, isRacyClean=false, read=2021-01-05 08:25:52.412000000, lastModified=1970-01-01 01:00:00.000000000, delta=1609835152412000000 ns, racy<=2500000000 ns
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, is unmodified
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, isRacyClean=false, read=2021-01-05 08:25:52.413000000, lastModified=2021-01-05 08:01:45.000000000, delta=1447413000000 ns, racy<=2500000000 ns
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, is unmodified
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, create new FileSnapshot: lastRead=2021-01-05 08:25:57.746000000, lastModified=2021-01-05 08:01:41.000000000, size=208, fileKey=(dev=10301,ino=95420544)
2021-01-05T08:25:57.746+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, isRacyClean=false, read=2021-01-05 08:25:52.386000000, lastModified=1970-01-01 01:00:00.000000000, delta=1609835152386000000 ns, racy<=2500000000 ns
2021-01-05T08:25:57.747+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/home/xxx, is unmodified
2021-01-05T08:25:57.747+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] file=/xxx, isRacyClean=false, read=2021-01-05 08:25:52.412000000, ns
[...]
2021-01-05T08:25:57.896+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Merge base sha1: xxx
2021-01-05T08:25:57.897+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Fork detected at 'develop'
2021-01-05T08:25:57.969+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analysis report generated in 250ms, dir size=180 KB
2021-01-05T08:25:57.988+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analysis report compressed in 18ms, zip size=35 KB
2021-01-05T08:25:57.988+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analysis report generated in /xxx/sonar/scanner-report
2021-01-05T08:25:57.988+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Upload report
2021-01-05T08:25:57.993+0000 [DEBUG] [okhttp3.internal.http2.Http2] >> 0x0000004f   208 HEADERS       END_HEADERS
2021-01-05T08:25:57.994+0000 [DEBUG] [okhttp3.internal.http2.Http2] >> 0x0000004f 16384 DATA          
2021-01-05T08:25:57.994+0000 [DEBUG] [okhttp3.internal.http2.Http2] >> 0x0000004f 16384 DATA          
2021-01-05T08:25:57.995+0000 [DEBUG] [okhttp3.internal.http2.Http2] >> 0x0000004f  3406 DATA          END_STREAM
2021-01-05T08:25:59.224+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] POST 200 sonarxxx/api/ce/submit?projectKey=xxx&projectName=xxx&characteristic=branch%xxx&characteristic=branchType%3DBRANCH | time=1234ms
2021-01-05T08:25:59.226+0000 [DEBUG] [okhttp3.internal.concurrent.TaskRunner] Q10000 scheduled after   0 µs: OkHttp ConnectionPool
2021-01-05T08:25:59.226+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analysis report uploaded in 1237ms
2021-01-05T08:25:59.228+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Report metadata written to /xxx/sonar/report-task.txt
2021-01-05T08:25:59.228+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] ANALYSIS SUCCESSFUL, you can browse sonarxxx/dashboard?id=xxx&branch=xxx
2021-01-05T08:25:59.228+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Note that you will be able to access the updated dashboard once the server has processed the submitted analysis report
2021-01-05T08:25:59.228+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] More about the report processing at sonarxxx/api/ce/task?id=xxx
2021-01-05T08:25:59.230+0000 [DEBUG] [org.sonarqube.gradle.SonarQubeTask] Post-jobs : 
2021-01-05T08:25:59.232+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analysis total time: 9.447 s
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Completing Build operation 'Execute run for :xxx:sonarqube'
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Build operation 'Execute run for :xxx:sonarqube' completed
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Build operation 'Snapshot outputs after executing task ':xxx:sonarqube'' started
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Completing Build operation 'Snapshot outputs after executing task ':xxx:sonarqube''
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Build operation 'Snapshot outputs after executing task ':xxx:sonarqube'' completed
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.api.internal.tasks.execution.ResolveTaskExecutionModeExecuter] Removed task artifact state for task ':xxx:sonarqube' from context.
2021-01-05T08:25:59.234+0000 [WARN] [org.gradle.api.Project] :xxx:sonarqube finished, took 10476ms
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Completing Build operation 'Task :xxx:sonarqube'
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Build operation 'Task :xxx:sonarqube' completed
2021-01-05T08:25:59.234+0000 [INFO] [org.gradle.execution.plan.DefaultPlanExecutor] :xxx:sonarqube (Thread[Execution worker for ':',5,main]) completed. Took 10.477 secs.
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultExecutionPlan] Node :xxx:sonarqube finished executing
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultExecutionPlan] Node :xxx:sonarqube completed, executed: true
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Execution worker for ':': released lock on :xxx
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.work.DefaultWorkerLeaseService] Worker lease root.1.128 completed (1 worker(s) in use)
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Execution worker for ':': released lock on root.1.128
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Execution worker for ':',5,main]] finished, busy: 10.569 secs, idle: 0.004 secs
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Execution worker for ':' Thread 4,5,main]] finished, busy: 0.0 secs, idle: 10.573 secs
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Execution worker for ':' Thread 7,5,main]] finished, busy: 0.0 secs, idle: 10.572 secs
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Daemon worker Thread 5,5,main]] finished, busy: 0.0 secs, idle: 10.573 secs
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Execution worker for ':' Thread 6,5,main]] finished, busy: 0.0 secs, idle: 10.573 secs
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Execution worker for ':' Thread 3,5,main]] finished, busy: 0.0 secs, idle: 10.573 secs
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Execution worker for ':' Thread 2,5,main]] finished, busy: 0.0 secs, idle: 10.573 secs
2021-01-05T08:25:59.234+0000 [DEBUG] [org.gradle.execution.plan.DefaultPlanExecutor] Execution worker [Thread[Execution worker for ':' Thread 5,5,main]] finished, busy: 0.0 secs, idle: 10.573 secs
2021-01-05T08:25:59.235+0000 [DEBUG] [org.gradle.execution.taskgraph.DefaultTaskExecutionGraph] Timing: Executing the DAG took 10.575 secs
2021-01-05T08:25:59.235+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Completing Build operation 'Run tasks'
2021-01-05T08:25:59.235+0000 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationExecutor] Build operation 'Run tasks' completed
2021-01-05T08:25:59.236+0000 [QUIET] [system.out] Task timings (>10sec):
2021-01-05T08:25:59.236+0000 [QUIET] [system.out]   0min 10s  :xxx:sonarqube
2021-01-05T08:25:59.236+0000 [DEBUG] [org.gradle.internal.work.DefaultWorkerLeaseService] Worker lease root.1 completed (0 worker(s) in use)
2021-01-05T08:25:59.236+0000 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Daemon worker Thread 5: released lock on root.1
2021-01-05T08:25:59.236+0000 [WARN] [org.gradle.internal.featurelifecycle.LoggingDeprecatedFeatureHandler] 
2021-01-05T08:25:59.236+0000 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] 
2021-01-05T08:25:59.236+0000 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] BUILD SUCCESSFUL in 12s

Hello!

Any idea as to why it would take so much time?

Thank you!
Iuliana

Hi @iarama,

Can you provide the debug logs but just attach the org.sonarqube.gradle.SonarQubeTask associated logs? Just copy those lines and paste it into another file to help keep the log file smaller. I would like to see where it spends its time.

This is probably the reason, but let’s confirm with your debug logs.

Joe

Hello,

I’ve gathered in this file all the lines containing org.sonarqube.gradle.SonarQubeTask
Please let me know if anything else is needed.

sonarqubetaskslines.txt (107.6 KB)

Thank you,
Iuliana

@iarama: did you mean to attach the logs?

Yes, sorry, I edited my previous reply.

1 Like

@iarama: Thank you for providing the logs. I see this in the last line of the log file:

2021-01-05T16:59:27.101+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analysis total time: 16.537 s

Total analysis time was 16.537s, which seems comparable/similar to your original scan on SonarQube 7.6 as 12s. Am I missing something or can you show where the delay is?

Also, in your earlier post in this thread here, I saw the analysis time as quite small also:

2021-01-05T08:25:59.232+0000 [INFO] [org.sonarqube.gradle.SonarQubeTask] Analysis total time: 9.447 s

9.447s, comparable as well.

Joe

Thanks for checking this.

I have one other curiosity. It seems that what indeed is taking a lot of time for us is the background task for the Quality Gate check. It appears that for first time runs, it takes a lot of time - for 2.2k lines of code, it took exactly 1h 0min to finish this check. For subsequent runs, we’ve set new code to reference previous run so the time is significantly decreased.

My question would be, is it expected to take so much time for the first runs?

Thank you!

@iarama: Let’s look at the logs for more information again.

  • Change your Log Level to DEBUG ( Administration > System > Log Level )
  • Repeat the issue
  • Zip $SONARQUBE_HOME/logs/ directory and attach on your next response