From 1931a0b59b63656746a1ff0698e195dbbc8f6fb9 Mon Sep 17 00:00:00 2001 From: Tomasz Kowalczewski Date: Sun, 9 Feb 2025 13:18:27 +0100 Subject: [PATCH] Re #142: Agrona does not like array backed buffers due to mis-alignment performance hit. It does not allow to turn off the check on arm. (#143) --- README.md | 2 +- core/pom.xml | 7 ---- .../pl/tkowalcz/tjahzi/TjahziInitializer.java | 16 ++------- .../java/pl/tkowalcz/tjahzi/HeadersTest.java | 11 +++--- .../tjahzi/LoggingSystemSanityCheckTest.java | 3 +- .../pl/tkowalcz/tjahzi/LoggingSystemTest.java | 3 +- .../pl/tkowalcz/tjahzi/ReconnectTest.java | 8 +++-- .../tjahzi/ResourcesCleanupOnCloseTest.java | 2 -- log4j2-appender/README.md | 6 ---- log4j2-appender/pom.xml | 29 ++-------------- .../tjahzi/log4j2/LokiAppenderBuilder.java | 12 ------- logback-appender/README.md | 1 - logback-appender/pom.xml | 31 ----------------- .../logback/LokiAppenderConfigurator.java | 9 ----- .../tjahzi/logback/LokiAppenderFactory.java | 1 - pom.xml | 34 +++++++++++++++++-- 16 files changed, 52 insertions(+), 123 deletions(-) diff --git a/README.md b/README.md index 187f740..896e7c3 100644 --- a/README.md +++ b/README.md @@ -42,7 +42,7 @@ Logging should be lightweight and not interfere with main business tasks of thre Asking the logging subsystem to log a message should be as CPU efficient as possible. That's a truism. Apart from computation itself there are many other causes of jitter (varying speed of code execution). Thread can be slowed down by excessive allocations, by initialization code running in constructors of unnecessarily allocated objects, -by garbage collector activity that is triggered by it. There can by configuration refresh checks on logging path, inter thread signaling etc. +by garbage collector activity that is triggered by it. There can be configuration refresh checks on logging path, inter thread signaling etc. To avoid these effects we strive to adhere to the following principles (and document any violations): diff --git a/core/pom.xml b/core/pom.xml index cb02064..0e3f428 100644 --- a/core/pom.xml +++ b/core/pom.xml @@ -33,12 +33,5 @@ 4.1.17 provided - - - - org.apache.logging.log4j - log4j-slf4j-impl - test - diff --git a/core/src/main/java/pl/tkowalcz/tjahzi/TjahziInitializer.java b/core/src/main/java/pl/tkowalcz/tjahzi/TjahziInitializer.java index 78cae72..54436ff 100644 --- a/core/src/main/java/pl/tkowalcz/tjahzi/TjahziInitializer.java +++ b/core/src/main/java/pl/tkowalcz/tjahzi/TjahziInitializer.java @@ -26,11 +26,10 @@ public class TjahziInitializer { int bufferSizeBytes, long logShipperWakeupIntervalMillis, long shutdownTimeoutMillis, - boolean offHeap, boolean useDaemonThreads ) { bufferSizeBytes = findNearestPowerOfTwo(bufferSizeBytes); - ByteBuffer javaBuffer = allocateJavaBuffer(bufferSizeBytes, offHeap); + ByteBuffer javaBuffer = allocateJavaBuffer(bufferSizeBytes); ManyToOneRingBuffer logBuffer = new ManyToOneRingBuffer( new UnsafeBuffer(javaBuffer) @@ -93,17 +92,8 @@ public class TjahziInitializer { return bufferSize; } - private ByteBuffer allocateJavaBuffer( - int bufferSize, - boolean offHeap) { + private ByteBuffer allocateJavaBuffer(int bufferSize) { int totalSize = bufferSize + RingBufferDescriptor.TRAILER_LENGTH; - - if (offHeap) { - return ByteBuffer.allocateDirect(totalSize) - .order(ByteOrder.LITTLE_ENDIAN); - } - - return ByteBuffer.allocate(totalSize) - .order(ByteOrder.LITTLE_ENDIAN); + return ByteBuffer.allocateDirect(totalSize).order(ByteOrder.LITTLE_ENDIAN); } } diff --git a/core/src/test/java/pl/tkowalcz/tjahzi/HeadersTest.java b/core/src/test/java/pl/tkowalcz/tjahzi/HeadersTest.java index c66c36e..45bfb71 100644 --- a/core/src/test/java/pl/tkowalcz/tjahzi/HeadersTest.java +++ b/core/src/test/java/pl/tkowalcz/tjahzi/HeadersTest.java @@ -14,7 +14,13 @@ import java.nio.ByteBuffer; import java.util.Map; import java.util.concurrent.TimeUnit; -import static com.github.tomakehurst.wiremock.client.WireMock.*; +import static com.github.tomakehurst.wiremock.client.WireMock.aResponse; +import static com.github.tomakehurst.wiremock.client.WireMock.equalTo; +import static com.github.tomakehurst.wiremock.client.WireMock.matching; +import static com.github.tomakehurst.wiremock.client.WireMock.post; +import static com.github.tomakehurst.wiremock.client.WireMock.postRequestedFor; +import static com.github.tomakehurst.wiremock.client.WireMock.urlEqualTo; +import static com.github.tomakehurst.wiremock.client.WireMock.urlMatching; import static com.github.tomakehurst.wiremock.core.WireMockConfiguration.wireMockConfig; import static org.awaitility.Awaitility.await; @@ -91,7 +97,6 @@ class HeadersTest { 1024 * 1024, 250, 10_000, - false, false ); loggingSystem.start(); @@ -146,7 +151,6 @@ class HeadersTest { 1024 * 1024, 250, 10_000, - false, false ); loggingSystem.start(); @@ -203,7 +207,6 @@ class HeadersTest { 1024 * 1024, 250, 10_000, - false, false ); loggingSystem.start(); diff --git a/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemSanityCheckTest.java b/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemSanityCheckTest.java index 33d836d..b96a101 100644 --- a/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemSanityCheckTest.java +++ b/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemSanityCheckTest.java @@ -69,7 +69,6 @@ class LoggingSystemSanityCheckTest { 1024 * 1024, 250, 10_000, - false, false ); @@ -126,7 +125,7 @@ class LoggingSystemSanityCheckTest { .body("data.result[0].stream.server", equalTo("127.0.0.1")) .body("data.result[0].stream.version", equalTo("0.43")) .body("data.result[0].stream.level", equalTo("warn")) - .body("data.result[0].values[0]", hasItems("" + (timestamp * 1000_000 +882), "Test")); + .body("data.result[0].values[0]", hasItems("" + (timestamp * 1000_000 + 882), "Test")); }); } } diff --git a/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemTest.java b/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemTest.java index 72413ea..30e6fcd 100644 --- a/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemTest.java +++ b/core/src/test/java/pl/tkowalcz/tjahzi/LoggingSystemTest.java @@ -73,7 +73,6 @@ class LoggingSystemTest { 0, 250, 10_000, - false, false ); @@ -159,7 +158,7 @@ class LoggingSystemTest { index--; return actualTimestamp == expectedTimestamp - && actualLogLine.equals(expectedLogLine); + && actualLogLine.equals(expectedLogLine); } })); }); diff --git a/core/src/test/java/pl/tkowalcz/tjahzi/ReconnectTest.java b/core/src/test/java/pl/tkowalcz/tjahzi/ReconnectTest.java index d6027f7..b4e1a40 100644 --- a/core/src/test/java/pl/tkowalcz/tjahzi/ReconnectTest.java +++ b/core/src/test/java/pl/tkowalcz/tjahzi/ReconnectTest.java @@ -14,7 +14,11 @@ import java.nio.ByteBuffer; import java.util.Map; import java.util.concurrent.TimeUnit; -import static com.github.tomakehurst.wiremock.client.WireMock.*; +import static com.github.tomakehurst.wiremock.client.WireMock.aResponse; +import static com.github.tomakehurst.wiremock.client.WireMock.post; +import static com.github.tomakehurst.wiremock.client.WireMock.postRequestedFor; +import static com.github.tomakehurst.wiremock.client.WireMock.urlEqualTo; +import static com.github.tomakehurst.wiremock.client.WireMock.urlMatching; import static com.github.tomakehurst.wiremock.core.WireMockConfiguration.wireMockConfig; import static org.awaitility.Awaitility.await; @@ -86,7 +90,6 @@ public class ReconnectTest { 1024 * 1024, 250, 10_000, - false, false ); loggingSystem.start(); @@ -139,7 +142,6 @@ public class ReconnectTest { 1024 * 1024, 250, 10_000, - false, false ); loggingSystem.start(); diff --git a/core/src/test/java/pl/tkowalcz/tjahzi/ResourcesCleanupOnCloseTest.java b/core/src/test/java/pl/tkowalcz/tjahzi/ResourcesCleanupOnCloseTest.java index 5945386..c5a6ef7 100644 --- a/core/src/test/java/pl/tkowalcz/tjahzi/ResourcesCleanupOnCloseTest.java +++ b/core/src/test/java/pl/tkowalcz/tjahzi/ResourcesCleanupOnCloseTest.java @@ -82,7 +82,6 @@ class ResourcesCleanupOnCloseTest { 1024 * 1024, 250, 10_000, - false, false ); loggingSystem.start(); @@ -146,7 +145,6 @@ class ResourcesCleanupOnCloseTest { 1024 * 1024, 250, 10_000, - false, true ); loggingSystem.start(); diff --git a/log4j2-appender/README.md b/log4j2-appender/README.md index cd62889..f060045 100644 --- a/log4j2-appender/README.md +++ b/log4j2-appender/README.md @@ -327,12 +327,6 @@ to retry indefinitely employing exponential backoff (initial backoff = 250ms, ma Sets socket read timeout on Loki connection. -#### useOffHeapBuffer (optional, default = true) - -Whether Tjahzi should allocate native buffer for `Log buffer` component. We can go into a rabbit hole of divagations -what are the implications of this. Most important in our view is that having 10s or 100s of MB of space taken out of -heap is not very friendly to garbage collector which might have to occasionally copy it around. - #### batchSize (optional, default = 10_2400) Like diff --git a/log4j2-appender/pom.xml b/log4j2-appender/pom.xml index f526ed9..306f62b 100644 --- a/log4j2-appender/pom.xml +++ b/log4j2-appender/pom.xml @@ -1,4 +1,5 @@ - 4.0.0 @@ -40,30 +41,4 @@ test - - - - allocation-profiling - - - - org.apache.maven.plugins - maven-surefire-plugin - - - -javaagent:"${settings.localRepository}/com/google/code/java-allocation-instrumenter/java-allocation-instrumenter/3.3.0/java-allocation-instrumenter-3.3.0.jar" - - - - - com.google.code.java-allocation-instrumenter - java-allocation-instrumenter - 3.3.0 - - - - - - - diff --git a/log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/LokiAppenderBuilder.java b/log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/LokiAppenderBuilder.java index e73fded..93c083c 100644 --- a/log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/LokiAppenderBuilder.java +++ b/log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/LokiAppenderBuilder.java @@ -71,9 +71,6 @@ public class LokiAppenderBuilder> extends Abstr @PluginBuilderAttribute private int bufferSizeMegabytes = 32; - @PluginBuilderAttribute - private boolean useOffHeapBuffer = true; - @PluginBuilderAttribute private String logLevelLabel; @@ -158,7 +155,6 @@ public class LokiAppenderBuilder> extends Abstr bufferSizeBytes, logShipperWakeupIntervalMillis, TimeUnit.SECONDS.toMillis(shutdownTimeoutSeconds), - isUseOffHeapBuffer(), useDaemonThreads ); @@ -280,14 +276,6 @@ public class LokiAppenderBuilder> extends Abstr this.bufferSizeMegabytes = bufferSizeMegabytes; } - public boolean isUseOffHeapBuffer() { - return useOffHeapBuffer; - } - - public void setUseOffHeapBuffer(boolean useOffHeapBuffer) { - this.useOffHeapBuffer = useOffHeapBuffer; - } - public String getLogLevelLabel() { return logLevelLabel; } diff --git a/logback-appender/README.md b/logback-appender/README.md index 3127828..c74d14a 100644 --- a/logback-appender/README.md +++ b/logback-appender/README.md @@ -281,7 +281,6 @@ or use Tjahzi optimized efficient, low allocation encoder: | MaxRetries | 3 | Maximum number of retries to perform when delivering log message to Loki. Log buffer data is delivered in order, one batch after the other, so too much retries will block delivery of subsequent log batches (on the other hand if we need to retry many times then next batches will probably fail too). | | ConnectTimeoutMillis | 5s | This configures socket connect timeout when connecting to Loki. After unsuccessful connection attempt it will continue to retry indefinitely employing exponential backoff (initial backoff = 250ms, maximum backoff = 30s, multiplier = 3). | | ReadTimeoutMillis | 60s | Sets socket read timeout on Loki connection. | -| UseOffHeapBuffer | true | Whether Tjahzi should allocate native buffer for `Log buffer` component. We can go into a rabbit hole of divagations what are the implications of this. Most important in our view is that having 10s or 100s of MB of space taken out of heap is not very friendly to garbage collector which might have to occasionally copy it around. | | BatchSize | 100 KB | Like in [promtail configuration](https://grafana.com/docs/loki/latest/clients/promtail/configuration/) `maximum batch size (in bytes) of logs to accumulate before sending the batch to Loki`. | | BatchWait | 5s | Like in [promtail configuration](https://grafana.com/docs/loki/latest/clients/promtail/configuration/) `maximum amount of time to wait before sending a batch, even if that batch isn't full`. | | logShipperWakeupIntervalMillis | 10 | The agent that reads data from log buffer, compresses it and sends to Loki via http is called `LogShipper`. This property controls how often it wakes up to perform its duties. Other properties control how often the data should be sent to Loki (`batchSize`, `batchWait`) this one just control how often to wake up and check for these conditions. In versions before `0.9.17` it was left at default 1ms which caused high CPU usage on some setups. | diff --git a/logback-appender/pom.xml b/logback-appender/pom.xml index 0cbacb1..8c5aa18 100644 --- a/logback-appender/pom.xml +++ b/logback-appender/pom.xml @@ -49,35 +49,4 @@ test - - - - allocation-profiling - - - - org.apache.maven.plugins - maven-surefire-plugin - 3.0.0-M5 - - - -javaagent:"${settings.localRepository}/com/google/code/java-allocation-instrumenter/java-allocation-instrumenter/3.3.0/java-allocation-instrumenter-3.3.0.jar" - - - - - - com.google.code.java-allocation-instrumenter - - - java-allocation-instrumenter - - 3.3.0 - - - - - - - diff --git a/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderConfigurator.java b/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderConfigurator.java index f997e7c..27fa5a4 100644 --- a/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderConfigurator.java +++ b/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderConfigurator.java @@ -29,7 +29,6 @@ public abstract class LokiAppenderConfigurator extends UnsynchronizedAppenderBas private int maxRetries = 3; private int bufferSizeMegabytes = 32; - private boolean useOffHeapBuffer = true; private String logLevelLabel; private String loggerNameLabel; @@ -142,14 +141,6 @@ public abstract class LokiAppenderConfigurator extends UnsynchronizedAppenderBas this.bufferSizeMegabytes = bufferSizeMegabytes; } - public boolean isUseOffHeapBuffer() { - return useOffHeapBuffer; - } - - public void setUseOffHeapBuffer(boolean useOffHeapBuffer) { - this.useOffHeapBuffer = useOffHeapBuffer; - } - public String getLogLevelLabel() { return logLevelLabel; } diff --git a/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderFactory.java b/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderFactory.java index 59da390..cc10670 100644 --- a/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderFactory.java +++ b/logback-appender/src/main/java/pl/tkowalcz/tjahzi/logback/LokiAppenderFactory.java @@ -93,7 +93,6 @@ public class LokiAppenderFactory { bufferSizeBytes, configurator.getLogShipperWakeupIntervalMillis(), TimeUnit.SECONDS.toMillis(configurator.getShutdownTimeoutSeconds()), - configurator.isUseOffHeapBuffer(), configurator.isUseDaemonThreads() ); } diff --git a/pom.xml b/pom.xml index d88fcde..f35c682 100644 --- a/pom.xml +++ b/pom.xml @@ -357,8 +357,10 @@ 3.5.2 - --add-opens java.base/java.net=ALL-UNNAMED - --add-opens java.base/sun.net=ALL-UNNAMED + --add-opens + java.base/java.net=ALL-UNNAMED + --add-opens + java.base/sun.net=ALL-UNNAMED @@ -366,5 +368,33 @@ + + allocation-profiling + + + + org.apache.maven.plugins + maven-surefire-plugin + 3.0.0-M5 + + + -javaagent:"${settings.localRepository}/com/google/code/java-allocation-instrumenter/java-allocation-instrumenter/3.3.0/java-allocation-instrumenter-3.3.0.jar" + + + + + + com.google.code.java-allocation-instrumenter + + + java-allocation-instrumenter + + 3.3.0 + + + + + +