JDK-8249943 : [TESTBUG] runtime/cds/serviceability/transformRelatedClasses/TransformInterfaceAndImplementor.java
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 15,16
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2020-07-23
  • Updated: 2021-09-24
  • Resolved: 2020-09-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 11 JDK 16
11.0.12Fixed 16 b18Fixed
Related Reports
Relates :  
JDK-8253572 - [windows] CDS archive may fail to open with long file names
Relates :  
JDK-8250911 - [windows] os::pd_map_memory error detection broken
Relates :  
JDK-8245925 - G1 allocates EDEN region after CDS has executed GC
Description
Since mid of June (first time observed on June 15) we see on Windows x64 this test failing.

jtr shows:

[0.052s][error][cds       ] failed to map relocation bitmap
Error occurred during initialization of VM
Unable to use shared archive.

(full jtr attached to this issue)

Errors started after:

8245925: G1 allocates EDEN region after CDS has executed GC

We build nightly, so whatever was pushed that day must have caused the bug; but 8245925 seems the most likely candidate.
Comments
Changeset: b66fa8f4 Author: Thomas Stuefe <stuefe@openjdk.org> Date: 2020-09-26 04:12:54 +0000 URL: https://git.openjdk.java.net/jdk/commit/b66fa8f4
26-09-2020
Okay I think I found it. On Windows, we open the archive for reading to read the header. Using os::open(). Which uses _wopen with an UNC pathname, which works with long path names. Then, we attempt to map the different sections of the archive files into the pre-reserved address space. That uses os::map_memory(). That uses WIN32 API in their non-unicode form (CreateFile). That fails if the filename is larger than the OS limit - older windows, or windows 10 with short path names enabled, have still the 260 char limit. In a second attempt, we then retry - under the false assumption that we did not get the desired mapping address. Now we read the whole archive via open() and read(). All but the relocation bitmap, which we still map using os::map_memory(). Which again fails. This is easy to reproduce by starting the jtreg tests from a directory whose path is ~170 characters, since that path + the long jsa file name will bring us above 260 characters. Of course, the machine must have long path names disabled (see https://docs.microsoft.com/en-us/windows/win32/fileio/maximum-file-path-limitation). A longer path for the current directory will cause the jtreg test to fail earlier (javac cannot compile the test). Since this is more of an generic issue I opened JDK-8253572 with the correct bug title and description.
24-09-2020
logged with cds*=debug and os=debug: stdout: [[0.004s][info][cds] Using optimized module handling disabled due to incompatible property: jdk.module.addmods.0=java.instrument [0.004s][debug][os ] Initial active processor count set to 8 [0.005s][info ][os ] SafePoint Polling address, bad (protected) page:0x000002439aa90000, good (unprotected) page:0x000002439aa91000 [0.005s][info ][os ] attempting shared library load of D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\sapjvm_16\\bin\\instrument.dll [0.006s][info ][os ] shared library load of D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\sapjvm_16\\bin\\instrument.dll was successful [0.010s][info ][os ] attempting shared library load of D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\sapjvm_16\\bin\\java.dll [0.010s][info ][os ] shared library load of D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\sapjvm_16\\bin\\java.dll was successful [0.011s][info ][class,load] opened: D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\sapjvm_16\\lib\\modules [0.012s][info ][os ] attempting shared library load of D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\sapjvm_16\\bin\\zip.dll [0.012s][info ][os ] shared library load of D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\sapjvm_16\\bin\\zip.dll was successful [0.012s][info ][class,load] opened: D:\\jvmtests\\output_openjdk16_dev_dbgU_ntamd64\\jtreg_hotspot_tier1_work\\JTwork\\runtime\\cds\\serviceability\\transformRelatedClasses\\TransformInterfaceAndImplementor\\Interface-Implementor.jar [0.018s][info ][os ] attempting shared library load of vmGuestLib [0.020s][info ][os ] shared library load of vmGuestLib was successful [0.039s][info ][cds ] trying to map runtime.cds.serviceability.transformRelatedClasses.TransformInterfaceAndImplementor.java00h46m59s355.jsa [0.039s][info ][cds ] Opened archive runtime.cds.serviceability.transformRelatedClasses.TransformInterfaceAndImplementor.java00h46m59s355.jsa. [0.039s][info ][cds ] Archive was created with UseCompressedOops = 1, UseCompressedClassPointers = 1 [0.040s][info ][cds ] use_optimized_module_handling disabled: archive was created without optimized module handling [0.040s][debug][cds ] Reserved archive_space_rs [0x0000000800000000 - 0x0000000800c00000] (12582912) bytes [0.040s][debug][cds ] Reserved class_space_rs [0x0000000800c00000 - 0x0000000840c00000] (1073741824) bytes [0.040s][info ][cds ] Windows mmap workaround: releasing archive space. A -> [0.040s][info ][os ] ReadFile() failed: GetLastError->6. [0.040s][info ][cds ] Unable to map MiscCode shared space at 0x0000000800000000 [0.040s][debug][cds ] Released shared space (classes) 0x0000000800c00000 B -> [0.040s][info ][cds ] Try to map archive(s) at an alternative address [0.040s][debug][cds ] Reserved archive_space_rs [0x00000243b8000000 - 0x00000243b8c00000] (12582912) bytes [0.040s][debug][cds ] Reserved class_space_rs [0x00000243b8c00000 - 0x00000243f8c00000] (1073741824) bytes C -> [0.040s][info ][cds ] Commit static region #0 at base 0x00000243b8000000 top 0x00000243b8010000 (MiscCode) exec C -> [0.040s][info ][cds ] Mapped static region #0 at base 0x00000243b8000000 top 0x00000243b8010000 (MiscCode) C -> [0.040s][info ][cds ] Commit static region #1 at base 0x00000243b8010000 top 0x00000243b8450000 (ReadWrite) C -> [0.044s][info ][cds ] Mapped static region #1 at base 0x00000243b8010000 top 0x00000243b8450000 (ReadWrite) C -> [0.044s][info ][cds ] Commit static region #2 at base 0x00000243b8450000 top 0x00000243b8ba0000 (ReadOnly) C -> [0.050s][info ][cds ] Mapped static region #2 at base 0x00000243b8450000 top 0x00000243b8ba0000 (ReadOnly) D -> [0.050s][debug][cds,reloc ] runtime archive relocation start E -> [0.050s][info ][os ] CreateFileMapping() failed: GetLastError->87. [0.050s][error][cds ] failed to map relocation bitmap [0.050s][debug][cds ] Released shared space (archive) 0x00000243b8000000 [0.052s][debug][cds ] Released shared space (classes) 0x00000243b8c00000 Error occurred during initialization of VM ------------------- (A) The first attempt to map archives fails due to: "ReadFile() failed: GetLastError->6." (ERROR_INVALID_HANDLE) (os_windows.cpp:5024) (We attempt to map the archive which appearantly has allow_exec set to 1, which activates special handling in os::pd_map_memory() to not map but read the content, see comment). (B) Since we fail, we assume the mapping is wrong and the base address base is occupied (which is not the case) and retry mapping at another address. This time around we activate the special-cds-workaround where we read instead of mapping all archives. (C) which works so okay... (D) and we start relocating. (E) For that we need the relocation bitmap. But again run into a mapping error here: "CreateFileMapping() failed: GetLastError->87." -- I looked at os::pd_map_memory and found that there is a long standing error where error checking is wrong. Both (A) and (E) indicate that the preceeding CreateFile() call actually failed but we did not notice. I filed a bug. https://bugs.openjdk.java.net/browse/JDK-8250911. Lets see if fixing that clears things up here too.
01-08-2020
The unused archiveName variable seems to be relic from an older version of this test: latest: http://hg.openjdk.java.net/jdk/jdk/annotate/f25a5b35e983/test/hotspot/jtreg/runtime/cds/serviceability/transformRelatedClasses/TransformRelatedClasses.java#l69 old: http://hg.openjdk.java.net/jdk/jdk/annotate/dbd59c1da636/hotspot/test/runtime/SharedArchiveFile/serviceability/transformRelatedClasses/TransformRelatedClasses.java#l68 The latest version uses CDSTestUtils.createArchiveAndCheck() which automatically assigns the archive with a unique name that looks like this: runtime.cds.serviceability.transformRelatedClasses.TransformInterfaceAndImplementor.java21h39m39s762.jsa
30-07-2020
I may be missing something but in the test the archiveName variable is unused. Does this mean it is accidentally creating the archive with a name/location that might conflict with other tests?
30-07-2020
According to [~stuefe] only this test has consistently failed in their windows test environment. No other tests have failed. This seems odd. This seems odd. We have never seen this type of failures. Maybe this test produces a particular bit pattern that trips the windows virus scanner? Assigning to Thomas for further investigation.
30-07-2020
ILW = MLM = P4
28-07-2020