Optimize tracingSpanToLineData and loggers (#303)

* Skip expensive `DelegatingLogger#inferCaller()`

* Optimize StringBuilder for Spans

* Early return for other loggers

src/main/java/com/wavefront/sdk/common/Utils.java

@@ -326,67 +326,56 @@ public static String tracingSpanToLineData(String name, long startMillis, long d
      *           1533531013 343500"
      */
 
-    if (source == null || source.isEmpty()) {
+    if (isNullOrEmpty(source)) {
       source = defaultSource;
     }
-    if (name == null || name.isEmpty()) {
+    if (isNullOrEmpty(name)) {
       throw new IllegalArgumentException("span name cannot be blank " +
           getContextInfo(name, source, tags));
     }
-    if (source == null || source.isEmpty()) {
+    if (isNullOrEmpty(source)) {
       throw new IllegalArgumentException("span source cannot be blank " +
           getContextInfo(name, source, tags));
     }
-    final StringBuilder sb = new StringBuilder();
-    sb.append(sanitizeValue(name));
-    sb.append(" source=");
-    sb.append(sanitizeValue(source));
-    sb.append(" traceId=");
-    sb.append(traceId);
-    sb.append(" spanId=");
-    sb.append(spanId);
+
+    int initialCapacity = estimateSpanSize(name, source, parents, followsFrom, tags, spanLogs);
+    final StringBuilder sb = new StringBuilder(initialCapacity);
+    sb.append(sanitizeValue(name))
+        .append(" source=").append(sanitizeValue(source))
+        .append(" traceId=").append(traceId)
+        .append(" spanId=").append(spanId);
     if (parents != null) {
       for (UUID parent : parents) {
-        sb.append(" parent=");
-        sb.append(parent.toString());
+        sb.append(" parent=").append(parent);
       }
     }
     if (followsFrom != null) {
       for (UUID item : followsFrom) {
-        sb.append(" followsFrom=");
-        sb.append(item.toString());
+        sb.append(" followsFrom=").append(item);
       }
     }
     if (tags != null) {
       for (final Pair<String, String> tag : tags) {
         String key = tag._1;
         String val = tag._2;
-        if (key == null || key.isEmpty()) {
+        if (isNullOrEmpty(key)) {
           throw new IllegalArgumentException("span tag key cannot be blank " +
               getContextInfo(name, source, tags));
         }
-        if (val == null || val.isEmpty()) {
+        if (isNullOrEmpty(val)) {
           throw new IllegalArgumentException("span tag value cannot be blank for " +
               "tag key: " + key + " " + getContextInfo(name, source, tags));
         }
-        sb.append(' ');
-        sb.append(sanitize(key));
-        sb.append('=');
-        sb.append(sanitizeValue(val));
+        sb.append(' ').append(sanitize(key)).append('=').append(sanitizeValue(val));
       }
     }
     if (spanLogs != null && !spanLogs.isEmpty()) {
-      sb.append(' ');
-      sb.append(sanitize(SPAN_LOG_KEY));
-      sb.append('=');
-      sb.append(sanitize("true"));
+      sb.append(" \"").append(SPAN_LOG_KEY).append("\"=\"true\"");
     }
-    sb.append(' ');
-    sb.append(startMillis);
-    sb.append(' ');
-    sb.append(durationMillis);
+    sb.append(' ').append(startMillis)
+        .append(' ').append(durationMillis)
+        .append('\n');
     // TODO - Support SpanLogs
-    sb.append('\n');
     return sb.toString();
   }
 
@@ -626,22 +615,61 @@ public static void shutdownExecutorAndWait(ExecutorService tpe) {
       Thread.currentThread().interrupt();
     }
   }
-
+
+  /**
+   * Make an educated guess about the amount of characters needed for a Span.
+   */
+  private static int estimateSpanSize(String name, String source, List<UUID> parents, List<UUID> followsFrom, List<Pair<String, String>> tags, List<SpanLog> spanLogs) {
+    final int SANITIZE_CHARS = 2;
+    final int GUID_CHARS = 36;
+
+    int size = 0;
+    size += name.length() + SANITIZE_CHARS;
+    size += " source=".length() + source.length() + SANITIZE_CHARS;
+    size += " traceId=".length() + GUID_CHARS;
+    size += " spanId=".length() + GUID_CHARS;
+    if (parents != null) {
+      size += parents.size() * (" parent=".length() + GUID_CHARS);
+    }
+    if (followsFrom != null) {
+      size += followsFrom.size() * (" followsFrom=".length() + GUID_CHARS);
+    }
+    if (tags != null) {
+      // A tag of <foo,bar> will result in ' "foo"="bar"'
+      // Random guess that the average tag KV is 16 chars, but add two more for the ' ' and `='.
+      size += tags.size() * (18 + SANITIZE_CHARS * 2);
+    }
+
+    if (spanLogs != null) {
+      // results in ' "_spanLogs"="true"'
+      size += (" \"" + SPAN_LOG_KEY + "\"=\"true\"").length();
+    }
+
+    size +=  1; // space
+    size += 13; // startMillis (from epoch), e.g. 1697039471941 = 13 chars
+    size +=  1; // space
+    size +=  6; // durationMillis shouldn't exceed 6 digits (999999 = 16 minutes)
+    size +=  1; // newline
+    size += 16; // extra buffer just in case
+    return size;
+  }
+
   private static String sanitizeInternal(String s, boolean addQuotes, boolean ignoreSlash) {
     /*
      * Sanitize string of metric name, source and key of tags according to the rule of Wavefront proxy.
      */
 
-    StringBuilder sb = new StringBuilder();
+    int capacity = s.length() + (addQuotes ? 2 : 0);
+    StringBuilder sb = new StringBuilder(capacity);
     if (addQuotes) {
       sb.append('"');
     }
+    boolean isTildaPrefixed = s.charAt(0) == 126;
+    boolean isDeltaPrefixed = (s.charAt(0) == 0x2206) || (s.charAt(0) == 0x0394);
+    boolean isDeltaTildaPrefixed = isDeltaPrefixed && s.charAt(1) == 126;
     for (int i = 0; i < s.length(); i++) {
       char cur = s.charAt(i);
       boolean isLegal = true;
-      boolean isTildaPrefixed = s.charAt(0) == 126;
-      boolean isDeltaPrefixed = (s.charAt(0) == 0x2206) || (s.charAt(0) == 0x0394);
-      boolean isDeltaTildaPrefixed = isDeltaPrefixed && s.charAt(1) == 126;
       if (!(44 <= cur && cur <= 57) && !(65 <= cur && cur <= 90) && !(97 <= cur && cur <= 122) &&
           cur != 95) {
         if (!(i == 0 && (isDeltaPrefixed || isTildaPrefixed) || (i == 1 && isDeltaTildaPrefixed))) {

src/main/java/com/wavefront/sdk/common/logging/DelegatingLogger.java

@@ -30,6 +30,9 @@ public DelegatingLogger(Logger delegate) {
   /** {@inheritDoc} */
   @Override
   public void log(LogRecord logRecord) {
+    if (!isLoggable(logRecord.getLevel())) {
+      return;
+    }
     logRecord.setLoggerName(delegate.getName());
     // Infer caller so that the log message contains the right '[source class] [source method]'
     // instead of 'DelegatingLogger log'

src/main/java/com/wavefront/sdk/common/logging/MessageDedupingLogger.java

@@ -45,6 +45,10 @@ public RateLimiter load(String s) {
   /** {@inheritDoc} */
   @Override
   public void log(Level level, String message) {
+    if (!isLoggable(level)) {
+      return;
+    }
+
     try {
       if (Objects.requireNonNull(rateLimiterCache.get(message)).tryAcquire()) {
         log(new LogRecord(level, message));
@@ -63,6 +67,10 @@ public void log(Level level, String message) {
    * @param message             String to write to log.
    */
   public void log(String messageDedupingKey, Level level, String message) {
+    if (!isLoggable(level)) {
+      return;
+    }
+
     try {
       if (Objects.requireNonNull(rateLimiterCache.get(messageDedupingKey)).tryAcquire()) {
         log(new LogRecord(level, message));
@@ -82,6 +90,10 @@ public void log(String messageDedupingKey, Level level, String message) {
    * @param thrown              Throwable associated with log message.
    */
   public void log(String messageDedupingKey, Level level, String message, Throwable thrown) {
+    if (!isLoggable(level)) {
+      return;
+    }
+
     LogRecord logRecord = new LogRecord(level, message);
     logRecord.setThrown(thrown);
     try {

src/main/java/com/wavefront/sdk/common/logging/MessageSuppressingLogger.java

@@ -39,6 +39,10 @@ public MessageSuppressingLogger(Logger delegate, long suppressTime, TimeUnit tim
    * @param message    Log message.
    */
   public void log(String messageKey, Level level, String message) {
+    if (!isLoggable(level)) {
+      return;
+    }
+
     cache.asMap().compute(messageKey,
         (key, prevTime) -> logMessageAndComputeTimestamp(message, level, prevTime));
   }
@@ -55,6 +59,10 @@ public void reset(String key) {
   /** {@inheritDoc} */
   @Override
   public void log(Level level, String message) {
+    if (!isLoggable(level)) {
+      return;
+    }
+
     cache.asMap().compute(message,
         (key, prevTime) -> logMessageAndComputeTimestamp(message, level, prevTime));
   }

src/test/java/com/wavefront/sdk/common/logging/DelegatingLoggerTest.java

@@ -0,0 +1,76 @@
+package com.wavefront.sdk.common.logging;
+
+import org.easymock.Capture;
+import org.easymock.CaptureType;
+import org.easymock.EasyMock;
+import org.junit.jupiter.api.Test;
+
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+import java.util.logging.Logger;
+
+import static org.easymock.EasyMock.capture;
+import static org.easymock.EasyMock.expect;
+import static org.easymock.EasyMock.expectLastCall;
+import static org.easymock.EasyMock.replay;
+import static org.easymock.EasyMock.reset;
+import static org.easymock.EasyMock.verify;
+import static org.junit.jupiter.api.Assertions.*;
+
+/**
+ * Tests for {@link DelegatingLogger}.
+ *
+ * @author Glenn Oppegard (goppegard@vmware.com).
+ */
+class DelegatingLoggerTest {
+
+  @Test
+  void skipsDelegatingBasedOnLevel() {
+    Logger mockLogger = EasyMock.createMock(Logger.class);
+    reset(mockLogger);
+    expect(mockLogger.getName()).andReturn("loggerName").anyTimes();
+    replay(mockLogger);
+    DelegatingLoggerImpl log = new DelegatingLoggerImpl(mockLogger);
+
+    reset(mockLogger);
+    expect(mockLogger.getName()).andReturn("loggerName").anyTimes();
+    Capture<LogRecord> logs = Capture.newInstance(CaptureType.ALL);
+    mockLogger.log(capture(logs));
+    expectLastCall().times(5);
+    replay(mockLogger);
+
+    log.setLevel(Level.FINE);
+    log.severe("severe");
+    log.warning("warning");
+    log.info("info");
+    log.config("config");
+    log.fine("fine");
+
+    log.finer("not delegated");
+    log.finest("not delegated");
+
+    verify(mockLogger);
+    assertEquals(5, logs.getValues().size());
+    assertEquals("severe", logs.getValues().get(0).getMessage());
+    assertEquals(Level.SEVERE, logs.getValues().get(0).getLevel());
+    assertEquals("warning", logs.getValues().get(1).getMessage());
+    assertEquals(Level.WARNING, logs.getValues().get(1).getLevel());
+    assertEquals("info", logs.getValues().get(2).getMessage());
+    assertEquals(Level.INFO, logs.getValues().get(2).getLevel());
+    assertEquals("config", logs.getValues().get(3).getMessage());
+    assertEquals(Level.CONFIG, logs.getValues().get(3).getLevel());
+    assertEquals("fine", logs.getValues().get(4).getMessage());
+    assertEquals(Level.FINE, logs.getValues().get(4).getLevel());
+  }
+
+  class DelegatingLoggerImpl extends DelegatingLogger {
+    public DelegatingLoggerImpl(Logger delegate) {
+      super(delegate);
+    }
+
+    @Override
+    public void log(Level level, String message) {
+      log(new LogRecord(level, message));
+    }
+  }
+}

src/test/java/com/wavefront/sdk/common/logging/MessageDedupingLoggerTest.java

@@ -39,6 +39,7 @@ public void testLogger() {
     expectLastCall().times(5);
     replay(mockLogger);
 
+    log.setLevel(Level.ALL);
     log.severe("msg1");
     log.severe("msg1");
     log.warning("msg1");