Internal - Lazy debug/trace logging to cut string-building overhead on disabled log levels

benchmarks/README.md

@@ -0,0 +1,34 @@
+# Benchmarks
+
+JMH microbenchmarks for the solarwinds-apm-java project, using the
+[`me.champeau.jmh`](https://github.com/melix/jmh-gradle-plugin) Gradle plugin.
+
+## Running
+
+Run all benchmarks:
+
+```shell
+./gradlew :benchmarks:jmh
+```
+
+Run a specific benchmark by class name (regex matched against the fully
+qualified benchmark name):
+
+```shell
+./gradlew :benchmarks:jmh -Pjmh.include=LoggerLazyLoggingBenchmark
+```
+
+Results are written in CSV format to `benchmarks/build/results/jmh/results.csv`.
+
+## Adding a benchmark
+
+Benchmark sources live under `src/jmh/java`. Add the module under test as a
+`jmh` dependency in `build.gradle.kts`, then write a class annotated with
+JMH's `@Benchmark` and related annotations (see
+`LoggerLazyLoggingBenchmark` for an example).
+
+## Existing benchmarks
+
+- `LoggerLazyLoggingBenchmark` — compares eager (`debug(String)`) vs. lazy
+  (`debug(Supplier<String>)`) logging calls, at both a disabled (`INFO`) and
+  enabled (`DEBUG`) log level.

benchmarks/build.gradle.kts

@@ -0,0 +1,28 @@
+/*
+ * © SolarWinds Worldwide, LLC. All rights reserved.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+plugins {
+  id("solarwinds.java-conventions")
+  id("me.champeau.jmh") version "0.7.2"
+}
+
+dependencies {
+  jmh(project(":libs:logging"))
+}
+
+jmh {
+  resultFormat.set("CSV")
+}

benchmarks/src/jmh/java/com/solarwinds/benchmarks/LoggerLazyLoggingBenchmark.java

@@ -0,0 +1,144 @@
+/*
+ * © SolarWinds Worldwide, LLC. All rights reserved.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.solarwinds.benchmarks;
+
+import com.solarwinds.joboe.logging.LogSetting;
+import com.solarwinds.joboe.logging.Logger;
+import com.solarwinds.joboe.logging.LoggerConfiguration;
+import com.solarwinds.joboe.logging.LoggerFactory;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.BenchmarkMode;
+import org.openjdk.jmh.annotations.Fork;
+import org.openjdk.jmh.annotations.Level;
+import org.openjdk.jmh.annotations.Measurement;
+import org.openjdk.jmh.annotations.Mode;
+import org.openjdk.jmh.annotations.OutputTimeUnit;
+import org.openjdk.jmh.annotations.Param;
+import org.openjdk.jmh.annotations.Scope;
+import org.openjdk.jmh.annotations.Setup;
+import org.openjdk.jmh.annotations.State;
+import org.openjdk.jmh.annotations.Warmup;
+
+/**
+ * Compares eager {@code debug(String)} against lazy {@code debug(Supplier<String>)} logging.
+ *
+ * <p>Four scenarios are driven by the {@link #loggerLevel} parameter:
+ *
+ * <ul>
+ *   <li><b>INFO</b> — the {@code DEBUG} level is <em>disabled</em>. This is where lazy logging pays
+ *       off: the eager call still builds the message via {@code String.format} and throws it away,
+ *       while the lazy call skips construction entirely (the supplier's {@code get()} is never
+ *       invoked).
+ *   <li><b>DEBUG</b> — the {@code DEBUG} level is <em>enabled</em>. Here the message is built in
+ *       both cases, so this measures the overhead lazy logging <em>adds</em> (the capturing-lambda
+ *       allocation) when the work cannot be skipped. This is the cost that justified removing the
+ *       unused supplier overloads on always-enabled levels (info/warn/error/fatal).
+ * </ul>
+ *
+ * <p>Both stdout and stderr streams are disabled on the logger so that the benchmark measures
+ * message construction and dispatch (the {@code shouldLog} guard, lambda allocation, formatting)
+ * rather than console I/O throughput.
+ *
+ * <p>Run with:
+ *
+ * <pre>{@code
+ * ./gradlew :benchmarks:jmh -Pjmh.include=LoggerLazyLoggingBenchmark
+ * }</pre>
+ */
+@Fork(2)
+@State(Scope.Benchmark)
+@BenchmarkMode(Mode.AverageTime)
+@Warmup(iterations = 5, time = 1)
+@OutputTimeUnit(TimeUnit.NANOSECONDS)
+@Measurement(iterations = 100, time = 1)
+public class LoggerLazyLoggingBenchmark {
+
+  /** "INFO" leaves DEBUG disabled (the win); "DEBUG" enables it (the cost). */
+  @Param({"INFO", "DEBUG"})
+  public String loggerLevel;
+
+  private Logger logger;
+
+  private int statusCode;
+
+  private long durationNanos;
+
+  private String payload;
+
+  @Setup(Level.Trial)
+  public void setUp() {
+    Logger.Level level = Logger.Level.fromLabel(loggerLevel.toLowerCase(Locale.ROOT));
+    // stdoutEnabled=false, stderrEnabled=false => the logger's output stream is a no-op, so we do
+    // not measure console I/O even in the DEBUG (enabled) scenario.
+    LogSetting logSetting = new LogSetting(level, false, false, null, null, null);
+    LoggerFactory.init(LoggerConfiguration.builder().logSetting(logSetting).build());
+    logger = LoggerFactory.getLogger();
+
+    statusCode = 200;
+    durationNanos = 1_234_567_890L;
+    payload = "instance-identity-document";
+  }
+
+  /** Eager, {@code String.format}: format runs unconditionally, before {@code debug} checks. */
+  @Benchmark
+  public void eagerFormat() {
+    logger.debug(
+        String.format(
+            "Retrieved metadata: status=%d durationNanos=%d payload=%s",
+            statusCode, durationNanos, payload));
+  }
+
+  /** Lazy, {@code String.format}: the supplier is only evaluated when DEBUG is enabled. */
+  @Benchmark
+  public void lazyFormat() {
+    logger.debug(
+        () ->
+            String.format(
+                "Retrieved metadata: status=%d durationNanos=%d payload=%s",
+                statusCode, durationNanos, payload));
+  }
+
+  /**
+   * Eager, string concatenation: the {@code +} expression runs unconditionally, before {@code
+   * debug} checks the level.
+   */
+  @Benchmark
+  public void eagerConcat() {
+    logger.debug(
+        "Retrieved metadata: status="
+            + statusCode
+            + " durationNanos="
+            + durationNanos
+            + " payload="
+            + payload);
+  }
+
+  /** Lazy, string concatenation: the supplier is only evaluated when DEBUG is enabled. */
+  @Benchmark
+  public void lazyConcat() {
+    logger.debug(
+        () ->
+            "Retrieved metadata: status="
+                + statusCode
+                + " durationNanos="
+                + durationNanos
+                + " payload="
+                + payload);
+  }
+}

bootstrap/src/main/java/com/solarwinds/opentelemetry/core/Util.java

@@ -139,7 +139,7 @@ public static String parsePath(String url) {
       try {
         return new URL(url).getPath();
       } catch (MalformedURLException e) {
-        logger.debug("Cannot parse URL " + url);
+        logger.debug(() -> "Cannot parse URL " + url);
       }
     }
     return null;

custom/src/main/java/com/solarwinds/opentelemetry/extensions/SolarwindsAgentListener.java

@@ -84,10 +84,11 @@ private void executeStartupTasks() {
                         : Collections.<String>emptyList();
 
                 logger.debug(
-                    "Detected host id: "
-                        + HostInfoUtils.getHostId()
-                        + " ip addresses: "
-                        + ipAddresses);
+                    () ->
+                        "Detected host id: "
+                            + HostInfoUtils.getHostId()
+                            + " ip addresses: "
+                            + ipAddresses);
 
                 CountDownLatch settingsLatch =
                     SettingsManager.initialize(
@@ -101,7 +102,7 @@ private void executeStartupTasks() {
                 if (JavaRuntimeVersionChecker.isJdkVersionSupported()
                     && profilerSetting != null
                     && profilerSetting.isEnabled()) {
-                  logger.debug("Profiler is enabled, local settings : " + profilerSetting);
+                  logger.debug(() -> "Profiler is enabled, local settings : " + profilerSetting);
                   Profiler.initialize(
                       profilerSetting,
                       ReporterFactory.getInstance()

custom/src/main/java/com/solarwinds/opentelemetry/extensions/SolarwindsProfilingSpanProcessor.java

@@ -95,15 +95,17 @@ public void onEnding(ReadWriteSpan readWriteSpan) {
           if (profile.isSampled()) {
             readWriteSpan.setAttribute(SW_KEY_PREFIX + "profile.spans", 1);
             logger.debug(
-                String.format(
-                    "Profiling stopped with sw.profile.spans=1, trace_id=%s span_id=%s",
-                    spanContext.getTraceId(), spanContext.getSpanId()));
+                () ->
+                    String.format(
+                        "Profiling stopped with sw.profile.spans=1, trace_id=%s span_id=%s",
+                        spanContext.getTraceId(), spanContext.getSpanId()));
           } else {
             readWriteSpan.setAttribute(SW_KEY_PREFIX + "profile.spans", 0);
             logger.debug(
-                String.format(
-                    "Profiling stopped with sw.profile.spans=0, trace_id=%s span_id=%s",
-                    spanContext.getTraceId(), spanContext.getSpanId()));
+                () ->
+                    String.format(
+                        "Profiling stopped with sw.profile.spans=0, trace_id=%s span_id=%s",
+                        spanContext.getTraceId(), spanContext.getSpanId()));
           }
         }
       }

custom/src/main/java/com/solarwinds/opentelemetry/extensions/config/ConfigurationLoader.java

@@ -426,7 +426,8 @@ public static void processConfigs(ConfigContainer configs) throws InvalidConfigE
                 + ServiceKeyUtils.maskServiceKey(serviceKey));
         configs.put(ConfigProperty.AGENT_SERVICE_KEY, serviceKey, true);
       }
-      logger.debug("Service key (masked) is [" + ServiceKeyUtils.maskServiceKey(serviceKey) + "]");
+      logger.debug(
+          () -> "Service key (masked) is [" + ServiceKeyUtils.maskServiceKey(serviceKey) + "]");
 
     } else {
       if (!configs.containsProperty(ConfigProperty.AGENT_SERVICE_KEY)) {

custom/src/main/java/com/solarwinds/opentelemetry/extensions/config/HttpSettingsReader.java

@@ -54,7 +54,9 @@ public Settings getSettings() {
     String tokenHeader = String.format("Bearer %s", apiToken);
     Settings fetchedSettings = delegate.fetchSettings(settingsUrl, tokenHeader);
     logger.debug(
-        String.format("Got settings from http: %s, serviceName: %s", fetchedSettings, serviceName));
+        () ->
+            String.format(
+                "Got settings from http: %s, serviceName: %s", fetchedSettings, serviceName));
 
     return fetchedSettings;
   }

custom/src/test/java/com/solarwinds/opentelemetry/extensions/SolarwindsProfilingSpanProcessorTest.java

@@ -259,7 +259,6 @@ void onEndingShouldSetAttributeToOneWhenProfileHasSample() throws InvalidConfigE
     when(mockSpan.getSpanContext()).thenReturn(mockSpanContext);
     when(mockSpanContext.isSampled()).thenReturn(true);
     when(mockSpanContext.getTraceId()).thenReturn(traceId);
-    when(mockSpanContext.getSpanId()).thenReturn(spanId);
     profilerMock.when(Profiler::hasActiveProfiles).thenReturn(true);
 
     when(mockSpan.toSpanData()).thenReturn(mockSpanData);
@@ -283,7 +282,6 @@ void onEndingShouldSetAttributeToZeroWhenProfileHasNoSample() throws InvalidConf
     profilerMock.when(Profiler::hasActiveProfiles).thenReturn(true);
 
     when(mockSpanContext.getTraceId()).thenReturn(traceId);
-    when(mockSpanContext.getSpanId()).thenReturn(spanId);
     when(mockSpan.toSpanData()).thenReturn(mockSpanData);
 
     when(mockSpanData.getParentSpanContext()).thenReturn(mockParentSpanContext);

instrumentation/instrumentation-shared/src/main/java/com/solarwinds/opentelemetry/instrumentation/StatementTruncator.java

@@ -46,7 +46,7 @@ public static void maybeTruncateStatement(Context context) {
         getAttribute.setAccessible(true);
         sql = (String) getAttribute.invoke(span, DbAttributes.DB_QUERY_TEXT);
       } catch (Throwable throwable) {
-        logger.debug("Cannot execute method getAttribute: " + throwable);
+        logger.debug(() -> "Cannot execute method getAttribute: " + throwable);
       }
       if (sql == null) {
         return;
@@ -60,12 +60,14 @@ public static void maybeTruncateStatement(Context context) {
         sql = sql.substring(0, sqlMaxLength);
         span.setAttribute(QueryTruncatedAttributeKey.KEY, true);
         span.setAttribute(DbAttributes.DB_QUERY_TEXT, sql);
+        int truncatedLength = sql.length();
         logger.debug(
-            "SQL Query trimmed as its length ["
-                + sql.length()
-                + "] exceeds max ["
-                + sqlMaxLength
-                + "]");
+            () ->
+                "SQL Query trimmed as its length ["
+                    + truncatedLength
+                    + "] exceeds max ["
+                    + sqlMaxLength
+                    + "]");
       }
     }
   }

libs/config/src/main/java/com/solarwinds/joboe/config/ConfigContainer.java

@@ -125,15 +125,17 @@ public void put(ConfigProperty propertyKey, Object value, boolean override)
     if (!override
         && configMap.containsKey(
             propertyKey)) { // the key was already inserted before, do NOT overwrite
-      if (!configMap.get(propertyKey).equals(value)) {
+      Object existingValue = configMap.get(propertyKey);
+      if (!existingValue.equals(value)) {
         logger.debug(
-            "key ["
-                + propertyKey
-                + "] is already defined with value ["
-                + configMap.get(propertyKey)
-                + "]. Ignoring new value ["
-                + value
-                + "]");
+            () ->
+                "key ["
+                    + propertyKey
+                    + "] is already defined with value ["
+                    + existingValue
+                    + "]. Ignoring new value ["
+                    + value
+                    + "]");
       }
     } else {
       if (value == null) { // Do not allow null via put by string value

libs/config/src/main/java/com/solarwinds/joboe/config/ConfigManager.java

@@ -60,9 +60,10 @@ public static void removeConfig(ConfigProperty configKey) {
   public static Object getConfig(ConfigProperty configKey) {
     if (SINGLETON.configs == null) {
       logger.debug(
-          "Failed to read config property ["
-              + configKey
-              + "] as agent is not initialized properly, config is null!");
+          () ->
+              "Failed to read config property ["
+                  + configKey
+                  + "] as agent is not initialized properly, config is null!");
       return null;
     }
 
@@ -73,9 +74,10 @@ public static Object getConfig(ConfigProperty configKey) {
   public static <T> T getConfigOptional(ConfigProperty configKey, T defaultValue) {
     if (SINGLETON.configs == null) {
       logger.debug(
-          "Failed to read config property ["
-              + configKey
-              + "] as agent is not initialized properly, config is null!");
+          () ->
+              "Failed to read config property ["
+                  + configKey
+                  + "] as agent is not initialized properly, config is null!");
       return defaultValue;
     }
     Object value = SINGLETON.configs.get(configKey);