JDK-8321276 : runtime/cds/appcds/dynamicArchive/DynamicSharedSymbols.java failed with "'17 2: jdk/test/lib/apps ' missing from stdout/stderr"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 22
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2023-12-04
  • Updated: 2024-06-17
  • Resolved: 2023-12-04
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 21 JDK 22
21.0.4-oracleFixed 22 b27Fixed
Related Reports
Relates :  
JDK-8315559 - Delay TempSymbol cleanup to avoid symbol table churn
Relates :  
JDK-8334360 - runtime/cds/appcds/dynamicArchive/DynamicSharedSymbols.java failed with "'17 3: jdk/test/lib/apps ' missing from stdout/stderr"
Description
The following test failed in the JDK22 CI:

runtime/cds/appcds/dynamicArchive/DynamicSharedSymbols.java

Here's a snippet from the log file:

#section:main
----------messages:(6/420)----------
command: main -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xbootclasspath/a:./WhiteBox.jar DynamicSharedSymbols
reason: User specified action: run main/othervm/timeout=500 -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xbootclasspath/a:./WhiteBox.jar DynamicSharedSymbols 
started: Mon Dec 04 13:31:01 UTC 2023
Mode: othervm [/othervm specified]
finished: Mon Dec 04 13:31:06 UTC 2023
elapsed time (seconds): 5.78
----------configuration:(0/0)----------
----------System.out:(99/10964)----------
Command line: ['/opt/mach5/mesos/work_dir/jib-master/install/jdk-22+27-2180/linux-x64-debug.jdk/jdk-22/fastdebug/bin/java' '-XX:MaxRAMPercentage=4.16667' '-Dtest.boot.jdk=/opt/mach5/mesos/work_dir/jib-master/install/jdk/21/35/bundles/linux-x64/jdk-21_linux-x64_bin.tar.gz/jdk-21' '-Djava.io.tmpdir=/opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/tmp' '-XX:ArchiveClassesAtExit=/opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/scratch/0/top-13h31m01s785.jsa' '-Xlog:cds,cds+dynamic=info' '-cp' '/opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/scratch/0/loadclass.jar' 'JCmdTestLingeredApp' '563c8be6-3359-499f-b6cb-c91a0eb51391.lck']
LingeredApp startup took 1231ms
Check for hs_err_pid/core/mdmp files:
None.
 LingeredApp stdout: [[0.059s][info][cds] trying to map /opt/mach5/mesos/work_dir/jib-master/install/jdk-22+27-2180/linux-x64-debug.jdk/jdk-22/fastdebug/lib/server/classes.jsa
[0.059s][info][cds] Opened archive /opt/mach5/mesos/work_dir/jib-master/install/jdk-22+27-2180/linux-x64-debug.jdk/jdk-22/fastdebug/lib/server/classes.jsa.
[0.059s][info][cds] Archive was created with UseCompressedOops = 1, UseCompressedClassPointers = 1
[0.059s][info][cds] Core region alignment: 4096
[0.059s][info][cds] Reserved archive_space_rs [0x0000000800000000 - 0x0000000801000000] (16777216) bytes
[0.059s][info][cds] Reserved class_space_rs   [0x0000000801000000 - 0x0000000841000000] (1073741824) bytes
[0.059s][info][cds] Mapped static  region #0 at base 0x0000000800000000 top 0x000000080050e000 (ReadWrite)
[0.059s][info][cds] Mapped static  region #1 at base 0x000000080050e000 top 0x0000000800d40000 (ReadOnly)
[0.059s][info][cds] ArchiveRelocationMode == 1: always map archive(s) at an alternative address
[0.059s][info][cds] Unmapping region #0 at base 0x0000000800000000 (ReadWrite)
[0.059s][info][cds] Unmapping region #1 at base 0x000000080050e000 (ReadOnly)
[0.060s][info][cds] Try to map archive(s) at an alternative address
[0.060s][info][cds] Reserved archive_space_rs [0x00007f50f2000000 - 0x00007f50f3000000] (16777216) bytes
[0.060s][info][cds] Reserved class_space_rs   [0x00007f50f3000000 - 0x00007f5133000000] (1073741824) bytes
[0.060s][info][cds] Mapped static  region #0 at base 0x00007f50f2000000 top 0x00007f50f250e000 (ReadWrite)
[0.060s][info][cds] Mapped static  region #1 at base 0x00007f50f250e000 top 0x00007f50f2d40000 (ReadOnly)
[0.060s][info][cds] Mapped static  region #2 at base 0x00007f516c11d000 top 0x00007f516c15e000 (Bitmap)
[0.081s][info][cds] CDS archive was created with max heap size = 128M, and the following configuration:
[0.081s][info][cds]     narrow_klass_base at mapping start address, narrow_klass_shift = 0
[0.081s][info][cds]     narrow_oop_mode = 0, narrow_oop_base = 0x0000000000000000, narrow_oop_shift = 0
[0.081s][info][cds] The current max heap size = 990M, HeapRegion::GrainBytes = 1048576
[0.081s][info][cds]     narrow_klass_base = 0x00007f50f2000000, narrow_klass_shift = 0
[0.081s][info][cds]     narrow_oop_mode = 0, narrow_oop_base = 0x0000000000000000, narrow_oop_shift = 0
[0.081s][info][cds]     heap range = [0x00000000c2200000 - 0x0000000100000000]
[0.081s][info][cds] Preferred address to map heap data (to avoid relocation) is 0x00000000ffe00000
[0.081s][info][cds] Heap data mapped at 0x00000000ffe00000, size =  1092944 bytes
[0.081s][info][cds] CDS heap data relocation delta = 0 bytes
[0.081s][info][cds] initial optimized module handling: enabled
[0.081s][info][cds] initial full module graph: enabled
[0.082s][info][cds] _archived_main_module_name (null)
[0.082s][info][cds] optimized module handling: enabled
[0.082s][info][cds] full module graph: enabled
[0.082s][info][cds] use_full_module_graph = true; java.base = 0x00007f50f2508f00
[0.082s][info][cds] Unmapping region #2 at base 0x00007f516c11d000 (Bitmap)
Could not load Hello java.lang.ClassNotFoundException: Hello[1.302s][info][cds,dynamic] Preparing for dynamic dump at exit in thread main
[1.302s][info][cds        ] Regenerate MethodHandle Holder classes...
[1.624s][info][cds        ] Regenerate MethodHandle Holder classes...done
[1.631s][info][cds        ] Verify Before CDS dynamic dump
[1.723s][warning][cds        ] Skipping jdk/internal/event/ThreadSleepEvent: Not in loaded state
[1.723s][warning][cds        ] Skipping jdk/internal/event/ThreadSleepEvent: JFR event class
[1.723s][warning][cds        ] Skipping jdk/internal/event/Event: Not in loaded state
[1.723s][warning][cds        ] Skipping jdk/internal/event/Event: JFR event class
[1.723s][info   ][cds        ] Gathering all archivable objects ... 
[1.723s][info   ][cds        ] Gathering classes and symbols ... 
[1.728s][info   ][cds        ] _estimated_hashtable_bytes = 4680 + 1112 = 5792
[1.728s][info   ][cds        ] _estimated_metaspaceobj_bytes = 260848
[1.728s][info   ][cds        ] total estimate bytes = 274832
[1.728s][info   ][cds        ] Reserved output buffer space at 0x00007f515003e000 [278528 bytes]
[1.728s][info   ][cds,dynamic] Copying 31 klasses and 287 symbols
[1.728s][info   ][cds        ] Allocating RW objects ... 
[1.729s][info   ][cds        ] done (847 objects)
[1.729s][info   ][cds        ] Allocating RO objects ... 
[1.729s][info   ][cds        ] done (1607 objects)
[1.729s][info   ][cds        ] Relocating embedded pointers in core regions ... 
[1.730s][info   ][cds        ] MetaspaceObjs estimate = 260848 used = 260832; diff = 16 bytes
[1.730s][info   ][cds,dynamic] Archiving hidden sun.nio.fs.UnixFileAttributeViews$Basic$$Lambda/0x00007f50f3042680
[1.730s][info   ][cds        ] Hashtables estimate = 5792 used = 3808; diff = 1984 bytes
[1.731s][info   ][cds        ] Make classes shareable
[1.731s][info   ][cds        ] Number of classes 31
[1.731s][info   ][cds        ]     instance classes   =    29
[1.731s][info   ][cds        ]       boot             =    25
[1.731s][info   ][cds        ]       app              =     4
[1.731s][info   ][cds        ]       platform         =     0
[1.731s][info   ][cds        ]       unregistered     =     0
[1.731s][info   ][cds        ]       (hidden)         =     1
[1.731s][info   ][cds        ]       (unlinked)       =     0
[1.731s][info   ][cds        ]     obj array classes  =     2
[1.731s][info   ][cds        ]     type array classes =     0
[1.731s][info   ][cds        ]                symbols =   287
[1.731s][info   ][cds        ] Adjust lambda proxy class dictionary
[1.731s][info   ][cds        ] Dumping shared data to file: 
[1.731s][info   ][cds        ]    /opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/scratch/0/top-13h31m01s785.jsa
[1.731s][info   ][cds        ] Shared file region (rw) 0:   123984 bytes, addr 0x0000000800d40000 file offset 0x00001000 crc 0x0c13ec62
[1.731s][info   ][cds        ] Shared file region (ro) 1:   140656 bytes, addr 0x0000000800d5f000 file offset 0x00020000 crc 0x9a9da41d
[1.732s][info   ][cds        ] Shared file region (bm) 2:     4184 bytes, addr 0x0000000000000000 file offset 0x00043000 crc 0x93c47e57
[1.732s][info   ][cds,dynamic] Written dynamic archive 0x0000000800d40000 - 0x0000000800d81570 [792 bytes header, 267632 bytes total]
[1.732s][info   ][cds,dynamic] 31 klasses; 287 symbols
[1.732s][info   ][cds        ] Verify After CDS dynamic dump
];
 LingeredApp stderr: []
 LingeredApp exitValue = 0
Command line: ['/opt/mach5/mesos/work_dir/jib-master/install/jdk-22+27-2180/linux-x64-debug.jdk/jdk-22/fastdebug/bin/java' '-XX:MaxRAMPercentage=4.16667' '-Dtest.boot.jdk=/opt/mach5/mesos/work_dir/jib-master/install/jdk/21/35/bundles/linux-x64/jdk-21_linux-x64_bin.tar.gz/jdk-21' '-Djava.io.tmpdir=/opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/tmp' '-Xshare:on' '-XX:SharedArchiveFile=/opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/scratch/0/top-13h31m01s785.jsa' '-Xlog:cds,class+load' '-cp' '/opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/scratch/0/loadclass.jar' 'JCmdTestLingeredApp' '2dd21e8a-5468-43cf-ba8b-61a5742ae2e8.lck']
LingeredApp startup took 1002ms
Check for hs_err_pid/core/mdmp files:
None.
[2023-12-04T13:31:04.938661826Z] Gathering output for process 3473148
[ELAPSED: 1442 ms]
[logging stdout to /opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/scratch/0/runtime.cds.appcds.dynamicArchive.DynamicSharedSymbols.java-0000-jcmd-symboltable.stdout]
[logging stderr to /opt/mach5/mesos/work_dir/slaves/afbc6042-3a24-4198-9369-18c663a3f74c-S21881/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/cd54aced-0e33-4a0f-a255-f1fd56fccb9c/runs/9d82a49e-b64d-4c3a-b4db-9bf2bae87dff/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_tier2_runtime/scratch/0/runtime.cds.appcds.dynamicArchive.DynamicSharedSymbols.java-0000-jcmd-symboltable.stderr]
[STDERR]

[2023-12-04T13:31:06.372605581Z] Waiting for completion for process 3473148
[2023-12-04T13:31:06.372743232Z] Waiting for completion finished for process 3473148
[2023-12-04T13:31:06.380069117Z] Waiting for completion for process 3473148
[2023-12-04T13:31:06.380345440Z] Waiting for completion finished for process 3473148
----------System.err:(2080/84919)*----------
 stdout: [3473098:
VERSION: 1.1
25 2: [Ljava/util/jar/Manifest;
21 65535: ThreadSleepEvent.java
13 2: LambdaForm$MH
26 65535: Ljdk/internal/event/Event;

<snip>

10 65535: randomUUID
33 65535: jdk/test/lib/process/StreamPumper
53 65535: (Ljdk/test/lib/apps/LingeredApp;[Ljava/lang/String;)V
13 65535: setForceCrash
128 65535: (Ljava/lang/String;Ljdk/internal/logger/LazyLoggers$LazyLoggerFactories;Ljava/lang/Module;Ljava/util/function/BooleanSupplier;)V
];
 stderr: []
 exitValue = 0

java.lang.RuntimeException: '17 2: jdk/test/lib/apps
' missing from stdout/stderr
	at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:242)
	at DynamicSharedSymbols.doTest(DynamicSharedSymbols.java:93)
	at DynamicSharedSymbols.testDefaultBase(DynamicSharedSymbols.java:58)
	at DynamicArchiveTestBase.runTest(DynamicArchiveTestBase.java:76)
	at DynamicSharedSymbols.main(DynamicSharedSymbols.java:53)
	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:1570)

JavaTest Message: Test threw exception: java.lang.RuntimeException: '17 2: jdk/test/lib/apps
' missing from stdout/stderr
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: '17 2: jdk/test/lib/apps ' missing from stdout/stderr
----------rerun:(36/11223)*----------

There are five sightings of this failure mode in jdk-22+27-2180-tier2.
It appears to be failing on all platforms.
Comments
[jdk21u-fix-request] Approval Request from olivergillespie Clean backport of test assertion fix, required for the backport of JDK-8315559. Risk is low as it is a change in a test assertion only.
19-03-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk21u-dev/pull/154 Date: 2024-01-09 16:46:27 +0000
18-03-2024
The fix for this bug is integrated in jdk-22+27-2186.
04-12-2023
Changeset: 316b7833 Author: Coleen Phillimore <coleenp@openjdk.org> Date: 2023-12-04 18:01:31 +0000 URL: https://git.openjdk.org/jdk/commit/316b78336c9fbf290e6d423f831f9eff1a84bc40
04-12-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/16954 Date: 2023-12-04 16:43:17 +0000
04-12-2023
java.lang.RuntimeException: '17 2: jdk/test/lib/apps This should be 3. [~ogillespie] removed the code that drained the symbol cache at a safepoint at the end of the PR review.
04-12-2023
[~coleenp] - Can you please take a quick look at this regression? It started in jdk-22+27-2180-tier2 and the only changeset is: JDK-8315559 Delay TempSymbol cleanup to avoid symbol table churn We are seeing 5 test failures per Tier2 so it is very noisy.
04-12-2023