Slow analysis of Code after upgrade

Alexander_Dragun · June 1, 2021, 9:05am

Hi,

After upgrading from version 8.0 to version 8.9 (Community Edition), some tasks (not all, only some of them) are processed for a very long time (some tasks that took before seconds, is very slow now, and complete in tens of minutes, and some in several hours).

It was found that this is due to the latency between queries (example below) to the database (we use Postgresql-12, the same version as before). It is unclear what happens during these delays. The queries themselves are completed in milliseconds. On the contrary, in jobs that run as fast as before, there are no such delays between queries… :

 select                                                    
                                                       
 c.uuid,                                               
 c.kee as kee,                                         
 c.issue_key as issueKey,                              
 c.user_login as userUuid,                             
 c.change_type as changeType,                          
 c.change_data as changeData,                          
 c.created_at as createdAt,                            
 c.updated_at as updatedAt,                            
 c.project_uuid as projectUuid,                         
 c.issue_change_creation_date as issueChangeCreationDate
                                                        
 from issue_changes c                                   
 where  c.change_type='diff'                                 +
   and c.issue_key in                                   
  ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27,$28,$29,$30,$31,$32)

After the queries to the DB are executed, in the CE log we can see the lines below:

DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   Execution time for each component visitor:
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - LoadComponentUuidsHavingOpenIssuesVisitor | time=1ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - IntegrateIssuesVisitor | time=2262787ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - CloseIssuesOnRemovedComponentsVisitor | time=0ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - MaintainabilityMeasuresVisitor | time=50ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - NewMaintainabilityMeasuresVisitor | time=6ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - ReliabilityAndSecurityRatingMeasuresVisitor | time=25ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - NewReliabilityAndSecurityRatingMeasuresVisitor | time=2ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - SecurityReviewMeasuresVisitor | time=12ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - NewSecurityReviewMeasuresVisitor | time=1ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - LastCommitVisitor | time=3953ms
DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep]   - MeasureComputersVisitor | time=48ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Execute component visitors | status=SUCCESS | time=2267002ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Checks executed after computation of measures | status=SUCCESS | time=0ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Compute Quality Gate measures | status=SUCCESS | time=39ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Compute Quality profile measures | status=SUCCESS | time=3ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Generate Quality profile events | status=SUCCESS | time=1ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Generate Quality gate events | status=SUCCESS | time=14ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Check upgrade possibility for not analyzed code files. | status=SUCCESS | time=0ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist components | status=SUCCESS | time=3033ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist analysis | status=SUCCESS | time=7ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist analysis properties | status=SUCCESS | time=9ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist measures | inserts=62 | status=SUCCESS | time=44ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist live measures | insertsOrUpdates=61430 | status=SUCCESS | time=13980ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist duplication data | insertsOrUpdates=0 | status=SUCCESS | time=17ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist new ad hoc Rules | status=SUCCESS | time=0ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist issues | cacheSize=2 MB | inserts=2176 | updates=0 | merged=0 | status=SUCCESS | time=2076ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist project links | status=SUCCESS | time=0ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist events | status=SUCCESS | time=11ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist sources | status=SUCCESS | time=12563ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Persist cross project duplications | status=SUCCESS | time=0ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Enable analysis | status=SUCCESS | time=7ms
INFO  ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Update last usage date of quality profiles | status=SUCCESS | time=7ms

There are lines in the log above:

DEBUG ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.p.s.ExecuteVisitorsStep] - IntegrateIssuesVisitor | time=2262787ms

And

INFO ce[AXnF_QE-KyECyzt8rRYi][o.s.c.t.s.ComputationStepExecutor] Execute component visitors | status=SUCCESS | time=2267002ms

These steps in this example took about 37 minutes… Please tell me what could be the reason?

Thanks in advance!

Sylvain_Combe · June 2, 2021, 8:24am

Hello @Alexander_Dragun
and welcome to the Community!
From your report, I understand that you are experiencing some problems with the speed of some Analysis Background tasks on SonarQube server side, and not one code analysis (which is run with the scanner in your pipeline build agents).
And you have already linked this with some potential issue with your PostgreSQL DB performances. Well done!
From there two questions:

did you apply the VACUUM garbage collection step on your SonarQube DB after your upgrade, as is recommended for PostgreSQL with the Upgrade the Server documentation page?
Did you identify some particularly slow queries in the Compute Engine logs (at TRACE level)? Be careful, TRACE level is very verbose.

Best regards
Sylvain

Alexander_Dragun · June 2, 2021, 8:47am

Hi, Sylvain, much thanks for your response!

Yes, we applied VACUUM;
All right, the problem is observed on the server side, but not with all the tasks. In the CE trace log, we can see that some requests were processed much longer than before.

Alexander_Dragun · June 2, 2021, 9:00am

Also most commonly, but not always, it happens with new branches.

Sylvain_Combe · June 2, 2021, 9:11am

Hi @Alexander_Dragun
thanks for the clarification.
Java application slowness is very often (but not always) due to memory limits. You may have a look at the CE and ES JVM memory consumption and settings, and at the SonarQube Memory Tuning Guidelines in order to check this.

And branch analysis with the Community Edition is not something you will get help for in this forum.

Alexander_Dragun · June 2, 2021, 9:48am

Also, after reading the documentation, I still have a question: does Elasticsearch participate in the background task processing process? Or is it only involved in processing WEB server requests?

Alexander_Dragun · June 2, 2021, 9:53am

Right now:

2021.06.02 11:49:39 TRACE ce[AXnMEHjmaQpQKEvCLH4K][o.s.c.t.p.i.IntegrateIssuesVisitor] Visiting component SOME-PROJECT:prj-srv/src/main/resources/templates/2_2_SUBMIT_PROJECT.html:BRANCH:fixbug-SOMEPROJECT-8323-fe (done) | time=60213ms

Sylvain_Combe · June 2, 2021, 11:50am

Hello @Alexander_Dragun
the Compute Engine will both read from and write to the Search component during the Project Analysis background task.
Elasticsearch cache data is used as well (read from) by the Web component.
You may have a look at heap memory settings and current usage for all your SonarQube JVMs in the Administration->System page.
What do you find there?

Alexander_Dragun · June 2, 2021, 12:08pm

Hi)

Web JVM State

Max Memory (MB)	`1024`
Free Memory (MB)	`328`

Compute Engine JVM State

Max Memory (MB)	`512`
Free Memory (MB)	`386`

Search Engine

JVM Heap Usage	`19.0%`
JVM Heap Used	`192 MB`
JVM Heap Max	`989 MB`

Sylvain_Combe · June 2, 2021, 12:47pm

You should definitely extend the memory for the Compute Engine, 512MB is too little. 1GB should be considered a very minimal value for this component (this is what I use on my laptop test instance).

If you don’t have sufficient memory on your SonarQube server, you can temporarily reduce the memory allocated to the Web component to 512MB.

I can’t really comment on your search engine heap settings without the size of the SonarQube indices.

Alexander_Dragun · June 3, 2021, 7:14am

Hi Sylvain,

After getting over the CE logs again, it became clear that I was mistaken with the definition of the problem at the beginning. The real cause of the issue is that complex database queries take too long to execute. So, after tuning the postgresql configuration (in my case, increasing the value of the ‘work_mem’ parameter helped) background tasks began to pass as quickly as before.

P.S. Also I extended the memory for both CE and ES as you suggested).

Thanks a lot!

Sylvain_Combe · June 3, 2021, 12:43pm

That’s great.
And thanks for sharing!

system · June 10, 2021, 12:43pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.