SONAR-7532 Profiler can now put context before or after time

5 files changed, 233 insertions, 31 deletions

diff --git a/sonar-core/src/main/java/org/sonar/core/util/logs/DefaultProfiler.java b/sonar-core/src/main/java/org/sonar/core/util/logs/DefaultProfiler.java
index fff901f8f9f..c758fcff160 100644
--- a/sonar-core/src/main/java/org/sonar/core/util/logs/DefaultProfiler.java
+++ b/sonar-core/src/main/java/org/sonar/core/util/logs/DefaultProfiler.java
@@ -31,6 +31,7 @@ import org.sonar.api.utils.log.LoggerLevel;
 class DefaultProfiler extends Profiler {
 
   private static final String CONTEXT_SEPARATOR = " | ";
+  private static final String NO_MESSAGE_SUFFIX = "";
 
   private final LinkedHashMap<String, Object> context = new LinkedHashMap<>();
   private final Logger logger;
@@ -38,6 +39,7 @@ class DefaultProfiler extends Profiler {
   private long startTime = 0L;
   private String startMessage = null;
   private Object[] args = null;
+  private boolean logTimeLast = false;
 
   public DefaultProfiler(Logger logger) {
     this.logger = logger;
@@ -107,37 +109,37 @@ class DefaultProfiler extends Profiler {
 
   @Override
   public long stopTrace(String message) {
-    return doStop(LoggerLevel.TRACE, message, null, "");
+    return doStop(LoggerLevel.TRACE, message, null, NO_MESSAGE_SUFFIX);
   }
 
   @Override
   public long stopTrace(String message, Object... args) {
-    return doStop(LoggerLevel.TRACE, message, args, "");
+    return doStop(LoggerLevel.TRACE, message, args, NO_MESSAGE_SUFFIX);
   }
 
   @Override
   public long stopDebug(String message) {
-    return doStop(LoggerLevel.DEBUG, message, null, "");
+    return doStop(LoggerLevel.DEBUG, message, null, NO_MESSAGE_SUFFIX);
   }
 
   @Override
   public long stopDebug(String message, Object... args) {
-    return doStop(LoggerLevel.DEBUG, message, args, "");
+    return doStop(LoggerLevel.DEBUG, message, args, NO_MESSAGE_SUFFIX);
   }
 
   @Override
   public long stopInfo(String message) {
-    return doStop(LoggerLevel.INFO, message, null, "");
+    return doStop(LoggerLevel.INFO, message, null, NO_MESSAGE_SUFFIX);
   }
 
   @Override
   public long stopInfo(String message, Object... args) {
-    return doStop(LoggerLevel.INFO, message, args, "");
+    return doStop(LoggerLevel.INFO, message, args, NO_MESSAGE_SUFFIX);
   }
 
   @Override
   public long stopError(String message, Object... args) {
-    return doStop(LoggerLevel.ERROR, message, args, "");
+    return doStop(LoggerLevel.ERROR, message, args, NO_MESSAGE_SUFFIX);
   }
 
   private Profiler doStart(LoggerLevel logLevel, String message, Object... args) {
@@ -185,16 +187,36 @@ class DefaultProfiler extends Profiler {
       if (!StringUtils.isEmpty(message)) {
         sb.append(message);
         sb.append(messageSuffix);
-        sb.append(CONTEXT_SEPARATOR);
       }
-      sb.append("time=").append(duration).append("ms");
-      appendContext(sb);
+      if (logTimeLast) {
+        appendContext(sb);
+        appendTime(sb, duration);
+      } else {
+        appendTime(sb, duration);
+        appendContext(sb);
+      }
       log(level, sb.toString(), args);
     }
     reset();
     return duration;
   }
 
+  private static void appendTime(StringBuilder sb, long duration) {
+    if (sb.length() > 0) {
+      sb.append(CONTEXT_SEPARATOR);
+    }
+    sb.append("time=").append(duration).append("ms");
+  }
+
+  private void appendContext(StringBuilder sb) {
+    for (Map.Entry<String, Object> entry : context.entrySet()) {
+      if (sb.length() > 0) {
+        sb.append(CONTEXT_SEPARATOR);
+      }
+      sb.append(entry.getKey()).append("=").append(Objects.toString(entry.getValue()));
+    }
+  }
+
   void log(LoggerLevel level, String msg, @Nullable Object[] args) {
     switch (level) {
       case TRACE:
@@ -267,15 +289,6 @@ class DefaultProfiler extends Profiler {
     return true;
   }
 
-  private void appendContext(StringBuilder sb) {
-    for (Map.Entry<String, Object> entry : context.entrySet()) {
-      if (sb.length() > 0) {
-        sb.append(CONTEXT_SEPARATOR);
-      }
-      sb.append(entry.getKey()).append("=").append(Objects.toString(entry.getValue()));
-    }
-  }
-
   @Override
   public Profiler addContext(String key, @Nullable Object value) {
     if (value == null) {
@@ -286,4 +299,9 @@ class DefaultProfiler extends Profiler {
     return this;
   }
 
+  @Override
+  public Profiler logTimeLast(boolean flag) {
+    this.logTimeLast = flag;
+    return this;
+  }
 }
diff --git a/sonar-core/src/main/java/org/sonar/core/util/logs/NullProfiler.java b/sonar-core/src/main/java/org/sonar/core/util/logs/NullProfiler.java
index 7f3490b530e..7068d25afe9 100644
--- a/sonar-core/src/main/java/org/sonar/core/util/logs/NullProfiler.java
+++ b/sonar-core/src/main/java/org/sonar/core/util/logs/NullProfiler.java
@@ -128,4 +128,9 @@ class NullProfiler extends Profiler {
     // nothing to do
     return this;
   }
+
+  @Override
+  public Profiler logTimeLast(boolean flag) {
+    return this;
+  }
 }
diff --git a/sonar-core/src/main/java/org/sonar/core/util/logs/Profiler.java b/sonar-core/src/main/java/org/sonar/core/util/logs/Profiler.java
index 6b39185b56e..859d1fa40f3 100644
--- a/sonar-core/src/main/java/org/sonar/core/util/logs/Profiler.java
+++ b/sonar-core/src/main/java/org/sonar/core/util/logs/Profiler.java
@@ -91,4 +91,10 @@ public abstract class Profiler {
    * Context information is removed if value is <code>null</code>.
    */
   public abstract Profiler addContext(String key, @Nullable Object value);
+
+  /**
+   * Defines whether time is added to stop messages before or after context (if any).
+   * <p>{@code flag} is {@code false} by default.</p>
+   */
+  public abstract Profiler logTimeLast(boolean flag);
 }
diff --git a/sonar-core/src/test/java/org/sonar/core/util/logs/DefaultProfilerTest.java b/sonar-core/src/test/java/org/sonar/core/util/logs/DefaultProfilerTest.java
index 2e230fefc43..796095bc39b 100644
--- a/sonar-core/src/test/java/org/sonar/core/util/logs/DefaultProfilerTest.java
+++ b/sonar-core/src/test/java/org/sonar/core/util/logs/DefaultProfilerTest.java
@@ -19,8 +19,13 @@
  */
 package org.sonar.core.util.logs;
 
+import com.tngtech.java.junit.dataprovider.DataProvider;
+import com.tngtech.java.junit.dataprovider.DataProviderRunner;
+import com.tngtech.java.junit.dataprovider.UseDataProvider;
+import java.util.List;
 import org.junit.Rule;
 import org.junit.Test;
+import org.junit.runner.RunWith;
 import org.sonar.api.utils.log.LogTester;
 import org.sonar.api.utils.log.LoggerLevel;
 import org.sonar.api.utils.log.Loggers;
@@ -28,6 +33,7 @@ import org.sonar.api.utils.log.Loggers;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.junit.Assert.fail;
 
+@RunWith(DataProviderRunner.class)
 public class DefaultProfilerTest {
 
   @Rule
@@ -35,6 +41,14 @@ public class DefaultProfilerTest {
 
   Profiler underTest = Profiler.create(Loggers.get("DefaultProfilerTest"));
 
+  @DataProvider
+  public static Object[][] logTimeLastValues() {
+    return new Object[][] {
+      {true},
+      {false}
+    };
+  }
+
   @Test
   public void test_levels() throws Exception {
     // info by default
@@ -51,7 +65,9 @@ public class DefaultProfilerTest {
   }
 
   @Test
-  public void stop_reuses_start_message() throws InterruptedException {
+  @UseDataProvider("logTimeLastValues")
+  public void stop_reuses_start_message(boolean logTimeLast) throws InterruptedException {
+    underTest.logTimeLast(logTimeLast);
     tester.setLevel(LoggerLevel.TRACE);
 
     // trace
@@ -85,7 +101,9 @@ public class DefaultProfilerTest {
   }
 
   @Test
-  public void different_start_and_stop_messages() {
+  @UseDataProvider("logTimeLastValues")
+  public void different_start_and_stop_messages(boolean logTimeLast) {
+    underTest.logTimeLast(logTimeLast);
     tester.setLevel(LoggerLevel.TRACE);
 
     // start TRACE and stop DEBUG
@@ -113,7 +131,9 @@ public class DefaultProfilerTest {
   }
 
   @Test
-  public void log_on_at_stop() {
+  @UseDataProvider("logTimeLastValues")
+  public void log_on_at_stop(boolean logTimeLast) {
+    underTest.logTimeLast(logTimeLast);
     tester.setLevel(LoggerLevel.TRACE);
 
     // trace
@@ -138,27 +158,178 @@ public class DefaultProfilerTest {
   }
 
   @Test
-  public void add_context() {
-    org.sonar.core.util.logs.Profiler profiler = Profiler.create(Loggers.get("DefaultProfilerTest"));
-    profiler.addContext("a_string", "bar");
-    profiler.addContext("null_value", null);
-    profiler.addContext("an_int", 42);
-    profiler.start();
+  public void start_writes_no_log_even_if_there_is_context() {
+    underTest.addContext("a_string", "bar");
+    underTest.addContext("null_value", null);
+    underTest.addContext("an_int", 42);
+    underTest.start();
+
     // do not write context as there's no message
     assertThat(tester.logs()).isEmpty();
+  }
+
+  @Test
+  public void startInfo_writes_log_with_context_appended_when_there_is_a_message() {
+    addSomeContext(underTest);
+    underTest.startInfo("Foo");
+
+    assertThat(tester.logs(LoggerLevel.INFO)).containsOnly("Foo | a_string=bar | an_int=42 | after_start=true");
+  }
+
+  @Test
+  public void startDebug_writes_log_with_context_appended_when_there_is_a_message() {
+    tester.setLevel(LoggerLevel.DEBUG);
+    addSomeContext(underTest);
+    underTest.startDebug("Foo");
+
+    assertThat(tester.logs(LoggerLevel.DEBUG)).containsOnly("Foo | a_string=bar | an_int=42 | after_start=true");
+  }
+
+  @Test
+  public void startTrace_writes_log_with_context_appended_when_there_is_a_message() {
+    tester.setLevel(LoggerLevel.TRACE);
+    addSomeContext(underTest);
+    underTest.startTrace("Foo");
+
+    assertThat(tester.logs(LoggerLevel.TRACE)).containsOnly("Foo | a_string=bar | an_int=42 | after_start=true");
+  }
+
+  @Test
+  public void stopError_adds_context_after_time_by_default() {
+    addSomeContext(underTest);
+    underTest.start().stopError("Rules registered");
+
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs(LoggerLevel.ERROR).get(0))
+      .startsWith("Rules registered | time=")
+      .endsWith("ms | a_string=bar | an_int=42 | after_start=true");
+  }
+
+  @Test
+  public void stopInfo_adds_context_after_time_by_default() {
+    addSomeContext(underTest);
+    underTest.start().stopInfo("Rules registered");
+
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs(LoggerLevel.INFO).get(0))
+      .startsWith("Rules registered | time=")
+      .endsWith("ms | a_string=bar | an_int=42 | after_start=true");
+  }
+
+  @Test
+  public void stopTrace_adds_context_after_time_by_default() {
+    tester.setLevel(LoggerLevel.TRACE);
+    addSomeContext(underTest);
+    underTest.start().stopTrace("Rules registered");
 
-    profiler.addContext("after_start", true);
-    profiler.stopInfo("Rules registered");
     assertThat(tester.logs()).hasSize(1);
-    assertThat(tester.logs().get(0))
+    assertThat(tester.logs(LoggerLevel.TRACE).get(0))
       .startsWith("Rules registered | time=")
       .endsWith("ms | a_string=bar | an_int=42 | after_start=true");
   }
 
   @Test
+  public void stopError_adds_context_before_time_if_logTimeLast_is_true() {
+    addSomeContext(underTest);
+    underTest.logTimeLast(true);
+    underTest.start().stopError("Rules registered");
+
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs(LoggerLevel.ERROR).get(0))
+      .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=")
+      .endsWith("ms");
+  }
+
+  @Test
+  public void stopInfo_adds_context_before_time_if_logTimeLast_is_true() {
+    addSomeContext(underTest);
+    underTest.logTimeLast(true);
+    underTest.start().stopInfo("Rules registered");
+
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs(LoggerLevel.INFO).get(0))
+      .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=")
+      .endsWith("ms");
+  }
+
+  @Test
+  public void stopTrace_adds_context_before_time_if_logTimeLast_is_true() {
+    tester.setLevel(LoggerLevel.TRACE);
+    addSomeContext(underTest);
+    underTest.logTimeLast(true);
+    underTest.start().stopTrace("Rules registered");
+
+    assertThat(tester.logs()).hasSize(1);
+    assertThat(tester.logs(LoggerLevel.TRACE).get(0))
+      .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=")
+      .endsWith("ms");
+  }
+
+  @Test
+  public void stopInfo_clears_context() {
+    addSomeContext(underTest);
+    underTest.logTimeLast(true);
+    underTest.start().stopInfo("Foo");
+    underTest.start().stopInfo("Bar");
+
+    assertThat(tester.logs()).hasSize(2);
+    List<String> logs = tester.logs(LoggerLevel.INFO);
+    assertThat(logs.get(0))
+        .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=")
+        .endsWith("ms");
+    assertThat(logs.get(1))
+        .startsWith("Bar | time=")
+        .endsWith("ms");
+  }
+
+  @Test
+  public void stopDebug_clears_context() {
+    tester.setLevel(LoggerLevel.DEBUG);
+    addSomeContext(underTest);
+    underTest.logTimeLast(true);
+    underTest.start().stopDebug("Foo");
+    underTest.start().stopDebug("Bar");
+
+    assertThat(tester.logs()).hasSize(2);
+    List<String> logs = tester.logs(LoggerLevel.DEBUG);
+    assertThat(logs.get(0))
+        .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=")
+        .endsWith("ms");
+    assertThat(logs.get(1))
+        .startsWith("Bar | time=")
+        .endsWith("ms");
+  }
+
+  @Test
+  public void stopTrace_clears_context() {
+    tester.setLevel(LoggerLevel.TRACE);
+    addSomeContext(underTest);
+    underTest.logTimeLast(true);
+    underTest.start().stopTrace("Foo");
+    underTest.start().stopTrace("Bar");
+
+    assertThat(tester.logs()).hasSize(2);
+    List<String> logs = tester.logs(LoggerLevel.TRACE);
+    assertThat(logs.get(0))
+        .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=")
+        .endsWith("ms");
+    assertThat(logs.get(1))
+        .startsWith("Bar | time=")
+        .endsWith("ms");
+  }
+
+  private static void addSomeContext(Profiler profiler) {
+    profiler.addContext("a_string", "bar");
+    profiler.addContext("null_value", null);
+    profiler.addContext("an_int", 42);
+    profiler.addContext("after_start", true);
+  }
+
+  @Test
   public void empty_message() {
     underTest.addContext("foo", "bar");
     underTest.startInfo("");
+
     assertThat(tester.logs()).containsOnly("foo=bar");
 
     underTest.addContext("after_start", true);
diff --git a/sonar-core/src/test/java/org/sonar/core/util/logs/NullProfilerTest.java b/sonar-core/src/test/java/org/sonar/core/util/logs/NullProfilerTest.java
index f2c1985bddd..6bcc79895ff 100644
--- a/sonar-core/src/test/java/org/sonar/core/util/logs/NullProfilerTest.java
+++ b/sonar-core/src/test/java/org/sonar/core/util/logs/NullProfilerTest.java
@@ -37,6 +37,8 @@ public class NullProfilerTest {
     assertThat(underTest.isDebugEnabled()).isFalse();
     assertThat(underTest.isTraceEnabled()).isFalse();
     assertThat(underTest.addContext("foo", "bar")).isSameAs(underTest);
+    assertThat(underTest.logTimeLast(true)).isSameAs(underTest);
+    assertThat(underTest.logTimeLast(false)).isSameAs(underTest);
   }
 
   @Test