Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay
David Holmes
david.holmes at oracle.com
Thu Jan 4 03:30:15 UTC 2018
On 4/01/2018 12:26 PM, Vitaly Davidovich wrote:
>
> On Wed, Jan 3, 2018 at 8:36 PM David Holmes <david.holmes at oracle.com
> <mailto:david.holmes at oracle.com>> wrote:
>
> On 4/01/2018 3:13 AM, Vitaly Davidovich wrote:
> > On Wed, Jan 3, 2018 at 12:00 PM, Alan Bateman
> <Alan.Bateman at oracle.com <mailto:Alan.Bateman at oracle.com>>
> > wrote:
> >
> >> The stack trace looks like JDK 8 or older. The initialization
> has changed
> >> quite a bit in JDK 9+ and would be interesting to see if you can
> duplicate
> >> it there.
> >>
> > Yes - it's 8u152 as I mentioned in the follow-up email (sorry,
> should've
> > mentioned that initially).
> >
> > Trying this on JDK9 is a bit tricky as the code (and its
> dependencies) in
> > question isn't easily runnable on 9 without quite a bit of work.
> >
> > Do you agree with the deadlock assessment though? That's what it
> looks like
> > to me but wanted to make sure I'm not missing anything.
>
> You're not missing anything. It's a class initialization related
> "deadlock".
>
> Thread A has called FileSystems.getDefault() which is doing <clinit> of
> DefaultFileSystemHolder, which in turn leads to Runtime.loadLibrary0
> which needs to lock the Runtime instance.
>
> Thread B is already doing a loadLibrary and holds the Runtime lock, the
> loadLibrary code then needs to do FileSystems.getDefault() which has to
> load and initialize DefaultFileSystemHolder, but that initialization is
> already in progress so internally the thread does a wait().
>
> So Thread B is waiting for Thread A to finish initialization, but holds
> the monitor lock that Thread A needs to finish the initialization.
> Deadlock.
>
> AFAICS this will still be possible in 9/10/11
>
>
> That’s what I thought - thanks for confirming David. I’m slightly
> surprised this hasn’t been reported before, although perhaps I’ve failed
> in finding the report.
I couldn't find anything either. Although it seems "obvious" upon
analysis it may be very rare to have such an initialization race.
>
> Does this deserve a bug report? I know Hotspot and some core classes in
> the JDK do an elaborate dance to avoid classloading issues, but this is
> “user” code. This has been worked around on our end by forcing the
> default FS to load before this code runs. Perhaps something similar can
> be done as the JDK bootstraps.
Definitely worth a bug report. Not sure what we can do on the JDK side
as I'm unclear whether the default filesystem necessarily gets
initialized after the module system is up.
Cheers,
David
>
>
> Cheers,
> David
>
> > Thanks Alan
> >
> >>
> >> -Alan
> >>
> >>
> >> On 03/01/2018 16:56, Vitaly Davidovich wrote:
> >>
> >>> Hi all,
> >>>
> >>> Consider the following stacktraces of the main app thread and a
> background
> >>> thread:
> >>>
> >>> "main" #1 prio=5 os_prio=0 tid=0x0000000001bfd000 nid=0x1958
> waiting for
> >>> monitor entry [0x00002b98ceba3000]
> >>>
> >>> java.lang.Thread.State: BLOCKED (on object monitor)
> >>>
> >>> at
> java.lang.Runtime.loadLibrary0(Runtime.java:862)
> >>>
> >>> - waiting to lock <0x00000007bf834b20> (a
> >>> java.lang.Runtime)
> >>>
> >>> at java.lang.System.loadLibrary(System.java:1122)
> >>>
> >>> at sun.nio.fs.UnixNativeDispatcher$1.run(
> >>> UnixNativeDispatcher.java:573)
> >>>
> >>> at sun.nio.fs.UnixNativeDispatcher$1.run(
> >>> UnixNativeDispatcher.java:571)
> >>>
> >>> at
> java.security.AccessController.doPrivileged(Native
> >>> Method)
> >>>
> >>> at sun.nio.fs.UnixNativeDispatcher.<clinit>(
> >>> UnixNativeDispatcher.java:571)
> >>>
> >>> at sun.nio.fs.UnixFileSystem.<ini
> >>> t>(UnixFileSystem.java:67)
> >>>
> >>> at sun.nio.fs.LinuxFileSystem.<
> >>> init>(LinuxFileSystem.java:39)
> >>>
> >>> at
> sun.nio.fs.LinuxFileSystemProvider.newFileSystem(
> >>> LinuxFileSystemProvider.java:46)
> >>>
> >>> at
> sun.nio.fs.LinuxFileSystemProvider.newFileSystem(
> >>> LinuxFileSystemProvider.java:39)
> >>>
> >>> at sun.nio.fs.UnixFileSystemProvider.<init>(
> >>> UnixFileSystemProvider.java:56)
> >>>
> >>> at sun.nio.fs.LinuxFileSystemProvider.<init>
> >>> (LinuxFileSystemProvider.java:41)
> >>>
> >>> at
> >>> sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
> >>> Method)
> >>>
> >>> at sun.reflect.NativeConstructorA
> >>> ccessorImpl.newInstance(
> >>> NativeConstructorAccessorImpl.java:62)
> >>>
> >>> at sun.reflect.DelegatingConstructorAccessorI
> >>> mpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> >>>
> >>> at java.lang.reflect.Constructor.
> >>> newInstance(Constructor.java:423)
> >>>
> >>> at java.lang.Class.newInstance(Class.java:442)
> >>>
> >>> at
> sun.nio.fs.DefaultFileSystemProvider.createProvider(
> >>> DefaultFileSystemProvider.java:48)
> >>>
> >>> at sun.nio.fs.DefaultFileSystemProvider.create(
> >>> DefaultFileSystemProvider.java:63)
> >>>
> >>> at
> java.nio.file.FileSystems$DefaultFileSystemHolder.
> >>> getDefaultProvider(FileSystems.java:108)
> >>>
> >>> at
> java.nio.file.FileSystems$DefaultFileSystemHolder.
> >>> access$000(FileSystems.java:89)
> >>>
> >>> at java.nio.file.FileSystems$Defa
> >>> ultFileSystemHolder$1.run(
> >>> FileSystems.java:98)
> >>>
> >>> at java.nio.file.FileSystems$Defa
> >>> ultFileSystemHolder$1.run(
> >>> FileSystems.java:96)
> >>>
> >>> at
> java.security.AccessController.doPrivileged(Native
> >>> Method)
> >>>
> >>> at
> java.nio.file.FileSystems$DefaultFileSystemHolder.
> >>> defaultFileSystem(FileSystems.java:96)
> >>>
> >>> at
> java.nio.file.FileSystems$DefaultFileSystemHolder.<
> >>> clinit>(FileSystems.java:90)
> >>>
> >>> at java.nio.file.FileSystems.getD
> >>> efault(FileSystems.java:
> >>> 176)
> >>>
> >>> at java.nio.file.Paths.get(Paths.java:84)
> >>>
> >>> at <some_package>.ServiceLoader.
> >>> setup(ServiceLoader.java:446)
> >>>
> >>> at <some_package>.MetadataAdminLoader.main(
> >>> MetadataAdminLoader.java:52)
> >>>
> >>>
> >>>
> >>>
> >>>
> >>> "shardDbExecutor-0-pool-0" #33 prio=5 os_prio=0
> tid=0x0000000001ebf000
> >>> nid=0x1d01 in Object.wait() [0x00002b991f941000]
> >>>
> >>> java.lang.Thread.State: RUNNABLE
> >>>
> >>> at java.nio.file.FileSystems.getD
> >>> efault(FileSystems.java:
> >>> 176)
> >>>
> >>> at java.nio.file.Paths.get(Paths.java:138)
> >>>
> >>> at sun.misc.Launcher$ExtClassLoader.findLibrary(
> >>> Launcher.java:224)
> >>>
> >>> at java.lang.ClassLoader.loadLibr
> >>> ary(ClassLoader.java:1830)
> >>>
> >>> at
> java.lang.Runtime.loadLibrary0(Runtime.java:870)
> >>>
> >>> - locked <0x00000007bf834b20> (a
> java.lang.Runtime)
> >>>
> >>> at java.lang.System.loadLibrary(System.java:1122)
> >>>
> >>> at sun.security.ec.SunEC$1.run(SunEC.java:60)
> >>>
> >>> at sun.security.ec.SunEC$1.run(SunEC.java:58)
> >>>
> >>> at
> java.security.AccessController.doPrivileged(Native
> >>> Method)
> >>>
> >>> at sun.security.ec.SunEC.<clinit>(SunEC.java:58)
> >>>
> >>> at
> >>> sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
> >>> Method)
> >>>
> >>> at sun.reflect.NativeConstructorA
> >>> ccessorImpl.newInstance(
> >>> NativeConstructorAccessorImpl.java:62)
> >>>
> >>> at sun.reflect.DelegatingConstructorAccessorI
> >>> mpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> >>>
> >>> at java.lang.reflect.Constructor.
> >>> newInstance(Constructor.java:423)
> >>>
> >>> at java.lang.Class.newInstance(Class.java:442)
> >>>
> >>> at sun.security.jca.ProviderConfig$2.run(
> >>> ProviderConfig.java:221)
> >>>
> >>> at sun.security.jca.ProviderConfig$2.run(
> >>>
> >>> ProviderConfig.java:206)
> >>>
> >>> at
> java.security.AccessController.doPrivileged(Native
> >>> Method)
> >>>
> >>> at
> sun.security.jca.ProviderConfig.doLoadProvider(
> >>> ProviderConfig.java:206)
> >>>
> >>> at sun.security.jca.ProviderConfig.getProvider(
> >>> ProviderConfig.java:187)
> >>>
> >>> - locked <0x00000007bea03f48> (a
> sun.security.jca.
> >>> ProviderConfig)
> >>>
> >>> at sun.security.jca.ProviderList.
> >>> getProvider(ProviderList.java:233)
> >>>
> >>> at sun.security.jca.ProviderList.
> >>> getService(ProviderList.java:331)
> >>>
> >>> at sun.security.jca.GetInstance.
> >>> getInstance(GetInstance.java:157)
> >>>
> >>> at javax.net.ssl.SSLContext.getIn
> >>> stance(SSLContext.java:156)
> >>>
> >>> at com.microsoft.sqlserver.jdbc.
> >>> TDSChannel.enableSSL(IOBuffer.java:1658)
> >>>
> >>> at
> com.microsoft.sqlserver.jdbc.SQLServerConnection.
> >>> connectHelper(SQLServerConnection.java:1976)
> >>>
> >>> at com.microsoft.sqlserver.jdbc.S
> >>> QLServerConnection.login(
> >>> SQLServerConnection.java:1627)
> >>>
> >>> at
> com.microsoft.sqlserver.jdbc.SQLServerConnection.
> >>> connectInternal(SQLServerConnection.java:1458)
> >>>
> >>> at com.microsoft.sqlserver.jdbc.S
> >>> QLServerConnection.connect(
> >>> SQLServerConnection.java:772)
> >>>
> >>> at
> com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(
> >>> SQLServerDriver.java:1168)
> >>>
> >>> at
> java.sql.DriverManager.getConnection(DriverManager.
> >>> java:664)
> >>>
> >>> at
> java.sql.DriverManager.getConnection(DriverManager.
> >>> java:208)
> >>>
> >>> at
> <some_package>.ConnectionPool.createGoodConnection(
> >>> ConnectionPool.java:565)
> >>>
> >>> at
> <some_package>.ConnectionPool.createNewConnection(
> >>> ConnectionPool.java:519)
> >>>
> >>> at <some_package>.ConnectionPool.
> >>> getConnection(ConnectionPool.java:407)
> >>>
> >>> at <some_package>.StatementCachingConnectionImpl
> >>> .setupConnection(StatementCachingConnectionImpl.java:94)
> >>>
> >>> at
> <some_package>.StatementCachingConnectionImpl.<init>(
> >>> StatementCachingConnectionImpl.java:54)
> >>>
> >>> at <some_package>.TestConnectionFactories$
> >>> FaultInjectingConnection.<init>(TestConnectionFactories.java:90)
> >>>
> >>> at <some_package>.TestConnectionF
> >>> actories.lambda$static$3(
> >>> TestConnectionFactories.java:33)
> >>>
> >>> at <some_package>.TestConnectionFactories$$
> >>> Lambda$12/1738236591.newConnection(Unknown Source)
> >>>
> >>> at <some_package>.SedaExecutor.
> >>> setupConnections(SedaExecutor.java:130)
> >>>
> >>> at
> <some_package>.SedaExecutor$SedaThreadFactory.lambda$
> >>> newThread$0(SedaExecutor.java:165)
> >>>
> >>> at
> >>> <some_package>.SedaExecutor$SedaThreadFactory$$Lambda$22/139
> >>> 2419022.run(Unknown
> >>> Source)
> >>>
> >>> at java.lang.Thread.run(Thread.java:748)
> >>>
> >>>
> >>> The application intermittently hangs on startup, and the above
> callstacks
> >>> are present. It seems like there's a deadlock due to
> concurrent class
> >>> loading and default FileSystem initialization (which itself
> triggers class
> >>> loading here).
> >>>
> >>> I wasn't able to find any existing JBS entries reporting
> anything similar.
> >>> Am I seeing this right? Is this a known issue?
> >>>
> >>> Thanks
> >>>
> >>
> >>
>
> --
> Sent from my phone
More information about the core-libs-dev
mailing list