add support for message arguments to Profiler

also removed as much string building as possible internally

4 files changed, 167 insertions, 55 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 83bbde6e92d..562f20a36f2 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
@@ -37,6 +37,7 @@ class DefaultProfiler extends Profiler {
 
   private long startTime = 0L;
   private String startMessage = null;
+  private Object[] args = null;
 
   public DefaultProfiler(Logger logger) {
     this.logger = logger;
@@ -61,37 +62,33 @@ class DefaultProfiler extends Profiler {
 
   @Override
   public Profiler startTrace(String message) {
-    this.startTime = System2.INSTANCE.now();
-    this.startMessage = message;
-    StringBuilder sb = new StringBuilder();
-    sb.append(message);
-    appendContext(sb);
-    logger.trace(sb.toString());
-    return this;
+    return doStart(LoggerLevel.TRACE, message);
+  }
+
+  @Override
+  public Profiler startTrace(String message, Object... args) {
+    return doStart(LoggerLevel.TRACE, message, args);
   }
 
   @Override
   public Profiler startDebug(String message) {
-    this.startTime = System2.INSTANCE.now();
-    this.startMessage = message;
-    StringBuilder sb = new StringBuilder();
-    sb.append(message);
-    appendContext(sb);
-    logger.debug(sb.toString());
-    return this;
+    return doStart(LoggerLevel.DEBUG, message);
+  }
+
+  @Override
+  public Profiler startDebug(String message, Object... args) {
+    return doStart(LoggerLevel.DEBUG, message, args);
   }
 
   @Override
   public Profiler startInfo(String message) {
-    this.startTime = System2.INSTANCE.now();
-    this.startMessage = message;
-    StringBuilder sb = new StringBuilder();
-    sb.append(message);
-    appendContext(sb);
-    logger.info(sb.toString());
-    return this;
+    return doStart(LoggerLevel.INFO, message);
   }
 
+  @Override
+  public Profiler startInfo(String message, Object... args) {
+    return doStart(LoggerLevel.INFO, message, args);
+  }
 
   @Override
   public long stopTrace() {
@@ -108,70 +105,143 @@ class DefaultProfiler extends Profiler {
     return doStopWithoutMessage(LoggerLevel.INFO);
   }
 
-  private long doStopWithoutMessage(LoggerLevel level) {
-    if (startMessage == null) {
-      throw new IllegalStateException("Profiler#stopXXX() can't be called without any message defined in start methods");
-    }
-    return doStop(level, startMessage, " (done)");
+  @Override
+  public long stopTrace(String message) {
+    return doStop(LoggerLevel.TRACE, message, null, "");
   }
 
   @Override
-  public long stopTrace(String message) {
-    return doStop(LoggerLevel.TRACE, message, "");
+  public long stopTrace(String message, Object... args) {
+    return doStop(LoggerLevel.TRACE, message, args, "");
   }
 
   @Override
   public long stopDebug(String message) {
-    return doStop(LoggerLevel.DEBUG, message, "");
+    return doStop(LoggerLevel.DEBUG, message, null, "");
+  }
+
+  @Override
+  public long stopDebug(String message, Object... args) {
+    return doStop(LoggerLevel.DEBUG, message, args, "");
   }
 
   @Override
   public long stopInfo(String message) {
-    return doStop(LoggerLevel.INFO, message, "");
+    return doStop(LoggerLevel.INFO, message, null, "");
   }
 
-  private long doStop(LoggerLevel level, @Nullable String message, String messageSuffix) {
+  @Override
+  public long stopInfo(String message, Object... args) {
+    return doStop(LoggerLevel.INFO, message, args, "");
+  }
+
+  private Profiler doStart(LoggerLevel logLevel, String message, Object... args) {
+    init(message, args);
+    logStartMessage(logLevel, message, args);
+    return this;
+  }
+
+  private void init(String message, Object... args) {
+    this.startTime = System2.INSTANCE.now();
+    this.startMessage = message;
+    this.args = args;
+  }
+
+  private void reset() {
+    this.startTime = 0L;
+    this.startMessage = null;
+    this.args = null;
+    this.context.clear();
+  }
+
+  private void logStartMessage(LoggerLevel loggerLevel, String message, Object... args) {
+    if (shouldLog(logger, loggerLevel)) {
+      StringBuilder sb = new StringBuilder();
+      sb.append(message);
+      appendContext(sb);
+      logger.trace(sb.toString(), args);
+    }
+  }
+
+  private long doStopWithoutMessage(LoggerLevel level) {
+    if (startMessage == null) {
+      throw new IllegalStateException("Profiler#stopXXX() can't be called without any message defined in start methods");
+    }
+    return doStop(level, startMessage, this.args, " (done)");
+  }
+
+  private long doStop(LoggerLevel level, @Nullable String message, @Nullable Object[] args, String messageSuffix) {
     if (startTime == 0L) {
       throw new IllegalStateException("Profiler must be started before being stopped");
     }
     long duration = System2.INSTANCE.now() - startTime;
-    StringBuilder sb = new StringBuilder();
-    if (!StringUtils.isEmpty(message)) {
-      sb.append(message);
-      sb.append(messageSuffix);
-      sb.append(CONTEXT_SEPARATOR);
+    if (shouldLog(logger, level)) {
+      StringBuilder sb = new StringBuilder();
+      if (!StringUtils.isEmpty(message)) {
+        sb.append(message);
+        sb.append(messageSuffix);
+        sb.append(CONTEXT_SEPARATOR);
+      }
+      sb.append("time=").append(duration).append("ms");
+      appendContext(sb);
+      log(level, sb.toString(), args);
     }
-    sb.append("time=").append(duration).append("ms");
-    appendContext(sb);
-    log(level, sb.toString());
-    startTime = 0L;
-    startMessage = null;
-    context.clear();
+    reset();
     return duration;
   }
 
-  void log(LoggerLevel level, String msg) {
+  void log(LoggerLevel level, String msg, @Nullable Object[] args) {
     switch (level) {
       case TRACE:
-        logger.trace(msg);
+        if (args == null) {
+          logger.trace(msg);
+        } else {
+          logger.trace(msg, args);
+        }
         break;
       case DEBUG:
-        logger.debug(msg);
+        if (args == null) {
+          logger.debug(msg);
+        } else {
+          logger.debug(msg, args);
+        }
         break;
       case INFO:
-        logger.info(msg);
+        if (args == null) {
+          logger.info(msg);
+        } else {
+          logger.info(msg, args);
+        }
         break;
       case WARN:
-        logger.warn(msg);
+        if (args == null) {
+          logger.warn(msg);
+        } else {
+          logger.warn(msg, args);
+        }
         break;
       case ERROR:
-        logger.error(msg);
+        if (args == null) {
+          logger.error(msg);
+        } else {
+          logger.error(msg, args);
+        }
         break;
       default:
         throw new IllegalArgumentException("Unsupported LoggerLevel value: " + level);
     }
   }
 
+  private static boolean shouldLog(Logger logger, LoggerLevel level) {
+    if (level == LoggerLevel.TRACE && !logger.isTraceEnabled()) {
+      return false;
+    }
+    if (level == LoggerLevel.DEBUG && !logger.isDebugEnabled()) {
+      return false;
+    }
+    return true;
+  }
+
   private void appendContext(StringBuilder sb) {
     for (Map.Entry<String, Object> entry : context.entrySet()) {
       if (sb.length() > 0) {
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 665f71d9c9b..eec8190f4db 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
@@ -49,16 +49,31 @@ class NullProfiler extends Profiler {
   }
 
   @Override
+  public Profiler startTrace(String message, Object... args) {
+    return this;
+  }
+
+  @Override
   public Profiler startDebug(String message) {
     return this;
   }
 
   @Override
+  public Profiler startDebug(String message, Object... args) {
+    return this;
+  }
+
+  @Override
   public Profiler startInfo(String message) {
     return this;
   }
 
   @Override
+  public Profiler startInfo(String message, Object... args) {
+    return this;
+  }
+
+  @Override
   public long stopTrace() {
     return 0;
   }
@@ -79,16 +94,31 @@ class NullProfiler extends Profiler {
   }
 
   @Override
+  public long stopTrace(String message, Object... args) {
+    return 0;
+  }
+
+  @Override
   public long stopDebug(String message) {
     return 0;
   }
 
   @Override
+  public long stopDebug(String message, Object... args) {
+    return 0;
+  }
+
+  @Override
   public long stopInfo(String message) {
     return 0;
   }
 
   @Override
+  public long stopInfo(String message, Object... args) {
+    return 0;
+  }
+
+  @Override
   public Profiler addContext(String key, @Nullable Object value) {
     // nothing to do
     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 eaf79605f5a..ee1487e54dd 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
@@ -54,10 +54,16 @@ public abstract class Profiler {
 
   public abstract Profiler startTrace(String message);
 
+  public abstract Profiler startTrace(String message, Object... args);
+
   public abstract Profiler startDebug(String message);
 
+  public abstract Profiler startDebug(String message, Object... args);
+
   public abstract Profiler startInfo(String message);
 
+  public abstract Profiler startInfo(String message, Object... args);
+
   /**
    * Works only if a message have been set in startXXX() methods.
    */
@@ -69,10 +75,16 @@ public abstract class Profiler {
 
   public abstract long stopTrace(String message);
 
+  public abstract long stopTrace(String message, Object... args);
+
   public abstract long stopDebug(String message);
 
+  public abstract long stopDebug(String message, Object... args);
+
   public abstract long stopInfo(String message);
 
+  public abstract long stopInfo(String message, Object... args);
+
   /**
    * Context information is removed if value is <code>null</code>.
    */
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 7a71b45a9b4..e4f316a004c 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
@@ -55,13 +55,13 @@ public class DefaultProfilerTest {
     tester.setLevel(LoggerLevel.TRACE);
 
     // trace
-    underTest.startTrace("Register rules");
+    underTest.startTrace("Register rules {}", 1);
     Thread.sleep(2);
-    assertThat(tester.logs()).containsOnly("Register rules");
+    assertThat(tester.logs()).containsOnly("Register rules 1");
     long timing = underTest.stopTrace();
     assertThat(timing).isGreaterThan(0);
     assertThat(tester.logs()).hasSize(2);
-    assertThat(tester.logs().get(1)).startsWith("Register rules (done) | time=" + timing);
+    assertThat(tester.logs().get(1)).startsWith("Register rules 1 (done) | time=" + timing);
     tester.clear();
 
     // debug
@@ -97,10 +97,10 @@ public class DefaultProfilerTest {
     tester.clear();
 
     // start DEBUG and stop INFO
-    underTest.startDebug("Register rules");
+    underTest.startDebug("Register rules {}", 10);
     underTest.stopInfo("Rules registered");
     assertThat(tester.logs()).hasSize(2);
-    assertThat(tester.logs().get(0)).contains("Register rules");
+    assertThat(tester.logs().get(0)).contains("Register rules 10");
     assertThat(tester.logs().get(1)).startsWith("Rules registered | time=");
     tester.clear();
 
@@ -125,9 +125,9 @@ public class DefaultProfilerTest {
 
     // debug
     underTest.start();
-    underTest.stopDebug("Rules registered");
+    underTest.stopDebug("Rules registered {} on {}", 6, 10);
     assertThat(tester.logs()).hasSize(1);
-    assertThat(tester.logs().get(0)).startsWith("Rules registered | time=");
+    assertThat(tester.logs().get(0)).startsWith("Rules registered 6 on 10 | time=");
     tester.clear();
 
     // info