JDK-8287832 : jdk/jfr/event/runtime/TestActiveSettingEvent.java failed with "Expected two batches of Active Setting events"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jfr
  • Affected Version: 19,20
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2022-06-04
  • Updated: 2023-12-01
  • Resolved: 2022-10-10
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 17 JDK 20
17.0.11Fixed 20 b19Fixed
Related Reports
Duplicate :  
JDK-8288663 - JFR: Disabling the JfrThreadSampler commits only a partially disabled state
Relates :  
JDK-8295274 - HelidonAppTest.java fails "assert(event->should_commit()) failed: invariant" from compiled frame"
Sub Tasks
JDK-8289857 :  
ProblemList jdk/jfr/event/runtime/TestActiveSettingEvent.java - Resolved
Description
The following test failed in the JDK19 CI:

jdk/jfr/event/runtime/TestActiveSettingEvent.java

Here's a snippet from the log file:

#section:main
----------messages:(5/295)----------
command: main jdk.jfr.event.runtime.TestActiveSettingEvent
reason: User specified action: run main/othervm jdk.jfr.event.runtime.TestActiveSettingEvent 
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules jdk.jfr,java.management
elapsed time (seconds): 1.436
----------configuration:(3/54)----------
Boot Layer
  add modules: jdk.jfr java.management

----------System.out:(2/62)----------
Testing configuration default
Testing configuration profile
----------System.err:(12/1000)----------
java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...)
	at jdk.jfr.event.runtime.TestActiveSettingEvent.testChangedSetting(TestActiveSettingEvent.java:213)
	at jdk.jfr.event.runtime.TestActiveSettingEvent.main(TestActiveSettingEvent.java:69)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:1596)

JavaTest Message: Test threw exception: java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...)
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...)
----------rerun:(41/5363)*----------
Comments
Fix Request (17u): This is an addition to JDK-8288663 and JDK-8295274. Having disabled events in recordings is also quite unexpected. The patch got minor technical corrections https://github.com/openjdk/jdk17u-dev/pull/2002 Testing: tier1, tier2, jdk_jfr, gc/stress/jfr (linux-aarch64 fastdebug), pre-submit checks.
30-11-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk17u-dev/pull/2002 Date: 2023-11-29 18:55:53 +0000
29-11-2023
Changeset: 4df4a1f8 Author: Markus Grönlund <mgronlun@openjdk.org> Date: 2022-10-10 12:40:58 +0000 URL: https://git.openjdk.org/jdk/commit/4df4a1f8e238ebf49d4b0e1e102ccdc3cdb82de9
10-10-2022
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/10575 Date: 2022-10-05 12:26:08 +0000
05-10-2022
The test fails because of an unexpected event in the event stream. The recording does not explicitly enable any events, yet, occasionally, there are some. From where do these events originate? The JfrEvent C++ classes check enabled state in the constructor, and some event instances have extent across a potential safepoint. A safepoint could result from JFR rotating and stopping to record. As a result, an event can still be enabled after JFR stops and then restarts, resulting in unexpected events in the event stream of the newly started recording. Most common unexpected events seen are: jdk.JavaMonitorWait jdk.Compilation jdk.NativeMethodSample A solution to this problem is to move the event-enabled check from the constructor to the shouldCommit() and commit() functions. For durational events, it requires two is_enabled() tests, as one will still be needed in the constructor, for decision about starttime. No tangible performance impact is expected.
05-10-2022
Here's a log file snippet from the jdk-20+5-225-tier3 sighting: jdk/jfr/event/runtime/TestActiveSettingEvent.java #section:main ----------messages:(5/290)---------- command: main jdk.jfr.event.runtime.TestActiveSettingEvent reason: User specified action: run main/othervm jdk.jfr.event.runtime.TestActiveSettingEvent Mode: othervm [/othervm specified] Additional options from @modules: --add-modules jdk.jfr,java.management elapsed time (seconds): 1.405 ----------configuration:(3/51)---------- Boot Layer add modules: jdk.jfr java.management ----------System.out:(2/60)---------- Testing configuration default Testing configuration profile ----------System.err:(12/988)---------- java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...) at jdk.jfr.event.runtime.TestActiveSettingEvent.testChangedSetting(TestActiveSettingEvent.java:213) at jdk.jfr.event.runtime.TestActiveSettingEvent.main(TestActiveSettingEvent.java:69) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) at java.base/java.lang.reflect.Method.invoke(Method.java:578) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:1589) JavaTest Message: Test threw exception: java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...) JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...) ----------rerun:(36/6471)*----------
06-07-2022
This is strange, the same testcase, testChangedSetting() failed again, this time the file looks like this: jdk.Compilation { startTime = 10:53:09.727 (2022-06-24) duration = 90,0 ms compileId = 2008 compiler = "c2" method = jdk.jfr.internal.consumer.ConstantMap.get(long) compileLevel = 4 succeded = true isOsr = false codeSize = 12,8 kB inlinedBytes = 1,6 kB eventThread = "C2 CompilerThread2" (javaThreadId = 15) } jdk.ActiveSetting { startTime = 10:53:09.824 (2022-06-24) id = 7 name = "stackTrace" value = "true" eventThread = "MainThread" (javaThreadId = 22) } jdk.ActiveSetting { startTime = 10:53:09.824 (2022-06-24) id = 7 name = "enabled" value = "false" eventThread = "MainThread" (javaThreadId = 22) } jdk.ActiveSetting { startTime = 10:53:09.824 (2022-06-24) id = 8 name = "enabled" value = "false" eventThread = "MainThread" (javaThreadId = 22) } This time, instead of containing an unrelated event of type jdk.NativeMethodSample, which was fixed as of JDK-8288663, an event of type jdk.Compilation is included, an event type that should also be disabled and not have been generated. [~egahlin] Can you take a look at how the enable/disable mechanism for testChangedSetting() is implemented? Is there at first a default enabling and then disabling that could account for this? I will try to to see if there is a race in how the buffers are cleared, jdk.jfr.internal.consumer.ConstantMap.get(long) is likely a method compliled when parsing the results from the preceding testcase, which could indicate stale data is included in the next recording.
27-06-2022
Here's a log file snippet for the jdk-19+29-2118-tier3 sighting: jdk/jfr/event/runtime/TestActiveSettingEvent.java #section:main ----------messages:(5/290)---------- command: main jdk.jfr.event.runtime.TestActiveSettingEvent reason: User specified action: run main/othervm jdk.jfr.event.runtime.TestActiveSettingEvent Mode: othervm [/othervm specified] Additional options from @modules: --add-modules jdk.jfr,java.management elapsed time (seconds): 1.517 ----------configuration:(3/51)---------- Boot Layer add modules: jdk.jfr java.management ----------System.out:(2/60)---------- Testing configuration default Testing configuration profile ----------System.err:(12/988)---------- java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...) at jdk.jfr.event.runtime.TestActiveSettingEvent.testChangedSetting(TestActiveSettingEvent.java:213) at jdk.jfr.event.runtime.TestActiveSettingEvent.main(TestActiveSettingEvent.java:69) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) at java.base/java.lang.reflect.Method.invoke(Method.java:578) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:1589) JavaTest Message: Test threw exception: java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...) JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.Exception: Expected two batches of Active Setting events, at Recording.start() and during Recording.setSetting(...) ----------rerun:(36/6498)*---------- This failure occurred in jdk-19+29-2118-tier3. The fix for the following bug: JDK-8288663 JFR: Disabling the JfrThreadSampler commits only a partially disabled state was integrated in jdk-19+28-2094 so that fix is in place. This bug (JDK-8287832) was originally closed as a duplicate of JDK-8288663 so I have reopened this bug.
24-06-2022
jdk.NativeMethodSample { startTime = 09:47:33.035 (2022-06-04) sampledThread = "MainThread" (javaThreadId = 23) state = "STATE_RUNNABLE" stackTrace = [ jdk.jfr.internal.JVM.counterTime() jdk.jfr.internal.SettingsManager.setSettings(List, boolean) line: 145 jdk.jfr.internal.MetadataRepository.setSettings(List, boolean) line: 229 jdk.jfr.internal.PlatformRecorder.updateSettingsButIgnoreRecording(PlatformRecording, boolean) line: 396 jdk.jfr.internal.PlatformRecorder.updateSettings(boolean) line: 385 jdk.jfr.internal.PlatformRecorder.start(PlatformRecording) line: 257 jdk.jfr.internal.PlatformRecording.start() line: 120 jdk.jfr.Recording.start() line: 177 jdk.jfr.event.runtime.TestActiveSettingEvent.testChangedSetting() line: 197 jdk.jfr.event.runtime.TestActiveSettingEvent.main(String[]) line: 69 ] } jdk.ActiveSetting { startTime = 09:47:33.035 (2022-06-04) id = 7 name = "stackTrace" value = "true" eventThread = "MainThread" (javaThreadId = 23) } The recording contains an unrelated event of type jdk.NativeMethodSample, an event type that is currently disabled and should not have been generated.
17-06-2022