SONAR-11077 ability to log statistics from CE task steps

6 files changed, 234 insertions, 21 deletions

diff --git a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStep.java b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStep.java
index 3766ecd826f..1d9f67e2e9d 100644
--- a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStep.java
+++ b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStep.java
@@ -20,12 +20,43 @@
 package org.sonar.ce.task.step;
 
 /**
- * A way of splitting the processing of a task into smaller items which can be executed sequencially
+ * A way of splitting the processing of a task into smaller items which can be executed sequentially
  * by {@link ComputationStepExecutor}.
  */
 public interface ComputationStep {
 
-  void execute();
+  /**
+   * Statistics are displayed in the step ending log. They help
+   * understanding the runtime context and potential performance hotspots.
+   *
+   * <p/>
+   * Example:
+   * <code>
+   *   statistics.add("inserts", 200);
+   *   statistics.add("updates", 50);
+   * </code>
+   * adds two parameters to the log:
+   * <code>
+   * 2018.07.26 10:22:58 DEBUG ce[AWTVrwb-KZf9YbDx-laU][o.s.s.c.t.s.ComputationStepExecutor] Persist issues | inserts=200 | updates=50 | time=30ms
+   * </code>
+   *
+   * <p/>
+   * Statistics are logged in the order of insertion.
+   */
+  interface Statistics {
+    /**
+     * @throws NullPointerException if key or value is null
+     * @throws IllegalArgumentException if key has already been set
+     * @throws IllegalArgumentException if key is "time", to avoid conflict with the profiler field with same name
+     */
+    void add(String key, Object value);
+  }
+
+  interface Context {
+    Statistics getStatistics();
+  }
+
+  void execute(Context context);
 
   String getDescription();
 }
diff --git a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java
index 9fa8eea74dd..d706b8914fa 100644
--- a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java
+++ b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java
@@ -25,6 +25,9 @@ import org.sonar.api.utils.log.Logger;
 import org.sonar.api.utils.log.Loggers;
 import org.sonar.core.util.logs.Profiler;
 
+import static com.google.common.base.Preconditions.checkArgument;
+import static java.util.Objects.requireNonNull;
+
 public final class ComputationStepExecutor {
   private static final Logger LOGGER = Loggers.get(ComputationStepExecutor.class);
 
@@ -46,7 +49,7 @@ public final class ComputationStepExecutor {
   }
 
   public void execute() {
-    Profiler stepProfiler = Profiler.create(LOGGER);
+    Profiler stepProfiler = Profiler.create(LOGGER).logTimeLast(true);
     boolean allStepsExecuted = false;
     try {
       executeSteps(stepProfiler);
@@ -59,9 +62,11 @@ public final class ComputationStepExecutor {
   }
 
   private void executeSteps(Profiler stepProfiler) {
+    StepStatisticsImpl statistics = new StepStatisticsImpl(stepProfiler);
+    ComputationStep.Context context = new StepContextImpl(statistics);
     for (ComputationStep step : steps.instances()) {
       stepProfiler.start();
-      step.execute();
+      step.execute(context);
       stepProfiler.stopInfo(step.getDescription());
     }
   }
@@ -80,4 +85,34 @@ public final class ComputationStepExecutor {
   public interface Listener {
     void finished(boolean allStepsExecuted);
   }
+
+  private static class StepStatisticsImpl implements ComputationStep.Statistics {
+    private final Profiler profiler;
+
+    private StepStatisticsImpl(Profiler profiler) {
+      this.profiler = profiler;
+    }
+
+    @Override
+    public void add(String key, Object value) {
+      requireNonNull(key, "Statistic has null key");
+      requireNonNull(value, () -> String.format("Statistic with key [%s] has null value", key));
+      checkArgument(!key.equalsIgnoreCase("time"), "Statistic with key [time] is not accepted");
+      checkArgument(!profiler.hasContext(key), "Statistic with key [%s] is already present", key);
+      profiler.addContext(key, value);
+    }
+  }
+
+  private static class StepContextImpl implements ComputationStep.Context {
+    private final ComputationStep.Statistics statistics;
+
+    private StepContextImpl(ComputationStep.Statistics statistics) {
+      this.statistics = statistics;
+    }
+
+    @Override
+    public ComputationStep.Statistics getStatistics() {
+      return statistics;
+    }
+  }
 }
diff --git a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStep.java b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStep.java
index 6508d1d5e0b..8b7c2040f99 100644
--- a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStep.java
+++ b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStep.java
@@ -43,7 +43,7 @@ public class ExecuteStatelessInitExtensionsStep implements ComputationStep {
   }
 
   @Override
-  public void execute() {
+  public void execute(Context context) {
     for (StatelessInitExtension extension : extensions) {
       extension.onInit();
     }
diff --git a/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java
index e8ae8735f05..8e7acad22f5 100644
--- a/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java
+++ b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java
@@ -31,6 +31,7 @@ import org.sonar.ce.task.ChangeLogLevel;
 
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.fail;
+import static org.mockito.ArgumentMatchers.any;
 import static org.mockito.ArgumentMatchers.anyBoolean;
 import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.inOrder;
@@ -56,11 +57,11 @@ public class ComputationStepExecutorTest {
       .execute();
 
     InOrder inOrder = inOrder(computationStep1, computationStep2, computationStep3);
-    inOrder.verify(computationStep1).execute();
+    inOrder.verify(computationStep1).execute(any());
     inOrder.verify(computationStep1).getDescription();
-    inOrder.verify(computationStep2).execute();
+    inOrder.verify(computationStep2).execute(any());
     inOrder.verify(computationStep2).getDescription();
-    inOrder.verify(computationStep3).execute();
+    inOrder.verify(computationStep3).execute(any());
     inOrder.verify(computationStep3).getDescription();
     inOrder.verifyNoMoreInteractions();
   }
@@ -72,7 +73,7 @@ public class ComputationStepExecutorTest {
     ComputationStep computationStep = mockComputationStep("step1");
     doThrow(new RuntimeException(message))
       .when(computationStep)
-      .execute();
+      .execute(any());
 
     ComputationStepExecutor computationStepExecutor = new ComputationStepExecutor(mockComputationSteps(computationStep));
 
@@ -83,17 +84,70 @@ public class ComputationStepExecutorTest {
   }
 
   @Test
-  public void execute_logs_end_timing_for_each_ComputationStep_in_INFO_level() {
+  public void execute_logs_end_timing_and_statistics_for_each_ComputationStep_in_INFO_level() {
+    ComputationStep step1 = new StepWithStatistics("Step One", "foo", "100", "bar", "20");
+    ComputationStep step2 = new StepWithStatistics("Step Two", "foo", "50", "baz", "10");
+    ComputationStep step3 = new StepWithStatistics("Step Three");
+
     try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, LoggerLevel.INFO);
-      ChangeLogLevel step1 = new ChangeLogLevel(computationStep1.getClass(), LoggerLevel.INFO);
-      ChangeLogLevel step2 = new ChangeLogLevel(computationStep2.getClass(), LoggerLevel.INFO)) {
-      new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2))
-        .execute();
+      ChangeLogLevel logLevel1 = new ChangeLogLevel(step1.getClass(), LoggerLevel.INFO);
+      ChangeLogLevel logLevel2 = new ChangeLogLevel(step1.getClass(), LoggerLevel.INFO);
+      ChangeLogLevel logLevel3 = new ChangeLogLevel(step2.getClass(), LoggerLevel.INFO)) {
+      new ComputationStepExecutor(mockComputationSteps(step1, step2, step3)).execute();
 
       List<String> infoLogs = logTester.logs(LoggerLevel.INFO);
-      assertThat(infoLogs).hasSize(2);
-      assertThat(infoLogs.get(0)).contains("step1 | time=");
-      assertThat(infoLogs.get(1)).contains("step2 | time=");
+      assertThat(infoLogs).hasSize(3);
+      assertThat(infoLogs.get(0)).contains("Step One | foo=100 | bar=20 | time=");
+      assertThat(infoLogs.get(1)).contains("Step Two | foo=50 | baz=10 | time=");
+      assertThat(infoLogs.get(2)).contains("Step Three | time=");
+    }
+  }
+
+  @Test
+  public void execute_throws_IAE_if_step_adds_time_statistic() {
+    ComputationStep step = new StepWithStatistics("A Step", "foo", "100", "time", "20");
+
+    try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, LoggerLevel.INFO)) {
+      expectedException.expect(IllegalArgumentException.class);
+      expectedException.expectMessage("Statistic with key [time] is not accepted");
+
+      new ComputationStepExecutor(mockComputationSteps(step)).execute();
+    }
+  }
+
+  @Test
+  public void execute_throws_IAE_if_step_adds_statistic_multiple_times() {
+    ComputationStep step = new StepWithStatistics("A Step", "foo", "100", "foo", "20");
+
+    try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, LoggerLevel.INFO)) {
+      expectedException.expect(IllegalArgumentException.class);
+      expectedException.expectMessage("Statistic with key [foo] is already present");
+
+      new ComputationStepExecutor(mockComputationSteps(step)).execute();
+    }
+  }
+
+  @Test
+  public void execute_throws_NPE_if_step_adds_statistic_with_null_key() {
+    ComputationStep step = new StepWithStatistics("A Step", "foo", "100", null, "bar");
+
+    try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, LoggerLevel.INFO)) {
+      expectedException.expect(NullPointerException.class);
+      expectedException.expectMessage("Statistic has null key");
+
+      new ComputationStepExecutor(mockComputationSteps(step)).execute();
+    }
+  }
+
+  @Test
+  public void execute_throws_NPE_if_step_adds_statistic_with_null_value() {
+    ComputationStep step = new StepWithStatistics("A Step", "foo", "100", "bar", null);
+
+    try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, LoggerLevel.INFO)) {
+      expectedException.expect(NullPointerException.class);
+      expectedException.expectMessage("Statistic with key [bar] has null value");
+
+      new ComputationStepExecutor(mockComputationSteps(step)).execute();
     }
   }
 
@@ -111,7 +165,7 @@ public class ComputationStepExecutorTest {
     RuntimeException toBeThrown = new RuntimeException("simulating failing execute Step method");
     doThrow(toBeThrown)
       .when(computationStep1)
-      .execute();
+      .execute(any());
 
     try {
       new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2), listener)
@@ -145,4 +199,26 @@ public class ComputationStepExecutorTest {
     when(mock.getDescription()).thenReturn(desc);
     return mock;
   }
+
+  private static class StepWithStatistics implements ComputationStep {
+    private final String description;
+    private final String[] statistics;
+
+    private StepWithStatistics(String description, String... statistics) {
+      this.description = description;
+      this.statistics = statistics;
+    }
+
+    @Override
+    public void execute(Context context) {
+      for (int i = 0; i < statistics.length; i += 2) {
+        context.getStatistics().add(statistics[i], statistics[i + 1]);
+      }
+    }
+
+    @Override
+    public String getDescription() {
+      return description;
+    }
+  }
 }
diff --git a/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStepTest.java b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStepTest.java
index 15d0664f2ba..030b4d6fed3 100644
--- a/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStepTest.java
+++ b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ExecuteStatelessInitExtensionsStepTest.java
@@ -49,7 +49,7 @@ public class ExecuteStatelessInitExtensionsStepTest {
     ExecuteStatelessInitExtensionsStep underTest = new ExecuteStatelessInitExtensionsStep();
 
     // no failure
-    underTest.execute();
+    underTest.execute(new TestComputationStepContext());
   }
 
   @Test
@@ -59,7 +59,7 @@ public class ExecuteStatelessInitExtensionsStepTest {
 
     ExecuteStatelessInitExtensionsStep underTest = new ExecuteStatelessInitExtensionsStep(
       new StatelessInitExtension[] {ext1, ext2});
-    underTest.execute();
+    underTest.execute(new TestComputationStepContext());
 
     InOrder inOrder = inOrder(ext1, ext2);
     inOrder.verify(ext1).onInit();
@@ -77,7 +77,7 @@ public class ExecuteStatelessInitExtensionsStepTest {
       new StatelessInitExtension[] {ext1, ext2, ext3});
 
     try {
-      underTest.execute();
+      underTest.execute(new TestComputationStepContext());
       fail();
     } catch (IllegalStateException e) {
       assertThat(e).hasMessage("BOOM");
diff --git a/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/TestComputationStepContext.java b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/TestComputationStepContext.java
new file mode 100644
index 00000000000..dc560ed8aaa
--- /dev/null
+++ b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/TestComputationStepContext.java
@@ -0,0 +1,71 @@
+/*
+ * SonarQube
+ * Copyright (C) 2009-2018 SonarSource SA
+ * mailto:info AT sonarsource DOT com
+ *
+ * This program 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.
+ *
+ * This program 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 this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+ */
+package org.sonar.ce.task.step;
+
+import java.util.HashMap;
+import java.util.Map;
+import javax.annotation.Nullable;
+
+import static com.google.common.base.Preconditions.checkArgument;
+import static java.util.Objects.requireNonNull;
+import static org.assertj.core.api.Assertions.assertThat;
+
+/**
+ * Implementation of {@link ComputationStep.Context} for unit tests.
+ */
+public class TestComputationStepContext implements ComputationStep.Context {
+
+  private final ComputationStep.Statistics statistics = new TestStatistics();
+
+  @Override
+  public ComputationStep.Statistics getStatistics() {
+    return statistics;
+  }
+
+  public static class TestStatistics implements ComputationStep.Statistics {
+    private final Map<String, Object> map = new HashMap<>();
+
+    @Override
+    public void add(String key, Object value) {
+      requireNonNull(key, "Statistic has null key");
+      requireNonNull(value, () -> String.format("Statistic with key [%s] has null value", key));
+      checkArgument(!key.equalsIgnoreCase("time"), "Statistic with key [time] is not accepted");
+      checkArgument(!map.containsKey(key), "Statistic with key [%s] is already present", key);
+      map.put(key, value);
+    }
+
+    public Map<String, Object> getAll() {
+      return map;
+    }
+
+    public Object get(String key) {
+      return requireNonNull(map.get(key));
+    }
+
+    public TestStatistics assertValue(String key, @Nullable Object expectedValue) {
+      if (expectedValue == null) {
+        assertThat(map.get(key)).as(key).isNull();
+      } else {
+        assertThat(map.get(key)).as(key).isEqualTo(expectedValue);
+      }
+      return this;
+    }
+  }
+}