RFR(L): 8219436: Safepoint logs correction and misc
Robbin Ehn
robbin.ehn at oracle.com
Wed Feb 20 09:34:28 UTC 2019
Hi all,
Issue:
https://bugs.openjdk.java.net/browse/JDK-8219436
Changeset:
http://cr.openjdk.java.net/~rehn/8219436/v01/webrev/
Safepoint logs takes multiple time-stamps for same measurement but different
logs. The most meaningful logs is not under just safepoint tag.
The sync phase ignored some potential time-consuming parts, joing GC-threads
with STS-joiner and grabbing the Threads_lock, which is now included in 'sync'.
"Reaching safepoint" is sync + cleanup.
Also 'unused' JFR event removed and SafepointTimeout was not working proper.
"-Xlog:safepoint" now gives you only:
[2.045s][info][safepoint] Safepoint "Cleanup", Time since last: 34559 ns,
Reaching safepoint: 307612 ns, At safepoint: 26194 ns, Total: 333806 ns
[2.046s][info][safepoint] Safepoint "RevokeBias", Time since last: 99207 ns,
Reaching safepoint: 319601 ns, At safepoint: 168210 ns, Total: 487811 ns
"-Xlog:safepoint+stats" now gives you this updated table:
[1.308s][info][safepoint,stats] VM Operation [ threads: total
initial_running ][ time: sync cleanup vmop total ]
page_trap_count
[1.308s][info][safepoint,stats] Cleanup [ 9
1 ][ 2175486 233869 20660 2430015 ] 0
[1.602s][info][safepoint,stats] Deoptimize [ 14
0 ][ 30698 289306 168425 488429 ] 0
[1.605s][info][safepoint,stats] Deoptimize [ 14
0 ][ 22789 68223 156759 247771 ] 0
[1.917s][info][safepoint,stats] EnableBiasedLocking [ 19
0 ][ 40133 651166 561768 1253067 ] 0
With the usual exits logs:
[2.286s][info][safepoint,stats] Cleanup 1
[2.286s][info][safepoint,stats] Deoptimize 2
[2.286s][info][safepoint,stats] G1CollectForAllocation 1
[2.286s][info][safepoint,stats] EnableBiasedLocking 1
[2.286s][info][safepoint,stats] RevokeBias 12
[2.286s][info][safepoint,stats] Exit 1
[2.286s][info][safepoint,stats] VM operations coalesced during safepoint 32
[2.286s][info][safepoint,stats] Maximum sync time 2175486 ns
[2.286s][info][safepoint,stats] Maximum vm operation time (except for Exit VM
operation) 88697164 ns
"-Xlog:safepoint+stats" and "-Xlog:safepoint" use the same timestamp, so if you
have both logs enabled they add up.
Thanks, Robbin
More information about the hotspot-runtime-dev
mailing list