Bug 63251 - [JDK-8194653] Deadlock in FileSystems.getDefault on catalina startup
Summary: [JDK-8194653] Deadlock in FileSystems.getDefault on catalina startup
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 9.0.14
Hardware: PC Linux
: P2 major (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-03-09 13:11 UTC by Dmitry Bedrin
Modified: 2019-03-15 16:54 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Dmitry Bedrin 2019-03-09 13:11:07 UTC
Tomcat 9.0.14 fails to start with default logging settings intermittently.
Thread dump shows a dead lock (known issue in JRE: https://bugs.openjdk.java.net/browse/JDK-8194653)

Other libraries like Gatling, Payara and others workaround it by calling FileSystems.getDefault from main thread before starting other threads.

Full thread dump OpenJDK 64-Bit Server VM (25.201-b10 mixed mode):

"FileHandlerLogFilesCleaner-1" #11 daemon prio=5 os_prio=0 tid=0x00007fcfc41c4000 nid=0x27 waiting for monitor entry [0x00007fcf8fffa000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.lang.Runtime.loadLibrary0(Runtime.java:862)
	- waiting to lock <0x000000008001a690> (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.DelegatingConstructorAccessorImpl.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.io.File.toPath(File.java:2234)
	- locked <0x0000000080b1c268> (a java.io.File)
	at org.apache.juli.FileHandler.streamFilesForDelete(FileHandler.java:559)
	at org.apache.juli.FileHandler.lambda$clean$0(FileHandler.java:546)
	at org.apache.juli.FileHandler$$Lambda$1/20132171.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

"AsyncFileHandlerWriter-1259475182" #10 daemon prio=5 os_prio=0 tid=0x00007fcfc4141800 nid=0x25 waiting on condition [0x00007fcfb41f8000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000008011cac8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522)
	at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684)
	at org.apache.juli.AsyncFileHandler$LoggerThread.run(AsyncFileHandler.java:159)

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007fcfc40cd800 nid=0x1c runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fcfc40c6800 nid=0x1b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fcfc40c4000 nid=0x1a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fcfc40c2000 nid=0x19 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fcfc407a800 nid=0x18 in Object.wait() [0x00007fcfb47fe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000080008ed0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x0000000080008ed0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fcfc4078000 nid=0x17 in Object.wait() [0x00007fcfc81c6000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000080006bf8> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x0000000080006bf8> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007fcfc400a800 nid=0x15 in Object.wait() [0x00007fcfcb86e000]
   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:235)
	at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1830)
	at java.lang.Runtime.loadLibrary0(Runtime.java:870)
	- locked <0x000000008001a690> (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.DelegatingConstructorAccessorImpl.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 <0x000000008005db60> (a sun.security.jca.ProviderConfig)
	at sun.security.jca.ProviderList.getProvider(ProviderList.java:233)
	at sun.security.jca.ProviderList.getIndex(ProviderList.java:263)
	at sun.security.jca.ProviderList.getProviderConfig(ProviderList.java:247)
	at sun.security.jca.ProviderList.getProvider(ProviderList.java:253)
	at java.net.URL.getURLStreamHandler(URL.java:1159)
	at java.net.URL.<init>(URL.java:421)
	at sun.misc.URLClassPath$JarLoader.<init>(URLClassPath.java:822)
	at sun.misc.URLClassPath$3.run(URLClassPath.java:575)
	at sun.misc.URLClassPath$3.run(URLClassPath.java:565)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.misc.URLClassPath.getLoader(URLClassPath.java:564)
	at sun.misc.URLClassPath.getLoader(URLClassPath.java:529)
	- locked <0x00000000808c3b48> (a sun.misc.URLClassPath)
	at sun.misc.URLClassPath.getNextLoader(URLClassPath.java:494)
	- locked <0x00000000808c3b48> (a sun.misc.URLClassPath)
	at sun.misc.URLClassPath.getResource(URLClassPath.java:248)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
	- locked <0x00000000808cf780> (a java.lang.Object)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	at org.apache.catalina.startup.Bootstrap.init(Bootstrap.java:263)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:461)
	- locked <0x000000008086db40> (a java.lang.Object)

"VM Thread" os_prio=0 tid=0x00007fcfc406e800 nid=0x16 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007fcfc40d0800 nid=0x1d waiting on condition 

JNI global references: 322

Heap
 def new generation   total 157248K, used 13977K [0x0000000080000000, 0x000000008aaa0000, 0x00000000aaaa0000)
  eden space 139776K,  10% used [0x0000000080000000, 0x0000000080da67d8, 0x0000000088880000)
  from space 17472K,   0% used [0x0000000088880000, 0x0000000088880000, 0x0000000089990000)
  to   space 17472K,   0% used [0x0000000089990000, 0x0000000089990000, 0x000000008aaa0000)
 tenured generation   total 349568K, used 0K [0x00000000aaaa0000, 0x00000000c0000000, 0x0000000100000000)
   the space 349568K,   0% used [0x00000000aaaa0000, 0x00000000aaaa0000, 0x00000000aaaa0200, 0x00000000c0000000)
 Metaspace       used 6094K, capacity 6240K, committed 6400K, reserved 1056768K
  class space    used 664K, capacity 741K, committed 768K, reserved 1048576K
Comment 1 Mark Thomas 2019-03-15 16:54:38 UTC
Thanks for the report and the stack trace showing the problem.

Fixed in:
- master for 9.0.18 onwards
- 8.5.x for 8.5.40 onwards
- 7.0.x for 7.0.94 onwards