詭異提交失敗問題追查

來源:本站原創 專業IT吐槽 超過699 views圍觀 0條評論

摘要:

自四月份以來,貼吧遇到了發帖失敗的問題,現象比較詭異。經過追查發現是操作系統刷磁盤時,阻塞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

 

李蕭明吐槽,別尼妹的沒事就說網絡問題,網絡也是個妹紙好不,不要動不動就怪別人。妹紙哥會護著你的。

文章出自:CCIE那點事 http://www.qdxgqk.live/ 版權所有。本站文章除注明出處外,皆為作者原創文章,可自由引用,但請注明來源。 禁止全文轉載。
本文鏈接:http://www.qdxgqk.live/?p=910轉載請注明轉自CCIE那點事
如果喜歡:點此訂閱本站
  • 相關文章
  • 為您推薦
  • 各種觀點
?
暫時還木有人評論,坐等沙發!
發表評論

您必須 [ 登錄 ] 才能發表留言!

?
?
萌宠夺宝游戏