-
Enhancement
-
Resolution: Fixed
-
P4
-
17, 19, 20
-
b25
Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-8308629 | 17.0.8 | Aleksey Shipilev | P4 | Resolved | Fixed | b04 |
When backporting JDK-8280784, I realized that safepoint cleanup logging added by JDK-8219436 is misleading. `-Xlog:safepoint` output includes "cleanup" time into "Reaching safepoint", which users can arguably expect to be only the time-to-safepoint. With large reported "Reaching safepoint" time, users would chase a safepoint polling / scheduling problem, rather than suspect the safepoint cleanup costs.
It can be clearly observed if you enable both `-Xlog:safepoint` and `-Xlog:safepoint+stats` and run this on busy machine:
```
$ build/linux-x86_64-server-fastdebug/images/jdk/bin/java -XX:+SafepointALot -XX:GuaranteedSafepointInterval=1000 -Xlog:safepoint -Xlog:safepoint+stats ManyThreads.java
[1.647s][info][safepoint,stats] VM Operation [ threads: total initial_running ][ time: sync cleanup vmop total ] page_trap_count
[1.647s][info][safepoint,stats] Cleanup [ 15 1 ][ 26541 240544 30371 297456 ] 0
[1.647s][info][safepoint ] Safepoint "Cleanup", Time since last: 1499772987 ns, Reaching safepoint: 267085 ns, At safepoint: 30371 ns, Total: 297456 ns
```
Note how "sync" takes only 26541 ns, "cleanup" takes 240544 ns, yet "Reaching safepoint" reports the sums of both.
It can be clearly observed if you enable both `-Xlog:safepoint` and `-Xlog:safepoint+stats` and run this on busy machine:
```
$ build/linux-x86_64-server-fastdebug/images/jdk/bin/java -XX:+SafepointALot -XX:GuaranteedSafepointInterval=1000 -Xlog:safepoint -Xlog:safepoint+stats ManyThreads.java
[1.647s][info][safepoint,stats] VM Operation [ threads: total initial_running ][ time: sync cleanup vmop total ] page_trap_count
[1.647s][info][safepoint,stats] Cleanup [ 15 1 ][ 26541 240544 30371 297456 ] 0
[1.647s][info][safepoint ] Safepoint "Cleanup", Time since last: 1499772987 ns, Reaching safepoint: 267085 ns, At safepoint: 30371 ns, Total: 297456 ns
```
Note how "sync" takes only 26541 ns, "cleanup" takes 240544 ns, yet "Reaching safepoint" reports the sums of both.
- backported by
-
JDK-8308629 Improve safepoint cleanup logging
- Resolved
- relates to
-
CODETOOLS-7903413 JMH: Safepoint profiler should parse JDK 13+ -Xlog:safepoint
- Resolved
-
JDK-8219436 Safepoint logs correction and misc
- Resolved
- links to
-
Commit openjdk/jdk17u-dev/879f4c59
-
Commit openjdk/jdk/086763a6
-
Review openjdk/jdk17u-dev/1378
-
Review openjdk/jdk/11194
(2 links to)