[
https://issues.apache.org/jira/browse/LOG4J2-250?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14003309#comment-14003309
]
Remko Popma commented on LOG4J2-250:
------------------------------------
I did some research to see if it is worth making the proposed change. It turns
out that the performance difference between constructing a Log4jLogEvent with
or without an exception is quite dramatic.
Here are the latency numbers generated by JMH:
{code}
Benchmark Mode Thr Count Sec Mean Mean
error Units
o.s.MyBenchmark.testBaseline sample 1 6703951 1 22.780
0.741 ns/op
o.s.MyBenchmark.testException sample 1 188867 1 26455.008
116.268 ns/op
o.s.MyBenchmark.testNoException sample 1 5457363 1 130.162
10.459 ns/op
{code}
Constructing a Log4jLogEvent with a null exception costs 130 nanoseconds. With
non-null exception this becomes 26,455 nanoseconds. A 200x difference.
Throughput numbers:
{code}
Benchmark Mode Thr Count Sec Mean Mean
error Units
o.s.MyBenchmark.testBaseline thrpt 1 5 1 2385314.189
185910.970 ops/ms
o.s.MyBenchmark.testException thrpt 1 5 1 35.390
3.086 ops/ms
o.s.MyBenchmark.testNoException thrpt 1 5 1 10441.802
621.190 ops/ms
{code}
Here is the microbenchmark code:
{code}
package org.sample;
import org.openjdk.jmh.annotations.GenerateMicroBenchmark;
import org.openjdk.jmh.logic.BlackHole;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.SimpleMessage;
public class MyBenchmark {
private static final Message MESSAGE = new SimpleMessage("Test message");
private static final Throwable ERROR = new Exception("test");
@GenerateMicroBenchmark
public void testBaseline(BlackHole bh) {
}
@GenerateMicroBenchmark
public void testNoException(BlackHole bh) {
Throwable t = null;
Log4jLogEvent event = new Log4jLogEvent("a.b.c", null, "a.b.c",
Level.INFO, MESSAGE, t);
bh.consume(event);
}
@GenerateMicroBenchmark
public void testException(BlackHole bh) {
Throwable t = ERROR;
Log4jLogEvent event = new Log4jLogEvent("a.b.c", null, "a.b.c",
Level.INFO, MESSAGE, t);
bh.consume(event);
}
}
{code}
The command to run the latency test:
{code}
java -jar microbenchmarks.jar ".*MyBenchmark.*" -i 5 -f 1 -wi 5 -bm sample -tu
ns
{code}
The command to run the throughput test:
{code}
java -jar microbenchmarks.jar ".*MyBenchmark.*" -i 5 -f 1 -wi 5 -bm Throughput
-tu ms
{code}
To set up for the above test, first follow the *Basic Usage* instructions from
the JMH page: http://openjdk.java.net/projects/code-tools/jmh/
Then replace the generated test/pom.xml with the pom.xml below:
{code}
<?xml version="1.0"?>
<project xsi:schemaLocation="http://maven.apache.org/POM/4.0.0
http://maven.apache.org/xsd/maven-4.0.0.xsd";
xmlns="http://maven.apache.org/POM/4.0.0";
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance";>
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-parent</artifactId>
<version>1.0-SNAPSHOT</version>
</parent>
<groupId>org.sample</groupId>
<artifactId>test</artifactId>
<version>1.0</version>
<name>Auto-generated JMH benchmark</name>
<properties>
<slf4j.version>1.7.5</slf4j.version>
<logback.version>1.0.13</logback.version>
<log4j2.version>2.0-rc1</log4j2.version>
<maven.compile.source>1.6</maven.compile.source>
<maven.compile.target>1.6</maven.compile.target>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
</properties>
<dependencies>
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-core</artifactId>
<version>1.0-SNAPSHOT</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>${slf4j.version}</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-ext</artifactId>
<version>${slf4j.version}</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-core</artifactId>
<version>${logback.version}</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>${logback.version}</version>
</dependency>
<dependency>
<groupId>log4j</groupId>
<artifactId>log4j</artifactId>
<version>1.2.17</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>${log4j2.version}</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>${log4j2.version}</version>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<artifactId>maven-compiler-plugin</artifactId>
<version>3.0</version>
<configuration>
<compilerVersion>1.6</compilerVersion>
<source>1.6</source>
<target>1.6</target>
</configuration>
</plugin>
<plugin>
<artifactId>maven-shade-plugin</artifactId>
<version>2.0</version>
<executions>
<execution>
<phase>package</phase>
<goals>
<goal>shade</goal>
</goals>
<configuration>
<finalName>microbenchmarks</finalName>
<transformers>
<transformer
implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
<mainClass>org.openjdk.jmh.Main</mainClass>
</transformer>
</transformers>
</configuration>
</execution>
</executions>
</plugin>
</plugins>
</build>
</project>
{code}
> (TBD) Refactor Log4jLogEvent to lazily create ThrowableProxy
> ------------------------------------------------------------
>
> Key: LOG4J2-250
> URL: https://issues.apache.org/jira/browse/LOG4J2-250
> Project: Log4j 2
> Issue Type: Improvement
> Components: Core
> Affects Versions: 2.0-beta5
> Reporter: Remko Popma
>
> Background: during investigation of LOG4J2-245, several people raised
> performance concerns regarding ThrowableProxy. This issue is to separate that
> concern so that LOG4J2-245 can focus on resolving the EmptyStackException.
> ThrowableProxy does quite a bit of expensive-looking work to find the JAR
> file or directory where the class that threw the exception is located. This
> work is done for every event that contains an exception.
> However, this information is only used when the configuration contains either
> a RootThrowablePattern {"rEx", "rThrowable", "rException" } or an
> ExtendedThrowablePattern {"xEx", "xThrowable", "xException" } or when the
> LogEvent is serialized.
> I propose to change the Log4jLogEvent implementation: instead of
> unconditionally creating a ThrowableProxy object every time a log event
> contains an exception, only wrap this exception in a ThrowableProxy when
> either:
> * the {{getThrownProxy()}} method is called
> * the log event is serialized
> For reference, similar work has already been done on
> {{o.a.l.l.core.async.RingBufferLogEvent}}.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
