Unexpectedly long scanner run times with MSBuild scanner

SonarQube
,
1

Hi,
We recently had an MSBuild analysis that was previously taking ~10 min begin to take 1hr+ with minimal code changes, and we are trying to narrow down possibilities.

Unfortunately, the configuration that runs this analysis in TeamCity is somewhat difficult to reproduce locally, so it is slow & difficult to test out changes to the conifguration.

Versions:

  • MSBuild SonarScanner: 4.4.2
  • SonarQube Server: 7.9.1

Project size: 100k LOC

(I will be attempting to run the analysis with an upgraded MSBuild Scanner version, but it will take some time to configure)

In the meantime, I was hoping some insight could be provided into some of the DEBUG messages we are receiving in the log.

I cannot post the full log due to corporate policy, but I can provide a summary:

Lines 1-10000: seemingly regular output
Lines 10k-2mil (that’s right, 2 million):

]16:47:06.110 DEBUG: file=C:\[path-to-project]\.git\objects\pack, isRacyClean=false, read=2020-10-05 16:42:08.547000000, lastModified=2020-10-05 16:36:14.747740000, delta=353799260000 ns, racy<=2502500 ns

16:47:06.110 DEBUG: file=C:\[path-to-project]\.git\objects\pack, is unmodified

repeated verbatim (only the pre-“DEBUG” timestamp changes)
Last 20 lines: successful analysis

These 2 million identical lines appear to be occurring during a CPD analysis, as this is the message after these 2mil lines are repeated:

16:47:06.622 INFO: 3/3 files analyzed
16:47:07.109 INFO: 71 files had no CPD blocks

Some followup questions on this error:
Are .git files being analyzed?
Would the size of the pack file influence this debug message being repeated? (This project is part of a much larger monorepo)
Are there any rules I can disable that might be affecting this?

Let me know if there’s any more information I can provide. Thank you!

2

Hello @lukebickell and welcome to the community forum!

To clarify: did the msbuild time increase or the END step time increase?

What exactly changed in your system that lead to this increase in time? Did you upgrade SQ, or a certain plugin from the SQ Marketplace?

3

@Andrei_Epure

Only the END step time increased.

What changed:
After comparing between the longer build times with older runs that ran in a normal amount of time, it appears that there are no differences in the SonarQube configuration. The only difference is in code – the code changes themselves have no configuration changes, primarily just added tests.

The monorepo in question is unfortunately very large, otherwise I would have already used git bisect to figure out which commit caused the time increase. I’m still very confused by the
isRacyClean debug lines, since that seems to be what’s causing the slowdown.

4

Thank you @lukebickell.

Another clarification question - have you checked the time stamps, is the additional time being spent only during the CPD analysis?

It would help us to have the logs, would you be willing to send them if I send you a private message?

5

Unfortunately, the way the scanner process is invoked pipes the output after the process has run:

[13:13:57][Step 6/7] PowerShell arguments: -NoProfile, -NonInteractive, -ExecutionPolicy, ByPass, -File, C:\BuildAgent\temp\buildTmp\powershell801124890625306305.ps1
[14:09:23][Step 6/7] SonarScanner for MSBuild 4.4.2

As you can see, 50 minutes occurs “between” these two log steps, but in actuality, the rest of the 1.9 million lines “occurred” during that time, but were printed to stdout afterwards.

I may be able to send the logs in a PM if I properly redact some terms

6

A post was split to a new topic: Unexpectedly long time when running analysis with the maven scanner