一次活動引起的血案

本文來自網易雲社區

做者： 方金德

 「咚咚」，接連收到好幾個報警短信，顯示線上集羣的幾個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

本文來自網易雲社區，經做者方金德受權發佈。

相關文章：
【推薦】 Android 應用防止被二次打包指南
【推薦】 塊存儲、文件存儲、對象存儲這三者的本質差異
【推薦】 感受要火！妹子實地採訪網易豬廠程序員七夕怎麼過