[
https://issues.apache.org/jira/browse/LOG4J2-1096?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14704121#comment-14704121
]
Gary Gregory commented on LOG4J2-1096:
--------------------------------------
Thank you Remko :-)
Here are my results with Windows 7, Java 1.8.0_51 64-bit, Intel Core i7-2760QM
CPU (4 cores, 8 threads) @ 2.40GHz.
{noformat}
>java -jar log4j-perf/target/benchmarks.jar ".*ParameterizedMessage.*" -f 1 -wi
>5 -i 10
# VM invoker: C:\Program Files\Java\jre1.8.0_51\bin\java.exe
# VM options: <none>
# Warmup: 5 iterations, 1 s each
# Measurement: 10 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.ParameterizedMessageBenchmark.format
# Run progress: 0.00% complete, ETA 00:00:45
# Fork: 1 of 1
# Warmup Iteration 1: n = 29141, mean = 659 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 857, 2140, 9347, 123203, 1236992
ns/op
# Warmup Iteration 2: n = 14657, mean = 605 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 857, 2140, 6137, 47178, 57344 ns/op
# Warmup Iteration 3: n = 17023, mean = 536 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1284, 4142, 6848 ns/op
# Warmup Iteration 4: n = 14772, mean = 623 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 857, 2568, 3852, 87124, 157696 ns/op
# Warmup Iteration 5: n = 17201, mean = 532 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1284, 10867, 12400 ns/op
Iteration 1: n = 17200, mean = 533 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1284, 4824, 12832 ns/op
Iteration 2: n = 17280, mean = 527 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1164, 2684, 2996 ns/op
Iteration 3: n = 17230, mean = 532 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1185, 11143, 14544 ns/op
Iteration 4: n = 17158, mean = 533 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1284, 8801, 9408 ns/op
Iteration 5: n = 17127, mean = 537 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1712, 14502, 21824 ns/op
Iteration 6: n = 16913, mean = 547 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 1284, 1321, 20879, 35072 ns/op
Iteration 7: n = 17285, mean = 528 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1162, 13791, 20960 ns/op
Iteration 8: n = 17224, mean = 532 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1284, 6365, 10688 ns/op
Iteration 9: n = 16861, mean = 551 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1284, 42182, 127872 ns/op
Iteration 10: n = 17113, mean = 536 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1712, 8815, 11552 ns/op
Result: 535.532 ▒(99.9%) 3.141 ns/op [Average]
Statistics: (min, avg, max) = (428.000, 535.532, 127872.000), stdev = 395.122
Confidence interval (99.9%): [532.392, 538.673]
Samples, N = 171391
mean = 535.532 ▒(99.9%) 3.141 ns/op
min = 428.000 ns/op
p( 0.0000) = 428.000 ns/op
p(50.0000) = 428.000 ns/op
p(90.0000) = 856.000 ns/op
p(95.0000) = 856.000 ns/op
p(99.0000) = 857.000 ns/op
p(99.9000) = 1284.000 ns/op
p(99.9900) = 9408.000 ns/op
p(99.9990) = 61620.224 ns/op
p(99.9999) = 127872.000 ns/op
max = 127872.000 ns/op
# VM invoker: C:\Program Files\Java\jre1.8.0_51\bin\java.exe
# VM options: <none>
# Warmup: 5 iterations, 1 s each
# Measurement: 10 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.ParameterizedMessageBenchmark.format0
# Run progress: 33.33% complete, ETA 00:00:37
# Fork: 1 of 1
# Warmup Iteration 1: n = 20516, mean = 578 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 856, 2140, 35057, 141699, 917504 ns/op
# Warmup Iteration 2: n = 11684, mean = 401 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1284, 31325, 35072 ns/op
# Warmup Iteration 3: n = 11660, mean = 399 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 857, 19469, 22240 ns/op
# Warmup Iteration 4: n = 11648, mean = 398 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1284, 32143, 36800 ns/op
# Warmup Iteration 5: n = 11652, mean = 415 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1284, 39508, 40640 ns/op
Iteration 1: n = 11647, mean = 398 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 857, 16789, 19680 ns/op
Iteration 2: n = 11604, mean = 404 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1284, 16821, 18400 ns/op
Iteration 3: n = 11638, mean = 400 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 857, 9198, 9408 ns/op
Iteration 4: n = 11606, mean = 402 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1025, 8015, 8976 ns/op
Iteration 5: n = 11606, mean = 402 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 857, 4074, 4280 ns/op
Iteration 6: n = 11559, mean = 404 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1712, 7206, 7272 ns/op
Iteration 7: n = 11560, mean = 400 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 857, 5026, 5560 ns/op
Iteration 8: n = 11607, mean = 404 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1712, 14100, 15408 ns/op
Iteration 9: n = 11605, mean = 400 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1284, 2499, 2568 ns/op
Iteration 10: n = 11632, mean = 403 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 857, 6644, 7272 ns/op
Result: 401.849 ▒(99.9%) 1.740 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 401.849, 19680.000), stdev = 180.145
Confidence interval (99.9%): [400.109, 403.589]
Samples, N = 116064
mean = 401.849 ▒(99.9%) 1.740 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 428.000 ns/op
p(90.0000) = 428.000 ns/op
p(95.0000) = 429.000 ns/op
p(99.0000) = 856.000 ns/op
p(99.9000) = 857.000 ns/op
p(99.9900) = 7014.844 ns/op
p(99.9990) = 19474.368 ns/op
p(99.9999) = 19680.000 ns/op
max = 19680.000 ns/op
# VM invoker: C:\Program Files\Java\jre1.8.0_51\bin\java.exe
# VM options: <none>
# Warmup: 5 iterations, 1 s each
# Measurement: 10 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.ParameterizedMessageBenchmark.format0_inlined2
# Run progress: 66.67% complete, ETA 00:00:18
# Fork: 1 of 1
# Warmup Iteration 1: n = 29541, mean = 328 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 1284, 10463, 76896, 109056 ns/op
# Warmup Iteration 2: n = 15562, mean = 290 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 1284, 10495, 12400 ns/op
# Warmup Iteration 3: n = 17049, mean = 285 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 2266, 2568 ns/op
# Warmup Iteration 4: n = 17077, mean = 285 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 2889, 4704 ns/op
# Warmup Iteration 5: n = 17078, mean = 285 ns/op, p{0.00, 0.50, 0.90, 0.95,
0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 1837, 2140 ns/op
Iteration 1: n = 16678, mean = 299 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 75317, 219904 ns/op
Iteration 2: n = 17114, mean = 284 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 2140, 2140 ns/op
Iteration 3: n = 17125, mean = 284 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 3493, 6848 ns/op
Iteration 4: n = 16941, mean = 287 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 1415, 1712 ns/op
Iteration 5: n = 17027, mean = 291 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 21681, 46656 ns/op
Iteration 6: n = 17074, mean = 288 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 429, 6154, 10688 ns/op
Iteration 7: n = 17010, mean = 293 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 42421, 49600 ns/op
Iteration 8: n = 16859, mean = 293 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 856, 2678, 3852 ns/op
Iteration 9: n = 11594, mean = 323 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 856, 857, 11037, 12400 ns/op
Iteration 10: n = 16826, mean = 290 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99,
0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 857, 14655, 15824 ns/op
Result: 292.084 ▒(99.9%) 4.996 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 292.084, 219904.000), stdev = 615.263
Confidence interval (99.9%): [287.088, 297.079]
Samples, N = 164248
mean = 292.084 ▒(99.9%) 4.996 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 428.000 ns/op
p(90.0000) = 428.000 ns/op
p(95.0000) = 428.000 ns/op
p(99.0000) = 429.000 ns/op
p(99.9000) = 856.000 ns/op
p(99.9900) = 3670.143 ns/op
p(99.9990) = 110485.383 ns/op
p(99.9999) = 219904.000 ns/op
max = 219904.000 ns/op
# Run complete. Total time: 00:00:56
Benchmark Mode Samples
Score Error Units
o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 171391
535.532 ▒ 3.141 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 116064
401.849 ▒ 1.740 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inlined2 sample 164248
292.084 ▒ 4.996 ns/op
{noformat}
> Performance improvement for PatternMessage.format
> -------------------------------------------------
>
> Key: LOG4J2-1096
> URL: https://issues.apache.org/jira/browse/LOG4J2-1096
> Project: Log4j 2
> Issue Type: Improvement
> Components: API, Layouts
> Affects Versions: 2.3
> Reporter: Remko Popma
> Assignee: Remko Popma
> Fix For: 2.4
>
> Attachments: sync_log_jvisualvm_profiler.png
>
>
> Doing some profiling for log4j2 synchronous logging I found that the
> PatternConverters are hot methods. Improving these should have large impact
> on logging performance.
> At the top of the list was {{ParameterizedMessage.format}}.
> !sync_log_jvisualvm_profiler.png!
> I experimented a little and got a nice improvement by using a char[] array
> instead of a StringBuilder in this method. Explanation of the below benchmark
> results:
> * format = current master: StringBuilder based code
> * format0 = use char[] array instead of StringBuilder
> * format0_inline = format0 + refactor to call small methods
> * format0_inline2 = format0_inline + avoid index check inside loop
> * format0_inline3 = refactored format0_inline2 to make all methods 35 byte
> codes or less (not very readable any more...)
> {noformat}
> Windows:
> Benchmark Mode Samples
> Score Error Units
> o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 122654
> 27.628 ± 0.894 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 130088
> 364.905 ± 20.410 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 121087
> 188.281 ± 1.772 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 123966
> 195.806 ± 23.696 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 128577
> 186.900 ± 1.724 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 124877
> 190.462 ± 2.061 ns/op
> Linux
> Benchmark Mode Samples
> Score Error Units
> o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 2934379
> 30.959 ± 0.035 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 2630377
> 361.414 ± 1.960 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 2030686
> 240.816 ± 2.143 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 2296404
> 221.649 ± 4.264 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 2113582
> 234.008 ± 1.939 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 3618971
> 270.600 ± 3.689 ns/op
> {noformat}
> Code (sorry, I will move this into a benchmark in git when I get home):
> {code}
> public static String format0_inlined2(final String messagePattern,
> final String[] arguments) {
> int len = 0;
> if (messagePattern == null || (len = messagePattern.length()) == 0
> || arguments == null || arguments.length == 0) {
> return messagePattern;
> }
> return format0_inlined22(messagePattern, len, arguments);
> }
> private static String format0_inlined22(final String messagePattern,
> final int len, final String[] arguments) {
> final char[] result = new char[len + totalLength(arguments)];
> int pos = 0;
> int escapeCounter = 0;
> int currentArgument = 0;
> int i = 0;
> for (; i < len - 1; i++) {
> final char curChar = messagePattern.charAt(i);
> if (curChar == ESCAPE_CHAR) {
> escapeCounter++;
> } else {
> if (isDelimPair(messagePattern, i, curChar)) {
> i++;
> // write escaped escape chars
> pos = format0_writeEscapedEscapeChars(escapeCounter,
> result, pos);
> if (isEscapeCounterOdd(escapeCounter)) {
> // i.e. escaped
> // write escaped escape chars
> pos = format0_writeDelimPair(result, pos);
> } else {
> // unescaped
> pos = format0_appendArg(arguments, currentArgument,
> result, pos);
> currentArgument++;
> }
> } else {
> pos = format0_handleLiteralChar(result, pos, escapeCounter,
> curChar);
> }
> escapeCounter = 0;
> }
> }
> pos = format0_handleMaybeLastChar(messagePattern, len, result, pos,
> escapeCounter, i);
> return new String(result, 0, pos);
> }
> // 27 bytes
> private static int totalLength(String[] arguments) {
> int result = 0;
> for (int i = 0; i < arguments.length; i++) {
> result += arguments[i].length();
> }
> return result;
> }
> // 22 bytes
> private static boolean isDelimPair(final String messagePattern, int i,
> final char curChar) {
> return curChar == DELIM_START
> && messagePattern.charAt(i + 1) == DELIM_STOP;
> }
> private static int format0_handleMaybeLastChar(final String messagePattern,
> final int len, final char[] result, int pos, int escapeCounter,
> int i) {
> if (i == len - 1) {
> final char curChar = messagePattern.charAt(i);
> pos = format0_handleLastChar(result, pos, escapeCounter, curChar);
> }
> return pos;
> }
> private static int format0_handleLastChar(final char[] result, int pos,
> int escapeCounter, final char curChar) {
> if (curChar == ESCAPE_CHAR) {
> pos = format0_writeUnescapedEscapeChars(escapeCounter + 1, result,
> pos);
> } else {
> pos = format0_handleLiteralChar(result, pos, escapeCounter, curChar);
> }
> return pos;
> }
> private static int format0_handleLiteralChar(final char[] result, int pos,
> int escapeCounter, final char curChar) {
> // any other char beside ESCAPE or DELIM_START/STOP-combo
> // write unescaped escape chars
> pos = format0_writeUnescapedEscapeChars(escapeCounter, result, pos);
> result[pos++] = curChar;
> return pos;
> }
> private static int format0_writeDelimPair(final char[] result, int pos) {
> result[pos++] = DELIM_START;
> result[pos++] = DELIM_STOP;
> return pos;
> }
> private static boolean isEscapeCounterOdd(int escapeCounter) {
> return (escapeCounter & 1) == 1;
> }
> private static int format0_writeEscapedEscapeChars(int escapeCounter,
> char[] result, int pos) {
> final int escapedEscapes = escapeCounter >> 1; // divide by two
> return format0_writeUnescapedEscapeChars(escapedEscapes, result, pos);
> }
> private static int format0_writeUnescapedEscapeChars(int escapeCounter,
> char[] result, int pos) {
> while (escapeCounter > 0) {
> result[pos++] = ESCAPE_CHAR;
> escapeCounter--;
> }
> return pos;
> }
> private static int format0_appendArg(final String[] arguments,
> int currentArgument, final char[] result, int pos) {
> if (currentArgument < arguments.length) {
> pos = format0_appendArg0(arguments, currentArgument, result, pos);
> } else {
> pos = format0_writeDelimPair(result, pos);
> }
> return pos;
> }
> private static int format0_appendArg0(final String[] arguments,
> int currentArgument, final char[] result, int pos) {
> final String arg = arguments[currentArgument];
> final int argLen = arg.length();
> arg.getChars(0, argLen, result, pos);
> return pos + argLen;
> }
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
