事件背景

當事人所在的公司核心業(yè)務是做政府信息化軟件的，就是為政府部門開發(fā)信息化系統。其中有一款信息化軟件是客戶每天需要使用的，并且他們面向的客戶就是老百姓。

某年某月，某地區(qū)信息化系統，周末升級系統以后，后面連續(xù)一周，持續(xù)出現系統不穩(wěn)定、宕機、服務假死、數據庫鎖表等事件。甚至星期五下午，出現三個多小時無法恢復系統，造成惡劣影響。

系統整體運行架構

系統整體架構

相對傳統的一個負載均衡運行架構。系統建設時間比較早(2016年)，沒有分布式框架，就是傳統的SpringMVC+Mybatis架構，并且服務器都是基于Windows Server 2008的。

這套架構是出問題之前的架構，存在比較大的問題，在后續(xù)負載均衡章節(jié)會詳細說明。

事件過程

事件持續(xù)了一周左右，出現了好幾類的嚴重問題。

事故時間軸

事件造成的影響

公司口碑受到重大影響，此次事件公司常務副總、研發(fā)中心經理、主管全部出動，去安撫客戶和解決問題(系統所在地區(qū)是沿海省會級城市，面向百姓，影響比較大)。

出嚴重問題當天，剛好有督查組來訪問，碰到這個事件，機構年度考核扣了好多分。

后續(xù)行機構收到了大量投訴，影響了很多人考評。

事件一：服務假死無法訪問

9.21日上午，系統出現大面積服務假死，訪問長時間沒有響應。服務器網絡延遲也非常嚴重。

分析過程

• 查看服務器發(fā)現CPU異常飆高;
• 通過jstack發(fā)現大量服務在等待中(當時時間緊迫，不允許做太多的操作，要馬上恢復)。直接重啟了其中一臺服務器上的所有服務。
• 發(fā)現沒有變化，新來的請求還是直接掛起，推測不是服務的問題；
• 檢查網絡狀態(tài)，發(fā)現服務器的網絡延遲非常嚴重，開始懷疑是否是網絡出現問題，聯系網絡管理員排查發(fā)現只有我們系統所在服務器出現延遲，其他服務器都正常，并且本身服務器CPU也異常，基本排除了網絡引起的原因(為什么網絡會大面積延遲，后面會提起)；
• 馬上去查看數據庫監(jiān)控，發(fā)現數據庫CPU和IO異常(數據庫由第三方公司管理，我們前期無法直接查看，聯系他們以后給的監(jiān)控報告)
• 通過DBA查詢數據庫掛起的腳本，發(fā)現有個update請求把數據庫資源全部占用了，導致其他數據庫請求無法進來或者響應非常慢，從而導致服務都假死了。

原因追溯

經查詢，發(fā)現此次操作是一個名為更新“數據實例”功能，每次升級版本需要手動操作下此功能(情況比較復雜，無法做成自動處理)。所有的歷史實例數據都會存在這個表，發(fā)生事故的時候，這張表大概有「1億3千多萬」的數據(Oracle比較能抗，數據量不算太大)，更新實例這個功能又包含了「表結構調整、索引重建、數據更新」等功能(業(yè)務場景需要，原則上屬于每次升級操作一次就可以)，所以操作的時候會鎖全表。

本來這個操作是要在系統升級完成以后操作的，但是升級的時候現場人員是新人不太熟悉情況，運行過程中客戶發(fā)現數據有問題，經溝通后發(fā)現少了更新實例的操作，客戶催的比較急，就直接在上線期間去操作了這個功能。因為這張表是核心表，所有業(yè)務都會走這張表的，就造成所有服務都卡死了。

后來是直接重啟了數據庫服務器(那時候DBA已經無法干掉進程，重啟服務也失敗，時間比較緊迫，經過溝通以后直接重啟服務器), 之后系統恢復了，整個過程大約持續(xù)了30分鐘。

解決措施

• 系統優(yōu)化，原來實例表是單表，數據量后續(xù)也會越來越大，就對程序做了改造，針對這張表做了分表功能(按照時間點建立分表，程序自動處理數據，自動建立分表，相應的查詢統計等都做了調整)；
• 增加了權限控制，更新實例功能只允許管理員角色操作；
• 強化現場實施人員培訓，哪些操作是決不允許在上線期限操作的；

因為系統所在區(qū)域的業(yè)務量還算是比較龐大的，數據積累很快，所以很久以前的一些架構設計其實是存在問題的，后續(xù)針對類似這些數據表都做了相同的處理。

本來想改整體業(yè)務架構的，但是發(fā)現帶來的代價太大，不僅僅涉及本身系統修改，還涉及一系列供應鏈上系統的修改，所以就放棄了這個方案。

事件二：tomcat內存溢出崩潰

9.21日下午，發(fā)現兩個核心服務會不定時出現內存溢出，然后tomcat直接崩潰， 9.22日下午，發(fā)現另外一個服務不定期出現tomcat內存溢出問題，同樣造成tomcat崩潰

做過軟件的都知道，雖然異常表象是一樣的，但是實際產生的原因可能是完全不一樣的。

分析過程

因為涉及到tomcat崩潰，在tomcat目錄下產生了hs_err_pid.log日志，所以原因相對比較容易找，結合業(yè)務日志反查分析以后，就定位到了問題所在。

原因追溯

死循環(huán)

9.21下午出現的兩個核心服務不定時出現內存溢出，查詢日志發(fā)現出問題時間段內會出現大量的服務訪問日志，經過追溯代碼以后，發(fā)現前端的判斷邏輯存在問題，會造成服務死循環(huán)訪問，即A-->B，A-->B，.....

歷史原因，部分業(yè)務邏輯代碼在前端進行處理，本來服務A訪問成功以后，會繼續(xù)訪問B服務，然后B服務訪問成功以后就結束了。但是這里的代碼在特定條件下邏輯判斷不嚴謹，會觸發(fā)刷新服務，會一直重復訪問A，B服務。

模糊查詢

9.22下午出現的另外一個服務內存溢出，經過同樣的分析以后，發(fā)現是一個模糊查詢的請求出現異常了，正常看代碼沒什么問題，但是分析日志以后發(fā)現，都是一些模糊條件比較簡單的請求，初步懷疑是數據沒做過濾，當時數據全部加載到內存里了。

因為分析的時候是上線期間，防止系統出現問題，沒有直接抓出原請求去復現問題。后面是讓DBA，基于查詢的SQL語句，去數據庫日志里查詢當時的執(zhí)行記錄，發(fā)現這幾個請求平均返回的記錄數都在「200萬」以上。至此基本上知道造成內存溢出的原因，程序里不僅僅是加載數據，還有進行數據處理的計算。

解決措施

• 第一個問題比較容易處理，程序修復就行，后續(xù)對這段代碼邏輯重新進行了審計，最大限度排除邏輯上的缺陷。這些情況也整理了相應的測試用例，后續(xù)納入常規(guī)測試計劃里。
• 第二個問題處理過程比較簡單，對模糊查詢做了數據量返回限制，以當時的業(yè)務場景，限制返回1000條，找不到記錄再輸入更精確的查詢條件，并簡化了代碼里面的邏輯運算，大部分場景移到數據庫計算(不影響整體性能)。「但是這個程序本身出現的問題其實比較低級，當時審計過程也存在問題，這種問題不應該出現」。

后面問過當事人，為什么要這么查詢，一問發(fā)現還是我們自己的問題(設計不合理)。這個版本上線增加了回車查詢的功能，然后客戶在一個詞輸完以后，習慣性的會敲回車，然后觸發(fā)了查詢，就造成了前面的事故。比如要查詢XXXX省的某個坐落門牌號，然后在輸入XXXX省以后輸入按了回車，就變成把全部的XXXX省數據都查詢出來了。

事后公司內部小組內也進行了案例分析，其實很多開發(fā)人員對這種問題不以為然，認為不是太大的問題，就改兩句代碼就行。但是實際造成的后果可以對標互聯網的P0級事故，這個帶來的可不是人力成本上的損失，還有很多看不見的諸如口碑，信任等損失。

負載均衡問題

21號-24號中間出現幾次問題，其實大部分時候都是某一臺服務器上的服務出現問題，但是發(fā)現負載均衡沒有發(fā)揮任何作用，服務都掛掉了，請求也一直過來。

剛好周五下午也出現了更重大的事故，所以在后面就把整體策略調整了。負載均衡設備的問題也算是為我們周五的大事故轉移了一些視線吧，壓力相對減輕了一些

原先的運行架構圖

系統整體架構端口

存在的問題

負載均衡監(jiān)測策略不對，只是針對端口做了類似telnet測試，只要端口能訪問就行，服務假死的時候，端口還是可以訪問的，所以他認為服務還是正常的，請求照樣過來。

負載均衡訪問策略也不是很合理，事故前設置的按照IP哈希的方式(經詢問，原先是為了會話保持，設備的訪問策略也很少，只有兩三種方式)，當中間一臺下線，請求轉到另外一臺以后，后續(xù)另外一臺重啟起來，請求就不會過來了。所以很多時候，監(jiān)測會發(fā)現，兩臺服務器的壓力差異非常大。

整體負載均衡方案也有問題，只做了服務器負載，系統整體架構是A-->B-->C這種形式的，如上圖，策略只針對兩臺服務器的服務1所在端口做了負載，就是如果服務1端口沒有問題，服務都會一直過來。如上圖鏈路上服務2，服務3不管出現什么問題，請求還是照樣會過來的。

廠商其實是個小代理商，設備也比較low，前期的時候也比較拽，上面的幾個問題據說前期都是溝通過的，但是人不配合。做過政府信息化軟件的都清楚，內部會涉及多方博弈，有時候很多問題不是技術能解決的。

這次事故也算是一件好事，至少讓甲方意識到設備是有問題的，叫上了設備供應商對負載均衡各項內容進行了調整；對我們來說，甲方的炮火也適當轉移了一部分，我們的壓力也減輕了。

解決措施

• 增加了服務監(jiān)測(「原來的端口監(jiān)測保留，也增加其他服務的端口監(jiān)測」)，為了不影響系統運行，我們針對每個服務額外編寫了一個監(jiān)測服務接口，專門用于設備配置服務監(jiān)測。(「因為老系統是基于jsp運行的，所以不能是html頁面，需要jsp頁面，返回200表示正常，其他就是異?！?
• 訪問策略修改成輪詢策略，平衡分布請求流量
• 調整程序配置，支持服務之間負載(類似分布式架構)

服務和端口監(jiān)測場景?

系統整體架構服務監(jiān)測

服務訪問場景

系統整體架構服務訪問

所有內部服務訪問都通過負載去轉發(fā)，做到每個服務都高可用。

需要承擔的風險：

1、高度依賴負載均衡設備的穩(wěn)定性，以前請求較少，現在請求都會經過。(后面出現過一次負載扛不住壓力，系統全面崩盤的情況)。

2、會話保持需要依賴于軟件架構的設計，如果會話保持無法做到，此套架構無法使用

當時負載均衡策略根據上述的方式做了調整，效現場果還是不行。

當時設置完成以后，廠商才告訴我們，老的設備監(jiān)測有問題了，要10分鐘才會切換(好像是老設備的問題)，需要更換新的設備才行。10分鐘對業(yè)務來說太長了，這種效果根本沒用。

回到當時內部的多方博弈，業(yè)務部門要求換，信息部門要求我們「軟件供應商」寫一個保證，更換設備以后，系統100%不出問題。這種說法就是耍流氓了，我敢說沒有一家軟件公司敢說自己產品100%沒有Bug，再說硬件負載切換更換，為什么要軟件公司來保障。后來這個事情就不了了之了。

網上經常說的那句話，「“往往最樸素的方法就是最有效的方法”」，甲方后來也知道他們硬件設備不行，采用了「重啟大法」，他們會定期(差不多一個月)的樣子，重啟下所有設備，后面確實沒發(fā)生什么大問題了。

后來我們在公司內部完全模擬了現場的情況，采用了國內知名硬件廠商的負載均衡設備(不打品牌了，有打廣告的嫌疑)， 發(fā)現效果非常理想，可以達到預期的切換的效果。說明說做的策略沒有任何問題。

系統宕機，無法恢復

9.25下午開始，那就是災難性的了，也是那天，所有領導齊聚現場，安撫客戶。這天出現了將近三個小時無法恢復系統，業(yè)務直接停擺。

黑色的一個星期五，我也是在這天到現場的，前面都是遠程指揮的(開發(fā)負責人在現場)

系統無法恢復時間軸

整個事件莫名其妙來，莫名其妙走，從星期五晚上開始(通宵了兩晚)，一直到星期六半夜里吧，經過多人的頭腦風暴以后，才基本確定了問題的所在。

?真的找到問題以后發(fā)現過程很可笑，但是代價太慘痛

前面我們是一直在懷疑是中午12:00左右更新的代碼引起的問題，因為從各種現象來說，就是更新了以后出現的問題，但是經過一個多小時的反復驗證和討論，直接排除這方面的原因，那時候就直接開玩笑說了，「敢用腦袋擔保新加的代碼是沒問題的」。

后面開始翻看各種本地日志，那時候日志文件很大，好幾百兆(其實這個文件大小就是有問題了，只是所有人都沒意識到，為了排查方便，是每天備份清理日志的，正常業(yè)務不應該產生這么大的日志，況且這天下午基本沒有業(yè)務辦理，只是那時候我剛到，不了解情況，也沒多想)，日志非常大，加載又慢，看了「一大堆無用」的「運行日志」，沒發(fā)現任何有價值的信息

快到天亮的時候，翻看了很多代碼和日志，也是「毫無頭緒」。真的是毫無頭緒，連疑似的原因都找不到，本來說讓性能測試組過來，看能不能復現，但是源頭都沒有，性能測試總不可能一個個場景壓過去去找問題吧。

白天休息了一個多小時吧，起來繼續(xù)工作了。

因為我屬于被拉過去的，正兒八經排查代碼是有其他開發(fā)負責人在的，前面我大部分時間就是跟他們頭腦風暴，然后翻翻日志文件什么的。那時候潛意識也是認為應該跟代碼沒什么關系，還是跟環(huán)境有關系。所以第二天一早，我開始查看服務器上的部署文件，算是漫無目的吧，因為根本沒頭緒。

「細節(jié)決定成敗」， 我在翻看配置文件的時候，發(fā)現同級目錄下的log4j.properties文件的修改時間不正常，「是25號下午17:03分」，這個時間差不多就是我們最后一次重啟的時間，那時候本能的反應就是這個和這次事故有關系。打開文件看了下內容，看起來很正常，日志級別也是ERROR的(我們要求生產環(huán)境不允許開啟Debug日志的)，但是這個修改時間表明當時這個文件被覆蓋過或者修改過。那時候真的，一下子來了精神，看到曙光了。

我叫上相關的所有人，開始反推當時從12:00更新開始的全過程，也把當時更新服務器的開發(fā)人員叫上，努力回想當時干了什么事情。經過將近兩個多小時左右的回溯和頭腦風暴，終于把事情理清楚了。

星期五中午的時候，開發(fā)人員更新了幾個文件，其中就有l(wèi)og4j.properties，他自己也沒注意到，然后覆蓋上去的文件，是開啟日志模式為Debug的。當時下午大家一團鬧哄哄，他潛意識也壓根聯想不到這塊，后來也是明確定位到這個文件，他才想起來。

我們重新把配置文件修改成debug模式，然后啟動服務，果然出現了當時的情況，「兩臺服務器CPU飚高了，但是大概10幾分鐘以后恢復下來了」，所以中午重啟完以后，我們都去吃飯了，也沒管服務器，那時候應該也是CPU異常，只是后續(xù)自動恢復了。(這個也很郁悶，到時如果我們能多等一會，可能就不會造成這么大的事故了)。

分析了下，為什么開啟Debug以后會造成CPU異常，原因就是系統啟動的時候tomcat控制臺瘋狂刷日志，「導致控制臺假死，進而導致服務器CPU異常系統假死」(為什么會這樣，后面會詳細描述)。

而導致控制臺瘋狂刷日志的原因是因為會話同步的功能，因為架構比較老，并且是負載均衡，需要保持會話一直，所以采用的是Shiro+Ehcache緩存來管理會話，然后通過Ehcache來實現兩臺服務器的會話同步。因為會話是做了持久化+超期時間的方式，所以后續(xù)每次啟動的時候都會執(zhí)行會話同步的功能。

本來這個事情也沒什么關系，但是因為業(yè)務場景需要，會話里是存了用戶大部分的信息，其中就包括「指紋特征碼」(系統支持指紋登錄)，然后指紋特征碼是一串Base64編碼的字符串，非常長，所以同步的過程中日志都輸出了，在控制臺瘋狂滾屏，就造成了第4步描述的局面。后面關掉會話同步的功能，程序就啟動正常了，不會假死，也印證了我們的猜想（單臺服務啟動，不一會兒也會假死，也是這個會話同步造成的）。

然后就是下午14:00的時候，上班高峰期為什么也會造成系統崩潰，那時候會話同步已經結束了，因為知道tomcat控制臺瘋狂刷日志，所以反向分析，當時應該是大量登錄的場景，所以我們找了客戶端打開系統，登錄了下，果然發(fā)現問題了，只要一打開系統，控制臺就開始瘋狂刷新日志，CPU也逐漸上去了，那時候幾百個客戶端差不多時間登錄，那就造成系統崩潰了

查看日志以后發(fā)現也是在刷用戶信息(同會話同步)，進一步排查代碼以后是指紋登錄功能引起的。指紋登錄的設備是甲方自己采購的，當時設備沒有提供JAVA的SDK，只有JS的SDK，也就是不支持后臺比對指紋，所以當時的做法是把「所有用戶(大幾百個)的指紋信息輸出到前端」，然后前端根據指紋特征碼循環(huán)去比較，匹配以后，找到指紋對應的用戶，在進行系統登錄。(客戶要求直接按指紋就登錄，而不是先用用戶名登錄，然后再指紋二次登錄，所以用了比較傻瓜的方式，指紋特征碼也不能直接Base64字符串比較，要根據匹配程度，然后有一套算法去匹配的。也得虧系統在內網，帶寬高，不然這種玩法，老早掛了)

到此為止，基本上已經分析清楚了造成問題的原因，也一步步復現了當時系統所有的異常現象。

為什么控制臺刷日志會造成CPU異常?

但是最關鍵的問題來了，為什么控制臺刷日志會造成CPU異常，這個也是阻礙我們排查問題的最大原因，我們也在自己筆記本上做了大量模擬，包括通過JMeter做壓測，都沒發(fā)現控制臺刷日志會造成CPU異常。

其實解決過程很簡單，關閉debug日志，系統基本就是正常了，但是本著刨根究底的態(tài)度，這個問題卡在這里很難受，這類問題也就獨此一家吧。

因為那天甲方人也在，硬件公司也來了，聊天的過程中終于發(fā)現了問題所在。

服務器分布圖

?你看的沒錯，運行了系統這么久的服務器居然是「兩臺VM虛擬機」。

用過虛擬機的都知道，虛擬機是公用主機的內存和CPU，是通過動態(tài)計算分配出來的，經過和專業(yè)人士交流以后，「虛擬機內部很多操作都是通過軟件模擬出來的，比如網絡」。這也解釋了9.21號服務器CPU異常以后，造成網絡大面積延遲。

大概的過程基本就是CMD封裝刷日志-->CPU異常-->進而掛起了其他所有操作(包括網絡等)，等待CMD日志刷完，釋放CPU以后，又恢復正常了。

因為對操作系統原理其實不是特別了解，所以也一直分析不到到底是什么情況，到時cmd刷日志占用了所有的CPU，也不給我們權限去查看VM服務端相關的日志，這個屬于硬件公司管轄范圍

硬件公司死活不承認VM虛擬化做服務器是有問題的，但是從我的角度看，單單就是CPU飆高，網絡會出現大面積延遲就是有問題的?？赡苡布局镭埬伆桑砸膊唤o我們看服務端日志，他們一直強調服務器是沒問題的。

前面也講到，回公司以后，我們搭建過一套一模一樣的環(huán)境(實體機)，就是怎么也復現不了控制臺瘋狂刷日志，造成CPU異常，系統假死的情況。

總結?

人的習慣就是這樣，第一印象把問題都會甩給“異常輸出的平臺”，所以這個事件基本上由我們軟件平臺全部背鍋了，我們事后還寫了很大一份“「事故總結報告」”，各種“「保證書」”等等。