本文來自網易雲社區

作者： 方金德

“咚咚”，接連收到好幾個報警短信，顯示線上集群的幾個tomcat應用的接連端口異常。不好，線上可能出狀況了，訪問網站，果然已經顯示為維護中了。趕緊登陸到服務器，但服務器的cpu，load，內存，io等基本指標都還是挺正常的，應用日誌端也沒有明顯異常信息，不過nginx的訪問日誌的確顯示後端服務器都已基本為504請求超時了。不管那麽多了，距離上次發布已經有幾個小時了，應該不是新版本bug直接導致的問題，先嘗試不回滾重啟吧。於是火速重啟了集群中一個節點，很快線上應用訪問正常了。然後把另外兩個節點的jvm的stack和memory信息導出來後，也重啟後加回到線上。

線上是正常了，但我們其實並沒有找到問題的原因。沒有找到問題的誘因，也就意味著這個問題可能還會再發生。和相關的同事們再一起排查了一遍線上應用日誌和tomcat容器日誌，也沒有發現什麽可挖掘的異常點。再跑到網易的監控平臺看歷史的監控數據，系統層面的cpu、load、 中斷、 memory、 swap、 ioutil、網絡流量等都沒有特別的異常；jvm層面的gc、thread數也都沒有什麽明顯異常。gc沒有問題，直接放棄了memory dump信息的查看。再簡單地看了下jstack信息，好像也沒有什麽異常，統計了下線程數，跟線上的線程數也差不多，猜測應該也不是屬於並發超限吧。。。

最近產品這邊正在做活動，大概的內容是鼓勵用戶邀請好友來註冊。可能是大獎比較對其口味吧，來了幾個不受歡迎的“hacker”用戶。不知道他們在哪搞了一推“真實的“urs賬號，然後通過腳步註冊成為我們的用戶（這裏說一下，我們產品是直接接受新來訪的urs賬號為新註冊用戶的）。最近的日新增用戶數和在線用戶數分別是平常的3和2倍左右，於是有同事懷疑，是不是訪問壓力大了導致？這個懷疑非常應景，但我覺得缺少相應的服務器數據說明。如果是訪問壓力大的原因，不可能cpu，load，網絡流量等都還是比較正常的，而且重啟後也能一直訪問正常。也曾想把這個問題歸結到可憐的雲主機上，因為現在一些節點，由於雲主機超售，到導致cpu steal現象嚴重，load異常偏高，不過確實這個更加沒有根據了，純yy下吧！~ 好了，連活動導致訪問量大這個這麽應景的疑點，也沒法成為癥結。一時間沒了想法，線上系統恢復後也運行的挺正常的（包括服務器、jvm等指標以及日誌信息），加上最近大家的業務開發任務也挺重的，這個問題的根本原因的排查便被當做一個遺留問題，日後再排查吧。當然，作為技術人員，遇到了解決不了的技術問題，肯定是要“不開心”了。。。

帶著這個問題回到了家。平常工作時間思緒比較繁雜，難免導致推斷邏輯毛糙。趁著洗澡時沒什麽雜念，再重新理一遍整個過程。果然是最近腦子不好使了，其實問題還是挺明顯的。服務器各項指標是比較正常的，但是前端的nginx連接過來都是504請求超時，那多半應該是後端的tomcat的請求過程被鎖住了。有可能是請求被死鎖了，也有可能是請求等待內部的其他請求超時了，也就是線程的WAIT或TIMED_WAIT狀態。想到這裏，發現自己下午只是簡單的人肉掃了一下jstack內容和統計了下線程數，真是“too young，too simple，sometime naive”了~ 。

寫個腳步掃一下WAIT線程情況吧，“ cat jstack20141127 | sed -n "/WAIT/,/^$/p" ”，在逐個看下具體的堆棧內容。排除了JMS receiver等正常的情況，發現了一個等待異常非常可疑，具體內容如下圖。這裏我把相關背景這這裏簡單的描述下。這端邏輯發生在我們產品的認證過濾器AuthenticationFilter，

中，主要的邏輯是這樣的，首先是檢查用戶的登錄cookie（例如urs cookie等）是否有效，進而判斷該urs賬號是否已經是我們的用戶，如果是就加載用戶相關信息到session，否則增加該用戶，並更新用戶信息到session。其中，我們增加了使用zookeeper實現的分布式互斥鎖來防止並發 新增相同的用戶記錄。 （這裏順便說下，因為ddb數據庫不支持非均衡字段unique key，所以無法簡單地使用unique key 來實現。當然，使用zookeeper lock來做並發控制本身也是一個更好的選擇，可以避免無謂的錯誤數據庫請求。）

再用腳步掃描了這種問題的個數，多達200個。200這個數字，正好是tomcat默認的maxThreads值。線上的tomcat應用服務器也的確是使用了這個默認值作為應用容器的過載保護。（發生問題的應用所在的雲主機的配置不高，這個配置應該也是合理的。）說也是巧，正在此時，服務器再度報警，癥狀完全一致。不多想了，趕緊重啟，並在間隙中做了必要的場景記錄。可重現的問題，是一顆定時炸彈，必須趕緊修復啊。不過既然問題可以規律性的重現，那麽肯定也會是好解決的~

好了，重新整理下思緒 ，推斷有如下四種可能：

1.lock和unlock不能嚴格匹配保證，存在有節點被lock住了後沒有釋放的情況，導致後續相同key的請求被死鎖。

2.zookeeper的lock機制本身或者我們的應用方式是否存在問題，例如在lock客戶端（即應用服務器）發生重啟或網絡問題時，是否可能會導致lock節點發生釋放泄漏的問題？

3.lock所保護的臨界區代碼塊，內部執行非常緩慢，而外部卻因為好友邀請註冊活動（加上hacker問題）導致請求量偏大。生產持續大於消費，導致並發情況下lock數量累增並超限。

4.基本同上，但是因為 臨界區代碼塊內部邏輯導致發生死鎖。導致lock數量穩增不減，並最後超限。

在逐一分析上述可能之前，我先補充下我們這邊的lock設計。

如上圖，總體的設計思路同JDK的ConcurrentHashMap。每個lockContext代表一個業務場景，包含了業務場景的描述desciription，命名空間namespace（zookeeper的path prefix），和並發度concurrencyLevel（類似於 ConcurrentHashMap的桶數量 ） 。 lockContext會 對輸入key的原生hashcode值做Wang/Jenkins hash計算，再按照 concurrencyLevel取余得到對應lock節點位置。最終index值一樣的key會被放在一個節點（桶）上排隊（等待鎖資源）。例如一個典型的用戶登錄的lock節點位置如下：/prod-edu-share/locks_v2/userLoginSession/102/[ephemeral node] 。這麽做的原因，還是類似於 ConcurrentHashMap的設計初衷，一方面，通過控制桶數量，來控制單位場景使用的資源數（例如zookeeper的節點數，這將限制zookeeper的內存消耗，單個目錄下節點數，以及list子節點內容等操作的性能）；另外一方面，通過 Wang/Jenkins hash等 有效的hash算法，盡可能均勻地根據數據內容對請求進行分割，以提交整體並發度。 正是因為上述設計，在用戶基數大的情況下，不同的用戶訪問也是有可能會因為hash碰撞到被放在一起排隊。不過這本身也是沒有問題的，因為正常情況下， 請求總能夠被快速處理完成，加上 hash算法夠均勻， 桶大小合乎請求並發度需求 ，是不會有功能或者性能問題的。當然，也許可能是現有的hash並發度設置開始顯小了？好吧，不管這麽樣，可以開始分析前面列的四種可能了。

首先，肯定是看case 1，即unlock是否能保證了。仔細的看了unlock的語句位置，它非常準確的立在了正確的finally語句塊裏面，jvm應該可以保證它不會出問題了。接著就看case 2了, zookeeper lock 畢竟也是個遠程服務啊，它本身是否可靠，在系統發生各種異常時（一般是服務器重啟，網絡不穩定等）。前面提到的finally語句塊，只能保證jvm運行時會被運行到，但如果在lock後，unlock執行前，jvm被關閉了呢？再重新仔細去看了zookeeper及lock功能的實現，發現zookeeper lock在實現時已經考慮到這些。lock的排隊節點，采用的是session生命周期的ephemeral node，而sessionId是zookeeper成功連接到服務器後，保留著zookeeper實例裏面，即位置在jvm內存裏面，所以到jvm發生重啟後，sessionId就消失了，亦即服務器端session也是遲早要失效的（這個有效期就是session timeout，可通過客戶端連接參數進行配置，一般是60s），session失效後，改節點就會從排隊中移除，從而不會導致死鎖問題。另外一種情況，就是client jvm沒有重啟，但是網絡不穩定，在這種情況下，如果網絡是短暫問題，你們底層的curator實現會保證unlock操作被重復運行直至連接恢復，刪除操作完成，而網絡問題如果是長期的，curator會重復嘗試直至session timeout後最終fail，但session node還是會在session invalid後被服務器刪除。因此，上述兩種網絡問題，也都不會導致節點刪除泄漏而被死鎖。

既然unlock操作或者session ephemeral node在底層機制上是有保障的，那麽問題就應該出現在臨界區代碼塊的實現上了。事實上，我們在應用這個zookeeper lock的業務場景還是挺廣泛了，但發生WAIT的線程卻只有這個一個業務點，一定程度上也能從側面回應這個結論。由於臨界區代碼的邏輯還是有點多的，這裏我就不貼出來了。大概是判斷member是否存在，沒有就新增member記錄，同時更新用戶附屬的其他表的初始化信息，然後是記錄登錄行為，更新相關營銷信息（ps：這兩者的確是可以異步處理的，可以後續優化，因為不是這個問題的重點，先不提了），最後更新用戶信息到session。而邏輯之所以復雜，是因為我們產品上是支持urs，sns以及一些特殊合作網站等多種賬號體系。但從技術上講，就是一些數據庫操作、日誌操作，cache操作，從代碼上看，也沒有什麽明顯問題（不過事後發現自己還是不夠仔細啊55~）。不管怎樣，還是很容易區分是case3還是4的，因為如果是3，那麽線上處於正確的運行態時，處於WAIT的線程數應該是動態的。jstack下線上服務器把，結果是這個數據基本上是比較穩定的，只升不降，而且即便到了晚上12以後，用戶很少訪問了還是如此。在從zookeeper 服務器端來看，部分桶上的ephemeral node，也是處於只增不刪的狀態。寫了個腳步掃描了下各個桶的臨時節點情況，發現有些大部分節點是正常的，但是個別節點數一直居高不下，例如下圖中其中一個節點下臨時子節點數居然搞到700+，汗 。

綜上，基本可以斷定，是屬於case4的情況，即存在代碼塊的死鎖。那麽到底是哪塊邏輯存在問題呢？而此時，已經夜深人困，還是先洗洗睡吧。

第二天到了公司，與相關同事同步了上述信息和推理。大家隨即檢測相關代碼塊哪裏存在死鎖問題。果然是“不知廬山真面目，只緣身在此山中”啊。其中一個同事很快發現兩個可疑點。一個是從獲取用戶信息時，會通過遠程調用從另外一個產品獲取用戶在那個產品中的信息，該遠程調用會不會也在走類似的認證過濾器時被阻塞呢？（ps:這裏要說明下，因為我們幾個產品間的用戶體系從邏輯上是互通的，在數據庫層面是統一的，但由於歷史問題尚未完成member的服務化，因此需要通過幾個產品共享同一個鎖進行並發控制。 ）針對這個問題，我們再一起仔細看了代碼，發現該遠程調用走的是dubbo服務，因此不會走web的認證過濾器；同時在具體的邏輯裏面，也沒有調用相同的userLoginSession鎖對象，因此可以排除。而另一個可疑點，是前面提到的那個特殊產品提供的賬號登錄驗證的代理服務，這家夥正好是一個基於http的實現，按照其url pattern的定義，會被web認證過濾器掃描到的，盡管該遠程服務其實是不需要也不應該經過認證過濾器的。開發者疏忽了，不管怎樣，先趕緊去除吧。

至此，問題已經明朗了。當存在這種新賬號類型的用戶在應用A上新註冊時，A應用便會先上鎖，然後發遠程請求給應用B，應用B因為相同用戶請求相同的鎖而發生死鎖，非常典型的死鎖實例。。。至於為什麽這個問題之前沒有爆發，最近才爆發，就涉及到一系列的歷史問題了，這裏就不再贅述了。大概是，其中該特殊賬號類型的登錄支持在產品A的加入，以及用戶登錄控制鎖的統一（之前的登錄鎖實現是獨立的，亦即沒有跨產品並發控制效果，後面做了修復），都是最近一段時間才上線的功能。雖然二者確實是引發問題的根本原因，但是該特殊賬號類型的登錄用戶量比較少，問題沒有被暴露出來；而最近的邀請註冊活動導致了大量的新用戶註冊行為，雖然賬號類型是urs為主，但還是會因為hash而碰撞，繼而累積導致http連接池耗盡，是問題的導火線。紙終究還是包不住火啊~

後面問題的解決，還出了點小插曲。就是按照設想，只要把幾個產品的集群都重啟下，就能消除所有的遺留session ephemeral node。然而在重啟完成後，監控相關服務器發現還是存在零星的死鎖線程，在60秒後（session 超時時間）還是如此，並且還在緩慢增加中。。。再分析下，原來是服務器的重啟順序不合理導致。得先把存在問題的產品服務器集群完全重啟完成後，再去重啟其他幾個產品集群。終於，死鎖線程都消失了，再監控了一段時間，也沒有再新增。開心了！~

最後，總結下幾點經驗教訓吧：

1.使用分布式鎖時，一定要檢查所包含的臨界區代碼塊，以及間接調用的同步遠程服務，確保其不會再請求相同的鎖。因為遠程服務不太好像本地線程一樣實現鎖的可重入性。

2.zookeeper非常有必要增加鎖目錄下ephemeral節點數的監控，以便能及時發現潛在的死鎖問題。

3.分析問題時，還是要有局外人的懷疑精神，敢於懷疑一切未經重新驗證的功能點。

4.俗話說，“三國臭皮匠，頂個諸葛亮”，團隊成員之間的分享和討論才是解決問題的關鍵。

網易雲大禮包：https://www.163yun.com/gift

本文來自網易雲社區，經作者方金德授權發布。

相關文章：
【推薦】 一個只有十行的精簡MVVM框架（下篇）
【推薦】 機器學習、深度學習、和AI算法可以在網絡安全中做什麽？
【推薦】 教你如何選擇BI數據可視化工具

一次活動引發的血案