From 3e4948264ba8bfbea54af70fa3f8caca722a19a2 Mon Sep 17 00:00:00 2001 From: Glenn Oppegard Date: Thu, 12 Oct 2023 09:17:20 -0600 Subject: [PATCH] Optimize tracingSpanToLineData and loggers (#303) * Skip expensive `DelegatingLogger#inferCaller()` * Optimize StringBuilder for Spans * Early return for other loggers --- .../java/com/wavefront/sdk/common/Utils.java | 98 ++++++++++++------- .../sdk/common/logging/DelegatingLogger.java | 3 + .../common/logging/MessageDedupingLogger.java | 12 +++ .../logging/MessageSuppressingLogger.java | 8 ++ .../common/logging/DelegatingLoggerTest.java | 76 ++++++++++++++ .../logging/MessageDedupingLoggerTest.java | 1 + 6 files changed, 163 insertions(+), 35 deletions(-) create mode 100644 src/test/java/com/wavefront/sdk/common/logging/DelegatingLoggerTest.java diff --git a/src/main/java/com/wavefront/sdk/common/Utils.java b/src/main/java/com/wavefront/sdk/common/Utils.java index af90acc3..47546dc0 100644 --- a/src/main/java/com/wavefront/sdk/common/Utils.java +++ b/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 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 parents, List followsFrom, List> tags, List 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 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))) { diff --git a/src/main/java/com/wavefront/sdk/common/logging/DelegatingLogger.java b/src/main/java/com/wavefront/sdk/common/logging/DelegatingLogger.java index 99aa7b55..7f81c5ca 100644 --- a/src/main/java/com/wavefront/sdk/common/logging/DelegatingLogger.java +++ b/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' diff --git a/src/main/java/com/wavefront/sdk/common/logging/MessageDedupingLogger.java b/src/main/java/com/wavefront/sdk/common/logging/MessageDedupingLogger.java index a089e503..0dacf230 100644 --- a/src/main/java/com/wavefront/sdk/common/logging/MessageDedupingLogger.java +++ b/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 { diff --git a/src/main/java/com/wavefront/sdk/common/logging/MessageSuppressingLogger.java b/src/main/java/com/wavefront/sdk/common/logging/MessageSuppressingLogger.java index 0e79bba7..4866f868 100644 --- a/src/main/java/com/wavefront/sdk/common/logging/MessageSuppressingLogger.java +++ b/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)); } diff --git a/src/test/java/com/wavefront/sdk/common/logging/DelegatingLoggerTest.java b/src/test/java/com/wavefront/sdk/common/logging/DelegatingLoggerTest.java new file mode 100644 index 00000000..4e81dacc --- /dev/null +++ b/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 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)); + } + } +} \ No newline at end of file diff --git a/src/test/java/com/wavefront/sdk/common/logging/MessageDedupingLoggerTest.java b/src/test/java/com/wavefront/sdk/common/logging/MessageDedupingLoggerTest.java index b2dc4648..693cae59 100644 --- a/src/test/java/com/wavefront/sdk/common/logging/MessageDedupingLoggerTest.java +++ b/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");