Repository: logging-log4j2 Updated Branches: refs/heads/master 3ee784e6b -> 5db285e10
Add benchmarks for markerfilter and mdcfilter Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/5db285e1 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/5db285e1 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/5db285e1 Branch: refs/heads/master Commit: 5db285e10389f316cb80e9a282e0f1e10f62d303 Parents: 3ee784e Author: Ralph Goers <[email protected]> Authored: Sat May 14 16:07:33 2016 -0700 Committer: Ralph Goers <[email protected]> Committed: Sat May 14 16:07:33 2016 -0700 ---------------------------------------------------------------------- log4j-perf/perf.txt | 23 +++++ .../log4j/perf/jmh/MDCFilterBenchmark.java | 80 +++++++++++++++ .../log4j/perf/jmh/MarkerFilterBenchmark.java | 98 +++++++++++++++++++ .../main/resources/log4j2-markerFilter-perf.xml | 31 ++++++ .../log4j2-threadContextFilter-perf.xml | 33 +++++++ .../resources/logback-markerFilter-perf.xml | 33 +++++++ .../main/resources/logback-mdcFilter-perf.xml | 34 +++++++ src/site/resources/images/MDCFilters.png | Bin 0 -> 29207 bytes src/site/resources/images/MarkerFilters.png | Bin 0 -> 31089 bytes src/site/xdoc/performance.xml | 75 ++++---------- 10 files changed, 350 insertions(+), 57 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/log4j-perf/perf.txt ---------------------------------------------------------------------- diff --git a/log4j-perf/perf.txt b/log4j-perf/perf.txt new file mode 100644 index 0000000..a558bb4 --- /dev/null +++ b/log4j-perf/perf.txt @@ -0,0 +1,23 @@ +# VM invoker: /Library/Java/JavaVirtualMachines/jdk1.7.0_80.jdk/Contents/Home/jre/bin/java +# VM options: <none> +# Warmup: 5 iterations, 1 s each +# Measurement: 5 iterations, 1 s each +# Timeout: 10 min per iteration +# Threads: 1 thread, will synchronize iterations +# Benchmark mode: Sampling time +# Benchmark: org.apache.logging.log4j.perf.jmh.MDCFilterBenchmark.baseline + +# Run progress: 0.00% complete, ETA 00:00:30 +# Fork: 1 of 1 +# Warmup Iteration 1: 12:58:43,899 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback-mdcFilter-perf.xml] at [jar:file:/Users/rgoers/projects/apache/logging/log4j/log4j2/logging-log4j2/log4j-perf/target/benchmarks.jar!/logback-mdcFilter-perf.xml] +12:58:43,920 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@74a40c91 - URL [jar:file:/Users/rgoers/projects/apache/logging/log4j/log4j2/logging-log4j2/log4j-perf/target/benchmarks.jar!/logback-mdcFilter-perf.xml] is not of type file +12:58:43,955 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set +12:58:43,976 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@23:17 - no applicable action for [onMisMatch], current ElementPath is [[configuration][turboFilter][onMisMatch]] +12:58:43,976 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] +12:58:43,978 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] +12:58:43,979 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property +12:58:44,003 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG +12:58:44,004 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT] +12:58:44,004 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. +12:58:44,006 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@3e353f6a - Registering current configuration as safe fallback point + http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MDCFilterBenchmark.java ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MDCFilterBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MDCFilterBenchmark.java new file mode 100644 index 0000000..ae264ce --- /dev/null +++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MDCFilterBenchmark.java @@ -0,0 +1,80 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache license, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the license for the specific language governing permissions and + * limitations under the license. + */ + +package org.apache.logging.log4j.perf.jmh; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.ThreadContext; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.Setup; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.TearDown; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +/** + * Benchmarks Log4j 2 and Logback ThreadContext/MDC Filter performance. + */ +// HOW TO RUN THIS TEST +// single thread: +// java -jar target/benchmarks.jar ".*MDCFilterBenchmark.*" -f 1 -i 5 -wi 5 -bm sample -tu ns +// +// multiple threads (for example, 4 threads): +// java -jar target/benchmarks.jar ".*MDCFilterBenchmark.*" -f 1 -i 5 -wi 5 -t 4 -si true -bm sample -tu ns + +@State(Scope.Thread) +public class MDCFilterBenchmark { + Logger log4jLogger; + org.slf4j.Logger slf4jLogger; + Integer j; + + @Setup + public void setUp() { + System.setProperty("log4j.configurationFile", "log4j2-threadContextFilter-perf.xml"); + System.setProperty("logback.configurationFile", "logback-mdcFilter-perf.xml"); + ThreadContext.put("user", "Apache"); + MDC.put("user", "Apache"); + + log4jLogger = LogManager.getLogger(MDCFilterBenchmark.class); + slf4jLogger = LoggerFactory.getLogger(MDCFilterBenchmark.class); + j = Integer.valueOf(2); + } + + @TearDown + public void tearDown() { + System.clearProperty("log4j.configurationFile"); + System.clearProperty("logback.configurationFile"); + } + + @Benchmark + public boolean baseline() { + return true; + } + + @Benchmark + public void log4jThreadContextFilter() { + log4jLogger.info("This is a test"); + } + + @Benchmark + public void slf4jMDCFilter() { + slf4jLogger.info("This is a test"); + } + +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MarkerFilterBenchmark.java ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MarkerFilterBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MarkerFilterBenchmark.java new file mode 100644 index 0000000..fc102ea --- /dev/null +++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/MarkerFilterBenchmark.java @@ -0,0 +1,98 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache license, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the license for the specific language governing permissions and + * limitations under the license. + */ + +package org.apache.logging.log4j.perf.jmh; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.Marker; +import org.apache.logging.log4j.MarkerManager; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.Setup; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.TearDown; +import org.slf4j.LoggerFactory; +import org.slf4j.MarkerFactory; + +/** + * Benchmarks Log4j 2 and Logback using a global MarkerFilter which will not be matched for this test. The Marker + * provided will have a + */ +// HOW TO RUN THIS TEST +// single thread: +// java -jar target/benchmarks.jar ".*MarkerFilterBenchmark.*" -f 1 -i 5 -wi 5 -bm sample -tu ns +// multiple threads (for example, 4 threads): +// java -jar target/benchmarks.jar ".*MarkerFilterBenchmark.*" -f 1 -i 5 -wi 5 -t 4 -si true -bm sample -tu ns +@State(Scope.Thread) +public class MarkerFilterBenchmark { + Logger log4jLogger; + org.slf4j.Logger slf4jLogger; + Integer j; + org.slf4j.Marker LOGBACK_FLOW_MARKER; + org.slf4j.Marker LOGBACK_ENTRY_MARKER; + Marker LOG4J_FLOW_MARKER; + Marker LOG4J_ENTRY_MARKER; + + @Setup + public void setUp() { + System.setProperty("log4j.configurationFile", "log4j2-markerFilter-perf.xml"); + System.setProperty("logback.configurationFile", "logback-markerFilter-perf.xml"); + LOGBACK_FLOW_MARKER = MarkerFactory.getMarker("FLOW"); + LOGBACK_ENTRY_MARKER = MarkerFactory.getMarker("ENTRY"); + LOG4J_FLOW_MARKER = MarkerManager.getMarker("FLOW"); + LOG4J_ENTRY_MARKER = MarkerManager.getMarker("ENTRY"); + LOGBACK_ENTRY_MARKER.add(LOGBACK_FLOW_MARKER); + LOG4J_ENTRY_MARKER.addParents(LOG4J_FLOW_MARKER); + log4jLogger = LogManager.getLogger(MarkerFilterBenchmark.class); + slf4jLogger = LoggerFactory.getLogger(MarkerFilterBenchmark.class);; + j = Integer.valueOf(2); + } + + @TearDown + public void tearDown() { + System.clearProperty("log4j.configurationFile"); + System.clearProperty("log4j.configuration"); + System.clearProperty("logback.configurationFile"); + } + + @Benchmark + public boolean baseline() { + return true; + } + + @Benchmark + public void log4jParentMarker() { + log4jLogger.info(LOG4J_ENTRY_MARKER, "This is a test"); + } + + + @Benchmark + public void log4jSimpleMarker() { + log4jLogger.info(LOG4J_FLOW_MARKER, "This is a test"); + } + + @Benchmark + public void logbackParentMarker() { + slf4jLogger.info(LOGBACK_ENTRY_MARKER, "This is a test"); + } + + @Benchmark + public void logbackSimpleMarker() { + slf4jLogger.info(LOGBACK_FLOW_MARKER, "This is a test"); + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/log4j-perf/src/main/resources/log4j2-markerFilter-perf.xml ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/resources/log4j2-markerFilter-perf.xml b/log4j-perf/src/main/resources/log4j2-markerFilter-perf.xml new file mode 100644 index 0000000..1110c02 --- /dev/null +++ b/log4j-perf/src/main/resources/log4j2-markerFilter-perf.xml @@ -0,0 +1,31 @@ +<?xml version="1.0" encoding="UTF-8"?> +<!-- + Licensed to the Apache Software Foundation (ASF) under one or more + contributor license agreements. See the NOTICE file distributed with + this work for additional information regarding copyright ownership. + The ASF licenses this file to You under the Apache License, Version 2.0 + (the "License"); you may not use this file except in compliance with + the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + +--> +<Configuration name="XMLPerfTest" status="error"> + <MarkerFilter marker="TestMarker" onMatch="NEUTRAL" onMismatch="DENY"/> + <Appenders> + <Console name="STDOUT"> + <PatternLayout pattern="%m%n"/> + </Console> + </Appenders> + <Loggers> + <Root level="debug"> + <AppenderRef ref="STDOUT"/> + </Root> + </Loggers> +</Configuration> \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/log4j-perf/src/main/resources/log4j2-threadContextFilter-perf.xml ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/resources/log4j2-threadContextFilter-perf.xml b/log4j-perf/src/main/resources/log4j2-threadContextFilter-perf.xml new file mode 100644 index 0000000..e38f56f --- /dev/null +++ b/log4j-perf/src/main/resources/log4j2-threadContextFilter-perf.xml @@ -0,0 +1,33 @@ +<?xml version="1.0" encoding="UTF-8"?> +<!-- + Licensed to the Apache Software Foundation (ASF) under one or more + contributor license agreements. See the NOTICE file distributed with + this work for additional information regarding copyright ownership. + The ASF licenses this file to You under the Apache License, Version 2.0 + (the "License"); you may not use this file except in compliance with + the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + +--> +<Configuration name="XMLPerfTest" status="error"> + <ThreadContextMapFilter onMatch="ACCEPT" onMismatch="DENY"> + <KeyValuePair key="User" value="JDoe"/> + </ThreadContextMapFilter> + <Appenders> + <Console name="STDOUT"> + <PatternLayout pattern="user=%X{user} %m%n"/> + </Console> + </Appenders> + <Loggers> + <Root level="debug"> + <AppenderRef ref="STDOUT"/> + </Root> + </Loggers> +</Configuration> \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/log4j-perf/src/main/resources/logback-markerFilter-perf.xml ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/resources/logback-markerFilter-perf.xml b/log4j-perf/src/main/resources/logback-markerFilter-perf.xml new file mode 100644 index 0000000..c6a88ab --- /dev/null +++ b/log4j-perf/src/main/resources/logback-markerFilter-perf.xml @@ -0,0 +1,33 @@ +<!-- + Licensed to the Apache Software Foundation (ASF) under one or more + contributor license agreements. See the NOTICE file distributed with + this work for additional information regarding copyright ownership. + The ASF licenses this file to You under the Apache License, Version 2.0 + (the "License"); you may not use this file except in compliance with + the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + +--> +<configuration> + <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter"> + <Marker>TestMarker</Marker> + <OnMatch>NEUTRAL</OnMatch> + <OnMismatch>DENY</OnMismatch> + </turboFilter> + <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> + <encoder> + <pattern>%msg %n</pattern> + </encoder> + </appender> + + <root level="debug"> + <appender-ref ref="STDOUT" /> + </root> +</configuration> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/log4j-perf/src/main/resources/logback-mdcFilter-perf.xml ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/resources/logback-mdcFilter-perf.xml b/log4j-perf/src/main/resources/logback-mdcFilter-perf.xml new file mode 100644 index 0000000..a0f09f3 --- /dev/null +++ b/log4j-perf/src/main/resources/logback-mdcFilter-perf.xml @@ -0,0 +1,34 @@ +<!-- + Licensed to the Apache Software Foundation (ASF) under one or more + contributor license agreements. See the NOTICE file distributed with + this work for additional information regarding copyright ownership. + The ASF licenses this file to You under the Apache License, Version 2.0 + (the "License"); you may not use this file except in compliance with + the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + +--> +<configuration> + <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter"> + <MDCKey>user</MDCKey> + <Value>JDoe</Value> + <OnMatch>ACCEPT</OnMatch> + <onMismatch>DENY</onMismatch> + </turboFilter> + <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> + <encoder> + <pattern>user=%X{user} %msg %n</pattern> + </encoder> + </appender> + + <root level="debug"> + <appender-ref ref="STDOUT" /> + </root> +</configuration> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/src/site/resources/images/MDCFilters.png ---------------------------------------------------------------------- diff --git a/src/site/resources/images/MDCFilters.png b/src/site/resources/images/MDCFilters.png new file mode 100644 index 0000000..36c1e8c Binary files /dev/null and b/src/site/resources/images/MDCFilters.png differ http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/src/site/resources/images/MarkerFilters.png ---------------------------------------------------------------------- diff --git a/src/site/resources/images/MarkerFilters.png b/src/site/resources/images/MarkerFilters.png new file mode 100644 index 0000000..11be2c2 Binary files /dev/null and b/src/site/resources/images/MarkerFilters.png differ http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/5db285e1/src/site/xdoc/performance.xml ---------------------------------------------------------------------- diff --git a/src/site/xdoc/performance.xml b/src/site/xdoc/performance.xml index a03edaa..35dfa5f 100644 --- a/src/site/xdoc/performance.xml +++ b/src/site/xdoc/performance.xml @@ -264,6 +264,23 @@ TODO <h4>Synchronous Socket Sustained Throughput Comparison</h4> <h4>Synchronous Syslog Sustained Throughput Comparison</h4> --> + <h4>Advanced Filtering</h4> + <p> + Both Logback and Log4j 2 support advanced filtering. Logback calls them TurboFilters while + Log4j 2 has a single Filter object. Advanced filtering provides the capability to filter + LogEvents using more than just the Level before the events are passed to Appenders. + However, this flexibility does come with some cost. Since multi-threading can also have an impact on the + performance of advanced filtering, the chart below shows the difference in performance of filtering based + on a value in the Log4j ThreadContext vs filtering in Logback on a value in the MDC. + </p><p><img src="images/MDCFilters.png" /></p> + <p>Log4j and Logback also support filtering on a Marker or a Marker's parent. It should be pointed out that + the poor performance of Logback's Marker filter is not due to a problem in Logback but in SLF4J. See + <a href="http://jira.qos.ch/browse/SLF4J-240";>SLF4J-240.</a>. The "simple" comparison checks to see if a Marker + that has no references to other markers matches the requested Marker. The "parent" comparison checks to see + if a Marker that does have references to other markers matches. </p> + <p><img src="images/MarkerFilters.png" /></p> + <p>See the MarkerFilterBenchmark and MDCFilterBenchmark in the log4j-perf module for details on these + benchmarks.</p> <a name="tradeoffs" /> <h3>Trade-offs</h3> <a name="whichAppender" /> @@ -403,63 +420,7 @@ TODO Log4j 2's fine-grained filtering capabilities. </p> --> - <h4>Advanced Filtering</h4> - <p> - Both Logback and Log4j 2 support advanced filtering. Logback calls them TurboFilters while - Log4j 2 has a single Filter object. Advanced filtering provides the capability to filter - LogEvents using more than just the Level before the events are passed to Appenders. - However, this flexibility does come with some cost. Since multi-threading can also have an impact on the - performance of advanced filtering, the table below shows the difference in performance in two different - sets of context-wide filters running on the same hardware as the previous tests using - various numbers of threads. - </p> - <table> - <tr> - <th>Test</th> - <th>1 thread</th> - <th>2 threads</th> - <th>5 threads</th> - <th>10 threads</th> - <th>20 threads</th> - <th>50 threads</th> - </tr> - <tr> - <td>Logback MDCFilter</td> - <td>37</td> - <td>50</td> - <td>145</td> - <td>316</td> - <td>606</td> - <td>1670</td> - </tr> - <tr> - <td>Log4j 2 ThreadContextMapFilter</td> - <td>30</td> - <td>35</td> - <td>85</td> - <td>165</td> - <td>341</td> - <td>864</td> - </tr> - <tr> - <td>Logback MarkerFilter</td> - <td>17</td> - <td>24</td> - <td>59</td> - <td>115</td> - <td>234</td> - <td>547</td> - </tr> - <tr> - <td>Log4j 2 MarkerFilter</td> - <td>4</td> - <td>5</td> - <td>7</td> - <td>20</td> - <td>35</td> - <td>92</td> - </tr> - </table> + <h4>Client vs Server</h4> <p>
