8351925: JFR: Microsecond time format precision for JFR tool

[shipilev]

Currently, JFR tool formats the times with millisecond precision:

jdk.ThreadSleep {
  startTime = 10:48:56.668 (2025-03-13)
  duration = 100 ms
  time = 100 ms
  eventThread = "main" (javaThreadId = 3)
  stackTrace = [...]
}

In modern world, a lot can happen within a millisecond. So it would be better to default to microsecond precision. Both timesources supported by JFR (RDTSC and os::elapsed_counter()) have enough enough precision to satisfy microsecond output, so microseconds are meaningful.

After the patch:

jdk.ThreadSleep {
  startTime = 11:23:32.314580 (2025-03-13)
  duration = 100 ms
  time = 100 ms
  eventThread = "main" (javaThreadId = 3)
  stackTrace = [...]
}

I think durations should also be more precise -- for example to compute the endTime precisely from (startTime+duration), but that is a more controversial/style question, so I would like to handle it separately.

---

Progress

• Change must be properly reviewed (1 review required, with at least 1 Reviewer)
• Change must not contain extraneous whitespace
• Commit message must refer to an issue

Issue

• JDK-8351925: JFR: Microsecond time format precision for JFR tool (Enhancement - P4) ⚠️ Issue is not open.

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/24029/head:pull/24029
$ git checkout pull/24029

Update a local copy of the PR:
$ git checkout pull/24029
$ git pull https://git.openjdk.org/jdk.git pull/24029/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 24029

View PR using the GUI difftool:
$ git pr show -t 24029

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/24029.diff

Using Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back shade! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

[openjdk]

❗ This change is not yet ready to be integrated.
See the Progress checklist in the description for automated requirements.

[openjdk]

@shipilev The following label will be automatically applied to this pull request:

• hotspot-jfr

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

[mlbridge]

Webrevs

• 00: Full (219d3d20)

[egahlin]

The default mode (PrettyWriter) aims to present human-readable output, striking a balance between clarity and concision. For more detailed information, including timestamps and time spans with nine-digit precision, jfr print --json is available as an alternative.

[shipilev]

The default mode (PrettyWriter) aims to present human-readable output, striking a balance between clarity and concision. For more detailed information, including timestamps and time spans with nine-digit precision, jfr print --json is available as an alternative.

I understand, no pressure.

I do see folks in my vicinity (myself included) reaching for human-readable output for quick and dirty analysis. Very often that human-readable output is really great to quickly capture what is going on. At the scales we operate on, it is useful to see microseconds to correlate events happening within a millisecond. Switching to JSON does work, but it feels like an unnecessary friction.

Microsecond precision for timings is not uncommon. For example, Linux perf tools routinely report ISO 8601 timestamps with microsecond precision.

[egahlin]

I do see folks in my vicinity (myself included) reaching for human-readable output for quick and dirty analysis. Very often that human-readable output is really great to quickly capture what is going on. At the scales we operate on, it is useful to see microseconds to correlate events happening within a millisecond. Switching to JSON does work, but it feels like an unnecessary friction.

Microsecond precision for timings is not uncommon. For example, Linux perf tools routinely report ISO 8601 timestamps with microsecond precision.

The output from PrettyWriter is used by RecordedEvent::toString(), so it serves more than one purpose. What is the primary friction you see in --json? The verbose stack traces, too much precision, or the need to specify a command-line flag?

[shipilev]

What is the primary friction you see in --json? The verbose stack traces, too much precision, or the need to specify a command-line flag?

JSON is too verbose for human consumption. I think this is mostly due to stack traces, but there are also other parts that are relatively noisy. So I cannot easily show the pair of events in a bug report / chat message to show a particular piece of JFR-captured info, without first truncating the output.

Compare the human-readable output for the same event:

jdk.JavaMonitorNotify {
  startTime = 19:09:11.996
  duration = 0.000602 ms
  monitorClass = java.lang.Object (classLoader = bootstrap)
  notifiedCount = 1
  address = 0x7C6F54001250
  eventThread = "main" (javaThreadId = 3)
  stackTrace = [
    java.lang.Object.notifyAll()
    NotifyWaitLatency.work() line: 22
    NotifyWaitLatency.main(String[]) line: 4
    jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 104
    java.lang.reflect.Method.invoke(Object, Object[]) line: 565
  ] 
}

...and JSON one:

      "type": "jdk.JavaMonitorNotify", 
      "values": {
        "startTime": "2025-03-14T19:09:11.996604879+01:00", 
        "duration": "PT0.000000602S", 
        "eventThread": {
          "osName": "main", 
          "osThreadId": 963561, 
          "javaName": "main", 
          "javaThreadId": 3, 
          "group": {
            "parent": {
              "parent": null, 
              "name": "system"
            }, 
            "name": "main"
          }, 
          "virtual": false
        }, 
        "stackTrace": {
          "truncated": false, 
          "frames": [{
            "method": {
              "type": {
                "classLoader": {
                  "type": null, 
                  "name": "bootstrap"
                }, 
                "name": "java\/lang\/Object", 
                "package": {
                  "name": "java\/lang", 
                  "module": {
                    "name": "java.base", 
                    "version": "25-internal", 
                    "location": "jrt:\/java.base", 
                    "classLoader": {
                      "type": null, 
                      "name": "bootstrap"
                    }
                  }, 
                  "exported": true
                }, 
                "modifiers": 1, 
                "hidden": false
              }, 
              "name": "notifyAll", 
              "descriptor": "()V", 
              "modifiers": 273, 
              "hidden": false
            }, 
            "lineNumber": -1, 
            "bytecodeIndex": 0, 
            "type": "Native"
          }, {
            "method": {
              "type": {
                "classLoader": {
                  "type": {
                    "classLoader": {
                      "type": {
                        "classLoader": {
                          "type": null, 
                          "name": "bootstrap"
                        }, 
                        "name": "jdk\/internal\/loader\/ClassLoaders$AppClassLoader", 
                        "package": {
                          "name": "jdk\/internal\/loader", 
                          "module": {
                            "name": "java.base", 
                            "version": "25-internal", 
                            "location": "jrt:\/java.base", 
                            "classLoader": {
                              "type": null, 
                              "name": "bootstrap"
                            }
                          }, 
                          "exported": true
                        }, 
                        "modifiers": 10, 
                        "hidden": false
                      }, 
                      "name": "app"
                    }, 
                    "name": "com\/sun\/tools\/javac\/launcher\/MemoryClassLoader", 
                    "package": {
                      "name": "com\/sun\/tools\/javac\/launcher", 
                      "module": {
                        "name": "jdk.compiler", 
                        "version": "25-internal", 
                        "location": "jrt:\/jdk.compiler", 
                        "classLoader": {
                          "type": {
                            "classLoader": {
                              "type": null, 
                              "name": "bootstrap"
                            }, 
                            "name": "jdk\/internal\/loader\/ClassLoaders$AppClassLoader", 
                            "package": {
                              "name": "jdk\/internal\/loader", 
                              "module": {
                                "name": "java.base", 
                                "version": "25-internal", 
                                "location": "jrt:\/java.base", 
                                "classLoader": {
                                  "type": null, 
                                  "name": "bootstrap"
                                }
                              }, 
                              "exported": true
                            }, 
                            "modifiers": 10, 
                            "hidden": false
                          }, 
                          "name": "app"
                        }
                      }, 
                      "exported": false
                    }, 
                    "modifiers": 16, 
                    "hidden": false
                  }, 
                  "name": null
                }, 
                "name": "NotifyWaitLatency", 
                "package": null, 
                "modifiers": 1, 
                "hidden": false
              }, 
              "name": "work", 
              "descriptor": "()V", 
              "modifiers": 9, 
              "hidden": false
            }, 
            "lineNumber": 22, 
            "bytecodeIndex": 44, 
            "type": "Interpreted"
          }, {
            "method": {
              "type": {
                "classLoader": {
                  "type": {
                    "classLoader": {
                      "type": {
                        "classLoader": {
                          "type": null, 
                          "name": "bootstrap"
                        }, 
                        "name": "jdk\/internal\/loader\/ClassLoaders$AppClassLoader", 
                        "package": {
                          "name": "jdk\/internal\/loader", 
                          "module": {
                            "name": "java.base", 
                            "version": "25-internal", 
                            "location": "jrt:\/java.base", 
                            "classLoader": {
                              "type": null, 
                              "name": "bootstrap"
                            }
                          }, 
                          "exported": true
                        }, 
                        "modifiers": 10, 
                        "hidden": false
                      }, 
                      "name": "app"
                    }, 
                    "name": "com\/sun\/tools\/javac\/launcher\/MemoryClassLoader", 
                    "package": {
                      "name": "com\/sun\/tools\/javac\/launcher", 
                      "module": {
                        "name": "jdk.compiler", 
                        "version": "25-internal", 
                        "location": "jrt:\/jdk.compiler", 
                        "classLoader": {
                          "type": {
                            "classLoader": {
                              "type": null, 
                              "name": "bootstrap"
                            }, 
                            "name": "jdk\/internal\/loader\/ClassLoaders$AppClassLoader", 
                            "package": {
                              "name": "jdk\/internal\/loader", 
                              "module": {
                                "name": "java.base", 
                                "version": "25-internal", 
                                "location": "jrt:\/java.base", 
                                "classLoader": {
                                  "type": null, 
                                  "name": "bootstrap"
                                }
                              }, 
                              "exported": true
                            }, 
                            "modifiers": 10, 
                            "hidden": false
                          }, 
                          "name": "app"
                        }
                      }, 
                      "exported": false
                    }, 
                    "modifiers": 16, 
                    "hidden": false
                  }, 
                  "name": null
                }, 
                "name": "NotifyWaitLatency", 
                "package": null, 
                "modifiers": 1, 
                "hidden": false
              }, 
              "name": "main", 
              "descriptor": "([Ljava\/lang\/String;)V", 
              "modifiers": 137, 
              "hidden": false
            }, 
            "lineNumber": 4, 
            "bytecodeIndex": 8, 
            "type": "Interpreted"
          }, {
            "method": {
              "type": {
                "classLoader": null, 
                "name": "java.lang.invoke.LambdaForm$DMH\/0x00007c6fe7001400", 
                "package": {
                  "name": "java\/lang\/invoke", 
                  "module": {
                    "name": "java.base", 
                    "version": "25-internal", 
                    "location": "jrt:\/java.base", 
                    "classLoader": {
                      "type": null, 
                      "name": "bootstrap"
                    }
                  }, 
                  "exported": true
                }, 
                "modifiers": 16, 
                "hidden": true
              }, 
              "name": "invokeStatic", 
              "descriptor": "(Ljava\/lang\/Object;Ljava\/lang\/Object;)V", 
              "modifiers": 8, 
              "hidden": true
            }, 
            "lineNumber": -1, 
            "bytecodeIndex": 10, 
            "type": "Interpreted"
          }, {
            "method": {
              "type": {
                "classLoader": null, 
                "name": "java.lang.invoke.LambdaForm$MH\/0x00007c6fe7191000", 
                "package": {
                  "name": "java\/lang\/invoke", 
                  "module": {
                    "name": "java.base", 
                    "version": "25-internal", 
                    "location": "jrt:\/java.base", 
                    "classLoader": {
                      "type": null, 
                      "name": "bootstrap"
                    }
                  }, 
                  "exported": true
                }, 
                "modifiers": 16, 
                "hidden": true
              }, 
              "name": "invoke", 
              "descriptor": "(Ljava\/lang\/Object;Ljava\/lang\/Object;Ljava\/lang\/Object;)Ljava\/lang\/Object;", 
              "modifiers": 8, 
              "hidden": true
            }, 
            "lineNumber": -1, 
            "bytecodeIndex": 33, 
            "type": "Interpreted"
          }]
        }, 
        "monitorClass": {
          "classLoader": {
            "type": null, 
            "name": "bootstrap"
          }, 
          "name": "java\/lang\/Object", 
          "package": {
            "name": "java\/lang", 
            "module": {
              "name": "java.base", 
              "version": "25-internal", 
              "location": "jrt:\/java.base", 
              "classLoader": {
                "type": null, 
                "name": "bootstrap"
              }
            }, 
            "exported": true
          }, 
          "modifiers": 1, 
          "hidden": false
        }, 
        "notifiedCount": 1, 
        "address": 136817592504912
      }

[egahlin]

What is the primary friction you see in --json? The verbose stack traces, too much precision, or the need to specify a command-line flag?

JSON is too verbose for human consumption. I think this is mostly due to stack traces, but there are also other parts that are relatively noisy. So I cannot easily show the pair of events in a bug report / chat message to show a particular piece of JFR-captured info, without first truncating the output.

The stack trace can be removed with --stack-depth 0, but I agree, it's still noisy.

When jfr and jfr print were conceived, the idea was that the --json option could always be used when full precision was needed for verification purposes. Although it may be a bit more cumbersome to read, at least the information would not be lost.

If the use case is to copy detailed human-readable output into a bug report, perhaps there should be a switch that prints numbers and timestamps in full precision. Six digits might not be sufficient for timestamps, and then there are durations as well. I created a prototype that prints durations and timestamps with nanosecond precision, as well as the full value of bytes, bits, and percentages.

#24372

[shipilev]

If the use case is to copy detailed human-readable output into a bug report, perhaps there should be a switch that prints numbers and timestamps in full precision. Six digits might not be sufficient for timestamps, and then there are durations as well. I created a prototype that prints durations and timestamps with nanosecond precision, as well as the full value of bytes, bits, and percentages.

#24372

This works for me! Feel free to take over this RFE, or I can close this one as duplicate of another RFE for --exact. Thanks!

[shipilev]

Closed in favor of JDK-8353614.