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

Improve safepoint cleanup logging

    XMLWordPrintable

Details

    • b25

    Backports

      Description

        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.

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                  Created:
                  Updated:
                  Resolved: