Significant increase in build times

ddarmonAC · June 3, 2021, 4:01pm

ALM used: Azure DevOps
CI system used: Azure DevOps

Scanner command used when applicable (private details masked):

We use Azure DevOps tasks. Snippet of relevant piece of pipeline

- task: SonarCloudPrepare@1
  inputs:
    SonarCloud: 'sonarcloud'
    organization: 'alayacare'
    scannerMode: 'MSBuild'
    projectKey: 'clinical-care-api-auth'
    projectName: 'clinical-care-api-auth'
    extraProperties: |
      sonar.cs.opencover.reportsPaths="**/*coverage*.xml"
- task: DotNetCoreCLI@2
  displayName: 'Restore Packages'
  inputs:
    command: restore
    projects: 'Tests/**/*.csproj'
    feedsToUse: 'select'
    vstsFeed: 'd2a39f60-7b57-4631-8ef6-06c61f453733'
- task: DotNetCoreCLI@2
  displayName: 'Run Tests'
  inputs:
    command: test
    projects: 'Tests/**/*.csproj'
    testRunTitle: 'Tests'
    arguments: '--no-restore /p:CollectCoverage=true /p:CoverletOutputFormat="opencover" --collect "XPlat Code Coverage"'
- task: PublishCodeCoverageResults@1
  inputs:
    codeCoverageTool: cobertura
    summaryFileLocation: $(Agent.TempDirectory)/**/coverage.cobertura.xml
    pathToSources: $(Build.SourcesDirectory)
    failIfCoverageEmpty: true
- task: SonarCloudAnalyze@1
- task: SonarCloudPublish@1
  inputs:
    pollingTimeoutSec: '300'

This part is the part that takes considerably longer when using SonarCloud:

- task: DotNetCoreCLI@2
 displayName: 'Run Tests'
 inputs:
   command: test
   projects: 'Tests/**/*.csproj'
   testRunTitle: 'Tests'
   arguments: '--no-restore /p:CollectCoverage=true /p:CoverletOutputFormat="opencover" --collect "XPlat Code Coverage"'

Languages of the repository: .NET Core
Error observed: n/a
Steps to reproduce: n/a
Potential workaround: n/a

Hi,

We are using the SonarCloud integration for Azure DevOps to analyze .NET Core and .NET Framework projects, but are experiencing a significant increase in build time, with builds previously taking less than a minute going up close to 10 minutes, and builds previously taking 10 minutes going up to almost an hour. We have experimented with using more powerful hardware, but that did not make a real difference.

Is this behavior expected? Are there ways to cut down the build time?

Thanks.

Andrei_Epure · June 4, 2021, 1:38pm

Hello @ddarmonAC and welcome to our community.

RE: how our analysis works, I encourage you to read this answer. To demistify a bit more our integration with MSBuild, also this answer.

RE: performance problem. We have a backlog of performance improvements to do (and we are doing them regularly). It may be due to a known issue or an unknown one. It would help us to learn more (and we could provide guidelines to help).

Could you please run the msbuild with /p:reportanalyzer=true /v:d to provide the time for each Roslyn analyzer?

And you can extract the time to analyze with this snippet after you download the logs:

dotnet build … -v:d -p:reportanalyzer=true > build_logs.txt

select-string -path “build_logs.txt ” -pattern “NOTE: Elapsed time may be less than analyzer execution time because analyzers can run concurrently.” -Context 5,30 > analyzer_times.txt

And share analyzer_times.txt with us.

Also, please share the logs from the SonarCloudAnalyze task with us.

Thanks,
Andrei

ddarmonAC · June 4, 2021, 9:12pm

Hi Andrei,

Here are logs you requested on a repo we are experiencing extra build time increases in.

analyzer_times.txt (62.0 KB)
sonarcloud_analyze_debug.txt (3.0 MB)

Many thanks.

ddarmonAC · June 15, 2021, 6:21pm

Hello Andrei,

Did you have any insights using those attached files?

Thanks,
Daniel

Andrei_Epure · June 21, 2021, 3:28pm

Hello @ddarmonAC , I apologize for the delay.

From the file you gave, I see our analyzer SonarAnalyzer.CSharp taking 7 seconds, 15 seconds and then for three projects taking under 10 seconds.

2021-06-04T17:06:52.0677045Z          Time (s)    %   Analyzer
2021-06-04T17:06:52.0677998Z             7.672   80   SonarAnalyzer.CSharp, 
2021-06-04T17:07:11.7852250Z            15.477   79   SonarAnalyzer.CSharp
2021-06-04T17:07:15.8415108Z             1.348   66   SonarAnalyzer.CSharp
2021-06-04T17:07:36.5263022Z             7.561   80   SonarAnalyzer.CSharp
2021-06-04T17:07:56.4058452Z             7.258   80   SonarAnalyzer.CSharp

Nothing out of the ordinary here.

This file seems to have trimmed logs. The end of the logs should contain a line EXECUTION SUCCESS and then something like Total time: 15:44.758s.

What I would like to see in the Analyze logs is a line like 2021-05-31T14:29:41.9901834Z INFO: Sensor CSharpSecuritySensor [security] (done) | time=740392ms, and from that point we can see if and which security rule might take longer. Or if the disk I/O takes too much time (case in which you may have the antivirus scanning the metadata files written by the analyzer on disk) - see this topic.

ddarmonAC · July 7, 2021, 1:38pm

Hello Andrei,

I have discussed with dev and it’s actually the dotnet test step that is the significant increase. SonarCloudAnalyze task also takes some extra time, but that does not account for most of the build time increase.

I’m attaching the full logs for both these
steps - could you see if this helps clarify anything?

Many thanks.
dotnet_test_full_log.txt.zip (1.6 MB)
SonarCloud_Analyze_log.txt.zip (10.7 KB)

Andrei_Epure · July 14, 2021, 11:57am

Hello Daniel,

I’m afraid I am still puzzled - the logs in dotnet_test_full_log.txt start at 2021-07-06T22:30:18 and finish at 2021-07-06T22:41:11 - this is 10 minutes, far from

These are the execution times for your projects:

Time (s)    %   Analyzer
8.258   78   SonarAnalyzer.CSharp
19.117   76   SonarAnalyzer.CSharp
1.718   73   SonarAnalyzer.CSharp
8.040   77   SonarAnalyzer.CSharp
0.351   34   SonarAnalyzer.CSharp
8.093   78   SonarAnalyzer.CSharp
77.647   85   SonarAnalyzer.CSharp
0.251   30   SonarAnalyzer.CSharp
8.809   78   SonarAnalyzer.CSharp
77.343   85   SonarAnalyzer.CSharp
48.018   75   SonarAnalyzer.CSharp
1.130   63   SonarAnalyzer.CSharp
9.231   80   SonarAnalyzer.CSharp
16.498   75   SonarAnalyzer.CSharp
72.364   84   SonarAnalyzer.CSharp
50.194   75   SonarAnalyzer.CSharp
40.810   74   SonarAnalyzer.CSharp
1.060   70   SonarAnalyzer.CSharp
1.215   68   SonarAnalyzer.CSharp

Indeed for some projects the analysis time is more than 60 seconds, but that’s expected.

If you look at

	Line 35286: 2021-07-06T22:32:52.7591064Z            77.647   85   SonarAnalyzer.CSharp, Version=8.25.0.0, Culture=neutral, PublicKeyToken=c5b62af9de6d7244

in the logs you can also see the “culprit” rules which take the most time:

Time (s)    %   Analyzer
77.647   85   SonarAnalyzer.CSharp, Version=8.25.0.0, Culture=neutral, PublicKeyToken=c5b62af9de6d7244
16.805   18      SonarAnalyzer.Rules.SymbolicExecution.SymbolicExecutionRunner (S1944, S2053, S2259, S2583, S2589, S3329, S3655, S3900, S3966, S4158, S5773)
8.324    9      SonarAnalyzer.Rules.CSharp.SymbolReferenceAnalyzer (S9999-symbolRef)
3.436    3      SonarAnalyzer.Rules.CSharp.DangerousGetHandleShouldNotBeCalled (S3869)
2.996    3      SonarAnalyzer.Rules.CSharp.TokenTypeAnalyzer (S9999-token-type)
2.759    3      SonarAnalyzer.Rules.CSharp.InsecureEncryptionAlgorithm (S2278, S5547)
2.748    3      SonarAnalyzer.Rules.CSharp.DeadStores (S1854)
2.696    2      SonarAnalyzer.Rules.CSharp.CopyPasteTokenAnalyzer (S9999-cpd)
2.027    2      SonarAnalyzer.Rules.CSharp.MetricsAnalyzer (S9999-metrics)
2.024    2      SonarAnalyzer.Rules.CSharp.VariableUnused (S1481)
1.663    1      SonarAnalyzer.Rules.CSharp.PrivateFieldUsedAsLocalVariable (S1450)
1.401    1      SonarAnalyzer.Rules.CSharp.UnusedPrivateMember (S1144, S4487)
1.382    1      SonarAnalyzer.Rules.CSharp.DoNotCallAssemblyLoadInvalidMethods (S3885)
1.256    1      SonarAnalyzer.Rules.CSharp.ThreadResumeOrSuspendShouldNotBeCalled (S3889)
1.248    1      SonarAnalyzer.Rules.CSharp.DoNotCallGCSuppressFinalize (S3971)
1.223    1      SonarAnalyzer.Rules.CSharp.DoNotCallGCCollectMethod (S1215)
1.157    1      SonarAnalyzer.Rules.CSharp.ReturnValueIgnored (S2201)

The SymbolicExecutionRunner is expected to take long - it’s simulating the data flow in each method to find tricky bugs - in parentheses you can see the IDs which get executed by this class. Null dereference, undisposed resources and other such high-value rules.

For the S9999-... analyzers - these are generating metadata and we have Add caching for symbols retrieved by TokenTypeAnalyzer and SymbolReferenceAnalyzer · Issue #4217 · SonarSource/sonar-dotnet · GitHub in our backlog to improve their performance. In general, we have a performance-related backlog and we make perf improvements almost in each release, in baby steps.

To sum up, in the current logs, I mainly see issues which we know about and will tackle in the future.

Coming back to your initial problem - I am more interested in the logs for the job that takes 1 hour - we may see some new performance hotspots in there which we are not aware of. Could you share those with us, too? Thank you!

mariella-dejong · July 16, 2021, 8:08pm

Thanks for your response, Andrei. The results are from a build that previously took less than a minute. I am a bit hesitant to gather logs for the build that will take over an hour, because that is a Windows application, for which we can’t containerize the CI process. After we executed SonarCloud, SonarCloud had made permanent changes to the build agent, and we had to redeploy our build agents to get build times back to normal.

At the present time, our only interest is code coverage analysis and code coverage enforcement. We are not interested in other analysis SonarCloud does, and it seems that the main culprit for the long build times. Can you tell us if there is a way to turn that off and/or skip it?

Andrei_Epure · July 19, 2021, 3:12pm

Hello @mariella-dejong

You can create a Quality Profile with no rules enabled. In this case, the only analyzers which will run during the build will be the utility ones that are needed to have syntax highlighting and copy-paste detection enabled. There’s a “Bulk change” option in the UI that allows you to deactivate all rules in a single click.

Static code analysis can help a lot not only in the maintainability of the project, but also with finding bugs and vulnerabilities. I strongly suggest to consider reading what rules we have to detect Bugs and Vulnerabilities in C# code, and enable some of them, in order to get an idea of the benefit our product can provide you.

I understand this and in the same time we would really appreciate to see those logs in order to be able to improve our products and prioritize what we will pick next from our performance backlog (or maybe find new issues which we aren’t aware of and manifest in your code base).

You can run the analysis on a local machine, there’s no need to run on the CI environment.

Could you please share what were the symptoms?

mariella-dejong · July 26, 2021, 3:50pm

Thanks for your response, Andrei! When running with a profile that has all analyzers disabled, the build time becomes accessible, so this is really great! There are some other issues blocking us from implementing SonarCloud for that repository at this time, but when we’ll get to it, I’ll do more testing with certain analyzers enabled, and see if we can get to a good compromise there.

Re: the permanent changes to the build machine - future builds (using a pipeline that was not configured to use SonarCloud) were still running all the analyzers. It appears that SonarCloud is making these configuration changes in the user profile of the user running the agent, and not reverting it and/or using a more volatile place.

I’ll see if I can gather some logs for you for the monolith build with all analyzers enabled.

Andrei_Epure · July 27, 2021, 8:34am

Hello @mariella-dejong
This may be related to a Known issue mentioned in the S4NET docs (scroll at the bottom):

I have multiple builds in the same pipeline, each of them getting analyzed even if the Run Code Analysis has already been executed
We don’t uninstall the global ImportBefore targets to support concurrent analyses on the same machine. Main effect is that if you build a solution where a .sonarqube folder is located nearby, then the sonar-dotnet analyzer will be executed along your build task.
To avoid that, you can disable the targets file by adding a build parameter:

msbuild /p:SonarQubeTargetsImported=true
dotnet build -p:SonarQubeTargetsImported=true

(you can add this parameter to the builds which don’t need SQ analysis)

Sounds good!

Tom_Howlett · October 19, 2021, 10:45am

Hello Mariella

In Sonarcloud you now have the ability to run the analysis in concurrent execution mode. This can significantly reduce your analysis time. Just set the following environment variable in the begin step:

SONAR_DOTNET_ENABLE_CONCURRENT_EXECUTION: true

We would love to hear if you have tried this, if you have please could you post a comment on this post and tell us how you got on?

Thanks

Tom