SONAR-6799 add log of Component visitor cumulative execution duration

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/component/PathAwareVisitorWrapper.java b/server/sonar-server/src/main/java/org/sonar/server/computation/component/PathAwareVisitorWrapper.java
index 902102e65421f75449f9ee1fba1d6e33980bf850..8f804ba5abe7fa287ed0700ee23b253dec3722ba 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/component/PathAwareVisitorWrapper.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/component/PathAwareVisitorWrapper.java
@@ -32,6 +32,11 @@ public class PathAwareVisitorWrapper<T> implements VisitorWrapper {
     this.delegate = delegate;
   }
 
+  @Override
+  public ComponentVisitor getWrappedVisitor() {
+    return this.delegate;
+  }
+
   @Override
   public void beforeComponent(Component component){
     stack.add(new PathElementImpl<>(component, createForComponent(component)));

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/component/TypeAwareVisitorWrapper.java b/server/sonar-server/src/main/java/org/sonar/server/computation/component/TypeAwareVisitorWrapper.java
index fc04c6e1fa41dcc5161efc469f2a70fc18768995..a5da916296c0113d12545362bb19ae7da2dbbea1 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/component/TypeAwareVisitorWrapper.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/component/TypeAwareVisitorWrapper.java
@@ -28,6 +28,11 @@ public class TypeAwareVisitorWrapper implements VisitorWrapper {
     this.delegate = delegate;
   }
 
+  @Override
+  public ComponentVisitor getWrappedVisitor() {
+    return this.delegate;
+  }
+
   @Override
   public void beforeComponent(Component component){
     // Nothing to do

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorWrapper.java b/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorWrapper.java
index 21a782f0ed6cea66f55c4cc47f1144b2c93589d1..2a0d7ec656f77e5463b2700760bed5d24b99e5a1 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorWrapper.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorWrapper.java
@@ -22,6 +22,8 @@ package org.sonar.server.computation.component;
 
 public interface VisitorWrapper extends TypeAwareVisitor {
 
+  ComponentVisitor getWrappedVisitor();
+
   void beforeComponent(Component component);
 
   void afterComponent(Component component);

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorsCrawler.java b/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorsCrawler.java
index ea5e20ee9a218a3d35143c33baf9bbdaa62169df..0b03029128135bfa88cbb3f31a355c4b1abc5b1e 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorsCrawler.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/component/VisitorsCrawler.java
@@ -23,11 +23,13 @@ package org.sonar.server.computation.component;
 import com.google.common.base.Function;
 import com.google.common.base.Predicate;
 import com.google.common.collect.ImmutableMap;
+import com.google.common.collect.Maps;
 import java.util.List;
 import java.util.Map;
 import javax.annotation.Nonnull;
-import org.sonar.api.utils.log.Logger;
+import javax.annotation.Nullable;
 import org.sonar.api.utils.log.Loggers;
+import org.sonar.core.util.logs.Profiler;
 
 import static com.google.common.collect.FluentIterable.from;
 import static com.google.common.collect.Iterables.concat;
@@ -38,8 +40,7 @@ import static java.util.Objects.requireNonNull;
  */
 public class VisitorsCrawler implements ComponentCrawler {
 
-  private static final Logger LOGGER = Loggers.get(VisitorsCrawler.class);
-
+  private final Map<ComponentVisitor, VisitorDuration> visitorCumulativeDurations;
   private final List<VisitorWrapper> preOrderVisitorWrappers;
   private final List<VisitorWrapper> postOrderVisitorWrappers;
 
@@ -47,6 +48,13 @@ public class VisitorsCrawler implements ComponentCrawler {
     List<VisitorWrapper> visitorWrappers = from(visitors).transform(ToVisitorWrapper.INSTANCE).toList();
     this.preOrderVisitorWrappers = from(visitorWrappers).filter(MathPreOrderVisitor.INSTANCE).toList();
     this.postOrderVisitorWrappers = from(visitorWrappers).filter(MatchPostOrderVisitor.INSTANCE).toList();
+    this.visitorCumulativeDurations = from(visitors).toMap(VisitorWrapperToInitialDuration.INSTANCE);
+  }
+
+  public Map<ComponentVisitor, Long> getCumulativeDurations() {
+    return ImmutableMap.copyOf(
+      Maps.transformValues(this.visitorCumulativeDurations, VisitorDurationToDuration.INSTANCE)
+      );
   }
 
   @Override
@@ -84,7 +92,8 @@ public class VisitorsCrawler implements ComponentCrawler {
   }
 
   private void visitNode(Component component, VisitorWrapper visitor) {
-    LOGGER.trace("Visitor '{}' is currently visiting component {}", visitor, component);
+    Profiler profiler = Profiler.create(Loggers.get(visitor.getWrappedVisitor().getClass()))
+      .startTrace("Visiting component {}", component.getKey());
     visitor.visitAny(component);
     switch (component.getType()) {
       case PROJECT:
@@ -111,6 +120,12 @@ public class VisitorsCrawler implements ComponentCrawler {
       default:
         throw new IllegalStateException(String.format("Unknown type %s", component.getType().name()));
     }
+    long duration = profiler.stopTrace();
+    incrementDuration(visitor, duration);
+  }
+
+  private void incrementDuration(VisitorWrapper visitorWrapper, long duration) {
+    visitorCumulativeDurations.get(visitorWrapper.getWrappedVisitor()).increment(duration);
   }
 
   private enum ToVisitorWrapper implements Function<ComponentVisitor, VisitorWrapper> {
@@ -173,4 +188,36 @@ public class VisitorsCrawler implements ComponentCrawler {
       return visitorWrapper.getOrder() == ComponentVisitor.Order.POST_ORDER;
     }
   }
+
+  private static final class VisitorDuration {
+    private long duration = 0;
+
+    public void increment(long duration) {
+      this.duration += duration;
+    }
+
+    public long getDuration() {
+      return duration;
+    }
+  }
+
+  private enum VisitorWrapperToInitialDuration implements Function<ComponentVisitor, VisitorDuration> {
+    INSTANCE;
+
+    @Override
+    @Nonnull
+    public VisitorDuration apply(@Nonnull ComponentVisitor visitorWrapper) {
+      return new VisitorDuration();
+    }
+  }
+
+  private enum VisitorDurationToDuration implements Function<VisitorDuration, Long> {
+    INSTANCE;
+
+    @Nullable
+    @Override
+    public Long apply(VisitorDuration input) {
+      return input.getDuration();
+    }
+  }
 }

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/step/ExecuteVisitorsStep.java b/server/sonar-server/src/main/java/org/sonar/server/computation/step/ExecuteVisitorsStep.java
index cf29c473e3c61472e5b4ad6f8bb90e96723163c0..480a8bdc591b1eaddda66d2a1a94106b37ed82c3 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/step/ExecuteVisitorsStep.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/step/ExecuteVisitorsStep.java
@@ -21,11 +21,17 @@
 package org.sonar.server.computation.step;
 
 import java.util.List;
+import java.util.Map;
+import org.sonar.api.utils.log.Logger;
+import org.sonar.api.utils.log.Loggers;
 import org.sonar.server.computation.component.ComponentVisitor;
 import org.sonar.server.computation.component.TreeRootHolder;
 import org.sonar.server.computation.component.VisitorsCrawler;
 
 public class ExecuteVisitorsStep implements ComputationStep {
+
+  private static final Logger LOGGER = Loggers.get(ExecuteVisitorsStep.class);
+
   private final TreeRootHolder treeRootHolder;
   private final List<ComponentVisitor> visitors;
 
@@ -35,12 +41,22 @@ public class ExecuteVisitorsStep implements ComputationStep {
   }
 
   @Override
-  public void execute() {
-    new VisitorsCrawler(visitors).visit(treeRootHolder.getRoot());
+  public String getDescription() {
+    return "Execute Component Visitors";
   }
 
   @Override
-  public String getDescription() {
-    return "Execute visitors";
+  public void execute() {
+    VisitorsCrawler visitorsCrawler = new VisitorsCrawler(visitors);
+    visitorsCrawler.visit(treeRootHolder.getRoot());
+    logVisitorExecutionDurations(visitors, visitorsCrawler);
+  }
+
+  private static void logVisitorExecutionDurations(List<ComponentVisitor> visitors, VisitorsCrawler visitorsCrawler) {
+    LOGGER.info("  Execution time for each Component visitor:");
+    Map<ComponentVisitor, Long> cumulativeDurations = visitorsCrawler.getCumulativeDurations();
+    for (ComponentVisitor visitor : visitors) {
+      LOGGER.info("  - {} | time={}ms", visitor.getClass().getSimpleName(), cumulativeDurations.get(visitor));
+    }
   }
 }