You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Gary Gregory (JIRA)" <ji...@apache.org> on 2015/08/20 05:09:45 UTC
[jira] [Commented] (LOG4J2-1097) [Perf] Custom TimeFormat
[ https://issues.apache.org/jira/browse/LOG4J2-1097?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14704227#comment-14704227 ]
Gary Gregory commented on LOG4J2-1097:
--------------------------------------
Here are the results on my PC (i7, Windows 7, 64-bit java 1.8.0_51):
{noformat}
>java -jar log4j-perf/target/benchmarks.jar ".*TimeFormat.*" -f 1 -wi 5 -i 5
# VM invoker: C:\Program Files\Java\jre1.8.0_51\bin\java.exe
# 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.TimeFormatBenchmark.baseline
# Run progress: 0.00% complete, ETA 00:01:40
# Fork: 1 of 1
# Warmup Iteration 1: n = 23092, mean = 25 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 428, 428, 429, 12997, 14544 ns/op
# Warmup Iteration 2: n = 16992, mean = 19 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 856, 857 ns/op
# Warmup Iteration 3: n = 15857, mean = 13 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 429, 429 ns/op
# Warmup Iteration 4: n = 15728, mean = 14 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 611, 856 ns/op
# Warmup Iteration 5: n = 15749, mean = 14 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 429, 429 ns/op
Iteration 1: n = 15867, mean = 12 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 429, 429 ns/op
Iteration 2: n = 15740, mean = 15 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 793, 1284 ns/op
Iteration 3: n = 14453, mean = 13 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 429, 429 ns/op
Iteration 4: n = 15757, mean = 13 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 1038, 1284 ns/op
Iteration 5: n = 15583, mean = 14 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 0, 0, 428, 429, 3829, 8128 ns/op
Result: 13.411 ▒(99.9%) 0.946 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 13.411, 8128.000), stdev = 80.015
Confidence interval (99.9%): [12.464, 14.357]
Samples, N = 77400
mean = 13.411 ▒(99.9%) 0.946 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 0.000 ns/op
p(90.0000) = 0.000 ns/op
p(95.0000) = 0.000 ns/op
p(99.0000) = 428.000 ns/op
p(99.9000) = 429.000 ns/op
p(99.9900) = 429.000 ns/op
p(99.9990) = 8128.000 ns/op
p(99.9999) = 8128.000 ns/op
max = 8128.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: 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.TimeFormatBenchmark.customBitFiddlingFormatBytes
# Run progress: 10.00% complete, ETA 00:01:54
# Fork: 1 of 1
# Warmup Iteration 1: n = 36259, mean = 150 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 62441, 1806336 ns/op
# Warmup Iteration 2: n = 20330, mean = 74 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 842, 857 ns/op
# Warmup Iteration 3: n = 19495, mean = 79 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 899, 1712 ns/op
# Warmup Iteration 4: n = 19489, mean = 78 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 878, 1284 ns/op
# Warmup Iteration 5: n = 19560, mean = 81 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 429, 429 ns/op
Iteration 1: n = 19370, mean = 76 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 1338, 2140 ns/op
Iteration 2: n = 19431, mean = 85 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 2028, 7272 ns/op
Iteration 3: n = 19504, mean = 80 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 856, 857 ns/op
Iteration 4: n = 19406, mean = 77 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 3855, 10688 ns/op
Iteration 5: n = 19314, mean = 84 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 2597, 2996 ns/op
Result: 80.522 ▒(99.9%) 1.834 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 80.522, 10688.000), stdev = 173.610
Confidence interval (99.9%): [78.688, 82.356]
Samples, N = 97025
mean = 80.522 ▒(99.9%) 1.834 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 0.000 ns/op
p(90.0000) = 428.000 ns/op
p(95.0000) = 428.000 ns/op
p(99.0000) = 428.000 ns/op
p(99.9000) = 429.000 ns/op
p(99.9900) = 1712.000 ns/op
p(99.9990) = 10688.000 ns/op
p(99.9999) = 10688.000 ns/op
max = 10688.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: 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.TimeFormatBenchmark.customBitFiddlingFormatString
# Run progress: 20.00% complete, ETA 00:01:41
# Fork: 1 of 1
# Warmup Iteration 1: n = 33752, mean = 257 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 19783, 218410, 1837056 ns/op
# Warmup Iteration 2: n = 18949, mean = 129 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 3691, 13264 ns/op
# Warmup Iteration 3: n = 10546, mean = 129 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 8602, 8976 ns/op
# Warmup Iteration 4: n = 10575, mean = 130 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 27119, 28672 ns/op
# Warmup Iteration 5: n = 10525, mean = 126 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 834, 856 ns/op
Iteration 1: n = 10490, mean = 127 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 1670, 1712 ns/op
Iteration 2: n = 10615, mean = 133 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 6903, 7272 ns/op
Iteration 3: n = 9634, mean = 129 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 1284, 1284 ns/op
Iteration 4: n = 10491, mean = 131 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 4175, 4280 ns/op
Iteration 5: n = 10584, mean = 131 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 4105, 4280 ns/op
Result: 130.238 ▒(99.9%) 2.915 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 130.238, 7272.000), stdev = 201.624
Confidence interval (99.9%): [127.323, 133.153]
Samples, N = 51814
mean = 130.238 ▒(99.9%) 2.915 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 0.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) = 429.000 ns/op
p(99.9900) = 1634.318 ns/op
p(99.9990) = 7272.000 ns/op
p(99.9999) = 7272.000 ns/op
max = 7272.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: 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.TimeFormatBenchmark.customFormatBytes
# Run progress: 30.00% complete, ETA 00:01:28
# Fork: 1 of 1
# Warmup Iteration 1: n = 36332, mean = 152 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 66204, 1845248 ns/op
# Warmup Iteration 2: n = 19583, mean = 80 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 1444, 14976 ns/op
# Warmup Iteration 3: n = 19016, mean = 84 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 5304, 6848 ns/op
# Warmup Iteration 4: n = 19003, mean = 82 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 856, 856 ns/op
# Warmup Iteration 5: n = 19017, mean = 84 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 856, 856 ns/op
Iteration 1: n = 18878, mean = 84 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 477, 856 ns/op
Iteration 2: n = 18781, mean = 85 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 1388, 2140 ns/op
Iteration 3: n = 18943, mean = 84 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 1802, 2568 ns/op
Iteration 4: n = 18976, mean = 84 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 944, 1712 ns/op
Iteration 5: n = 18871, mean = 85 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 2339, 7272 ns/op
Result: 84.409 ▒(99.9%) 1.848 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 84.409, 7272.000), stdev = 172.552
Confidence interval (99.9%): [82.562, 86.257]
Samples, N = 94449
mean = 84.409 ▒(99.9%) 1.848 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 0.000 ns/op
p(90.0000) = 428.000 ns/op
p(95.0000) = 428.000 ns/op
p(99.0000) = 428.000 ns/op
p(99.9000) = 429.000 ns/op
p(99.9900) = 1284.000 ns/op
p(99.9990) = 7272.000 ns/op
p(99.9999) = 7272.000 ns/op
max = 7272.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: 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.TimeFormatBenchmark.customFormatString
# Run progress: 40.00% complete, ETA 00:01:15
# Fork: 1 of 1
# Warmup Iteration 1: n = 39009, mean = 219 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 2136, 89950, 1812480 ns/op
# Warmup Iteration 2: n = 21410, mean = 168 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 8382, 1011712 ns/op
# Warmup Iteration 3: n = 10437, mean = 120 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 9296, 9408 ns/op
# Warmup Iteration 4: n = 9963, mean = 137 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 59456, 59456 ns/op
# Warmup Iteration 5: n = 11411, mean = 124 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 16626, 17952 ns/op
Iteration 1: n = 10268, mean = 123 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 845, 856 ns/op
Iteration 2: n = 11466, mean = 119 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 9371, 10688 ns/op
Iteration 3: n = 11450, mean = 118 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 1650, 1712 ns/op
Iteration 4: n = 11394, mean = 124 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 3733, 3852 ns/op
Iteration 5: n = 11349, mean = 119 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 2707, 2996 ns/op
Result: 120.721 ▒(99.9%) 2.776 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 120.721, 10688.000), stdev = 199.505
Confidence interval (99.9%): [117.945, 123.497]
Samples, N = 55927
mean = 120.721 ▒(99.9%) 2.776 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 0.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) = 429.000 ns/op
p(99.9900) = 1712.000 ns/op
p(99.9990) = 10688.000 ns/op
p(99.9999) = 10688.000 ns/op
max = 10688.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: 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.TimeFormatBenchmark.customFormatStringBuilder
# Run progress: 50.00% complete, ETA 00:01:02
# Fork: 1 of 1
# Warmup Iteration 1: n = 24967, mean = 310 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 6875, 1153209, 2088960 ns/op
# Warmup Iteration 2: n = 11767, mean = 104 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 11426, 13696 ns/op
# Warmup Iteration 3: n = 13641, mean = 110 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 1128, 1284 ns/op
# Warmup Iteration 4: n = 13543, mean = 116 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 705, 856 ns/op
# Warmup Iteration 5: n = 13485, mean = 114 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 2120, 2568 ns/op
Iteration 1: n = 13786, mean = 105 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 856, 856 ns/op
Iteration 2: n = 13714, mean = 106 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 428, 429, 429, 429 ns/op
Iteration 3: n = 13416, mean = 115 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 5497, 8128 ns/op
Iteration 4: n = 13558, mean = 115 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 857, 857 ns/op
Iteration 5: n = 13584, mean = 111 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 0, 428, 428, 429, 429, 1559, 1712 ns/op
Result: 110.310 ▒(99.9%) 2.396 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 110.310, 8128.000), stdev = 189.926
Confidence interval (99.9%): [107.914, 112.706]
Samples, N = 68058
mean = 110.310 ▒(99.9%) 2.396 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 0.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) = 429.000 ns/op
p(99.9900) = 856.194 ns/op
p(99.9990) = 8128.000 ns/op
p(99.9999) = 8128.000 ns/op
max = 8128.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: 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.TimeFormatBenchmark.fastDateFormatBytes
# Run progress: 60.00% complete, ETA 00:00:50
# Fork: 1 of 1
# Warmup Iteration 1: n = 24274, mean = 1076 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 1284, 1712, 2996, 47365, 1192813, 2924544 ns/op
# Warmup Iteration 2: n = 14507, mean = 720 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 1284, 1712, 2140, 3635, 51800, 58176 ns/op
# Warmup Iteration 3: n = 13601, mean = 589 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, 8266, 10272 ns/op
# Warmup Iteration 4: n = 12548, mean = 593 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 2140, 24928, 29504 ns/op
# Warmup Iteration 5: n = 15648, mean = 595 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 3852, 8560, 8560 ns/op
Iteration 1: n = 14272, mean = 589 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, 10089, 11552 ns/op
Iteration 2: n = 15779, mean = 585 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, 8486, 8976 ns/op
Iteration 3: n = 15377, mean = 601 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 856, 1284, 2140, 7441, 11120 ns/op
Iteration 4: n = 15629, mean = 592 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, 8742, 8976 ns/op
Iteration 5: n = 15393, mean = 607 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, 60841, 80000 ns/op
Result: 594.871 ▒(99.9%) 4.882 ns/op [Average]
Statistics: (min, avg, max) = (428.000, 594.871, 80000.000), stdev = 410.227
Confidence interval (99.9%): [589.989, 599.753]
Samples, N = 76450
mean = 594.871 ▒(99.9%) 4.882 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) = 1712.000 ns/op
p(99.9900) = 8707.638 ns/op
p(99.9990) = 80000.000 ns/op
p(99.9999) = 80000.000 ns/op
max = 80000.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: 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.TimeFormatBenchmark.fastDateFormatString
# Run progress: 70.00% complete, ETA 00:00:37
# Fork: 1 of 1
# Warmup Iteration 1: n = 31924, mean = 1289 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 856, 856, 1712, 32574, 299871, 19496960 ns/op
# Warmup Iteration 2: n = 18201, mean = 488 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 429, 856, 1284, 2996, 7504, 8560 ns/op
# Warmup Iteration 3: n = 17555, mean = 515 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 856, 1284, 1712, 2996, 3529, 3852 ns/op
# Warmup Iteration 4: n = 19703, mean = 464 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 429, 856, 857, 1284, 8800, 30816 ns/op
# Warmup Iteration 5: n = 19687, mean = 462 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 429, 856, 856, 1284, 6072, 8560 ns/op
Iteration 1: n = 19766, mean = 461 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 429, 856, 856, 1284, 3544, 8560 ns/op
Iteration 2: n = 19755, mean = 463 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 429, 856, 856, 1284, 6921, 9840 ns/op
Iteration 3: n = 19745, mean = 463 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 429, 856, 856, 1284, 3964, 41088 ns/op
Iteration 4: n = 19539, mean = 466 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 429, 856, 857, 1712, 10764, 20960 ns/op
Iteration 5: n = 18056, mean = 461 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 429, 856, 856, 1688, 7438, 8128 ns/op
Result: 462.899 ▒(99.9%) 2.159 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 462.899, 41088.000), stdev = 204.228
Confidence interval (99.9%): [460.739, 465.058]
Samples, N = 96861
mean = 462.899 ▒(99.9%) 2.159 ns/op
min = 0.000 ns/op
p( 0.0000) = 0.000 ns/op
p(50.0000) = 428.000 ns/op
p(90.0000) = 429.000 ns/op
p(95.0000) = 856.000 ns/op
p(99.0000) = 856.000 ns/op
p(99.9000) = 1284.000 ns/op
p(99.9900) = 5695.562 ns/op
p(99.9990) = 41088.000 ns/op
p(99.9999) = 41088.000 ns/op
max = 41088.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: 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.TimeFormatBenchmark.simpleDateFormatBytes
# Run progress: 80.00% complete, ETA 00:00:25
# Fork: 1 of 1
# Warmup Iteration 1: n = 23136, mean = 2234 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 856, 1284, 1712, 2140, 4704, 55502, 1375052, 13172736 ns/op
# Warmup Iteration 2: n = 14396, mean = 1376 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 856, 1284, 1284, 1284, 1284, 3852, 1323981, 2318336 ns/op
# Warmup Iteration 3: n = 13359, mean = 1201 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 856, 1284, 1284, 1284, 1284, 3270, 12259, 13264 ns/op
# Warmup Iteration 4: n = 15463, mean = 626 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 1284, 1284, 1284, 2369, 327486, 714752 ns/op
# Warmup Iteration 5: n = 18289, mean = 495 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, 6073, 8560 ns/op
Iteration 1: n = 18582, mean = 496 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, 9818, 27808 ns/op
Iteration 2: n = 16987, mean = 492 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, 11068, 27808 ns/op
Iteration 3: n = 18567, mean = 491 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, 3547, 4280 ns/op
Iteration 4: n = 18755, mean = 485 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 428, 428, 856, 856, 857, 1388, 4493, 5992 ns/op
Iteration 5: n = 18607, mean = 489 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, 2259, 2996 ns/op
Result: 490.508 ▒(99.9%) 2.264 ns/op [Average]
Statistics: (min, avg, max) = (428.000, 490.508, 27808.000), stdev = 208.102
Confidence interval (99.9%): [488.244, 492.772]
Samples, N = 91498
mean = 490.508 ▒(99.9%) 2.264 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) = 1712.000 ns/op
p(99.9900) = 3852.000 ns/op
p(99.9990) = 27808.000 ns/op
p(99.9999) = 27808.000 ns/op
max = 27808.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: 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.TimeFormatBenchmark.simpleDateFormatString
# Run progress: 90.00% complete, ETA 00:00:12
# Fork: 1 of 1
# Warmup Iteration 1: n = 25566, mean = 1957 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 856, 1284, 1284, 2140, 3852, 47428, 2876872, 6316032 ns/op
# Warmup Iteration 2: n = 14381, mean = 1203 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 856, 1284, 1284, 1284, 1712, 4542, 219953, 229376 ns/op
# Warmup Iteration 3: n = 15630, mean = 1155 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 856, 1284, 1284, 1284, 2140, 3852, 24329, 28672 ns/op
# Warmup Iteration 4: n = 19541, mean = 512 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 1284, 1284, 1712, 2996, 9362, 26080 ns/op
# Warmup Iteration 5: n = 11756, mean = 391 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 428, 429, 1816, 34928, 37632 ns/op
Iteration 1: n = 10625, mean = 393 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, 5002, 5136 ns/op
Iteration 2: n = 11821, mean = 386 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, 6337, 7272 ns/op
Iteration 3: n = 11716, mean = 386 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 978, 4411, 4704 ns/op
Iteration 4: n = 11586, mean = 396 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 856, 1033, 18875, 20096 ns/op
Iteration 5: n = 11752, mean = 389 ns/op, p{0.00, 0.50, 0.90, 0.95, 0.99, 0.999, 0.9999, 1.00} = 0, 428, 428, 429, 429, 1284, 4761, 5136 ns/op
Result: 389.843 ▒(99.9%) 2.489 ns/op [Average]
Statistics: (min, avg, max) = (0.000, 389.843, 20096.000), stdev = 181.380
Confidence interval (99.9%): [387.354, 392.332]
Samples, N = 57500
mean = 389.843 ▒(99.9%) 2.489 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) = 5136.000 ns/op
p(99.9990) = 20096.000 ns/op
p(99.9999) = 20096.000 ns/op
max = 20096.000 ns/op
# Run complete. Total time: 00:02:06
Benchmark Mode Samples Score Error Units
o.a.l.l.p.j.TimeFormatBenchmark.baseline sample 77400 13.411 ▒ 0.946 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.customBitFiddlingFormatBytes sample 97025 80.522 ▒ 1.834 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.customBitFiddlingFormatString sample 51814 130.238 ▒ 2.915 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.customFormatBytes sample 94449 84.409 ▒ 1.848 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.customFormatString sample 55927 120.721 ▒ 2.776 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.customFormatStringBuilder sample 68058 110.310 ▒ 2.396 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.fastDateFormatBytes sample 76450 594.871 ▒ 4.882 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.fastDateFormatString sample 96861 462.899 ▒ 2.159 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.simpleDateFormatBytes sample 91498 490.508 ▒ 2.264 ns/op
o.a.l.l.p.j.TimeFormatBenchmark.simpleDateFormatString sample 57500 389.843 ▒ 2.489 ns/op
{noformat}
> [Perf] Custom TimeFormat
> ------------------------
>
> Key: LOG4J2-1097
> URL: https://issues.apache.org/jira/browse/LOG4J2-1097
> Project: Log4j 2
> Issue Type: Improvement
> Components: Layouts, Pattern Converters
> Affects Versions: 2.3
> Reporter: Remko Popma
> Fix For: 2.4
>
>
> In addition to the work done for LOG4J2-812 (replace synchronized SimpleDateFormat with commons FastDateFormat) I see a way to improve performance for the timestamp even further.
> Ralph posted some very nice JMH benchmark results in LOG4J2-812, where the combination of caching, FastDateFormat and an AtomicReference was the winner.
> I believe this is the way to go, but we may be able to do even better. For some common date formats, it is possible to get a 5X speedup versus FastDateFormat.
> This is not as generic as FastDateFormat; at the moment it only supports {{HH:mm:ss,SSS}}. I would like to support the "common" DatePatternConverter formats ABSOLUTE, COMPACT, DATE_AND_TIME, DEFAULT, ISO8601_BASIC and ISO8601. For any other date format pattern we fall back to FastDateFormat.
> Performance results are below (benchmark is in git master):
> {noformat}
> Benchmark Mode Samples Score Error Units
> o.a.l.l.p.j.TimeFormatBenchmark.baseline sample 118021 18.783 ± 0.842 ns/op
> o.a.l.l.p.j.TimeFormatBenchmark.customBitFiddlingFormatString sample 157268 87.616 ± 1.557 ns/op
> o.a.l.l.p.j.TimeFormatBenchmark.customFormatString sample 170168 82.650 ± 1.326 ns/op
> o.a.l.l.p.j.TimeFormatBenchmark.customFormatStringBuilder sample 108884 67.825 ± 1.577 ns/op
> o.a.l.l.p.j.TimeFormatBenchmark.fastDateFormatString sample 148478 317.145 ± 1.850 ns/op
> o.a.l.l.p.j.TimeFormatBenchmark.simpleDateFormatString sample 173226 263.886 ± 10.615 ns/op{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org