Very slow analysis of code

SonarQube Server / Community Build
1

Hi,

We have been running sonarqube happily for quite some time, but last friday it got very slow. out of the blue. Tasks that took before 1min 30sec, is very slow, and complete in 10min.
for a bigger project, we went from 5min to 2 to 3hours…

We are trying to pinpoint what could be the underlaying issue, but are failing to find anything.

we are running Developer Edition Version 7.9.1 (build 27448)

given the log below, what can we infer ? SQL ? Elastic ? memory ? (we checked all of those but could not find anything)

thanks a lot in advance!

2020.06.22 14:51:02 INFO ce[][o.s.c.t.CeWorkerImpl] Execute task | project=com.stepstone.search.ssa:searchStatisticAnalysis | type=REPORT | id=AXLcFPNnrCNsbOoR3QJT | submitter=client_user
2020.06.22 14:51:02 INFO ce[AXLcFPNnrCNsbOoR3QJT][c.k.s.s.c.c.AbstractSlackNotifyingComponent] Constructor called, project slack channel config map constructed from general settings
2020.06.22 14:51:03 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Extract report | status=SUCCESS | time=149ms
2020.06.22 14:51:03 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist scanner context | status=SUCCESS | time=352ms
2020.06.22 14:51:03 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Propagate analysis warnings from scanner report | status=SUCCESS | time=35ms
2020.06.22 14:51:15 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Execute DB migrations for current project | status=SUCCESS | time=12051ms
2020.06.22 14:51:15 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Generate analysis UUID | status=SUCCESS | time=0ms
2020.06.22 14:51:16 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Load analysis metadata | status=SUCCESS | time=1045ms
2020.06.22 14:51:17 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Initialize | status=SUCCESS | time=1002ms
2020.06.22 14:51:17 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Verify billing | status=SUCCESS | time=0ms
2020.06.22 14:51:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Build tree of components | components=182 | status=SUCCESS | time=188ms
2020.06.22 14:51:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Validate project | status=SUCCESS | time=641ms
2020.06.22 14:51:45 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Load quality profiles | status=SUCCESS | time=26248ms
2020.06.22 14:51:45 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Load Quality gate | status=SUCCESS | time=370ms
2020.06.22 14:51:45 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Load new code period | status=SUCCESS | time=375ms
2020.06.22 14:51:47 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Detect file moves | reportFiles=128 | dbFiles=128 | addedFiles=0 | status=SUCCESS | time=1610ms
2020.06.22 14:51:47 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Load duplications | duplications=4 | status=SUCCESS | time=11ms
2020.06.22 14:51:47 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute cross project duplications | status=SUCCESS | time=1ms
2020.06.22 14:51:47 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute size measures | status=SUCCESS | time=67ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute new coverage | status=SUCCESS | time=30271ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute coverage measures | status=SUCCESS | time=20ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute comment measures | status=SUCCESS | time=6ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Copy custom measures | status=SUCCESS | time=7ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute duplication measures | status=SUCCESS | time=5ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute size measures on new code | status=SUCCESS | time=9ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute language distribution | status=SUCCESS | time=15ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute test measures | status=SUCCESS | time=5ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute complexity measures | status=SUCCESS | time=6ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Load measure computers | status=SUCCESS | time=5ms
2020.06.22 14:52:18 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute Quality Profile status | status=SUCCESS | time=52ms
2020.06.22 14:53:11 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Execute component visitors | status=SUCCESS | time=51351ms
2020.06.22 14:53:13 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Checks executed after computation of measures | status=SUCCESS | time=1540ms
2020.06.22 14:53:13 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute Quality Gate measures | status=SUCCESS | time=9ms
2020.06.22 14:53:13 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Compute Quality profile measures | status=SUCCESS | time=1ms
2020.06.22 14:53:13 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Generate Quality profile events | status=SUCCESS | time=350ms
2020.06.22 14:53:13 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Generate Quality gate events | status=SUCCESS | time=38ms
2020.06.22 14:53:14 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist components | status=SUCCESS | time=1267ms
2020.06.22 14:53:14 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist analysis | status=SUCCESS | time=19ms
2020.06.22 14:53:14 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist analysis properties | status=SUCCESS | time=1ms
2020.06.22 14:53:14 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist measures | inserts=118 | status=SUCCESS | time=104ms
2020.06.22 15:00:05 INFO ce[][o.s.s.l.ServerLogging] Level of logs changed to DEBUG
2020.06.22 15:00:31 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist live measures | insertsOrUpdates=9260 | status=SUCCESS | time=436242ms
2020.06.22 15:00:31 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist duplication data | insertsOrUpdates=0 | status=SUCCESS | time=35ms
2020.06.22 15:00:31 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist new ad hoc Rules | status=SUCCESS | time=1ms
2020.06.22 15:00:31 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist issues | inserts=0 | updates=0 | merged=0 | untouched=381 | status=SUCCESS | time=367ms
2020.06.22 15:00:32 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist project links | status=SUCCESS | time=584ms
2020.06.22 15:00:32 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist events | status=SUCCESS | time=692ms
2020.06.22 15:00:33 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist sources | status=SUCCESS | time=738ms
2020.06.22 15:00:33 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Persist cross project duplications | status=SUCCESS | time=0ms
2020.06.22 15:00:33 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Enable analysis | status=SUCCESS | time=384ms
2020.06.22 15:00:34 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Update last usage date of quality profiles | status=SUCCESS | time=624ms
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.KeepOneFilter] -> Keep one snapshot per day between 2020-05-25 and 2020-06-21
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.DefaultPeriodCleaner] <- Delete analyses of component AWc2SEgBG2l4FalVWqOa:
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.KeepOneFilter] -> Keep one snapshot per week between 2019-06-24 and 2020-05-25
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.DefaultPeriodCleaner] <- Delete analyses of component AWc2SEgBG2l4FalVWqOa:
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.KeepOneFilter] -> Keep one snapshot per month between 2015-06-29 and 2019-06-24
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.DefaultPeriodCleaner] <- Delete analyses of component AWc2SEgBG2l4FalVWqOa:
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.KeepWithVersionFilter] -> Keep analyses with a version prior to 2018-06-25
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.DefaultPeriodCleaner] <- Delete analyses of component AWc2SEgBG2l4FalVWqOa:
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.DeleteAllFilter] -> Delete data prior to: 2015-06-29
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.p.p.DefaultPeriodCleaner] <- Delete analyses of component AWc2SEgBG2l4FalVWqOa:
2020.06.22 15:00:35 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.purge.PurgeDao] <- Delete aborted builds
2020.06.22 15:00:37 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.d.purge.PurgeDao] <- Purge stale branches
2020.06.22 15:00:37 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Purge db | status=SUCCESS | time=3013ms
2020.06.22 15:00:37 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.p.s.IndexAnalysisStep] Call org.sonar.server.measure.index.ProjectMeasuresIndexer@5d019243
2020.06.22 15:00:56 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.p.s.IndexAnalysisStep] Call org.sonar.server.component.index.ComponentIndexer@54f0144f
2020.06.22 15:00:58 DEBUG ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.p.s.IndexAnalysisStep] Call org.sonar.server.issue.index.IssueIndexer@674a7b4f
2020.06.22 15:00:59 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Index analysis | status=SUCCESS | time=21882ms
2020.06.22 15:00:59 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Send issue notifications | newIssuesNotifs=0 | newIssuesDeliveries=0 | myNewIssuesNotifs=0 | myNewIssuesDeliveries=0 | changesNotifs=0 | changesDeliveries=0 | status=SUCCESS | time=502ms
2020.06.22 15:00:59 INFO ce[AXLcFPNnrCNsbOoR3QJT][o.s.c.t.s.ComputationStepExecutor] Publish task results | status=SUCCESS | time=0ms
2

Hi,

Welcome to the community!

Thanks for providing a relevant log section in your first post! :smiley:

What jumps out at me is (what I expected, actually) the ~7 min it takes to Persist live measures. That table can get very big. And yet. You say everything was working fine and then suddenly it slowed down. That makes me suspect that some love & care is needed on the DB side. (Disclaimer: I am not a DBA.) There’s some advice on the upgrade procedure page that might help. Alternately, you might look at the performance of the DB itself…

 
Ann

3

it was indeed the DB that was slow. as it is windows db server, a reboot did help :wink:
strangely all metrics on server were fine…

thanks for your help!

1 Like