系統背景介紹
用戶系統負責用戶生命周期管理，包括注冊、登陸、用戶信息獲取等，其作為基礎服務只提供內網服務，簡稱為service；application組件包裝service的服務對app渠道提供服務；service前面使用F5作為負載均衡器。
架構簡圖如下：
線上故障事件描述
上午9點50分，監控系統發出application組件可訪問性故障告警，一半的實例均有告警；無業務告警；無生產事件上報。運維將系統告警轉發相關開發負責人。
線上故障確定
告警屬於服務器告警，一半服務器實例均有告警；同時，發現告警服務器的TCP CLOSE_WAIT連接數暴增到10k，且application服務時延增大；可以斷定是線上故障，且可能已經影響到了業務服務。
線上故障定位
上半場
9:52 開發人員通過服務器監控，發現application告警服務器TCP CLOSE_WAIT連接數最近幾天暴增；開發人員提出疑問：最近是否有新功能上線？
9:53 運維人員貼出最近一次application版本內容，未有大的改動；
9:57 開發人員通過服務監控，發現application組件的服務時延均增大；服務訪問量中，getUserHeadPhoto服務的訪問量相比之前增加了100倍；同時發現getUserHeadPhoto服務時延最大，平均達到了5000ms，正常情況下20ms以下；
初步懷疑：可能和getUserHeadPhoto服務有關。getUserHeadPhoto服務的提供方是service。
9:59 開發人員發現application告警服務器上大部分CLOSE_WAIT連接都是到service F5上的；
懷疑：很有可能使由於service服務出現異常，導致application長時間等待service響應直到客戶端timeout，所以出現大量CLOSE_WAIT。但不一定是getUserHeadPhoto的原因，因為application包裝了service的很多服務。
10:00 開發人員通過service服務器監控，發現相比上周同時段，cpu使用率增加了1倍（10%-->20%）， TCP連接數增加了10倍以上，達到了7K，且伴有1.2k左右的CLOSE_WAIT，且IO讀寫均增加了10倍以上，內存使用率增加了一倍多；service的服務還能正常響應，但是時延均增高。
10:01 開發人員發現getUserHeadPhoto服務在service系統的時延為60ms，但是在application系統的時延為6000ms，差了10倍；
10:02 其他調用方陸續報警說service的時延增大；
10:03 開發人員檢查service tomcat error日志，發現有異常輸出，但是都是業務異常輸出，大部分是‘頭像不存在’的輸出，故忽略。
確定：通過service自身服務監控及上游系統的監控信息可以確定是service服務出現了問題，服務時延增大，導致上游的application受牽連；service服務時延增大，導致frontent調用超時，出現大量CLOSE_WAIT；很大可能和getUserHeadPhoto服務有關，現在還不確定。
10:04 開發人員確定service上周版本沒有大的變更，且並未更改getUserHeadPhoto服務。排除和service新版本發布的關系。
10:05 IOS開發同事確認前兩天上線的app X.0版本中，更改了getUserHeadPhoto服務調用的邏輯，導致getUserHeadPhoto服務的訪問量增加了100倍以上。原邏輯：用戶設置了頭像且更改過頭像才會從服務端請求getUserHeadPhoto獲取頭像信息；更改后不再有上述判定，用戶每次進個人中心，都會到服務端來拉取，帶來了100倍+的訪問量增加；剛好IOS app x.0版本是在上周五下班后發布市場，今天是周一，用戶量最多；而早ios一周發布一周的android沒有這個bug，上周也沒有此類故障告警。
重新梳理下getUserHeadPhoto服務的處理邏輯：如果用戶有頭像，則從NAS存儲中獲取頭像文件，轉換為二進制數組返回；如果不存在，則直接返回‘頭像不存在’的錯誤碼。IOS頭像拉取bug會導致有頭像的用戶不斷從服務端拉取頭像，現在app日活在200萬左右，ios大概占據100萬，按照5%比例的用戶設置了頭像，大概5萬日活用戶會擁有頭像，這會導致‘從存儲讀取文件’增多，從而導致磁盤IO讀增大，‘內存中完成文件流到二進制數組的轉化’導致service服務器內存使用增大。另一方面，ios剩下的95%沒有設置頭像的用戶也會不斷請求getUserHeadPhoto服務，從而導致getUserHeadPhoto服務的訪問量暴增100倍。此時getUserHeadPhoto的qps峰值達到了2000qps左右，但是按照之前性能測試得到的的性能曲線，這個壓力，service系統是完全可以抗住的，不應當出現故障。且這個壓力值下，不應當出現service系統cpu飆高一倍的現象。
所以這時候仍然不能確定故障的具體原因，也不能確定根本原因就一定是getUserHeadPhoto服務訪問量的暴漲。還有有兩個現象解釋不通：磁盤寫IO飆高10倍，service系統cpu飆高一倍。 getUserHeadPhoto服務只是io讀操作，怎么會造成這么大的IO寫呢？
半個小時過去了，仍未定位了故障根本原因，且getUserHeadPhoto服務還不支持服務降級，故暫無緊急措施可以實施；好在10點30分過后，用戶訪問量（業務規律）下來后，application服務逐漸恢復正常。現在，大家可以有大半天的時間來重新定位問題。
下半場
經過郵件討論，梳理出如下已有的信息：
- 故障出在service系統，service服務時延增大，導致上游的application出現調用超時，並出現大量的CLOSE_WAIT；
- service故障可能和getUserHeadPhoto訪問量暴漲有關；但還不確定具體原因；
- 仍然無法解釋現象：service系統cpu飆高一倍、磁盤寫IO飆高10倍
得到的兩個懷疑點如下：
- 運維人員懷疑service前面的F5的7層代理模式有性能問題，因為有一個現象是：同一次請求service耗時在60ms，而application的耗時卻為6000ms，他們懷疑是F5轉發時延過大；
- 開發人員懷疑getUserHeadPhoto訪問量暴增出發了service系統的某個bug；
鑒於線上故障已經得到緩和，擬在測試環境進行問題重現后，針對兩個懷疑點進行嘗試。
測試人員使用jmeter壓測工具對application發起線上同等壓力qps的getUserHeadPhoto調用，重現了線上問題：application時延在1500ms，service時延在20ms，service系統cpu使用率偏高。但io寫入偏高，tcp的CLOS_WAIT未大量出現。
驗證懷疑點一：將測試環境的F5轉發從7層模式更改為4層模式，再次壓測，問題仍然存在，application時延沒有得到好轉。
驗證懷疑點二：直接對service系統的getUserHeadPhoto進行同等qps的壓力測試，問題復現：service服務器cpu高，io寫入高。使用jmx監控，發現cpu50%時間消耗在log4j2的寫入操作上；查看service tomcat error日志，發現大量的堆棧信息寫入，這些異常會在用戶不存在頭像文件時拋出，並輸出到.out文件。
可能exception堆棧大量輸出導致io成為瓶頸，cpu切換頻繁，從而影響了服務。於是做如下嘗試：更改log4j2配置，將.out屏蔽，不再輸出日志，只輸出trace日志。重新測試，發現cpu降下來了，io寫入也降下來了。
再次從application發起壓力測試，服務恢復正常，時延降低到80ms，service時延為20ms。
至此，找到了故障的根本原因：service系統將異常堆棧輸出到.out日志，當getUserHeadPhoto訪問量暴增100倍且95%的訪問因為沒有頭像報出業務異常時，會大量輸出堆棧到.out日志，io成為瓶頸，cpu在線程切換增加，影響到服務響應，使得服務時延增加，在業務訪問量不減反增的情況下，service服務器的tcp連接數也增加。
線上故障排除
找到根本原因后，擬定了如下臨時和長期解決方案：
- 臨時方案——緊急更改線上service組件log4j2配置，將.out日志輸出屏蔽，帶來的異常堆棧丟失可以接受，因為trace日志會記錄異常碼，通常可以通過業務異常碼推測問
- 長期方案——修改service組件日志記錄邏輯，對於業務類異常（像這次的‘頭像不存在’）不再輸出堆棧信息到.out文件，因為業務異常不是程序bug，堆棧信息並無益處。本周版本上線。
- 更改頭像獲取方式，不再使用二進制數組方式的傳遞形式，改為接入新建的統一圖片服務，以外網url方式提供頭像。
長期方案也早已發布生產。
總結
這次線上故障並不是深奧的技術疑難雜症導致的，而是在某種小概率事件發生后，激發了線上應用的兩個不當設計——將業務一場堆棧輸出到.out文件+使用二進制數組傳遞文件內容，且這些不當設計在正常情況下看來是沒有什么大的害處的，比較隱蔽，所以排障過程也不是那么順利。
做的好的地方
運維、開發人員及時響應告警，並行查找線索，匯總信息；確保線上服務安全的前提下，冷靜徹底查清故障原因，並找到臨時方案緊急排除故障；同時，對不合理的設計進行改正。
做的不好的地方
- 故障確定在service后，未能及時獲取線上tomcat的dump文件並作分析；
- 在查看service組件error日志，發現大量堆棧輸出時，認為是業務異常，未引起警惕。
特別的教訓
- 墨菲定律，永遠不要小瞧小概率事件，莫名其妙的bug不知道在什么時候就出來了。
- 技術債遲早是要還的，晚還不如早還。當初上線service時，由於沒有統一圖片服務的基礎設施，為了趕項目工期，只能臨時采用二進制數組傳遞文件內容的方式實現頭像文件拉取，按照前后端約定的設計邏輯，沒有太大問題，畢竟更新頭像的人很少，但是經過兩個app版本迭代，一次大的重構就帶入了bug，觸發了潛在的系統設計漏洞。
故障處理路線圖
