SONAR-2017 Log execution time of decorators

2 files changed, 122 insertions, 5 deletions

diff --git a/sonar-batch/src/main/java/org/sonar/batch/phases/DecoratorsExecutor.java b/sonar-batch/src/main/java/org/sonar/batch/phases/DecoratorsExecutor.java
index 452c51c9f93..0a4bc8ff0a9 100644
--- a/sonar-batch/src/main/java/org/sonar/batch/phases/DecoratorsExecutor.java
+++ b/sonar-batch/src/main/java/org/sonar/batch/phases/DecoratorsExecutor.java
@@ -19,7 +19,9 @@
  */
 package org.sonar.batch.phases;
 
+import com.google.common.collect.Lists;
 import org.apache.commons.lang.StringUtils;
+import org.apache.commons.lang.SystemUtils;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.sonar.api.BatchComponent;
@@ -33,9 +35,10 @@ import org.sonar.batch.DecoratorsSelector;
 import org.sonar.batch.DefaultDecoratorContext;
 import org.sonar.batch.index.DefaultIndex;
 
-import java.util.ArrayList;
 import java.util.Collection;
+import java.util.IdentityHashMap;
 import java.util.List;
+import java.util.Map;
 
 public class DecoratorsExecutor implements BatchComponent {
 
@@ -59,24 +62,65 @@ public class DecoratorsExecutor implements BatchComponent {
       LOG.debug("Decorators: {}", StringUtils.join(decorators, " -> "));
     }
 
-    decorateResource(project, decorators, true);
+    DecoratorsProfiler profiler = new DecoratorsProfiler(decorators);
+    decorateResource(project, decorators, true, profiler);
     session.commit();
+    profiler.log();
   }
 
-  private DecoratorContext decorateResource(Resource resource, Collection<Decorator> decorators, boolean executeDecorators) {
-    List<DecoratorContext> childrenContexts = new ArrayList<DecoratorContext>();
+  private DecoratorContext decorateResource(Resource resource, Collection<Decorator> decorators, boolean executeDecorators, DecoratorsProfiler profiler) {
+    List<DecoratorContext> childrenContexts = Lists.newArrayList();
     for (Resource child : index.getChildren(resource)) {
       boolean isModule = (child instanceof Project);
-      DefaultDecoratorContext childContext = (DefaultDecoratorContext) decorateResource(child, decorators, !isModule);
+      DefaultDecoratorContext childContext = (DefaultDecoratorContext) decorateResource(child, decorators, !isModule, profiler);
       childrenContexts.add(childContext.setReadOnly(true));
     }
 
     DefaultDecoratorContext context = new DefaultDecoratorContext(resource, index, childrenContexts, session);
     if (executeDecorators) {
       for (Decorator decorator : decorators) {
+        profiler.start(decorator);
         decorator.decorate(resource, context);
+        profiler.stop();
       }
     }
     return context;
   }
+
+
+  static class DecoratorsProfiler {
+    Collection<Decorator> decorators;
+    Map<Decorator, Long> durations = new IdentityHashMap<Decorator, Long>();
+    long startTime;
+    Decorator currentDecorator;
+
+    DecoratorsProfiler(Collection<Decorator> decorators) {
+      this.decorators = decorators;
+      for (Decorator decorator : decorators) {
+        durations.put(decorator, 0L);
+      }
+    }
+
+    void start(Decorator decorator) {
+      this.startTime = System.currentTimeMillis();
+      this.currentDecorator = decorator;
+    }
+
+    void stop() {
+      Long cumulatedDuration = durations.get(currentDecorator);
+      durations.put(currentDecorator, cumulatedDuration + (System.currentTimeMillis() - startTime));
+    }
+
+    void log() {
+      LOG.debug(getMessage());
+    }
+
+    String getMessage() {
+      StringBuilder sb = new StringBuilder("Decorators time:" + SystemUtils.LINE_SEPARATOR);
+      for (Decorator decorator : decorators) {
+        sb.append("\t").append(decorator.toString()).append(": ").append(durations.get(decorator)).append("ms").append(SystemUtils.LINE_SEPARATOR);
+      }
+      return sb.toString();
+    }
+  }
 }
diff --git a/sonar-batch/src/test/java/org/sonar/batch/phases/DecoratorsExecutorTest.java b/sonar-batch/src/test/java/org/sonar/batch/phases/DecoratorsExecutorTest.java
new file mode 100644
index 00000000000..8f9c1bcd582
--- /dev/null
+++ b/sonar-batch/src/test/java/org/sonar/batch/phases/DecoratorsExecutorTest.java
@@ -0,0 +1,73 @@
+/*
+ * Sonar, open source software quality management tool.
+ * Copyright (C) 2009 SonarSource SA
+ * mailto:contact AT sonarsource DOT com
+ *
+ * Sonar is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * Sonar is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with Sonar; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02
+ */
+package org.sonar.batch.phases;
+
+import org.junit.Test;
+import org.sonar.api.batch.Decorator;
+import org.sonar.api.batch.DecoratorContext;
+import org.sonar.api.resources.Project;
+import org.sonar.api.resources.Resource;
+
+import java.util.Arrays;
+import java.util.List;
+
+import static org.hamcrest.number.OrderingComparisons.greaterThanOrEqualTo;
+import static org.hamcrest.number.OrderingComparisons.lessThan;
+import static org.junit.Assert.assertThat;
+
+public class DecoratorsExecutorTest {
+
+  @Test
+  public void shouldProfileExecutionTime() {
+    Decorator1 decorator1 = new Decorator1();
+    Decorator2 decorator2 = new Decorator2();
+    List<Decorator> decorators = Arrays.asList(decorator1, decorator2);
+    DecoratorsExecutor.DecoratorsProfiler profiler = new DecoratorsExecutor.DecoratorsProfiler(decorators);
+
+    profiler.start(decorator1);
+    profiler.stop();
+    profiler.start(decorator2);
+    profiler.stop();
+
+    assertThat(profiler.getMessage().indexOf("Decorator1"), greaterThanOrEqualTo(0));
+    assertThat(profiler.getMessage().indexOf("Decorator2"), greaterThanOrEqualTo(0));
+
+    // sequence of execution
+    assertThat(profiler.getMessage().indexOf("Decorator1"), lessThan(profiler.getMessage().indexOf("Decorator2")));
+  }
+
+  static class Decorator1 implements Decorator {
+    public void decorate(Resource resource, DecoratorContext context) {
+    }
+
+    public boolean shouldExecuteOnProject(Project project) {
+      return true;
+    }
+  }
+
+  static class Decorator2 implements Decorator {
+    public void decorate(Resource resource, DecoratorContext context) {
+    }
+
+    public boolean shouldExecuteOnProject(Project project) {
+      return true;
+    }
+  }
+}