[
https://issues.apache.org/jira/browse/LOG4J2-695?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14052770#comment-14052770
]
Remko Popma edited comment on LOG4J2-695 at 7/5/14 5:30 AM:
------------------------------------------------------------
(Attached jmh-based-perf-tests.zip)
It is notoriously hard to write reliable performance tests in Java. Even
performance experts (and I don't count myself as an expert) frequenty get this
wrong and end up measuring the wrong thing.
Oracle developed a microbenchmark test harness
([JMH|http://openjdk.java.net/projects/code-tools/jmh/]) for perf testing
components that go into the JDK. It may be worthwhile spending some time
getting to know this framework. The
[samples|http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-samples/src/main/java/org/openjdk/jmh/samples/]
explain about some of the pitfalls of Java performance testing and how to use
JMH to avoid them. They also show how easy it is to write a JMH benchmark,
often it is just one line of code.
The attached project jmh-based-perf-tests.zip contains JMH benchmarks for plain
log4j-1.2, plain log4j2, and the "CustomLogger" wrappers. Build with "mvn clean
install", and then run the microbenchmark tests with
{code}
java -jar target\microbenchmarks.jar -f 3 -wi 5 -i 10 -t 4
{code}
(3 forks, 5 warmup iterations each, 10 iterations each, using 4 threads)
See {{java -jar target\microbenchmarks.jar -h}} for more options.
I originally ran with the xml config you provided, but the log file is rolled
over 50 times during a five-minute test run, which distorts the results. I
assume that in production you won't be rolling over that often. It is better to
isolate things and just to focus on logging/formatting performance. However,
you can find the results of the performance test with the original (rollover)
config in perf-results-rollover.txt in the attached jmh-based-perf-tests.zip.
The results below are for logging with a simpler config without rollover,
tested on my laptop, sorted best first (higher throughput is better, lower
latency is better).
*Multi-Threaded (4 threads) JMH-based performance test results*
{code}
Benchmark Mode Samples
Mean Mean error Units
c.c.c.p.Log4j2Benchmark.throughput thrpt 5
160382.973 24551.987 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputSimple thrpt 5
121808.233 63652.539 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputStructured thrpt 5
89620.013 46714.437 ops/s
c.c.c.p.Log4j12Benchmark.throughput thrpt 5
81830.153 5322.326 ops/s
c.c.c.p.Log4j12WrapperBenchmark.throughputStructured thrpt 5
44412.047 5901.930 ops/s
c.c.c.p.Log4j2Benchmark.latency sample 217578
25740.849 2548.098 ns/op
c.c.c.p.Log4j2WrapperBenchmark.latencySimple sample 228618
38003.574 11831.611 ns/op
c.c.c.p.Log4j2WrapperBenchmark.latencyStructured sample 195705
45559.377 15356.024 ns/op
c.c.c.p.Log4j12Benchmark.latency sample 215196
51232.195 13861.898 ns/op
c.c.c.p.Log4j12WrapperBenchmark.latencyStructured sample 250896
65532.515 550.859 ns/op
c.c.c.p.UUIDBenchmark.latencyLog4jUuidUtil sample 359825
922.007 18.170 ns/op
c.c.c.p.UUIDBenchmark.latencyJavaUtilUUID sample 268700
4483.775 195.085 ns/op
{code}
*Single-Threaded JMH-based performance test results*
{code}
Benchmark Mode Samples
Mean Mean error Units
c.c.c.p.Log4j2Benchmark.throughput thrpt 5
170001.227 50107.994 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputSimple thrpt 5
136761.907 81214.606 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputStructured thrpt 5
102187.857 83593.656 ops/s
c.c.c.p.Log4j12Benchmark.throughput thrpt 5
92241.593 11135.458 ops/s
c.c.c.p.Log4j12WrapperBenchmark.throughputStructured thrpt 5
61559.163 7287.889 ops/s
c.c.c.p.Log4j2Benchmark.latency sample 63479
4751.966 849.427 ns/op
c.c.c.p.Log4j2WrapperBenchmark.latencySimple sample 53188
8223.552 5612.158 ns/op
c.c.c.p.Log4j2WrapperBenchmark.latencyStructured sample 38511
9883.048 5002.147 ns/op
c.c.c.p.Log4j12Benchmark.latency sample 63633
10641.491 117.592 ns/op
c.c.c.p.Log4j12WrapperBenchmark.latencyStructured sample 60302
11246.100 199.815 ns/op
c.c.c.p.UUIDBenchmark.latencyLog4jUuidUtil sample 84696
543.673 38.181 ns/op
c.c.c.p.UUIDBenchmark.latencyJavaUtilUUID sample 89573
959.441 31.136 ns/op
{code}
I hope this puts your performance concerns at ease.
was (Author: [email protected]):
(Attached jmh-based-perf-tests.zip)
It is notoriously hard to write reliable performance tests in Java. Even
performance experts (and I don't count myself as an expert) frequenty get this
wrong and end up measuring the wrong thing.
Oracle developed a microbenchmark test harness
([JMH|http://openjdk.java.net/projects/code-tools/jmh/]) for perf testing
components that go into the JDK. It may be worthwhile spending some time
getting to know this framework. The
[samples|http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-samples/src/main/java/org/openjdk/jmh/samples/]
explain about some of the pitfalls of Java performance testing and how to use
JMH to avoid them. They also show how easy it is to write a JMH benchmark,
often it is just one line of code.
The attached project jmh-based-perf-tests.zip contains JMH benchmarks for plain
log4j-1.2, plain log4j2, and the "CustomLogger" wrappers. Build with "mvn clean
install", and then run the microbenchmark tests with
{code}
java -jar target\microbenchmarks.jar -f 3 -wi 5 -i 10 -t 4
{code}
(3 forks, 5 warmup iterations each, 10 iterations each, using 4 threads)
See {{java -jar target\microbenchmarks.jar -h}} for more options.
Here are the results on my laptop, sorted best first (higher throughput is
better, lower latency is better).
*Multi-Threaded (4 threads) JMH-based performance test results*
{code}
Benchmark Mode Samples
Mean Mean error Units
c.c.c.p.Log4j2Benchmark.throughput thrpt 5
142103.723 56358.442 ops/s
c.c.c.p.Log4j12Benchmark.throughput thrpt 5
115191.860 53960.209 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputSimple thrpt 5
111972.003 51625.732 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputStructured thrpt 5
86456.453 77806.782 ops/s
c.c.c.p.Log4j12WrapperBenchmark.throughputStructured thrpt 5
56052.273 12251.655 ops/s
c.c.c.p.Log4j2Benchmark.latency sample 202540
26951.188 5656.753 ns/op
c.c.c.p.Log4j12Benchmark.latency sample 198186
36928.616 9900.761 ns/op
c.c.c.p.Log4j2WrapperBenchmark.latencySimple sample 185047
37602.442 11569.643 ns/op
c.c.c.p.Log4j2WrapperBenchmark.latencyStructured sample 268385
40677.894 9849.989 ns/op
c.c.c.p.Log4j12WrapperBenchmark.latencyStructured sample 251816
69113.760 2209.075 ns/op
c.c.c.p.UUIDBenchmark.latencyLog4jUuidUtil sample 315683
1073.822 336.690 ns/op
c.c.c.p.UUIDBenchmark.latencyJavaUtilUUID sample 227920
4404.286 136.545 ns/op
{code}
*Single-Threaded JMH-based performance test results*
{code}
Benchmark Mode Samples
Mean Mean error Units
c.c.c.p.Log4j2Benchmark.throughput thrpt 5
148547.110 85071.034 ops/s
c.c.c.p.Log4j12Benchmark.throughput thrpt 5
147644.213 34498.776 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputSimple thrpt 5
129002.810 106144.506 ops/s
c.c.c.p.Log4j2WrapperBenchmark.throughputStructured thrpt 5
91164.633 70051.617 ops/s
c.c.c.p.Log4j12WrapperBenchmark.throughputStructured thrpt 5
80571.847 23159.751 ops/s
c.c.c.p.Log4j2WrapperBenchmark.latencySimple sample 46582
6266.932 2480.337 ns/op
c.c.c.p.Log4j2Benchmark.latency sample 55292
6391.395 3296.095 ns/op
c.c.c.p.Log4j2WrapperBenchmark.latencyStructured sample 65796
7844.480 2892.088 ns/op
c.c.c.p.Log4j12Benchmark.latency sample 48726
10613.015 11484.948 ns/op
c.c.c.p.Log4j12WrapperBenchmark.latencyStructured sample 51337
13120.609 3327.841 ns/op
c.c.c.p.UUIDBenchmark.latencyLog4jUuidUtil sample 80614
530.533 25.620 ns/op
c.c.c.p.UUIDBenchmark.latencyJavaUtilUUID sample 88454
964.636 20.960 ns/op
{code}
I hope this puts your performance concerns at ease.
> Custom Logger with restrictions on existing methods
> ---------------------------------------------------
>
> Key: LOG4J2-695
> URL: https://issues.apache.org/jira/browse/LOG4J2-695
> Project: Log4j 2
> Issue Type: Bug
> Components: API
> Reporter: SIBISH BASHEER
> Labels: customlogger
> Attachments: AppAsyncMain.java, CustomLogger.java, CustomLogger.java,
> complete project.zip, final code V2 7 2 2014.zip, final code custom
> logger.zip, jmh-based-perf-tests.zip, performance log4j vs log4j2.zip,
> performance log4j vs log4j2.zip, performance log4jvslog4j2 singleclass.zip,
> to Ralph performance code.zip
>
>
> I have been looking at the Custom/Extended logger discussions. But none of
> them seems to fulfil what i am looking for.
> 1) I want custom methods as below:
> {code}
> private static CustomLogger logger =
> CustomLogger.getLogger(AppAsyncMain.class);
>
> logger.info( transaction_id, app_name + event_name +
> "inside the loop" + "inside the loop of
> the sample app" +
> "success" + "looped in" + "loop_count" +
> String.valueOf(i));
> {code}
>
> log:
> {code}
> 2014-06-30 16:09:28,268 log_level="INFO" thread_name="main"
> class_name="com.custom.samplelog4j.AppAsyncMain"
> transaction_id="79ea1071-9565-405a-aa18-75d271694bf2"
> event_id="dd5c69c0-4400-41fd-8a2e-5d538d8e8c9b" app="Sample Logging SDK App"
> event_name="Sample Event" action="start of sample app" desc="start of api"
> result="success" reason="start" token="abcdefg" alias="[email protected]"
> {code}
>
> 2) I want to show warning in existing logger methods so the teams using the
> custom logger doesn't use these methods other than for testing:
> {code}
> logger.info("start of statement");
> {code}
>
> log:
> {code}
> 2014-06-30 16:12:31,065 log_level="INFO" thread_name="main"
> class_name="com.custom.samplelog4j2.AppAsyncMain" start of statement
> customlogger_warning="method not recommended for production use"
> {code}
>
> 3) Custom validations for the fields:
> {code}
> private static String validateFields(String app_name, String event_name,
> String action, String desc, Result result, String
> reason) {
> String validateStatus = "";
> if (!ValidateAppName(app_name)) {
> validateStatus = "app_name";
> } else if (!ValidateEventName(event_name)) {
> validateStatus = "event_name";
> } else if (!ValidateAction(action)) {
> validateStatus = "action";
> } else if (!ValidateDesc(desc)) {
> validateStatus = "desc";
> } else if (!ValidateReason(result, reason)) {
> validateStatus = "reason";
> }
> return validateStatus;
> }
> {code}
> Options tried:
> 1.
> * extended ExtendedLoggerWrapper
> * created the map of the Custom logger
> * This option was failing because of "writing to a closed appender"
> * Attached is the code "CustomLogger.java"
>
> 2. Modified the AbstractLogger in Trunk and added the below methods:
> {code}
> @Override
> public void info(final String message) {
> String updtMessage = message + " amexlogger_error=\"Incorrect method
> used\"";
> logIfEnabled(FQCN, Level.INFO, null, updtMessage, (Throwable) null);
> }
> public void info(final String transactionId, final String app_name, final
> String event_name, final String action, final String desc, final String
> result, final String reason, final String... moreFields) {
> String message = "transaction_id=" + transactionId + " " + "app_name="
> + app_name + " " + "event_name=" + event_name + " " + "action=" + action;
>
> logIfEnabled(FQCN, Level.INFO, null, message, (Throwable) null);
> }
> {code}
> I don't want to modify the methods inside the log4j-api.
>
> Please help me with the correct approach on how to use log4j2 for this
> usecase.
> Thanks
> Sibish
--
This message was sent by Atlassian JIRA
(v6.2#6252)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
