[
https://issues.apache.org/jira/browse/LOG4J2-753?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14135145#comment-14135145
]
Remko Popma commented on LOG4J2-753:
------------------------------------
*Summary*
Observations from running the clock benchmarks on enterprise hardware with a
variety of OS's and JREs:
* System.currentTimeMillis() on Windows is about one order of magnitude faster
than Solaris 10 and RHEL 5.5.
* RHEL 6.5 is more recent than 5.5 but slower by yet another order of magnitude!
* Thread contention on the volatile field in oldCachedClock seems hardly a
problem in Solaris 10, RHEL 5.5 and RHEL 6.5. (This may be thanks to the
hardware though.)
* RHEL 6.5 (because the system clock is so slow) is the only environment where
CachedClock gives a clear advantage.
Details follow below.
*Solaris 10, Oracle Hotspot 1.7.0_06 with 8 threads (server 1)*
On Solaris 10 (64bit) with JDK1.7.0_06-b24 (Oracle Hotspot), 2 quad-core Xeon
X5570 dual CPUs @2.93Ghz with hyperthreading switched on (16 virtual cores):
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -t 8 -f 1 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 841437
334.712 0.257 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 723420
343.449 0.296 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 861240
652.454 0.781 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 809895
761.579 1.058 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 1288003
619.616 0.286 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 1310462
613.671 0.277 ns/op
{code}
*Solaris 10 + Hotspot with 1 thread*
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -t 1 -f 1 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 115922
255.214 0.545 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 99497
260.839 0.390 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 174245
262.613 0.202 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 77023
267.020 0.223 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 170278
517.511 1.723 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 171934
523.277 0.273 ns/op
{code}
*Red Hat Enterprise Linux 5.5, Oracle Hotspot 1.7.0_05 with 8 threads (server
2)*
On 64 bit RHEL 5.5 (Linux 2.6.18-194.el5) with JDK1.7.0_05-b06 (Oracle
Hotspot), 4 quad-core Xeon X5570 CPUs @2.93GHz with hyperthreading switched on
(16 virtual cores):
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -t 8 -f 1 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 1566345
114.263 0.851 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 1308907
118.248 0.933 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 1006970
516.047 1.706 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 1061763
591.377 1.795 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 1501542
171.024 1.015 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 1510465
179.717 1.042 ns/op
{code}
*Red Hat Enterprise Linux 5.5 + Hotspot with 1 thread*
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -t 1 -f 1 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 196319
114.049 2.370 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 163850
121.062 2.662 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 147926
125.265 2.844 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 139514
139.986 3.062 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 187743
171.341 2.871 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 188918
180.734 2.924 ns/op
{code}
----
*Red Hat Enterprise Linux 6.5, Oracle Hotspot 1.7.0_05 with 8 threads (server
3)*
On 64 bit RHEL 6.5 (Linux 2.6.32-431.el6.x86_64) with JDK1.7.0_05-b06 (Oracle
Hotspot), 4 quad-core Xeon X5570 CPUs @2.93GHz with hyperthreading switched on
(16 virtual cores):
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -f 1 -t 8 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 1151791
1908.181 3.557 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 1185633
1763.621 1.860 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 867575
2167.286 4.420 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 955946
2190.318 4.869 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 1004249
18316.428 50.738 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 928311
15070.335 36.932 ns/op
{code}
*Red Hat Enterprise Linux 6.5 + Hotspot with 1 thread*
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -f 1 -t 1 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 104741
2362.656 42.602 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 174631
1977.836 21.913 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 122760
1811.295 20.720 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 133229
1733.615 13.695 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 181383
3560.305 23.687 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 181763
3552.076 20.468 ns/op
{code}
*Red Hat Enterprise Linux 6.5, OpenJDK 1.7.0_45 with 8 threads (server 3 again)*
On 64 bit RHEL 6.5 (Linux 2.6.32-431.el6.x86_64) with JDK1.7.0_45 (OpenJDK
Runtime Environment (rhel-2.4.3.3.el6-x86_64 u45-b15)), 4 quad-core Xeon X5570
CPUs @2.93GHz with hyperthreading switched on (16 virtual cores):
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -t 8 -f 1 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 896056
1480.330 2.911 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 1227780
1848.169 2.562 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 1063503
2421.514 5.958 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 826153
2105.360 4.194 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 870539
17422.028 46.150 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 958396
16475.059 38.458 ns/op
{code}
*Red Hat Enterprise Linux 6.5 + OpenJDK with 1 thread*
{code}
java -jar microbenchmarks.jar ".*ClocksBench.*" -t 1 -f 1 -wi 10 -i 10
Benchmark Mode Samples
Mean Mean error Units
o.a.l.l.p.j.ClocksBenchmark.baseline sample 106384
1934.413 25.953 ns/op
o.a.l.l.p.j.ClocksBenchmark.coarseCachedClock sample 174132
1905.847 19.968 ns/op
o.a.l.l.p.j.ClocksBenchmark.cachedClock sample 127388
1703.390 14.118 ns/op
o.a.l.l.p.j.ClocksBenchmark.oldCachedClock sample 128520
1883.716 23.739 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemClock sample 184954
3502.222 18.449 ns/op
o.a.l.l.p.j.ClocksBenchmark.systemCurrentTimeMillis sample 133506
2955.925 17.282 ns/op
{code}
> CachedClock performs badly when contended by many threads
> ---------------------------------------------------------
>
> Key: LOG4J2-753
> URL: https://issues.apache.org/jira/browse/LOG4J2-753
> Project: Log4j 2
> Issue Type: Improvement
> Components: Core
> Affects Versions: 2.0
> Reporter: Remko Popma
> Assignee: Remko Popma
> Fix For: 2.1
>
>
> See LOG4J2-744 comments for JMH benchmarks highlighting the issue.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
