Java 为什么我要的锁不见了

线上遇到问题: 有些 Tomcat 线程卡住了, 卡住的越来越多, 重启虽然能暂时解决, 但不是长期解决办法, 如下图:
TomcatBusyThread.png

确定卡住的线程

随机找一个症状还在的服务器, 获取 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 里面, 却是也是设置的. 如下图:
timeout.png

为什么设置了 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)可以看到:
lock.png

矛盾的现象

这个线程拥有了这把锁(其实它拥有很多把锁, 从上面Locked ownable synchronizers可以看到), 却没有在使用这把锁做事情, 反而现在没有任何事情在做. 那么它就没有可能释放这把锁. 也就是说, 它曾经获得了这把锁, 但是没办法释放这把锁.

那么任何在等这把锁的对象, 都面临着永远等不来的情况.

为什么会造成这种情况

从现在的数据来看, 这种情况发生的几率很小, 没几天才能发生一次. 从已有的数据看, 很有可能是 Finalizer 线程在执行 sun.security.ssl.SSLSocketImplfinalize() 方法的时候, 获得了这把锁, 然而却没释放.

于是去查看这个版本的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 拥有.
lock2.png
这里的线程是 Finalizer, state 是1, 表示这个 ReentrantLock$NonfairSync 被进入一次.

是哪个神秘的力量救活了它?

标签: none

添加新评论