背景
線上環境一個後臺專案,提供基於dubbo實現的事件分發服務,最近突然出現心跳超時。
問題分析
檢查記憶體是否溢位
jstat -gcutil 8166 1000
意料之中,記憶體正常,因為內部有接入記憶體溢位告警,如果是記憶體溢位應該有收到通知,但是這次沒有溢位通知。
檢視執行緒棧
jstack -l 8166
發現有大量DubboServerHandler
開頭的執行緒阻塞在一個同樣的地方,脫敏簡化後資訊如下:
"DubboServerHandler-192.168.160.42:9184-thread-200" #372 daemon prio=5 os_prio=0 tid=0x0000000002342000 nid=0x252b waiting on condition [0x00007f2ce8deb000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000008a51c930> (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:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at com.▇▇▇▇▇▇.QueueMiddleComponent.save(QueueMiddleComponent.java:317)
...
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:81)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
可以看到執行緒正在申請加鎖,找到相關人員確認了這個不是業務程式碼而是我們自己內部封裝的一個框架邏輯,於是找到對應的專案程式碼拉到本地。
找到對應的執行程式碼段
final ReentrantLock writeLock = this.writeLock;
writeLock.lock();
WriteBatch wb = createWriteBatch();
try {
//業務程式碼
} finally {
try {
wb.close();
writeLock.unlock();
} catch (IOException e) {
writeLock.unlock();
throw new IllegalStateException(e.getMessage());
}
}
加鎖的程式碼就是writeLock.lock();
這一句,而當前物件的writeLock
是一個私有欄位,只有透過這裡加鎖和解鎖,於是懷疑是其他執行緒獲取到該鎖以後執行阻塞了。
但是透過檢查完整的執行緒棧,發現並沒有其他執行緒阻塞在該方法獲取到鎖以後的情況。
檢視記憶體物件
jmap -dump:format=b,file=8166.dump 8166
透過以上命令匯出記憶體dump檔案下載到本地,使用VisualVM載入dump檔案。
找到QueueMiddleComponent
物件,發現只有一個例項,其中writeLock
欄位的關鍵資訊如下
可以看到這個鎖當前被名為DubboServerHandler-192.168.160.42:9184-thread-93
的執行緒所持有,於是再從執行緒棧裡面找到這個執行緒的當前棧資訊
"DubboServerHandler-192.168.160.42:9184-thread-93" #259 daemon prio=5 os_prio=0 tid=0x0000000004b92800 nid=0x22b5 waiting on condition [0x00007f2cedc33000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000008a518f80> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:924)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
可以看到這個執行緒已經執行完框架層的程式碼,正在等待新的請求,意味著這個鎖已經不會再被釋放了,那麼是什麼原因導致這個執行緒在執行完框架程式碼的時候沒有釋放writeLock
這個鎖的呢?
定位原因
相信眼尖的同學已經發現了上面那段加鎖解鎖程式碼中的問題了,解釋如下
try {
//如果wb.close()丟擲異常,則不會執行unlock
wb.close();
writeLock.unlock();
} catch (IOException e) {
//如果丟擲的不是IOException,則不會執行unlock
writeLock.unlock();
throw new IllegalStateException(e.getMessage());
}
就是說在程式碼wb.close()
執行的時候丟擲了非IOException
異常,然後沒有被捕獲住,所以導致釋放鎖程式碼writeLock.unlock();
沒有被執行就結束了。
解決問題
知道了原因,解決就簡單了,只要稍微改造一下就可以了
try {
wb.close();
} catch (IOException e) {
throw new IllegalStateException(e.getMessage());
} finally {
writeLock.unlock();
}
只要把writeLock.unlock();
程式碼移動到finally
塊中,保證即時出現異常,也能正常解鎖就行了。
總結
簡單來說,這是一次使用鎖不恰當而導致的連鎖反應,,因為其中一個執行緒異常退出沒有解鎖,導致其他進來的執行緒一旦進入到這個方法就會被阻塞,dubbo的執行緒數是有限的(預設200),當所有執行緒都被阻塞的時候,dubbo就完全不能提供服務了。
吸取一下經驗
- 解鎖程式碼要放在
finally
塊中,保證即使執行緒異常,也能正常解鎖。 - 如果需要加鎖執行的程式碼,最好能做成非同步執行,這樣即使阻塞也只是阻塞非同步執行緒池,不會影響主工作執行緒的正常執行。