RFR: 8351925: JFR: Microsecond time format precision for JFR tool
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. ------------- Commit messages: - Fix Changes: https://git.openjdk.org/jdk/pull/24029/files Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=24029&range=00 Issue: https://bugs.openjdk.org/browse/JDK-8351925 Stats: 1 line in 1 file changed: 0 ins; 0 del; 1 mod Patch: https://git.openjdk.org/jdk/pull/24029.diff Fetch: git fetch https://git.openjdk.org/jdk.git pull/24029/head:pull/24029 PR: https://git.openjdk.org/jdk/pull/24029
On Thu, 13 Mar 2025 10:24:08 GMT, Aleksey Shipilev <shade@openjdk.org> wrote:
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.
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. ------------- PR Comment: https://git.openjdk.org/jdk/pull/24029#issuecomment-2725159598
On Fri, 14 Mar 2025 16:17:13 GMT, Erik Gahlin <egahlin@openjdk.org> wrote:
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. ------------- PR Comment: https://git.openjdk.org/jdk/pull/24029#issuecomment-2754890252
On Wed, 26 Mar 2025 15:44:15 GMT, Aleksey Shipilev <shade@openjdk.org> wrote:
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? ------------- PR Comment: https://git.openjdk.org/jdk/pull/24029#issuecomment-2765870818
On Mon, 31 Mar 2025 10:55:30 GMT, Erik Gahlin <egahlin@openjdk.org> wrote:
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 } ------------- PR Comment: https://git.openjdk.org/jdk/pull/24029#issuecomment-2765898065
On Mon, 31 Mar 2025 11:04:56 GMT, Aleksey Shipilev <shade@openjdk.org> wrote:
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. https://github.com/openjdk/jdk/pull/24372 ------------- PR Comment: https://git.openjdk.org/jdk/pull/24029#issuecomment-2772306157
On Thu, 13 Mar 2025 10:24:08 GMT, Aleksey Shipilev <shade@openjdk.org> wrote:
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.
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! ------------- PR Comment: https://git.openjdk.org/jdk/pull/24029#issuecomment-2772929997
On Thu, 13 Mar 2025 10:24:08 GMT, Aleksey Shipilev <shade@openjdk.org> wrote:
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.
Closed in favor of [JDK-8353614](https://bugs.openjdk.org/browse/JDK-8353614). ------------- PR Comment: https://git.openjdk.org/jdk/pull/24029#issuecomment-2782487771
On Thu, 13 Mar 2025 10:24:08 GMT, Aleksey Shipilev <shade@openjdk.org> wrote:
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.
This pull request has been closed without being integrated. ------------- PR: https://git.openjdk.org/jdk/pull/24029
participants (2)
-
Aleksey Shipilev
-
Erik Gahlin