詭異提交失敗問題追查

摘要:

自四月份以來，貼吧遇到了發帖失敗的問題，現象比較詭異。通過追查發現是操做系統刷磁盤時，阻塞write系統調用致使。本文主要分享問題追查過程，但願對你們平常工做中定位問題有必定幫助。

TAG:

提交、問題追查、髒頁

1 背景

好久前知道上有個問題：「從前天開始，跟帖就是發帖失敗，換個ID開始能發，後來又變成發帖失敗，很迷惑。誰知道怎麼回事麼。是系統問題麼，仍是網絡問題？」最佳答案是：「很大部分是網絡出現問題，你能夠從新提交下就能夠了」。

前段時間，貼吧的提交UI總是報警，晚上的時候手機叮叮咣咣地響，每次看都是apache進程數上千hold不住了，只好逐臺重啓。後來OP怒了，直接寫了個腳本，發現apache進程數上來就自動重啓。

好景不長，某天圖1被PM截下來發到羣上，本身發幾個貼測試下竟然復現了！看來真不是網絡的問題，必須好好追查下了。

 

2 提交系統綜述

先整理下貼吧提交的邏輯和涉及的模塊。圖2是貼吧提交系統的架構，一個完整的發帖流程須要通過下述模塊的處理。

l  提交UI。提交UI是接收用戶提交的帖子信息，進行合法性驗證後將數據提交給後端的PHP模塊，使用apache做爲服務器。

l  提交後端。某些提交操做好比發貼和刪帖對時序存在要求，全部與發帖有關的操做都經提交後端序列化後，持久化到本地di數據文件。消息隊列讀取di文件，轉發給訂閱相關消息的後端模塊。

l  提交代理層，簡稱proxy。貼吧除了發帖外，還有消息推送、消費吧豆等提交操做，所以提交後端以集羣的形式存在，而且每一個都是單點。proxy對UI層面屏蔽了各類提交後端的劃分，自動根據UI中的命令號轉發到相應的提交後端上。

提交UI經過RPC與proxy通訊，短鏈接。proxy使用rpc_client與提交後端通訊，短鏈接。proxy和提交後端都是使用rpc框架編寫的C模塊。

3 問題追查

發表一個帖子通過這麼多模塊，是在沒有頭緒，只好辛苦UI的同窗看看什麼狀況下會出現那個未知錯誤的哭臉。UI同窗很給力，立刻給出一個case，3000表明提交UI與cm_proxy交互失敗，從交互時間看，與cm_proxy交互時間爲1秒。剛好UI設置的超時爲1秒，去後端看看發生什麼回事。

拿着這個logid查cm_proxy和postcm日誌，發現兩個模塊都接收到UI的請求，而且把數據轉發到相應的後端模塊。繼續看warning日誌，發現cm_proxy等待postcm回覆超時！

3.1  RPCClient問題？

難道是提交後端處理這麼慢麼？查看本條請求處理時間，只有十幾毫秒，理論上不會超時。帶着這個問題請教之前負責這個模塊的高同窗，得知之前曾經出現相似的問題，猜想是RPCClient在壓力上千時，會出現大量讀超時。

爲了讓真兇現形，在OP mm的幫助下搭建好一套線下測試環境，使用壓力工具給予proxy 2000/s的壓力（線上峯值是1000/s）。一個小時，兩個小時……出現時的只是proxy queue full錯誤（等待鏈接池滿），沒有讀超時問題。而後wiki一下，也沒有找到相似錯誤的記錄，看來RPC庫是可依賴的。

3.2  TIME_WAIT問題？

一時找不到頭緒，看能不能從日誌中挖掘到一些線索。統計cm_proxy日誌狀況，根據錯誤號查看代碼，主要出現兩種類型錯誤。

讀超時：

鏈接postcm拒絕：

處理時間爲0竟然還讀超時，太詭異了！統計下5月22日一天proxy與提交後端交互失敗的分佈。

圖4 cm_proxy與提交後端交互失敗分佈

爲啥tc cm00這個機器的鏈接拒絕這麼多，讀超時這麼少呢？原來提交後端單點部署在這臺機器上，提交後端和proxy同機部署可能帶來一些問題。查看機器監控，發現這臺機器處於TIME_WAIT狀態的socket達到十幾萬。可是查看操做系統參數/proc/sys/net/ipv4/tcp_tw_reuse，值爲1。證實目前端口複用已經打開。爲了讓問題收斂，把tc cm00的proxy下掉，繼續跟進。

3.3  Backlog大小問題？

爲何會鏈接拒絕？帶着這個問題請教咱們的小強同窗。不愧是大牛，一下就發現tcp listen的時候，Backlog可能設置的過小了。翻閱資料充電：Backlog是listen系統調用的         第二個參數，這個參數所指明的是linux處理tcp鏈接是所設置的全鏈接隊列的長度。在socket程序設計中，當三次握手完成後，會把剛剛創建好的鏈接放入這個全鏈接隊列中，當服務器端調用accept系統調用的時候，會從這個全鏈接隊列裏取出已經創建好的鏈接供上層應用使用。這個值在系統中設置了上限，能夠經過/proc/sys/net/core/somaxconn查看。當listen系統調用使用的Backlog值小於這個值得時候系統取backlog值爲實際值，當Backlog的值大於這個值的時候，系統取SOMAXCONN的值爲默認值。

查看提交後端上系統SOMAXCONN的值爲2048，而listen時Backlog大小隻有100，貌似有點小。5月28日，OP操做把這個值調到1024，觀察效果。

圖5  22日和28日cm_proxy與提交後端交交互失敗分佈

調整後，交互失敗降低到原來的三分一，有點進度。可是若是僅僅是Backolg大小問題，爲何依然存在這麼多的交互失敗呢，看來幕後兇手尚未找到。

3.4  現場緝兇！

目前掌握的證據還不充分，實時觀察日誌或許能發現些東西。tail一臺proxy的錯誤日誌，發現每隔一段時間刷出一批錯誤日誌。統計每秒錯誤日誌數，發現一個規律，不少時候每隔15秒左右會一會兒刷子40條交互失敗的日誌。這個40有點眼熟，就是proxy的線程數！這意味這個時間點全部的交互都失敗了。

火速趕往提交後端機器，iostat一下，發現一個頗有意思的現象。IO的狀況隨着時間上下波動，而後每隔一段時間會有一次大的IO操做（>80M/s,持續1~3秒），此時proxy會有較大概率出現交互失敗。

爲了確認案情，統計6.2一天提交後端日誌，共有477個請求處理時間大於等於1000ms。這477個請求處理時間幾乎平均分佈在[1000,3995]ms中。目前proxy與提交後端鏈接超時爲1000ms，意味着477個請求持續時間內，proxy與提交後端有可能出現讀超時（根據IO被阻塞時間和請求達到提交後端時間肯定）

真正的緣由是在流量高峯期，postcm提交量上升， 當髒頁佔系統內存的比例超/proc/sys/vm/dirty_ratio的時候, write系統調用會被被阻塞,主動回寫dirty page,直到髒頁比例低於/proc/sys/vm/dirty_ratio。因爲提交後端單線程的工做模型，會致使提交後端短期內不能響應請求，形成上級模塊陸續超時或鏈接失敗。

4 解決辦法

整理一下思路，目前形成提交不穩定主要如下三個。

4.1  cm_proxy讀超時

l  修改操做系統參數，觀察效果並不斷調整。

由基礎架構的同窗總結，操做系統會在下面三種狀況下回寫髒頁：

1） 定時方式。定時回寫是基於這樣的原則:/proc/sys/vm/dirty_writeback_centisecs的值表示多長時間會啓動回寫pdflush線程,由這個定時器啓動的回寫線程只回寫在內存中爲dirty時間超過(/proc/sys/vm/didirty_expire_centisecs / 100)秒的頁(這個值默認是3000,也就是30秒),通常狀況下dirty_writeback_centisecs的值是500,也就是5秒,因此默認狀況下系統會5秒鐘啓動一次回寫線程,把dirty時間超過30秒的頁回寫,要注意的是,這種方式啓動的回寫線程只回寫超時的dirty頁，不會回寫沒超時的dirty頁。

2） 內存不足的時候。這時並不將全部的dirty頁寫到磁盤,而是每次寫大概1024個頁面,直到空閒頁面知足需求爲止。

3） 寫操做時發現髒頁超過必定比例: 當髒頁佔系統內存的比例超過/proc/sys/vm/dirty_background_ratio 的時候,write系統調用會喚醒pdflush回寫dirty page,直到髒頁比例低於/proc/sys/vm/dirty_background_ratio,但write系統調用不會被阻塞,當即返回.當髒頁佔系統內存的比例超/proc/sys/vm/dirty_ratio的時候, write系統調用會被被阻塞,主動回寫dirty page,直到髒頁比例低於/proc/sys/vm/dirty_ratio。

 

修改刷髒頁頻率，從5s調整到3s

echo 300 > /proc/sys/vm/dirty_writeback_centisecs

修改髒頁存在的時間限制，從30s調整到10s

echo 1000 > /proc/sys/vm/dirty_expire_centisecs

 

效果描述：

從iostat信息來看，刷髒頁的頻率變高，每次刷的髒頁數量變少。從上層應用程序來看，性能變得平穩。修改後天天超過1000ms的請求在200個左右。存在繼續優化的空間。

l  增大提交UI與proxy和proxy與提交後端的讀超時，從1000ms修改成3000ms。那麼天天在提交後端兩百多個超過1秒刷髒頁的時間範圍內，用戶的提交會延遲而不會失敗。

4.2  cm_proxy鏈接拒絕

當IO被阻塞期間，到達提交後端請求數超過鏈接隊列長度，則拒絕鏈接。經過實驗觀察提交後端Backlog的最佳大小，目前操做系統參數上限爲2048。根據實驗結果，將提交後端Backlog大小調整爲2048。

4.3  cm_proxy queue full

當proxy與提交後端交互失敗期間，若前端請求過多，若proxy工做線程數不足或proxy鏈接提交後端鏈接池鏈接數不足時出現。根據實驗結果和目前proxy壓力狀態（最大1000/s），將proxy線程數和提交後端鏈接池鏈接數修改成100。

總結

經過此次追查得出的經驗是一個問題的出現可能有不少現象，有些多是表面緣由，修改對問題會有很多的改善，但只有真正找到引起問題的緣由後，才能找到最恰當的解決辦法。本文小結了網絡交互失敗追查的一些方向和方法，但願對你們有所幫助。

by  chenyuzhe