Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

classic Classic list List threaded Threaded
10 messages Options
Reply | Threaded
Open this post in threaded view
|

Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Vitaly Davidovich
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.<init>(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.NativeConstructorAccessorImpl.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$DefaultFileSystemHolder$1.run(
FileSystems.java:98)

                at java.nio.file.FileSystems$DefaultFileSystemHolder$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.getDefault(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.getDefault(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.loadLibrary(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.NativeConstructorAccessorImpl.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.getInstance(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.SQLServerConnection.login(
SQLServerConnection.java:1627)

                at com.microsoft.sqlserver.jdbc.SQLServerConnection.
connectInternal(SQLServerConnection.java:1458)

                at com.microsoft.sqlserver.jdbc.SQLServerConnection.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>.TestConnectionFactories.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/1392419022.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
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Vitaly Davidovich
Sorry, I should've mentioned that this is 8u152.

On Wed, Jan 3, 2018 at 11:56 AM, Vitaly Davidovich <[hidden email]>
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.UnixNativeDispatche
> r$1.run(UnixNativeDispatcher.java:573)
>
>                 at sun.nio.fs.UnixNativeDispatche
> r$1.run(UnixNativeDispatcher.java:571)
>
>                 at java.security.AccessController.doPrivileged(Native
> Method)
>
>                 at sun.nio.fs.UnixNativeDispatche
> r.<clinit>(UnixNativeDispatcher.java:571)
>
>                 at sun.nio.fs.UnixFileSystem.<ini
> t>(UnixFileSystem.java:67)
>
>                 at sun.nio.fs.LinuxFileSystem.<in
> it>(LinuxFileSystem.java:39)
>
>                 at sun.nio.fs.LinuxFileSystemProv
> ider.newFileSystem(LinuxFileSystemProvider.java:46)
>
>                 at sun.nio.fs.LinuxFileSystemProv
> ider.newFileSystem(LinuxFileSystemProvider.java:39)
>
>                 at sun.nio.fs.UnixFileSystemProvi
> der.<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.DelegatingConstruc
> torAccessorImpl.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.DefaultFileSystemPr
> ovider.createProvider(DefaultFileSystemProvider.java:48)
>
>                 at sun.nio.fs.DefaultFileSystemPr
> ovider.create(DefaultFileSystemProvider.java:63)
>
>                 at java.nio.file.FileSystems$Defa
> ultFileSystemHolder.getDefaultProvider(FileSystems.java:108)
>
>                 at java.nio.file.FileSystems$Defa
> ultFileSystemHolder.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$Defa
> ultFileSystemHolder.defaultFileSystem(FileSystems.java:96)
>
>                 at java.nio.file.FileSystems$Defa
> ultFileSystemHolder.<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.s
> etup(ServiceLoader.java:446)
>
>                 at <some_package>.MetadataAdminLo
> ader.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$ExtClassLoad
> er.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.DelegatingConstruc
> torAccessorImpl.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.ProviderConfi
> g$2.run(ProviderConfig.java:221)
>
>                 at sun.security.jca.ProviderConfi
> g$2.run(ProviderConfig.java:206)
>
>                 at java.security.AccessController.doPrivileged(Native
> Method)
>
>                 at sun.security.jca.ProviderConfi
> g.doLoadProvider(ProviderConfig.java:206)
>
>                 at sun.security.jca.ProviderConfi
> g.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.g
> etInstance(GetInstance.java:157)
>
>                 at javax.net.ssl.SSLContext.getIn
> stance(SSLContext.java:156)
>
>                 at com.microsoft.sqlserver.jdbc.T
> DSChannel.enableSSL(IOBuffer.java:1658)
>
>                 at com.microsoft.sqlserver.jdbc.S
> QLServerConnection.connectHelper(SQLServerConnection.java:1976)
>
>                 at com.microsoft.sqlserver.jdbc.S
> QLServerConnection.login(SQLServerConnection.java:1627)
>
>                 at com.microsoft.sqlserver.jdbc.S
> QLServerConnection.connectInternal(SQLServerConnection.java:1458)
>
>                 at com.microsoft.sqlserver.jdbc.S
> QLServerConnection.connect(SQLServerConnection.java:772)
>
>                 at com.microsoft.sqlserver.jdbc.S
> QLServerDriver.connect(SQLServerDriver.java:1168)
>
>                 at java.sql.DriverManager.getConn
> ection(DriverManager.java:664)
>
>                 at java.sql.DriverManager.getConn
> ection(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>.StatementCachin
> gConnectionImpl.<init>(StatementCachingConnectionImpl.java:54)
>
>                 at <some_package>.TestConnectionF
> actories$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.se
> tupConnections(SedaExecutor.java:130)
>
>                 at <some_package>.SedaExecutor$Se
> daThreadFactory.lambda$newThread$0(SedaExecutor.java:165)
>
>                 at <some_package>.SedaExecutor$Se
> daThreadFactory$$Lambda$22/1392419022.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
>
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Alan Bateman
In reply to this post by Vitaly Davidovich
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.

-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.<init>(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.NativeConstructorAccessorImpl.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$DefaultFileSystemHolder$1.run(
> FileSystems.java:98)
>
>                  at java.nio.file.FileSystems$DefaultFileSystemHolder$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.getDefault(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.getDefault(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.loadLibrary(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.NativeConstructorAccessorImpl.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.getInstance(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.SQLServerConnection.login(
> SQLServerConnection.java:1627)
>
>                  at com.microsoft.sqlserver.jdbc.SQLServerConnection.
> connectInternal(SQLServerConnection.java:1458)
>
>                  at com.microsoft.sqlserver.jdbc.SQLServerConnection.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>.TestConnectionFactories.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/1392419022.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

Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Vitaly Davidovich
On Wed, Jan 3, 2018 at 12:00 PM, Alan Bateman <[hidden email]>
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.

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
>>
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

David Holmes
On 4/01/2018 3:13 AM, Vitaly Davidovich wrote:

> On Wed, Jan 3, 2018 at 12:00 PM, Alan Bateman <[hidden email]>
> 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

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
>>>
>>
>>
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Vitaly Davidovich
On Wed, Jan 3, 2018 at 8:36 PM David Holmes <[hidden email]> wrote:

> On 4/01/2018 3:13 AM, Vitaly Davidovich wrote:
> > On Wed, Jan 3, 2018 at 12:00 PM, Alan Bateman <[hidden email]>
> > 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.

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.

>
>
> 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
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

David Holmes
On 4/01/2018 12:26 PM, Vitaly Davidovich wrote:

>
> On Wed, Jan 3, 2018 at 8:36 PM David Holmes <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     On 4/01/2018 3:13 AM, Vitaly Davidovich wrote:
>      > On Wed, Jan 3, 2018 at 12:00 PM, Alan Bateman
>     <[hidden email] <mailto:[hidden email]>>
>      > 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
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Alan Bateman
In reply to this post by David Holmes
On 04/01/2018 01:35, David Holmes wrote:

>
> 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
Startup and initialization has changed quite a bit since JDK 8. In JDK 9
the file system is initialized early (long before main). However, it
changes again in JDK 10 due to ongoing work to makes things lazy and
improve startup time. Separately, FilePermission and the JarFile support
have been re-written so it should be loaded before any user code
executes. So I think needs to be studied again, I agree with your other
mail to create a bug to track that.

-Alan
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Vitaly Davidovich
On Thu, Jan 4, 2018 at 3:03 AM, Alan Bateman <[hidden email]>
wrote:

> On 04/01/2018 01:35, David Holmes wrote:
>
>>
>> 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
>>
> Startup and initialization has changed quite a bit since JDK 8. In JDK 9
> the file system is initialized early (long before main). However, it
> changes again in JDK 10 due to ongoing work to makes things lazy and
> improve startup time. Separately, FilePermission and the JarFile support
> have been re-written so it should be loaded before any user code executes.
> So I think needs to be studied again, I agree with your other mail to
> create a bug to track that.

Alan, David - thanks for your comments.

Alan - I'm assuming someone from Oracle will file a bug report for this?

>
>
> -Alan
>
Reply | Threaded
Open this post in threaded view
|

Re: Possible VM deadlock due to FileSystems.getDefault and System.loadLibrary interplay

Mandy Chung
In reply to this post by Alan Bateman


On 1/4/18 12:03 AM, Alan Bateman wrote:

> On 04/01/2018 01:35, David Holmes wrote:
>>
>> 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
> Startup and initialization has changed quite a bit since JDK 8. In JDK
> 9 the file system is initialized early (long before main). However, it
> changes again in JDK 10 due to ongoing work to makes things lazy and
> improve startup time. Separately, FilePermission and the JarFile
> support have been re-written so it should be loaded before any user
> code executes. So I think needs to be studied again, I agree with your
> other mail to create a bug to track that.
>

This is indeed a deadlock.   I created
https://bugs.openjdk.java.net/browse/JDK-8194653 to track this.

Mandy