Java 为什么我要的锁不见了
线上遇到问题: 有些 Tomcat 线程卡住了, 卡住的越来越多, 重启虽然能暂时解决, 但不是长期解决办法, 如下图:
确定卡住的线程
随机找一个症状还在的服务器, 获取 thread dump, 看到如下卡住的线程 (截取部分):
"MyTaskExecutor-127" #407 daemon prio=5 os_prio=0 tid=0x00007ff6d0019000 nid=0x1da waiting on condition [0x00007ff4159d7000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000075e438328> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:837)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:872)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1202)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:213)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:951)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
- locked <0x000000075e5b2488> (a java.io.BufferedInputStream)
at sun.net.www.MeteredStream.read(MeteredStream.java:134)
- locked <0x000000075e5b4400> (a sun.net.www.http.KeepAliveStream)
at java.io.FilterInputStream.read(FilterInputStream.java:133)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3471)
可以看出这是一个使用 HTTPS 访问外部请求的操作, 现在卡在了 SSLSocketImpl$AppInputStream.read()
上面, 现在它需要一把锁.
环境信息
Open JDK 1.8.362. 为什么要强调 JDK 版本, 后面会看到JDK涉及到这块的代码改动量非常大, 每个版本代码都不一样.
初步分析
一开始认为是没有设置 read timeout, 导致一直死等. 但是看了应用程序配置, 发现是设置的, 查看heapd dump 里面, 却是也是设置的. 如下图:
为什么设置了 connect 和 read timeout 还死等
根据这个栈可以看出, 连接已经建立(新建或者使用KeepLiveCache里面的), 所以, connect timeout 阶段已经过了, 不管用了.
同时, read time 是在使用 poll() 或者在它的外层 c代码 Java_java_net_SocketInputStream 里面才会计算 read timeout, 所以这里还没到.
这个线程等的锁被谁占用
通过 thread dump 很容易可以看到, 这个锁被下面的线程占着.
"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007ff8508d3000 nid=0x26 in Object.wait() [0x00007ff80f427000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007570016f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x00000007570016f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:188)
Locked ownable synchronizers:
- <0x000000075e438328> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075e438410> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075e613df8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075e6682c0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075e6a3e90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075e6b4070> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075e6c51f8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075ee84098> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000075f636998> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x00000007610a3e08> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x0000000766af21d0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x00000007759c8fd8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000078c1bed50> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000078d6fb888> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000078e2b8ff0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000078f448fc8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000078f592e50> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000078f5a9430> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x000000078f5bed40> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
从上面的信息中看到, 这个Finalizer
线程的 Locked ownable synchronizers
部分看, 它占有了很多锁. 其中第一个就是我们之前线程正想要获取的锁.
那么这个 Finalizer 在干嘛?
从上面的栈信息, 结合具体的源代码, 可以看到这个 Finalizer
线程其实在等下一个需要 finalize()
方法的对象. 并且当前没有在排队的对象(从heap dump)可以看到:
矛盾的现象
这个线程拥有了这把锁(其实它拥有很多把锁, 从上面Locked ownable synchronizers
可以看到), 却没有在使用这把锁做事情, 反而现在没有任何事情在做. 那么它就没有可能释放这把锁. 也就是说, 它曾经获得了这把锁, 但是没办法释放这把锁.
那么任何在等这把锁的对象, 都面临着永远等不来的情况.
为什么会造成这种情况
从现在的数据来看, 这种情况发生的几率很小, 没几天才能发生一次. 从已有的数据看, 很有可能是 Finalizer
线程在执行 sun.security.ssl.SSLSocketImpl
的 finalize()
方法的时候, 获得了这把锁, 然而却没释放.
于是去查看这个版本的sun.security.ssl.SSLSocketImpl
的源代码, 发现几乎每处使用这个锁的地方都是 try{}finally{} 方式, 在 finally{} 代码块里去释放的锁. 所以正常执行完不可能不释放.
唯一的可能性就是: finalize()
方法没有正常执行完. 在获得锁还没有释放锁的位置, finalize()
方法被中断了. 在JDK 里面, 根本不保证 finalize()
一定被执行, 什么时候被执行, 以及是不是执行完. 所以在 JDK 9 之后 finalize()
就被 deprecated 了.
思考
如果这个 sun.security.ssl.SSLSocketImpl
已经被开始执行 finalize()
方法, 那么它在某个时间点, 已经被 JVM GC 判定为不可达. 那么肯定有一种神秘的力量把它从死神哪里拉回来了. 并且现在正在被另外一个线程使用.
当一个 AbstractOwnableSynchronizer
的锁被一个线程使用的时候, 它会记录拥有锁的线程名字到它的 exclusiveOwnerThread
字段. 从heap dump, 我们可以证实这个锁也是被 Finalizer
拥有.
这里的线程是 Finalizer
, state 是1, 表示这个 ReentrantLock$NonfairSync 被进入一次.