From 93d189237b24152e8fa865157a71dd0d96a822f7 Mon Sep 17 00:00:00 2001 From: "tomasz.kowalczewski" Date: Sun, 7 Feb 2021 09:52:50 +0100 Subject: [PATCH] Re #5: Some cleanups. Also added experimental test that records allocations - results are mind blowing. Some improvements based on that test. --- loki-log4j2-appender/pom.xml | 44 +++++++++-- .../tkowalcz/tjahzi/log4j2/AppenderLogic.java | 4 +- .../tjahzi/log4j2/AllocationTest.java | 79 +++++++++++++++++++ ...sic-appender-test-log4j2-configuration.xml | 2 +- .../pl/tkowalcz/tjahzi/LogBufferAgent.java | 5 +- .../tkowalcz/tjahzi/LogBufferTranscoder.java | 17 ++-- .../thjazi/protobuf/ProtobufDeserializer.java | 14 ++-- .../LogBufferSerializerDeserializerTest.java | 2 +- .../tjahzi/LogBufferTranscoderTest.java | 4 +- 9 files changed, 142 insertions(+), 29 deletions(-) create mode 100644 loki-log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/AllocationTest.java diff --git a/loki-log4j2-appender/pom.xml b/loki-log4j2-appender/pom.xml index 848c7dd..17a2967 100644 --- a/loki-log4j2-appender/pom.xml +++ b/loki-log4j2-appender/pom.xml @@ -1,4 +1,5 @@ - + 4.0.0 @@ -30,6 +31,19 @@ 2.13.3 + + io.dropwizard.metrics + metrics-core + 4.1.17 + provided + + + + com.google.code.java-allocation-instrumenter + java-allocation-instrumenter + 3.3.0 + test + io.rest-assured rest-assured @@ -54,13 +68,6 @@ test - - io.dropwizard.metrics - metrics-core - 4.1.17 - provided - - org.junit.jupiter @@ -93,4 +100,25 @@ test + + + + + 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/loki-log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/AppenderLogic.java b/loki-log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/AppenderLogic.java index 66aa827..4637f17 100644 --- a/loki-log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/AppenderLogic.java +++ b/loki-log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/AppenderLogic.java @@ -9,7 +9,7 @@ import java.io.Serializable; import java.nio.ByteBuffer; -import java.util.Map; +import java.util.Collections; import java.util.concurrent.TimeUnit; import java.util.function.BiConsumer; @@ -56,7 +56,7 @@ public void accept(LogEvent event, ByteBuffer byteBuffer) { logger.log( event.getTimeMillis(), - Map.of(), + Collections.emptyMap(), logLevelLabel, logLevel, byteBuffer diff --git a/loki-log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/AllocationTest.java b/loki-log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/AllocationTest.java new file mode 100644 index 0000000..f2249f2 --- /dev/null +++ b/loki-log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/AllocationTest.java @@ -0,0 +1,79 @@ +package pl.tkowalcz.tjahzi.log4j2; + +import com.google.monitoring.runtime.instrumentation.AllocationRecorder; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.junit.jupiter.api.Disabled; +import org.junit.jupiter.api.Test; +import org.testcontainers.containers.BindMode; +import org.testcontainers.containers.GenericContainer; +import org.testcontainers.containers.wait.strategy.Wait; +import org.testcontainers.junit.jupiter.Container; +import org.testcontainers.junit.jupiter.Testcontainers; +import org.testcontainers.shaded.com.google.common.util.concurrent.Uninterruptibles; + +import java.net.URI; +import java.net.URISyntaxException; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicLong; + +@Testcontainers +public class AllocationTest { + + @Container + public GenericContainer loki = new GenericContainer("grafana/loki:latest") + .withCommand("-config.file=/etc/loki-config.yaml") + .withClasspathResourceMapping("loki-config.yaml", + "/etc/loki-config.yaml", + BindMode.READ_ONLY) + .waitingFor( + Wait.forHttp("/ready") + .forPort(3100) + ) + .withExposedPorts(3100); + + @Test + @Disabled + void shouldSendData() throws URISyntaxException { + AtomicLong allocatedMemory = new AtomicLong(); + Runtime.getRuntime().addShutdownHook(new Thread(() -> System.out.println("allocatedMemory = " + allocatedMemory))); + + // Given + System.setProperty("loki.host", loki.getHost()); + System.setProperty("loki.port", loki.getFirstMappedPort().toString()); + + URI uri = getClass() + .getClassLoader() + .getResource("basic-appender-test-log4j2-configuration.xml") + .toURI(); + + ((org.apache.logging.log4j.core.LoggerContext) LogManager.getContext(false)) + .setConfigLocation(uri); + + String logLine = "Cupcake ipsum dolor sit amet cake wafer. " + + "Souffle jelly beans biscuit topping. " + + "Danish bonbon gummies powder caramels. "; + + Logger logger = LogManager.getLogger(pl.tkowalcz.tjahzi.log4j2.LokiAppenderTest.class); + + // When + for (int i = 0; i < 1000; i++) { + logger.info(logLine); + Uninterruptibles.sleepUninterruptibly(10, TimeUnit.MILLISECONDS); + } + + AllocationRecorder.addSampler((count, desc, newObj, size) -> { + if (!desc.startsWith("java/time")) { + allocatedMemory.addAndGet(size); + } + }); + + for (int i = 0; i < 1000; i++) { + logger.info(logLine); + Uninterruptibles.sleepUninterruptibly(10, TimeUnit.MILLISECONDS); + } + + // Then + + } +} diff --git a/loki-log4j2-appender/src/test/resources/basic-appender-test-log4j2-configuration.xml b/loki-log4j2-appender/src/test/resources/basic-appender-test-log4j2-configuration.xml index 663c75b..b481161 100644 --- a/loki-log4j2-appender/src/test/resources/basic-appender-test-log4j2-configuration.xml +++ b/loki-log4j2-appender/src/test/resources/basic-appender-test-log4j2-configuration.xml @@ -13,7 +13,7 @@ - %X{tid} [%t] %d{MM-dd HH:mm:ss.SSS} %5p %c{1} - %m%n%exception{full} + %X{tid} [%t] %d{DEFAULT} %5p %c{1} - %m%n%exception{full}
diff --git a/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferAgent.java b/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferAgent.java index 9c839ed..1651a09 100644 --- a/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferAgent.java +++ b/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferAgent.java @@ -43,7 +43,10 @@ public LogBufferAgent( this.httpClient = httpClient; this.outputBuffer = new OutputBuffer(PooledByteBufAllocator.DEFAULT.buffer()); - this.logBufferTranscoder = new LogBufferTranscoder(staticLabels); + this.logBufferTranscoder = new LogBufferTranscoder( + staticLabels, + logBuffer.buffer() + ); } @Override diff --git a/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferTranscoder.java b/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferTranscoder.java index 0963883..d98ae97 100644 --- a/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferTranscoder.java +++ b/tjahzi-core/src/main/java/pl/tkowalcz/tjahzi/LogBufferTranscoder.java @@ -5,6 +5,7 @@ import io.netty.util.internal.StringUtil; import javolution.text.TextBuilder; import org.agrona.DirectBuffer; +import org.agrona.concurrent.AtomicBuffer; import pl.tkowalcz.tjahzi.http.TextBuilders; import java.nio.ByteBuffer; @@ -15,13 +16,18 @@ public class LogBufferTranscoder { private final Map staticLabels; private final String staticLabelsString; - public LogBufferTranscoder(Map staticLabels) { + private final ByteBuf logLineHolder; + + public LogBufferTranscoder(Map staticLabels, AtomicBuffer buffer) { this.staticLabels = staticLabels; this.staticLabelsString = buildLabelsStringIncludingStatic( staticLabels, StringUtil.EMPTY_STRING, TextBuilders.threadLocal().append("{ ") ).toString(); + + ByteBuffer byteBuffer = buffer.byteBuffer(); + logLineHolder = Unpooled.wrappedBuffer(byteBuffer); } public void deserializeIntoByteBuf(DirectBuffer buffer, int index, OutputBuffer outputBuffer) { @@ -43,11 +49,8 @@ public void deserializeIntoByteBuf(DirectBuffer buffer, int index, OutputBuffer labelsBuilder ); - ByteBuffer byteBuffer = buffer.byteBuffer(); - ByteBuf logLine = Unpooled.wrappedBuffer(byteBuffer) - .readerIndex(index); - - outputBuffer.addLogLine(actualLabels, timestamp, logLine); + logLineHolder.readerIndex(index); + outputBuffer.addLogLine(actualLabels, timestamp, logLineHolder); } private int readLabels( @@ -78,13 +81,11 @@ private static CharSequence buildLabelsStringIncludingStatic( } staticLabels.forEach((key, value) -> { -// if (!labels.containsKey(key)) { labels.append(key) .append("=") .append("\"") .append(value) .append("\","); -// } }); labels.setCharAt(labels.length() - 1, '}'); diff --git a/tjahzi-core/src/test/java/pl/tkowalcz/thjazi/protobuf/ProtobufDeserializer.java b/tjahzi-core/src/test/java/pl/tkowalcz/thjazi/protobuf/ProtobufDeserializer.java index deb3ef0..f2ea465 100644 --- a/tjahzi-core/src/test/java/pl/tkowalcz/thjazi/protobuf/ProtobufDeserializer.java +++ b/tjahzi-core/src/test/java/pl/tkowalcz/thjazi/protobuf/ProtobufDeserializer.java @@ -20,14 +20,16 @@ public class ProtobufDeserializer { @Test void shouldDeserialize() throws IOException { - ManyToOneRingBuffer logBuffer = new ManyToOneRingBuffer( - new UnsafeBuffer( - ByteBuffer.wrap( - new byte[1024 + RingBufferDescriptor.TRAILER_LENGTH] - ) + UnsafeBuffer buffer = new UnsafeBuffer( + ByteBuffer.wrap( + new byte[1024 + RingBufferDescriptor.TRAILER_LENGTH] ) ); + ManyToOneRingBuffer logBuffer = new ManyToOneRingBuffer( + buffer + ); + LogBufferSerializer serializer = new LogBufferSerializer(logBuffer.buffer()); serializer.writeTo( 0, @@ -38,7 +40,7 @@ void shouldDeserialize() throws IOException { ByteBuffer.wrap("Test".getBytes()) ); - LogBufferTranscoder deserializer = new LogBufferTranscoder(Map.of()); + LogBufferTranscoder deserializer = new LogBufferTranscoder(Map.of(), buffer); OutputBuffer outputBuffer = new OutputBuffer(PooledByteBufAllocator.DEFAULT.buffer()); deserializer.deserializeIntoByteBuf( logBuffer.buffer(), diff --git a/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferSerializerDeserializerTest.java b/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferSerializerDeserializerTest.java index ea0bf5b..1575ab8 100644 --- a/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferSerializerDeserializerTest.java +++ b/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferSerializerDeserializerTest.java @@ -96,7 +96,7 @@ void shouldSerializeMessage( // Then OutputBuffer outputBuffer = new OutputBuffer(PooledByteBufAllocator.DEFAULT.buffer()); - LogBufferTranscoder deserializer = new LogBufferTranscoder(Map.of()); + LogBufferTranscoder deserializer = new LogBufferTranscoder(Map.of(), buffer); deserializer.deserializeIntoByteBuf( buffer, 0, diff --git a/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferTranscoderTest.java b/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferTranscoderTest.java index 72e5aaa..062557c 100644 --- a/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferTranscoderTest.java +++ b/tjahzi-core/src/test/java/pl/tkowalcz/tjahzi/LogBufferTranscoderTest.java @@ -55,7 +55,7 @@ void shouldDeserializeMessageAndAddStaticLabels( OutputBuffer outputBuffer = new OutputBuffer(PooledByteBufAllocator.DEFAULT.buffer()); // When - LogBufferTranscoder deserializer = new LogBufferTranscoder(staticLabels); + LogBufferTranscoder deserializer = new LogBufferTranscoder(staticLabels, buffer); deserializer.deserializeIntoByteBuf( buffer, 0, @@ -122,7 +122,7 @@ void shouldOverrideStaticLabelsWithIncoming() throws InvalidProtocolBufferExcept OutputBuffer outputBuffer = new OutputBuffer(PooledByteBufAllocator.DEFAULT.buffer()); // When - LogBufferTranscoder deserializer = new LogBufferTranscoder(staticLabels); + LogBufferTranscoder deserializer = new LogBufferTranscoder(staticLabels, buffer); deserializer.deserializeIntoByteBuf( buffer, 0,