Add Performance test & Collect Debug logs by default (#7)

* fixing GPG import * fixing GPG import * fixing GPG import * Make build.sh executable * Make build.sh executable * enable maven publish * fixing GPG import * fixing GPG import * fixing GPG import * fixing GPG import * debugging * debugging * debugging * debugging * debugging * debugging * debugging * udpate env variable * udpate env variable * udpate env variable and run command * udpate env variable and run command * udpate env variable and run command testing * udpate env * remove settings.xml * add settings.xml * add github deploy package * update gitworkflows * delete builder.sh * delete setting.xml * Add basic perf testing * add some performance matrixes * move example to example package * TODO asyc logger * add async logger * Add disruptor code * collect debug logs along with info logs by default
parvez3019 · Apr 5, 2024 · 3f7269f · 3f7269f
1 parent 2b07f4f
commit 3f7269f
Show file tree

Hide file tree

Showing 13 changed files with 277 additions and 135 deletions.
diff --git a/pom.xml b/pom.xml
@@ -71,6 +71,47 @@
             <artifactId>maven-install-plugin</artifactId>
             <version>3.1.1</version>
         </dependency>
+
+        <!-- https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-core -->
+        <dependency>
+            <groupId>org.apache.logging.log4j</groupId>
+            <artifactId>log4j-core</artifactId>
+            <version>2.23.1</version>
+        </dependency>
+        <!-- https://mvnrepository.com/artifact/org.openjdk.jmh/jmh-core -->
+        <dependency>
+            <groupId>org.openjdk.jmh</groupId>
+            <artifactId>jmh-core</artifactId>
+            <version>1.37</version>
+            <scope>test</scope>
+        </dependency>
+
+        <dependency>
+            <groupId>org.openjdk.jmh</groupId>
+            <artifactId>jmh-generator-annprocess</artifactId>
+            <version>1.37</version>
+        </dependency>
+        <dependency>
+            <groupId>org.openjdk.jmh</groupId>
+            <artifactId>jmh-core</artifactId>
+            <version>1.37</version>
+            <scope>compile</scope>
+        </dependency>
+
+        <!-- https://mvnrepository.com/artifact/com.lmax/disruptor -->
+        <dependency>
+            <groupId>com.lmax</groupId>
+            <artifactId>disruptor</artifactId>
+            <version>3.3.0</version>
+        </dependency>
+
+        <!-- https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-core -->
+        <dependency>
+            <groupId>org.apache.logging.log4j</groupId>
+            <artifactId>log4j-core</artifactId>
+            <version>2.23.1</version>
+        </dependency>
+
     </dependencies>
     <build>
         <plugins>
@@ -154,7 +195,7 @@
 
     <scm>
         <connection>scm:git:git://github.com/parvez3019/log4error.git</connection>
-        <developerConnection>scm:git:ssh://github.com:parvez3019/log4error.git</developerConnection>        
+        <developerConnection>scm:git:ssh://github.com:parvez3019/log4error.git</developerConnection>
         <url>https://github.com/parvez3019/log4error.git</url>
         <tag>0.0.8</tag>
     </scm>

diff --git a/src/main/java/io/github/parvez3019/InfoLoggerEvent.java b/src/main/java/io/github/parvez3019/InfoLoggerEvent.java
@@ -1,19 +1,4 @@
 package io.github.parvez3019;
 
-public class InfoLoggerEvent {
-    private final String message;
-    private final Object[] argArray;
-
-    public InfoLoggerEvent(String message, Object[] argArray) {
-        this.message = message;
-        this.argArray = argArray;
-    }
-
-    public String getMessage() {
-        return message;
-    }
-
-    public Object[] getArgArray() {
-        return argArray;
-    }
+public record InfoLoggerEvent(LoggerLevel level, String message, Object[] argArray) {
 }
diff --git a/src/main/java/io/github/parvez3019/Logger.java b/src/main/java/io/github/parvez3019/Logger.java
@@ -5,20 +5,19 @@
 import org.springframework.stereotype.Component;
 import org.springframework.web.context.annotation.RequestScope;
 
-import java.util.Stack;
+import java.util.ArrayList;
 
 @Component
 @RequestScope
 public class Logger {
     private static final org.slf4j.Logger LOGGER = LoggerFactory.getLogger(Logger.class);
-
-    private final Stack<InfoLoggerEvent> infoLogs;
+    private final ArrayList<InfoLoggerEvent> collectedLogs;
 
     /**
      * No argument constructor for Logger.Class
      */
     public Logger() {
-        infoLogs = new Stack<>();
+        collectedLogs = new ArrayList<>();
     }
 
     /**
@@ -28,13 +27,17 @@ public Logger() {
      * @param obj     - array of objects
      */
     public void info(String message, Object... obj) {
-        Throwable throwableCandidate = MessageFormatter.getThrowableCandidate(obj);
-        if (throwableCandidate != null) {
-            Object[] trimmedCopy = MessageFormatter.trimmedCopy(obj);
-            this.infoLogs.push(new InfoLoggerEvent(message, trimmedCopy));
-        } else {
-            this.infoLogs.push(new InfoLoggerEvent(message, obj));
-        }
+        collectLog(LoggerLevel.INFO, message, obj);
+    }
+
+    /**
+     * This method will be pushing debug logs in to a stack of string
+     *
+     * @param message takes the logs message in pattern format eg "Exception occurred :{}, at time: {}, ex, time.now()"
+     * @param obj     - array of objects
+     */
+    public void debug(String message, Object... obj) {
+        collectLog(LoggerLevel.DEBUG, message, obj);
     }
 
     /**
@@ -54,16 +57,14 @@ public void error(String message, Object... obj) {
      * Print info log stack
      */
     public void printInfoLogs() {
-        infoLogs.forEach(p -> {
-            LOGGER.info(p.getMessage(), p.getArgArray());
-        });
+        collectedLogs.forEach(Logger::printLog);
     }
 
     /**
      * Clear up the info log stack
      */
     public void clearInfoLogStack() {
-        infoLogs.clear();
+        collectedLogs.clear();
     }
 
     /**
@@ -72,7 +73,7 @@ public void clearInfoLogStack() {
      * @param message takes the logs message in pattern format eg "Exception occurred :{}, at time: {}, ex, time.now()"
      * @param obj     - array of objects
      */
-    public static void printInfo(String message, Object... obj) {
+    public void pInfo(String message, Object... obj) {
         LOGGER.info(message, obj);
     }
 
@@ -82,7 +83,7 @@ public static void printInfo(String message, Object... obj) {
      * @param message takes the logs message in pattern format eg "Exception occurred :{}, at time: {}, ex, time.now()"
      * @param obj     - array of objects
      */
-    public static void printError(String message, Object... obj) {
+    public void pError(String message, Object... obj) {
         LOGGER.error(message, obj);
     }
 
@@ -92,7 +93,7 @@ public static void printError(String message, Object... obj) {
      * @param message takes the logs message in pattern format eg "Exception occurred :{}, at time: {}, ex, time.now()"
      * @param obj     - array of objects
      */
-    public static void warn(String message, Object... obj) {
+    public void pWarn(String message, Object... obj) {
         LOGGER.warn(message, obj);
     }
 
@@ -102,7 +103,26 @@ public static void warn(String message, Object... obj) {
      * @param message takes the logs message in pattern format eg "Exception occurred :{}, at time: {}, ex, time.now()"
      * @param obj     - array of objects
      */
-    public static void debug(String message, Object... obj) {
+    public void pDebug(String message, Object... obj) {
         LOGGER.debug(message, obj);
     }
+
+    private void collectLog(LoggerLevel level, String message, Object[] obj) {
+        Throwable throwableCandidate = MessageFormatter.getThrowableCandidate(obj);
+        if (throwableCandidate != null) {
+            Object[] trimmedCopy = MessageFormatter.trimmedCopy(obj);
+            this.collectedLogs.add(new InfoLoggerEvent(level, message, trimmedCopy));
+        } else {
+            this.collectedLogs.add(new InfoLoggerEvent(level, message, obj));
+        }
+    }
+
+    private static void printLog(InfoLoggerEvent p) {
+        if (p.level() == LoggerLevel.INFO) {
+            LOGGER.info(p.message(), p.argArray());
+        }
+        if (p.level() == LoggerLevel.DEBUG) {
+            LOGGER.debug(p.message(), p.argArray());
+        }
+    }
 }
diff --git a/src/main/java/io/github/parvez3019/LoggerLevel.java b/src/main/java/io/github/parvez3019/LoggerLevel.java
@@ -0,0 +1,6 @@
+package io.github.parvez3019;
+
+public enum LoggerLevel {
+    INFO,
+    DEBUG
+}
diff --git a/src/main/java/io/github/parvez3019/benchmarking/Log4ErrorBenchmark.java b/src/main/java/io/github/parvez3019/benchmarking/Log4ErrorBenchmark.java
@@ -0,0 +1,35 @@
+package io.github.parvez3019.benchmarking;
+
+import io.github.parvez3019.Logger;
+import org.openjdk.jmh.annotations.BenchmarkMode;
+import org.openjdk.jmh.annotations.*;
+
+import java.util.concurrent.TimeUnit;
+
+@State(Scope.Benchmark)
+@BenchmarkMode(Mode.AverageTime)
+@OutputTimeUnit(TimeUnit.NANOSECONDS)
+@Warmup(iterations = 2, time = 1, timeUnit = TimeUnit.SECONDS)
+@Measurement(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
+@Fork(value = 1)
+@Threads(8)
+public class Log4ErrorBenchmark {
+    private static final int LOG_COUNT = 100000;
+    private Logger logger;
+
+    @Setup
+    public void setup() {
+        logger = new Logger();
+    }
+
+    @TearDown
+    public void teardown() {
+    }
+
+    @Benchmark
+    public void customLoggerBenchmark() {
+        for (int i = 0; i < LOG_COUNT; i++) {
+            logger.info("Logging message " + i);
+        }
+    }
+}
diff --git a/src/main/java/io/github/parvez3019/benchmarking/Log4jBenchmark.java b/src/main/java/io/github/parvez3019/benchmarking/Log4jBenchmark.java
@@ -0,0 +1,35 @@
+package io.github.parvez3019.benchmarking;
+
+import org.apache.logging.log4j.LogManager;
+import org.openjdk.jmh.annotations.*;
+import org.apache.logging.log4j.Logger;
+
+import java.util.concurrent.TimeUnit;
+
+@State(Scope.Benchmark)
+@BenchmarkMode(Mode.AverageTime)
+@OutputTimeUnit(TimeUnit.NANOSECONDS)
+@Warmup(iterations = 2, time = 1, timeUnit = TimeUnit.SECONDS)
+@Measurement(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
+@Fork(value = 1)
+@Threads(8)
+public class Log4jBenchmark {
+    private static final int LOG_COUNT = 100000;
+    private Logger log4jLogger;
+
+    @Setup
+    public void setup() {
+        log4jLogger = LogManager.getLogger(Log4jBenchmark.class);
+    }
+
+    @TearDown
+    public void teardown() {
+    }
+
+    @Benchmark
+    public void log4jLoggerBenchmark() {
+        for (int i = 0; i < LOG_COUNT; i++) {
+            log4jLogger.info("Logging message " + i);
+        }
+    }
+}
diff --git a/src/main/java/io/github/parvez3019/benchmarking/Main.java b/src/main/java/io/github/parvez3019/benchmarking/Main.java
@@ -0,0 +1,16 @@
+package io.github.parvez3019.benchmarking;
+
+import org.openjdk.jmh.runner.Runner;
+import org.openjdk.jmh.runner.RunnerException;
+import org.openjdk.jmh.runner.options.Options;
+import org.openjdk.jmh.runner.options.OptionsBuilder;
+
+public class Main {
+    public static void main(String[] args) throws RunnerException {
+        Options opt = new OptionsBuilder().include(
+                Log4jBenchmark.class.getSimpleName()
+        ).build();
+        new Runner(opt).run();
+    }
+
+}
diff --git a/...ithub/parvez3019/LoggerFilterExample.java → ...rvez3019/example/LoggerFilterExample.java b/...ithub/parvez3019/LoggerFilterExample.java → ...rvez3019/example/LoggerFilterExample.java
@@ -1,5 +1,7 @@
-package io.github.parvez3019;
+package io.github.parvez3019.example;
 
+import io.github.parvez3019.Logger;
+import io.github.parvez3019.LoggerThreadLocal;
 import jakarta.servlet.FilterChain;
 import jakarta.servlet.ServletException;
 import jakarta.servlet.http.HttpServletRequest;

diff --git a/src/main/resources/benchmark/log4error b/src/main/resources/benchmark/log4error
@@ -0,0 +1,51 @@
+/Users/olx/Library/Java/JavaVirtualMachines/corretto-17.0.10/Contents/Home/bin/java -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=62488:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8 -classpath /Users/olx/repos/Personal projects/log4error/target/classes:/Users/olx/.m2/repository/org/apache/commons/commons-lang3/3.14.0/commons-lang3-3.14.0.jar:/Users/olx/.m2/repository/org/slf4j/slf4j-api/2.0.9/slf4j-api-2.0.9.jar:/Users/olx/.m2/repository/org/springframework/spring-context/5.3.33/spring-context-5.3.33.jar:/Users/olx/.m2/repository/org/springframework/spring-aop/5.3.33/spring-aop-5.3.33.jar:/Users/olx/.m2/repository/org/springframework/spring-beans/5.3.33/spring-beans-5.3.33.jar:/Users/olx/.m2/repository/org/springframework/spring-core/5.3.33/spring-core-5.3.33.jar:/Users/olx/.m2/repository/org/springframework/spring-jcl/5.3.33/spring-jcl-5.3.33.jar:/Users/olx/.m2/repository/org/springframework/spring-expression/5.3.33/spring-expression-5.3.33.jar:/Users/olx/.m2/repository/org/apache/tomcat/embed/tomcat-embed-core/10.1.19/tomcat-embed-core-10.1.19.jar:/Users/olx/.m2/repository/org/apache/tomcat/tomcat-annotations-api/10.1.19/tomcat-annotations-api-10.1.19.jar:/Users/olx/.m2/repository/javax/servlet/javax.servlet-api/4.0.1/javax.servlet-api-4.0.1.jar:/Users/olx/.m2/repository/org/springframework/spring-web/6.1.5/spring-web-6.1.5.jar:/Users/olx/.m2/repository/io/micrometer/micrometer-observation/1.12.4/micrometer-observation-1.12.4.jar:/Users/olx/.m2/repository/io/micrometer/micrometer-commons/1.12.4/micrometer-commons-1.12.4.jar:/Users/olx/.m2/repository/org/apache/maven/plugins/maven-install-plugin/3.1.1/maven-install-plugin-3.1.1.jar:/Users/olx/.m2/repository/org/eclipse/aether/aether-util/1.0.0.v20140518/aether-util-1.0.0.v20140518.jar:/Users/olx/.m2/repository/org/eclipse/aether/aether-api/1.0.0.v20140518/aether-api-1.0.0.v20140518.jar:/Users/olx/.m2/repository/org/codehaus/plexus/plexus-utils/3.5.0/plexus-utils-3.5.0.jar:/Users/olx/.m2/repository/org/apache/logging/log4j/log4j-core/2.23.1/log4j-core-2.23.1.jar:/Users/olx/.m2/repository/org/apache/logging/log4j/log4j-api/2.23.1/log4j-api-2.23.1.jar:/Users/olx/.m2/repository/org/openjdk/jmh/jmh-core/1.37/jmh-core-1.37.jar:/Users/olx/.m2/repository/net/sf/jopt-simple/jopt-simple/5.0.4/jopt-simple-5.0.4.jar:/Users/olx/.m2/repository/org/apache/commons/commons-math3/3.6.1/commons-math3-3.6.1.jar:/Users/olx/.m2/repository/org/openjdk/jmh/jmh-generator-annprocess/1.37/jmh-generator-annprocess-1.37.jar io.github.parvez3019.benchmarking.Main
+# JMH version: 1.37
+# VM version: JDK 17.0.10, OpenJDK 64-Bit Server VM, 17.0.10+7-LTS
+# VM invoker: /Users/olx/Library/Java/JavaVirtualMachines/corretto-17.0.10/Contents/Home/bin/java
+# VM options: -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=62488:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8
+# Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
+# Warmup: 2 iterations, 1 s each
+# Measurement: 5 iterations, 1 s each
+# Timeout: 10 min per iteration
+# Threads: 8 threads, will synchronize iterations
+# Benchmark mode: Average time, time/op
+# Benchmark: io.github.parvez3019.benchmarking.Log4ErrorBenchmark.customLoggerBenchmark
+
+# Run progress: 0.00% complete, ETA 00:00:07
+# Fork: 1 of 1
+# Warmup Iteration   1: SLF4J: No SLF4J providers were found.
+SLF4J: Defaulting to no-operation (NOP) logger implementation
+SLF4J: See https://www.slf4j.org/codes.html#noProviders for further details.
+81385352.176 ±(99.9%) 7305420.911 ns/op
+# Warmup Iteration   2: 69242245.939 ±(99.9%) 7584794.480 ns/op
+Iteration   1: 64745510.524 ±(99.9%) 7426180.878 ns/op
+Iteration   2: 72176655.171 ±(99.9%) 3430751.108 ns/op
+Iteration   3: 79056243.450 ±(99.9%) 5489979.364 ns/op
+Iteration   4: 60028728.111 ±(99.9%) 3853359.985 ns/op
+Iteration   5: 70212683.454 ±(99.9%) 3037753.934 ns/op
+
+
+Result "io.github.parvez3019.benchmarking.Log4ErrorBenchmark.customLoggerBenchmark":
+  69243964.142 ±(99.9%) 27965364.762 ns/op [Average]
+  (min, avg, max) = (60028728.111, 69243964.142, 79056243.450), stdev = 7262516.421
+  CI (99.9%): [41278599.380, 97209328.904] (assumes normal distribution)
+
+
+# Run complete. Total time: 00:00:09
+
+REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
+why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
+experiments, perform baseline and negative tests that provide experimental control, make sure
+the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
+Do not assume the numbers tell you what you want them to tell.
+
+NOTE: Current JVM experimentally supports Compiler Blackholes, and they are in use. Please exercise
+extra caution when trusting the results, look into the generated code to check the benchmark still
+works, and factor in a small probability of new VM bugs. Additionally, while comparisons between
+different JVMs are already problematic, the performance difference caused by different Blackhole
+modes can be very significant. Please make sure you use the consistent Blackhole mode for comparisons.
+
+Benchmark                                 Mode  Cnt         Score          Error  Units
+Log4ErrorBenchmark.customLoggerBenchmark  avgt    5  69243964.142 ± 27965364.762  ns/op
+
+Process finished with exit code 0