introduce CxxAstVisitorProfiler for CxxAstScanner

[ivangalkin]

Hi @guwirth, @Bertk, @jmecosta and All,

I am still suffering from the plugin slowdown, which is most probably caused by the CxxSquidSensor.
I tried hprof as profiling agent, but it is too fine-grained and works slow with the real SonarQube projects. Since we already plan to make the CxxSquidSensor parallel (#1493), my idea was to introduce some high-level "flight data recorder": for each check (or rather for each AstVisitor) collect its duration. See details below.

My hand-made profiler has several disadvantages, e.g. the analysis has to be implemented in some external tool (e.g. in python). Do you know some better standard profiling tools? Or maybe there are standard tools, which could import the fligh-data and visualize/analyze it? What do you think of this patch in particular? Any ideas are welcome. Thank you!

Details of the current patch:

• introduce the hidden property sonar.cxx.squidprofiler.out=<path>

• if property set, decorate each AstVisitor (all squid checks, CPD, highlighting etc), so that it tracks the elapsed time per source file

• dump this duration as well as other invocation details to <path> in JSON format

• currently only duration is logged

• for parallel execution we can log start/stop time also, in order to check the CPU utilization level (see Speed-up analysis time with thread pool #1493)

• output: semi-JSON format for python analysis (e.g. in http://jupyter.org/)
  { "visitor": "%s", "source_file": "%s", "duration_ms": "%d" }

---

This change is 

[guwirth]

@ivangalkin

• First of all the question is if a check is really the root cause? Have you turned all checks off to see if it is still slow?
• Think we should not introduce new files / settings, should be sonar.showProfiling
  or sonar.log.level=DEBUG/TRACE. By the way: have you already tried showProfiling?
  • Maybe you can also look at the core what they do in case of showProfiling=true
• I don't like to add this additional code. But it's just a feeling...

[ivangalkin]

Hi @guwirth,

thank you for your comments. I've overseen the existence of sonar.showProfiling property. I will give it a try, although I have not seen, that it is used in SSLR SquidBridge. This component "orchestrates" the whole analysis in sonar-cxx and this part is of the highest interest to me.

In a meantime I updated the patch in order to increase the scope of visitors. I've identified a couple of hotspots already and will come back with conclusions later.

There is no need to merge this PR. It's for internal usage only and probably of no interest to other developer AFAIS. Actually, I would like to propose it to sslr-squid-bridge, but this project looks almost frozen to me.

@m-g-sonar are you interested in profiling functionality for sslr-squid-bridge?

[m-g-sonar]

Hey @ivangalkin,

Thanks for the ping. We are indeed slowly but surely moving away from sslr-squid-bridge at SonarSource, dropping features and progressively stopping maintenance of the project. Today, we are only keeping it "more or less" up-to-date for a very limited set of projects at SonarSource. The idea being to completely remove all dependencies on it eventually. While help/simplify profiling is a quite interesting topic, sslr-squid-bridge is probably not the best place to introduce that! @henryju something to integrate/promote to the scanner API maybe?

Cheers,
Michael

[ivangalkin]

Hi @m-g-sonar! We suspected the sunsetting of sslr-squid-bridge. It is understandable, that there is no demand in features like profiling. Nevertheless thank you for the quick and very informative response! Best regards, Ivan

[ivangalkin]

1. Fix #1509 - enable custom metrics introduced by sonar-cxx #1514 improved performance and reduced the memory overhead: aggregation of metrics is not done in Hashtables anymore, but rather performed server-side in MeasureComputer. So there is no big need in profiling anymore.

2. there is no interest for merging this functionality neither from sonar-cxx, nor from sslr-squid-bridge side

3. I can imagine, that we could benefit from profiling, when somebody starts to implement Speed-up analysis time with thread pool #1493. But for now I will close this PR.

Thank you for the comments.

[jmecosta]

Hi Does anyone has problems on sending to much stuff to server side. When using community edition it ha only one worker and it slows down quite a bit concurruant builds if two much stuff happen there. In my case we have some big projects and when they take the server for 40 min we cannot anymore do branch analysis on many of the small projects we have. This was a pontual thing since those run during the night so they dont slow anyone. However it was enough to notice this issue. Imo because we have so many agents runnig analysis i dobt mind to much agents taking longer and cosuming more memory if they dont have a 2 long server side analysis. Does anyone has problem with this?

…

On Fri, 3 Aug 2018, 18:04 ivangalkin, ***@***.***> wrote: 1. #1514 <#1514> improved performance and reduced the memory overhead: aggregation of metrics is not done in Hashtables anymore, but rather performed server-side in MeasureComputer. So there is no big need in profiling anymore. 2. there is no interest for merging this functionality neither from sonar-cxx, nor from sslr-squid-bridge side 3. I can imagine, that we could benefit from profiling, when somebody starts to implement #1493 <#1493>. But for now I will close this PR. Thank you for the comments. — You are receiving this because your review was requested. Reply to this email directly, view it on GitHub <#1507 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA_jyKr0lZw7nHcLTrtGNf5AVAbhZmBVks5uNIKEgaJpZM4U27fs> .

[ivangalkin]

In case someone uses/will use this code for profiling: I've done a wrong assumption about the order of visitX()/leaveX() invocations. It's not enough to measure the elapsed time between visitFile() and leaveFile(). One has to measure time spent inside of each visitX()/leaveX() method. See implementation of org.sonar.squidbridge.AstScanner::scanFiles(Collection<File> files).

The following patch solves the problem:

diff --git a/cxx-squid/src/main/java/org/sonar/cxx/CxxAstVisitorProfiler.java b/cxx-squid/src/main/java/org/sonar/cxx/CxxAstVisitorProfiler.java
index fde2add..d2a44d9 100644
--- a/cxx-squid/src/main/java/org/sonar/cxx/CxxAstVisitorProfiler.java
+++ b/cxx-squid/src/main/java/org/sonar/cxx/CxxAstVisitorProfiler.java
@@ -48,7 +48,7 @@ public class CxxAstVisitorProfiler {
 
   public static class CxxProfilerDecorator_AstVisitor<G extends Grammar> extends SquidAstVisitor<G> {
     protected SquidAstVisitor<G> v;
-    private long startTimestamp = 0;
+    private long nanoPerFile = 0;
     private File outFile;
 
     public CxxProfilerDecorator_AstVisitor(SquidAstVisitor<G> visitor, File outF) {
@@ -99,25 +99,31 @@ public class CxxAstVisitorProfiler {
 
     @Override
     public void visitFile(@Nullable AstNode ast) {
-      startTimestamp = System.nanoTime();
+      final long startTimestamp = System.nanoTime();
       v.visitFile(ast);
+      nanoPerFile = System.nanoTime() - startTimestamp;
     }
 
     @Override
     public void leaveFile(@Nullable AstNode ast) {
+      final long startTimestamp = System.nanoTime();
       v.leaveFile(ast);
-      long nanoDuration = System.nanoTime() - startTimestamp;
-      writeEvent(nanoDuration);
+      nanoPerFile += System.nanoTime() - startTimestamp;
+      writeEvent(nanoPerFile);
     }
 
     @Override
     public void visitNode(AstNode ast) {
+      final long startTimestamp = System.nanoTime();
       v.visitNode(ast);
+      nanoPerFile += System.nanoTime() - startTimestamp;
     }
 
     @Override
     public void leaveNode(AstNode ast) {
+      final long startTimestamp = System.nanoTime();
       v.leaveNode(ast);
+      nanoPerFile += System.nanoTime() - startTimestamp;
     }
   }