Skip to content

Commit b435fff

Browse files
KarstenSchnitterKarstenSchnitter
committed
Introduce JHM Benchmarking for Log Backends
Changes to the JSON encoding and messages generation overall may impact the library performance and with this the application performance. To provide a toolset to measure impact of changes in future, the Java Microbenchmarking Harness (JMH) was introduce with a few simple benchmarks. The are implemented separately for log4j2 and logback. The current results from my machine are as follow: Logback: Benchmark Mode Cnt Score Error Units EncodingBenchmarks.minimalRequestRecord thrpt 5 84562,416 ± 8912,890 ops/s EncodingBenchmarks.simpleLog thrpt 5 115365,061 ± 15645,826 ops/s EncodingBenchmarks.singleCommonFieldFromMdc thrpt 5 113844,805 ± 3235,766 ops/s EncodingBenchmarks.singleCustomFieldFromArgument thrpt 5 109952,525 ± 9775,466 ops/s Log4j2: Benchmark Mode Cnt Score Error Units EncodingBenchmarks.minimalRequestRecord thrpt 5 114756,173 ± 7212,135 ops/s EncodingBenchmarks.simpleLog thrpt 5 170957,170 ± 2546,579 ops/s EncodingBenchmarks.singleCommonFieldFromMdc thrpt 5 164589,191 ± 29621,024 ops/s EncodingBenchmarks.singleCustomFieldFromArgument thrpt 5 173940,242 ± 24513,865 ops/s Signed-off-by: Karsten Schnitter <k.schnitter@sap.com>
1 parent 6e40037 commit b435fff

File tree

5 files changed

+199
-0
lines changed

5 files changed

+199
-0
lines changed

‎cf-java-logging-support-log4j2/src/test/java/com/sap/hcp/cf/log4j2/benchmark/BenchmarkRunner.java‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
package com.sap.hcp.cf.log4j2.benchmark;
2+
3+
import org.openjdk.jmh.runner.Runner;
4+
import org.openjdk.jmh.runner.RunnerException;
5+
import org.openjdk.jmh.runner.options.Options;
6+
import org.openjdk.jmh.runner.options.OptionsBuilder;
7+
8+
public class BenchmarkRunner {
9+
10+
public static void main(String[] args) throws RunnerException {
11+
Options options = new OptionsBuilder().include(EncodingBenchmarks.class.getSimpleName()).forks(1).build();
12+
new Runner(options).run();
13+
}
14+
15+
}

‎cf-java-logging-support-log4j2/src/test/java/com/sap/hcp/cf/log4j2/benchmark/EncodingBenchmarks.java‎

Lines changed: 78 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,78 @@
1+
package com.sap.hcp.cf.log4j2.benchmark;
2+
3+
import static com.sap.hcp.cf.logging.common.request.RequestRecordBuilder.requestRecord;
4+
5+
import java.io.PrintStream;
6+
import java.util.concurrent.TimeUnit;
7+
8+
import org.openjdk.jmh.annotations.Benchmark;
9+
import org.openjdk.jmh.annotations.Measurement;
10+
import org.openjdk.jmh.annotations.Scope;
11+
import org.openjdk.jmh.annotations.Setup;
12+
import org.openjdk.jmh.annotations.State;
13+
import org.openjdk.jmh.annotations.TearDown;
14+
import org.openjdk.jmh.annotations.Warmup;
15+
import org.openjdk.jmh.util.NullOutputStream;
16+
import org.slf4j.Logger;
17+
import org.slf4j.LoggerFactory;
18+
import org.slf4j.MDC;
19+
20+
import com.sap.hcp.cf.logging.common.Fields;
21+
import com.sap.hcp.cf.logging.common.Markers;
22+
import com.sap.hcp.cf.logging.common.customfields.CustomField;
23+
import com.sap.hcp.cf.logging.common.request.RequestRecord;
24+
25+
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
26+
@Measurement(iterations = 5, time = 5, timeUnit = TimeUnit.SECONDS)
27+
public class EncodingBenchmarks {
28+
29+
public static Logger LOG = LoggerFactory.getLogger(EncodingBenchmarks.class);
30+
31+
@State(Scope.Benchmark)
32+
public static class BenchmarkState {
33+
private PrintStream out;
34+
35+
public String simpleLogMessage = "Simple message benchmark";
36+
public CustomField customField = CustomField.customField("custom of ", CustomField.class.getSimpleName());
37+
public String componentId = EncodingBenchmarks.class.getSimpleName();
38+
public String requestLayer = "benchmark";
39+
40+
@Setup
41+
public void substituteSystemOut() {
42+
out = System.out;
43+
System.setOut(new PrintStream(new NullOutputStream()));
44+
}
45+
46+
@TearDown
47+
public void resetSystemOut() {
48+
System.setOut(out);
49+
}
50+
}
51+
52+
@Benchmark
53+
public void simpleLog(BenchmarkState state) {
54+
LOG.info(state.simpleLogMessage);
55+
}
56+
57+
@Benchmark
58+
public void singleCustomFieldFromArgument(BenchmarkState state) {
59+
LOG.info(state.simpleLogMessage, state.customField);
60+
}
61+
62+
@Benchmark
63+
public void singleCommonFieldFromMdc(BenchmarkState state) {
64+
MDC.put(Fields.COMPONENT_ID, state.componentId);
65+
LOG.info(state.simpleLogMessage);
66+
MDC.clear();
67+
}
68+
69+
@Benchmark
70+
public void minimalRequestRecord(BenchmarkState state) {
71+
RequestRecord requestRecord = requestRecord(state.requestLayer).addContextTag(Fields.COMPONENT_ID,
72+
state.componentId).build();
73+
requestRecord.start();
74+
requestRecord.stop();
75+
LOG.info(Markers.REQUEST_MARKER, "{}", requestRecord);
76+
}
77+
78+
}

‎cf-java-logging-support-logback/src/test/java/com/sap/hcp/cf/logback/benchmark/BenchmarkRunner.java‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
package com.sap.hcp.cf.logback.benchmark;
2+
3+
import org.openjdk.jmh.runner.Runner;
4+
import org.openjdk.jmh.runner.RunnerException;
5+
import org.openjdk.jmh.runner.options.Options;
6+
import org.openjdk.jmh.runner.options.OptionsBuilder;
7+
8+
public class BenchmarkRunner {
9+
10+
public static void main(String[] args) throws RunnerException {
11+
Options options = new OptionsBuilder().include(EncodingBenchmarks.class.getSimpleName()).forks(1).build();
12+
new Runner(options).run();
13+
}
14+
15+
}

‎cf-java-logging-support-logback/src/test/java/com/sap/hcp/cf/logback/benchmark/EncodingBenchmarks.java‎

Lines changed: 78 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,78 @@
1+
package com.sap.hcp.cf.logback.benchmark;
2+
3+
import static com.sap.hcp.cf.logging.common.request.RequestRecordBuilder.requestRecord;
4+
5+
import java.io.PrintStream;
6+
import java.util.concurrent.TimeUnit;
7+
8+
import org.openjdk.jmh.annotations.Benchmark;
9+
import org.openjdk.jmh.annotations.Measurement;
10+
import org.openjdk.jmh.annotations.Scope;
11+
import org.openjdk.jmh.annotations.Setup;
12+
import org.openjdk.jmh.annotations.State;
13+
import org.openjdk.jmh.annotations.TearDown;
14+
import org.openjdk.jmh.annotations.Warmup;
15+
import org.openjdk.jmh.util.NullOutputStream;
16+
import org.slf4j.Logger;
17+
import org.slf4j.LoggerFactory;
18+
import org.slf4j.MDC;
19+
20+
import com.sap.hcp.cf.logging.common.Fields;
21+
import com.sap.hcp.cf.logging.common.Markers;
22+
import com.sap.hcp.cf.logging.common.customfields.CustomField;
23+
import com.sap.hcp.cf.logging.common.request.RequestRecord;
24+
25+
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
26+
@Measurement(iterations = 5, time = 5, timeUnit = TimeUnit.SECONDS)
27+
public class EncodingBenchmarks {
28+
29+
public static Logger LOG = LoggerFactory.getLogger(EncodingBenchmarks.class);
30+
31+
@State(Scope.Benchmark)
32+
public static class BenchmarkState {
33+
private PrintStream out;
34+
35+
public String simpleLogMessage = "Simple message benchmark";
36+
public CustomField customField = CustomField.customField("custom of ", CustomField.class.getSimpleName());
37+
public String componentId = EncodingBenchmarks.class.getSimpleName();
38+
public String requestLayer = "benchmark";
39+
40+
@Setup
41+
public void substituteSystemOut() {
42+
out = System.out;
43+
System.setOut(new PrintStream(new NullOutputStream()));
44+
}
45+
46+
@TearDown
47+
public void resetSystemOut() {
48+
System.setOut(out);
49+
}
50+
}
51+
52+
@Benchmark
53+
public void simpleLog(BenchmarkState state) {
54+
LOG.info(state.simpleLogMessage);
55+
}
56+
57+
@Benchmark
58+
public void singleCustomFieldFromArgument(BenchmarkState state) {
59+
LOG.info(state.simpleLogMessage, state.customField);
60+
}
61+
62+
@Benchmark
63+
public void singleCommonFieldFromMdc(BenchmarkState state) {
64+
MDC.put(Fields.COMPONENT_ID, state.componentId);
65+
LOG.info(state.simpleLogMessage);
66+
MDC.clear();
67+
}
68+
69+
@Benchmark
70+
public void minimalRequestRecord(BenchmarkState state) {
71+
RequestRecord requestRecord = requestRecord(state.requestLayer).addContextTag(Fields.COMPONENT_ID,
72+
state.componentId).build();
73+
requestRecord.start();
74+
requestRecord.stop();
75+
LOG.info(Markers.REQUEST_MARKER, "{}", requestRecord);
76+
}
77+
78+
}

‎pom.xml‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -176,6 +176,7 @@
176176
<hamcrest.version>1.3</hamcrest.version>
177177
<junit.version>4.13.2</junit.version>
178178
<mockito.version>1.9.5</mockito.version>
179+
<jmh.version>1.34</jmh.version>
179180
<surefire.plugin.version>2.18.1</surefire.plugin.version>
180181
<animal.sniffer.version>1.19</animal.sniffer.version>
181182
<exec.plugin.version>1.4.0</exec.plugin.version>
@@ -221,6 +222,18 @@
221222
<version>${mockito.version}</version>
222223
<scope>test</scope>
223224
</dependency>
225+
<dependency>
226+
<groupId>org.openjdk.jmh</groupId>
227+
<artifactId>jmh-core</artifactId>
228+
<version>${jmh.version}</version>
229+
<scope>test</scope>
230+
</dependency>
231+
<dependency>
232+
<groupId>org.openjdk.jmh</groupId>
233+
<artifactId>jmh-generator-annprocess</artifactId>
234+
<version>${jmh.version}</version>
235+
<scope>test</scope>
236+
</dependency>
224237
</dependencies>
225238
<build>
226239
<plugins>

0 commit comments

Comments
 (0)