JDK-8333322 : Test jdk/jfr/jmx/streaming/TestStop.java failed: Expected outer dump to have 3 events
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jfr
  • Affected Version: 23
  • Priority: P3
  • Status: Closed
  • Resolution: Duplicate
  • Submitted: 2024-05-31
  • Updated: 2024-06-23
  • Resolved: 2024-06-23
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 23
23Resolved
Related Reports
Duplicate :  
JDK-8304732 - jdk/jfr/api/consumer/recordingstream/TestStop.java failed again with "Expected outer stream to have 3 events"
Relates :  
JDK-8331876 - JFR: Move file read and write events to java.base
Description
section:main
----------messages:(7/342)----------
command: main jdk.jfr.jmx.streaming.TestStop
reason: User specified action: run main/othervm jdk.jfr.jmx.streaming.TestStop 
started: Fri May 31 05:41:55 GMT 2024
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules jdk.jfr,jdk.management.jfr
finished: Fri May 31 05:41:56 GMT 2024
elapsed time (seconds): 1.399
----------configuration:(3/54)----------
Boot Layer
  add modules: jdk.jfr jdk.management.jfr

----------System.out:(32/1104)----------
RecordingStream outer:
[jdk.jfr.jmx.streaming.TestStop$MarkEvent {
  startTime = 05:41:56.662 (2024-05-31)
  id = "a"
  eventThread = "MainThread" (javaThreadId = 20)
  stackTrace = [
    jdk.jfr.jmx.streaming.TestStop.testNestedStop() line: 126
    jdk.jfr.jmx.streaming.TestStop.main(String[]) line: 63
    jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 103
    java.lang.reflect.Method.invoke(Object, Object[]) line: 580
    com.sun.javatest.regtest.agent.MainWrapper$MainTask.run() line: 138
  ]
}

]
RecordingStream inner:
[jdk.jfr.jmx.streaming.TestStop$MarkEvent {
  startTime = 05:41:56.656 (2024-05-31)
  id = "b"
  eventThread = "MainThread" (javaThreadId = 20)
  stackTrace = [
    jdk.jfr.jmx.streaming.TestStop.testNestedStop() line: 135
    jdk.jfr.jmx.streaming.TestStop.main(String[]) line: 63
    jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 103
    java.lang.reflect.Method.invoke(Object, Object[]) line: 580
    com.sun.javatest.regtest.agent.MainWrapper$MainTask.run() line: 138
  ]
}

]
Outer count: 3
Inner count: 1
----------System.err:(12/737)----------
java.lang.AssertionError: Expected outer dump to have 3 events
	at jdk.jfr.jmx.streaming.TestStop.testNestedStop(TestStop.java:159)
	at jdk.jfr.jmx.streaming.TestStop.main(TestStop.java:63)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
	at java.base/java.lang.Thread.run(Thread.java:1575)

Observed in the CI run with the fix for JDK-8331876
Comments
I think I have a lead, startNanos seems to be stuck for the two chunks. If they become the same +1 is added artificially in native. chunk 1: [0.036s][info][jfr,system,parser] Chunk: startNanos=1717134116654574006 [0.036s][info][jfr,system,parser] Chunk: startTicks=3196085542 [0.036s][info][jfr,system,parser] Chunk: ticksPerSecond=1000000000 chunk 2: [0.038s][info][jfr,system,parser] Chunk: startNanos=1717134116654574007 [0.038s][info][jfr,system,parser] Chunk: startTicks=3214314250 [0.038s][info][jfr,system,parser] Chunk: ticksPerSecond=1000000000 This may explain why event 'b' has an earlier timestamp than event 'a'. This might confuse the parser.
10-06-2024
It's hard to diagnose. The problem could be: - In the JVM - In the transfer of the file over JMX - In the parser and there is code that relies on timestamps. A clue is that we see the same problem when doing nested streams in process. See JDK-8304732. I don't think it's caused by JDK-8331876 JFR: Move file read and write events to java.base, but that enhancement improves startup (CPU and memory), so it might impact timing of JIT compilation or GCs.
07-06-2024