Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8297154

Improve safepoint cleanup logging

XMLWordPrintable

    • b25

        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.

              shade Aleksey Shipilev
              shade Aleksey Shipilev
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Created:
                Updated:
                Resolved: