Very slow performance analyzing c# builds. How can i diagnose it?

Mark_Oueis · May 14, 2021, 2:32pm

We are using Developer Edition Version 8.9 (build 43852)

Our builds take approximately 3-4 times as much time when using sonarqube vs not. Would be great if i can get some help diagnosing this.

Sonarqube counts 181,000 lines of code
The msbuild phase of the process takes 6 min with sonarqube as opposed to 2.
A slightly old report analyzer shows the following. I can get a newer one

Total analyzer execution time: 1864.688 seconds. (TaskId:2354)
NOTE: Elapsed time may be less than analyzer execution time because analyzers can run concurrently. (TaskId:2354)
(TaskId:2354)
Time (s) % Analyzer (TaskId:2354)
958.945 51 SonarAnalyzer.Security, Version=8.4.0.2759, Culture=neutral, PublicKeyToken=null (TaskId:2354)
958.945 51 SonarAnalyzer.Security.CSharp.UcfgGenerator (TaskId:2354)
(TaskId:2354)
905.323 48 SonarAnalyzer.CSharp, Version=8.9.0.0, Culture=neutral, PublicKeyToken=c5b62af9de6d7244 (TaskId:2354)
305.065 16 SonarAnalyzer.Rules.SymbolicExecution.SymbolicExecutionRunner (TaskId:2354)
63.712 3 SonarAnalyzer.Rules.CSharp.CbdeHandlerRule (TaskId:2354)
41.783 2 SonarAnalyzer.Rules.CSharp.PrivateFieldUsedAsLocalVariable (TaskId:2354)
16.697 <1 SonarAnalyzer.Rules.CSharp.DeadStores (TaskId:2354)
14.688 <1 SonarAnalyzer.Rules.CSharp.VariableUnused (TaskId:2354)
14.571 <1 SonarAnalyzer.Rules.CSharp.CollectionQuerySimplification (TaskId:2354)
14.178 <1 SonarAnalyzer.Rules.CSharp.UnnecessaryUsings (TaskId:2354)
13.954 <1 SonarAnalyzer.Rules.CSharp.UnusedPrivateMember (TaskId:2354)
12.416 <1 SonarAnalyzer.Rules.CSharp.InsecureEncryptionAlgorithm (TaskId:2354)
12.228 <1 SonarAnalyzer.Rules.CSharp.SymbolReferenceAnalyzer (TaskId:2354)
10.245 <1 SonarAnalyzer.Rules.CSharp.ReadingStandardInput (TaskId:2354)
8.991 <1 SonarAnalyzer.Rules.CSharp.TokenTypeAnalyzer (TaskId:2354)
8.873 <1 SonarAnalyzer.Rules.CSharp.UseStringIsNullOrEmpty (TaskId:2354)
8.759 <1 SonarAnalyzer.Rules.CSharp.DoNotCallGCCollectMethod (TaskId:2354)
8.511 <1 SonarAnalyzer.Rules.CSharp.DangerousGetHandleShouldNotBeCalled (TaskId:2354)
8.383 <1 SonarAnalyzer.Rules.CSharp.DoNotCallAssemblyLoadInvalidMethods (TaskId:2354)
8.277 <1 SonarAnalyzer.Rules.CSharp.ClassAndMethodName (TaskId:2354)
8.232 <1 SonarAnalyzer.Rules.CSharp.ThreadResumeOrSuspendShouldNotBeCalled (TaskId:2354)
8.045 <1 SonarAnalyzer.Rules.CSharp.DoNotCallGCSuppressFinalizeMethod (TaskId:2354)
8.023 <1 SonarAnalyzer.Rules.CSharp.BeginInvokePairedWithEndInvoke (TaskId:2354)

Then the “SonarScanner.MSBuild.exe end” phase takes 10 min

Sensor CSharpSecuritySensor [security] (done) | time=324225ms
Analysis report compressed in 213871ms, zip size=12 MB
Analysis total time: 10:17.277 s

I find it weird that compression takes 3.5 min alone. I must be doing something wrong

How can i improve this drastically?

Andrei_Epure · May 18, 2021, 8:26am

Hello @Mark_Oueis . Welcome to the community forum!

It would be nice to get a newer one, we are constantly making performance improvements and the list of worst-performing rules changes from time to time. Seeing how rules behave in the wild helps us prioritize which performance improvement to do next.

It would help to get verbose logs for the END step (please run SonarScanner.MSBuild.exe begin /k:"MyProject" /d:sonar.verbose=true as the BEGIN step, and please attach the output of END step).

To demistify what we’re doing during these steps, the analysis is done in two steps:

during the build - our native Roslyn analyzers are running for most of the rules (~250 in the default QP); also UCFG files (modelling the control flow of the program) are created for the vulnerability injection analysis which is done in the END step
during the END step - our security engine runs over the UCFG files to find vulnerabilities - we currently have 12 rules that detect injection vulnerabilities - this is expensive and it depends on how many “sources” (sources of user input) and “sinks” (DB access, file access etc) there are in the program.

Mark_Oueis · May 18, 2021, 6:35pm

Here is the latest report from msbuild

Total analyzer execution time: 250.154 seconds.
NOTE: Elapsed time may be less than analyzer execution time because analyzers can run concurrently.

     Time (s)    %   Analyzer
      209.971   83   SonarAnalyzer.CSharp, Version=8.22.0.0, Culture=neutral, PublicKeyToken=c5b62af9de6d7244
       41.440   16      SonarAnalyzer.Rules.SymbolicExecution.SymbolicExecutionRunner
       23.209    9      SonarAnalyzer.Rules.CSharp.UnnecessaryUsings
       22.350    8      SonarAnalyzer.Rules.CSharp.CbdeHandlerRule
       11.964    4      SonarAnalyzer.Rules.CSharp.SymbolReferenceAnalyzer
        9.407    3      SonarAnalyzer.Rules.CSharp.TokenTypeAnalyzer
        6.980    2      SonarAnalyzer.Rules.CSharp.PrivateFieldUsedAsLocalVariable
        4.999    1      SonarAnalyzer.Rules.CSharp.DeadStores
        3.954    1      SonarAnalyzer.Rules.CSharp.UnusedPrivateMember
        3.795    1      SonarAnalyzer.Rules.CSharp.MetricsAnalyzer
        3.791    1      SonarAnalyzer.Rules.CSharp.InsecureEncryptionAlgorithm

Here is the end of the logs for sonar end - somewhat redacted. Attached is the full sonar end logs
sonarendlogs.txt (89.1 KB)

17:24:30.639 DEBUG: Adding normal issue S1128: 1000s of files
17:24:32.164 INFO: Found 5 MSBuild C# projects: 3 MAIN projects. 2 TEST projects.
17:24:32.164 INFO: Sensor C# [csharp] (done) | time=16844ms
17:24:32.164 INFO: Sensor C# Tests Coverage Report Import [csharp]
17:24:32.165 DEBUG: Analyzing coverage with wildcardPatternFileProvider with base dir ‘C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf.’ and file separator ''.
17:24:32.166 DEBUG: Pattern matcher extracted prefix/absolute path ‘C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf.\Coverage\Report.html’ from the given pattern ‘Coverage\Report.html’.
17:24:32.166 DEBUG: Pattern matcher returns a single file: ‘C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf.\Coverage\Report.html’.
17:24:32.166 DEBUG: The current user dir is ‘C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf’.
17:24:32.166 INFO: Aggregating the HTML reports from ‘C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf.\Coverage\Report.html’.
17:24:32.212 DEBUG: dotCover aggregator: collected 1584 report files to parse.
17:24:32.212 INFO: Parsing the dotCover report *1000s of files
17:24:33.206 INFO: Adding this code coverage report to the cache for later reuse: C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf.\Coverage\Report.html
17:24:33.218 DEBUG: Analyzing coverage after aggregate found ‘1583’ coverage files.
17:24:33.219 DEBUG: Skipping *1000s of files
17:24:33.946 DEBUG: The total number of file count statistics is ‘1583’.
17:24:33.946 INFO: Coverage Report Statistics: 1583 files, 1154 main files, 1154 main files with coverage, 429 test files, 0 project excluded files, 0 other language files.
17:24:33.946 INFO: Sensor C# Tests Coverage Report Import [csharp] (done) | time=1782ms
17:24:33.946 INFO: Sensor Zero Coverage Sensor
17:24:34.028 INFO: Sensor Zero Coverage Sensor (done) | time=82ms
17:24:36.082 INFO: CPD Executor 714 files had no CPD blocks
17:24:36.083 INFO: CPD Executor Calculating CPD for 2310 files
17:24:36.083 DEBUG: Detection of duplications for 1000s of files
17:24:37.562 INFO: CPD Executor CPD calculation finished (done) | time=1479ms
17:24:37.574 DEBUG: SCM revision ID ‘59d447821b8b9477623271ad20bc7730fb84153b’
17:24:37.574 INFO: Load New Code definition
17:24:37.588 DEBUG: GET 200 http://SOMEIP/api/new_code_periods/show.protobuf?project=gc-api&branch=DEVOPS-2728-snarqube-build-perf | time=14ms
17:24:37.589 INFO: Load New Code definition (done) | time=15ms
17:24:43.580 INFO: Analysis report generated in 4341ms, dir size=32 MB
17:26:46.751 INFO: Analysis report compressed in 123171ms, zip size=12 MB
17:26:46.751 INFO: Analysis report generated in C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf.sonarqube\out.sonar\scanner-report
17:26:46.751 DEBUG: Upload report
17:26:47.429 DEBUG: POST 200 http://SOMEIP/api/ce/submit?projectKey=gc-api&characteristic=branch%3DDEVOPS-2728-snarqube-build-perf&characteristic=branchType%3DBRANCH | time=677ms
17:26:47.431 INFO: Analysis report uploaded in 680ms
17:26:47.433 DEBUG: Report metadata written to C:\Jenkins\workspace_DEVOPS-2728-snarqube-build-perf.sonarqube\out.sonar\report-task.txt
17:26:47.433 INFO: ANALYSIS SUCCESSFUL, you can browse http://SOMEIP/dashboard?id=gc-api&branch=DEVOPS-2728-snarqube-build-perf
17:26:47.433 INFO: Note that you will be able to access the updated dashboard once the server has processed the submitted analysis report
17:26:47.433 INFO: More about the report processing at http://SOMEIP/api/ce/task?id=AXmAhAf87-YLrK4ZV3Nn
17:26:47.435 DEBUG: Post-jobs :
17:26:47.439 INFO: Analysis total time: 6:33.387 s
17:26:47.442 INFO: ------------------------------------------------------------------------
17:26:47.442 INFO: EXECUTION SUCCESS
17:26:47.442 INFO: ------------------------------------------------------------------------
17:26:47.442 INFO: Total time: 6:34.764s
17:26:47.643 INFO: Final Memory: 61M/1706M
17:26:47.643 INFO: ------------------------------------------------------------------------
Process returned exit code 0
The SonarScanner CLI has finished

To help visualize the difference… Here is the exact same build WITHOUT sonarqube vs with sonarqube

WITHOUT

WITH

msbuild portion goes from 38s to 3min 33s and a whole new section for sonarqube adds an extra 6min 42s.

Thanks for your help!

Andrei_Epure · May 27, 2021, 4:07pm

Hello @Mark_Oueis

I had a look at the logs you gave (thank you!) and found the following interesting information:

17:20:45.085 INFO: Sensor CSharpSecuritySensor [security]
17:20:59.555 INFO: Read 2681 type definitions
17:20:59.591 INFO: Reading UCFGs from: C:\Jenkins\workspace\_DEVOPS-2728-snarqube-build-perf\.sonarqube\out\ucfg_cs2
17:23:52.538 INFO: 17:23:52.538 Building Runtime Type propagation graph
17:23:54.244 INFO: Analyzing 32268 ucfgs to detect vulnerabilities.
17:24:15.296 INFO: All rules entrypoints : 0 Retained UCFGs : 0
17:24:15.300 INFO: Sensor CSharpSecuritySensor [security] (done) | time=210215ms

The injection vulnerability analysis I previously mentioned didn’t actually take place due to some optimizations inside it (there were no entrypoints found in the application).

However, what it took time was actually to read the metadata files we generated for analysis (type information and UCFG files containing the application control flow graph information). This suggests either that:

you may want to look into optimizing the disk access on your build machines (either hardware or software)
you may want to look into your antivirus software configuration (and exclude the folder with the source code / where the analysis is done)

And regarding the other report, please bear in mind that we removed (because their performance problems) from the default Quality Profile the following two rules that you have activated:

       23.209    9      SonarAnalyzer.Rules.CSharp.UnnecessaryUsings
       22.350    8      SonarAnalyzer.Rules.CSharp.CbdeHandlerRule

UnnecessaryUsings is RSPEC-1128 (S1128) and it’s a code smell - you can remove it from the QP if you think it’s not worth the cost. CbdeHandlerRule refers to the rule RSPEC-3949 Calculations should not overflow (S3949), which currently does not have a good cost/benefit ratio in our opinion, hence we removed it from the SonarWay default Quality Profile.

The SymbolicExecutionRunner is running multiple bug-detection rules using the Symbolic Execution technique and we believe they are worth the costs given the benefit they bring.

Regarding this, given that you have in your Quality Profile rules that we removed from the default Quality Profile - your QP may be out of sync with the default one, which means you may not have the latest rules we have been adding - you may want to visit what rules you include in your QP and add the newest ones to benefit from them. We’ve added many vulnerability and security hotspot detection rules in the past year and it would be a pity not to benefit from them.

I hope this helps. Please let us know if you manage to improve your build times.

Thanks,
Andrei

Andrei_Epure · July 21, 2021, 12:39pm

Hi @Mark_Oueis - did you manage to improve the performance of your C# build and analysis?

Andrei_Epure · September 23, 2021, 9:27am

A post was split to a new topic: Performance problems with S3949