JDK-8245514 : appcds/XShareAutoWithChangedJar.java failed "assert(_reserved >= sz) failed: Negative amount"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 15
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: windows
  • CPU: x86_64
  • Submitted: 2020-05-20
  • Updated: 2020-05-26
  • Resolved: 2020-05-26
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 15
15Resolved
Related Reports
Duplicate :  
Relates :  
Relates :  
Description
The following test failed in the JDK15 CI:

runtime/cds/appcds/XShareAutoWithChangedJar.java

Here's a snippet from the log file:

----------System.err:(47/3358)*----------
 stdout: [[0.050s][info][cds] trying to map T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_cds_relocation\\scratch\\3\\appcds-22h26m45s277.jsa
[0.051s][info][cds] Archive was created with UseCompressedOops = 1, UseCompressedClassPointers = 1
[0.051s][info][cds] Try to map archive(s) at an alternative address
[0.051s][debug][cds] Reserved archive_space_rs     [0x000001f4af6d0000 - 0x000001f4b0250000] (12058624) bytes
[0.051s][debug][cds] Reserved class_space_rs [0x000001f4b0250000 - 0x000001f4f0250000] (1073741824) bytes
[0.051s][info ][cds] Commit static  region #0 at base 0x000001f4af6d0000 top 0x000001f4af6e0000 (MiscCode) exec
[0.051s][info ][cds] Mapped static  region #0 at base 0x000001f4af6d0000 top 0x000001f4af6e0000 (MiscCode)
[0.051s][info ][cds] Commit static  region #1 at base 0x000001f4af6e0000 top 0x000001f4afb10000 (ReadWrite)
[0.055s][info ][cds] Mapped static  region #1 at base 0x000001f4af6e0000 top 0x000001f4afb10000 (ReadWrite)
[0.055s][info ][cds] Commit static  region #2 at base 0x000001f4afb10000 top 0x000001f4b0250000 (ReadOnly)
[0.061s][info ][cds] Mapped static  region #2 at base 0x000001f4afb10000 top 0x000001f4b0250000 (ReadOnly)
[0.071s][info ][cds] UseSharedSpaces: A jar file is not the one used while building the shared archive file: T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_cds_relocation\\classes\\1\\runtime\\cds\\appcds\\XShareAutoWithChangedJar.d\\XShareAutoWithChangedJar.jar
[0.071s][debug][cds] Released shared space (archive+classes) 0x000001f4af6d0000
# To suppress the following error report, specify this argument
# after -XX: or in .hotspotrc:  SuppressErrorAt=\\services/virtualMemoryTracker.hpp:57
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (t:\\workspace\\open\\src\\hotspot\\share\\services/virtualMemoryTracker.hpp:57), pid=7528, tid=3052
#  assert(_reserved >= sz) failed: Negative amount
#
# JRE version:  (15.0+24) (fastdebug build )
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 15-ea+24-1166, mixed mode, sharing, tiered, compressed oops, g1 gc, windows-amd64)
# Core dump will be written. Default location: T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_cds_relocation\\scratch\\3\\hs_err_pid7528.mdmp
#
# An error report file with more information is saved as:
# T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_cds_relocation\\scratch\\3\\hs_err_pid7528.log
#
#
];
 stderr: []
 exitValue = 1

java.lang.RuntimeException: 'Hello World' missing from stdout/stderr 

	at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:196)
	at XShareAutoWithChangedJar.main(XShareAutoWithChangedJar.java:49)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298)
	at java.base/java.lang.Thread.run(Thread.java:832)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: 'Hello World' missing from stdout/stderr


test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: 'Hello World' missing from stdout/stderr

Here's the crashing thread's stack:

---------------  T H R E A D  ---------------

Current thread (0x000001f48ca129f0):  JavaThread "Unknown thread" [_thread_in_vm, id=3052, stack(0x0000000816900000,0x0000000816a00000)]

Stack: [0x0000000816900000,0x0000000816a00000]
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [jvm.dll+0xa320b1]  os::platform_print_native_stack+0xf1  (os_windows_x86.cpp:369)
V  [jvm.dll+0xc443c6]  VMError::report+0xf86  (vmError.cpp:729)
V  [jvm.dll+0xc45bbe]  VMError::report_and_die+0x7ee  (vmError.cpp:1528)
V  [jvm.dll+0xc46274]  VMError::report_and_die+0x64  (vmError.cpp:1321)
V  [jvm.dll+0x431ec7]  report_vm_error+0x117  (debug.cpp:264)
V  [jvm.dll+0xc3a4a3]  VirtualMemorySummary::record_released_memory+0x73  (virtualMemoryTracker.hpp:146)
V  [jvm.dll+0xc3a71b]  VirtualMemoryTracker::remove_released_region+0x16b  (virtualMemoryTracker.cpp:466)
V  [jvm.dll+0xa2256a]  os::release_memory+0x8a  (os.cpp:1755)
V  [jvm.dll+0xc40b31]  ReservedSpace::release+0x41  (virtualspace.cpp:277)
V  [jvm.dll+0x9a7930]  MetaspaceShared::map_archives+0x530  (metaspaceShared.cpp:2241)
V  [jvm.dll+0x9a6b70]  MetaspaceShared::initialize_runtime_shared_and_meta_spaces+0x1b0  (metaspaceShared.cpp:2092)
V  [jvm.dll+0x99df05]  Metaspace::global_initialize+0x45  (metaspace.cpp:1241)
V  [jvm.dll+0xc09f46]  universe_init+0x176  (universe.cpp:666)
V  [jvm.dll+0x5df900]  init_globals+0x90  (init.cpp:117)
V  [jvm.dll+0xbdb879]  Threads::create_vm+0x789  (thread.cpp:3887)
V  [jvm.dll+0x6b80de]  JNI_CreateJavaVM_inner+0xbe  (jni.cpp:3776)
V  [jvm.dll+0x6baf5f]  JNI_CreateJavaVM+0x1f  (jni.cpp:3859)
C  [jli.dll+0x53f7]  JavaMain+0x113  (java.c:417)
C  [ucrtbase.dll+0x21ffa]
C  [KERNEL32.DLL+0x17974]
C  [ntdll.dll+0x6a261]
Comments
"Fixed" is reserved for issues that have a changeset pushed using that issue id. Closing as a duplicate of JDK-8243392.
26-05-2020

This was fixed as a side effect of the CDS remodelling with JDK-8243392
26-05-2020

Found it. Conditions: - Windows, so special handling for mapping - ArchiveRelocationMode=1 - a broken jsa file which should lead to MAP_ARCHIVE_OTHER_FAILURE when trying to map and, important, as intermittent condition: - a **real** (not fake due to ArchiveRelocationMode) mapping error. Analyzing jtr output and souce code: ----------System.err:(47/3358)*---------- stdout: [[0.050s][info][cds] trying to map T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_cds_relocation\\scratch\\3\\appcds-22h26m45s277.jsa [0.051s][info][cds] Archive was created with UseCompressedOops = 1, UseCompressedClassPointers = 1 [0.051s][info][cds] Try to map archive(s) at an alternative address [0.051s][debug][cds] Reserved archive_space_rs [0x000001f4af6d0000 - 0x000001f4b0250000] (12058624) bytes [0.051s][debug][cds] Reserved class_space_rs [0x000001f4b0250000 - 0x000001f4f0250000] (1073741824) bytes [0.051s][info ][cds] Commit static region #0 at base 0x000001f4af6d0000 top 0x000001f4af6e0000 (MiscCode) exec [0.051s][info ][cds] Mapped static region #0 at base 0x000001f4af6d0000 top 0x000001f4af6e0000 (MiscCode) [0.051s][info ][cds] Commit static region #1 at base 0x000001f4af6e0000 top 0x000001f4afb10000 (ReadWrite) [0.055s][info ][cds] Mapped static region #1 at base 0x000001f4af6e0000 top 0x000001f4afb10000 (ReadWrite) [0.055s][info ][cds] Commit static region #2 at base 0x000001f4afb10000 top 0x000001f4b0250000 (ReadOnly) [0.061s][info ][cds] Mapped static region #2 at base 0x000001f4afb10000 top 0x000001f4b0250000 (ReadOnly) [0.071s][info ][cds] UseSharedSpaces: A jar file is not the one used while building the shared archive file: T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_cds_relocation\\classes\\1\\runtime\\cds\\appcds\\XShareAutoWithChangedJar.d\\XShareAutoWithChangedJar.jar - We enter MetaspaceShared::initialize_runtime_shared_and_meta_spaces() First round (use_requested_addr=true). - We attempt to map at default archive base (0x800000000) -> MetaspaceShared::map_archives(use_requested_addr=true) -> MetaspaceShared::reserve_address_space_for_archives(use_requested_addr=true) - Here we only attempt to reserve the class space, not the archive space, since this is Windows. - Reserving the range for the class space fails due to ASLR. - We return to caller without much ado, returning MAP_ARCHIVE_MMAP_FAILURE. Second round (use_requested_addr=false): "[0.051s][info][cds] Try to map archive(s) at an alternative address" - We call MetaspaceShared::map_archives(use_requested_addr=false) -> MetaspaceShared::reserve_address_space_for_archives(use_requested_addr=false) - We reserve one big space for archive + ccs. We split this in two. - this causes the following sequence of calls under the hood (see os::split_reserved_memory) : 1. os::reserve_memory(whole range) 2. os::release_memory(whole range) 3. os::reserve_memory(archive) 4. os::reserve_memory(ccs) - So, at NMT level we now have registered two separate regions, one for the archive one for the base. - But this is not reflected by the ReservedSpace classes. main_rs still refers to the whole address range: main_rs = (archive_rs + class_rs). - We return success. "[0.051s][debug][cds] Reserved archive_space_rs [0x000001f4af6d0000 - 0x000001f4b0250000] (12058624) bytes" "[0.051s][debug][cds] Reserved class_space_rs [0x000001f4b0250000 - 0x000001f4f0250000] (1073741824) bytes" - we map in static archive. That works. - we map in dynamic archive. This fails as intended, since the jsa is mismatched: "[0.071s][info ][cds] UseSharedSpaces: A jar file is not the one used while building the shared archive ... " - We then roll back everything: unmap_archive(static_mapinfo); unmap_archive(dynamic_mapinfo); These two are noops. Since we read the content of the jsa sequentially (wiondows special handling) release_reserved_spaces(main_rs, archive_space_rs, class_space_rs); Here is the error: At this point, main_rs range encompasses both archive and ccs. But this conflicts with NMT, since NMT only knows the split up version. So when we release main_rs: void MetaspaceShared::release_reserved_spaces(ReservedSpace& main_rs, ReservedSpace& archive_space_rs, ReservedSpace& class_space_rs) { if (main_rs.is_reserved()) { assert(main_rs.contains(archive_space_rs.base()), "must be"); assert(main_rs.contains(class_space_rs.base()), "must be"); log_debug(cds)("Released shared space (archive+classes) " INTPTR_FORMAT, p2i(main_rs.base())); main_rs.release(); <<<< assert here } else { .... } } we assert, since the mapping NMT knows of starting at main_rs base is the archive space, which is smaller than main_rs. --- This error occurs with the test only if the first attempt to map class space failed since if it succeeds, the bad jsa file causes an error in the first round (use_requested_addr=true) already, we never enter the second round (use_requested_addr=false). This may indicate a testing hole somewhere. --- Actually this is a simple coding error: when doing a split of a ReservedSpace (with split=true, so a real split) one must not refer to the original space anymore since it became invalid. The API (ReservedSpace::first_part) does not say so explicitly, but it should, so maybe one should update the comment. It will be solved with https://bugs.openjdk.java.net/browse/JDK-8243392 is pushed since it removes the ambiguity between main_rs and (archive_rs+ccs_rs). Also, https://bugs.openjdk.java.net/browse/JDK-8243535 will change things.
21-05-2020

This issue will be fixed by the remodelling of CDS/CCS reservation.
21-05-2020

It has only failed once so far in our tier 4 testing, but we haven't yet hit another tier 4 since then. The CI run contained the following changesets, none of which seem obviously relevant: 2020-05-20 13:56 stuefe: 0c21a8 - OpenJDK 8244733 Add ResourceHashtable::xxx_if_absent 2020-05-20 13:24 shade: 3df431 - OpenJDK 8245463 Shenandoah: refine ShenandoahPhaseTimings constructor arguments 2020-05-20 13:24 shade: df7076 - OpenJDK 8245461 Shenandoah: refine mode name()-s 2020-05-20 13:20 eosterlund: a4b9bc - OpenJDK 8244416 Remove incorrect assert during inline cache cleaning 2020-05-20 13:00 jlaskey: b01b57 - OpenJDK 8245398 Remove addition preview adornment from String::formatted The failure occurred with these flags: -J-Dtest.java.opts='-XX:+UnlockDiagnosticVMOptions -XX:ArchiveRelocationMode=1 -Xlog:cds=debug -XX:NativeMemoryTracking=detail'
21-05-2020

I'll take a look since I am in that area. Since when does this occur? Reproducable or intermittent?
21-05-2020