RFR 8187305: Add logging for shared library loads/unloads

Thu Feb 20 15:54:06 UTC 2020

Hi Harold,

after your change we see errors in the test (runtime/logging/loadLibraryTest/LoadLibraryTest.java) across several platforms:

----------System.err:(50/4412)----------
 stdout: [[0.054s][info][library] Failed to find JNI_OnLoad_net in library with handle 0x00000fff8ab7d670
[0.054s][info][library] Loaded library /priv/jvmtests/output_openjdk15_dev_optU_linuxppc64/sapjvm_15/lib/libnet.so, handle 0x0000000010394c60
[0.054s][info][library] Found JNI_OnLoad in library with handle 0x0000000010394c60
[0.054s][info][library] Found inet_pton in library with handle 0x0000000000000000
[0.054s][info][library] Failed to find JNI_OnLoad_nio in library with handle 0x00000fff8ab7d670
[0.055s][info][library] Loaded library /priv/jvmtests/output_openjdk15_dev_optU_linuxppc64/sapjvm_15/lib/libnio.so, handle 0x00000000103954e0
[0.055s][info][library] Found JNI_OnLoad in library with handle 0x00000000103954e0
[0.055s][info][library] Failed to find Java_sun_nio_ch_IOUtil_initIDs in library with handle 0x0000000010394c60
[0.055s][info][library] Found Java_sun_nio_ch_IOUtil_initIDs in library with handle 0x00000000103954e0
[0.055s][info][library] Failed to find Java_sun_nio_ch_IOUtil_iovMax in library with handle 0x0000000010394c60
[0.055s][info][library] Found Java_sun_nio_ch_IOUtil_iovMax in library with handle 0x00000000103954e0
[0.055s][info][library] Failed to find Java_sun_nio_ch_FileChannelImpl_initIDs in library with handle 0x0000000010394c60
[0.055s][info][library] Found Java_sun_nio_ch_FileChannelImpl_initIDs in library with handle 0x00000000103954e0
[0.055s][info][library] Failed to find Java_sun_nio_ch_FileDispatcherImpl_init in library with handle 0x0000000010394c60
[0.055s][info][library] Found Java_sun_nio_ch_FileDispatcherImpl_init in library with handle 0x00000000103954e0
[0.056s][info][library] Failed to find Java_sun_nio_ch_NativeThread_init in library with handle 0x0000000010394c60
[0.056s][info][library] Found Java_sun_nio_ch_NativeThread_init in library with handle 0x00000000103954e0
[0.056s][info][library] Failed to find Java_sun_nio_ch_NativeThread_current in library with handle 0x0000000010394c60
[0.056s][info][library] Found Java_sun_nio_ch_NativeThread_current in library with handle 0x00000000103954e0
[0.056s][info][library] Failed to find Java_sun_nio_ch_FileDispatcherImpl_size0 in library with handle 0x0000000010394c60
[0.056s][info][library] Found Java_sun_nio_ch_FileDispatcherImpl_size0 in library with handle 0x00000000103954e0
[0.062s][info][library] Failed to find Java_sun_nio_ch_FileChannelImpl_map0 in library with handle 0x0000000010394c60
[0.062s][info][library] Found Java_sun_nio_ch_FileChannelImpl_map0 in library with handle 0x00000000103954e0
[0.064s][info][library] Failed to find JNI_OnLoad_LoadLibraryClass in library with handle 0x00000fff8ab7d670
[0.064s][info][library] Failed to find JNI_OnLoad_LoadLibraryClass in library with handle 0x00000fff8ab7d670
[0.099s][info][library] Loaded library /priv/jvmtests/output_openjdk15_dev_optU_linuxppc64/grmpf/testdata/jtreg/jtreg_test_15/test/hotspot/jtreg/native/libLoadLibraryClass.so, handle 0x0000000010399d30
[0.099s][info][library] Failed to find JNI_OnLoad in library with handle 0x0000000010399d30
[0.100s][info][library] Found Java_LoadLibraryClass_nTest in library with handle 0x0000000010399d30
[0.116s][info][library] Failed to find Java_sun_nio_ch_FileChannelImpl_unmap0 in library with handle 0x0000000010394c60
[0.116s][info][library] Found Java_sun_nio_ch_FileChannelImpl_unmap0 in library with handle 0x00000000103954e0
];
 stderr: []
 exitValue = 0

java.lang.RuntimeException: 'Unloaded library with handle' missing from stdout/stderr

Seems like the class unloading mechanism doesn't trigger in the end.

The test failure also happens only for opt builds. Debug builds look fine.

Do you have any idea how the test can be improved?

Thanks
Christoph

> -----Original Message-----
> From: hotspot-runtime-dev <hotspot-runtime-dev-
> bounces at openjdk.java.net> On Behalf Of Harold Seigel
> Sent: Dienstag, 18. Februar 2020 21:27
> To: Thomas Stüfe <thomas.stuefe at gmail.com>
> Cc: hotspot-runtime-dev at openjdk.java.net; Baesken, Matthias
> <matthias.baesken at sap.com>
> Subject: Re: RFR 8187305: Add logging for shared library loads/unloads
> 
> Hi Thomas,
> 
> Thanks for pointing this out.
> 
> The fix for JDK-8187305
> <https://bugs.openjdk.java.net/browse/JDK-8187305> also includes logging
> for JVM_UnloadLibrary() and JVM_FindLibraryEntry().  So the two fixes do
> not completely overlap.  Is it confusing to keep both sets of logging?
> Or, should the JVM_UnloadLibrary() and JVM_FindLibraryEntry() be moved
> into platform dependent code?
> 
> Thanks,  Harold
> 
> On 2/18/2020 3:04 PM, Thomas Stüfe wrote:
> > Hi Harold,
> >
> > First off, thanks a lot for doing this!
> >
> > Unfortunately, our wires got crossed with this. Matthias already added
> > tracing for shared library loading with "8228902: add os::dll_load to
> > the unified logging os category". He did not know about this issue and
> > therefore did not update it.
> >
> > So arguably this issue is a duplicate of 8229802 and should have been
> > closed when 8229802 was pushed.
> >
> > His solution is somewhat more complete since he also reports errors
> > and error details when a library could not be loaded. Since he does
> > tracing in platform dependent code he has more information to trace.
> >
> > But he did not add tests, and I like your tests and it would be nice
> > to have them.
> >
> > Just a proposal, but one possibility would be to remove your tracing
> > from jvm.cpp and change the category of the existing tracing Matthias
> > did to your new category "library". And use the tests to test the
> > existing tracing. What do you think?
> >
> > Sorry again for the confusion and the redundant work!
> >
> > Cheers, Thomas
> >
> >
> >
> >
> >
> > On Fri, Feb 14, 2020 at 2:37 PM Harold Seigel
> > <harold.seigel at oracle.com <mailto:harold.seigel at oracle.com>> wrote:
> >
> >     Thanks David!
> >
> >     I'll use "driver" mode the next time I write a logging test.
> >
> >     Harold
> >
> >     On 2/13/2020 5:26 PM, David Holmes wrote:
> >     > Hi Harold,
> >     >
> >     > Looks good.
> >     >
> >     > Minor nit, in the test you could use "driver" mode.
> >     >
> >     > Thanks,
> >     > David
> >     >
> >     > On 14/02/2020 7:22 am, Harold Seigel wrote:
> >     >> Hi,
> >     >>
> >     >> Please review this small fix to add logging to loading, unloading,
> >     >> and finding entries in shared libraries.
> >     >>
> >     >> Open Webrev:
> >     >>
> http://cr.openjdk.java.net/~hseigel/bug_8187305/webrev/index.html
> >     >>
> >     >> JBS Bug: https://bugs.openjdk.java.net/browse/JDK-8187305
> >     >>
> >     >> The fix was regression tested by running Mach5 tiers 1 and 2 tests
> >     >> and builds on Linux-x64, Solaris, Windows, and Mac OS X, by
> >     running
> >     >> Mach5 tiers 3-5 tests on Linux-x64, and JCK lang and VM tests on
> >     >> Linux-x64.
> >     >>
> >     >> Thanks, Harold
> >     >>
> >