發現應用記錄日志內,出現網絡訪問延遲較大的情況。
此類問題較為常見,特別是之前參與輔助一個朋友項目運維的過程中,經常因為網絡訪問延遲較大,朋友認為是遭到了ddos攻擊或者是cc攻擊。網絡訪問延遲較大常常會給頂層業務帶來損失,甚至嚴重影響用戶體驗。
遇到這類問題,首先根據OSI七層模型,從上到下,盡可能脫離更加高層的協議帶來的影響。一般說來,稍微有經驗的人都會采用ping的方式,通過探尋icmp是否工作正常,來直接從網絡層面進行定位。
通過測試電腦ping業務服務器,發現如下詭異的回包情況:
可以看到,這張圖片內展示的上下部分,延遲極低,屬於正常。但是中間部分出現了延遲極高的現象。不但如此,紅框內的延遲變化情況,呈現詭異的逐步降低態勢。
如果是業務長期故障,延遲應該是高、數值穩定的。如果是偶發現象,延遲應該是突然增大,前后無變化趨勢的。這種有規律的從833ms逐步降低到10ms上下,讓人不禁思考,這個里面是不是隱藏着更大的秘密?
假設,在出現故障的時候,服務器的表現是一直再等待處理,故障過去,服務器突然統一按照順序開始處理,那么造成的結果就是——先發包的回包延遲極大,后續發包延遲逐漸降低。是不是十分吻合上述的情況?
如果這個假設成立,那么事情就變得更加有趣了起來~
我們先要明白,當網卡捕獲到icmp包的時候,需要向CPU提起中斷申請,CPU發生中斷,才能處理回包請求。那么,如果CPU在一段時間內,由於特殊原因,拒絕中斷,那么不就會造成上文所說的那種假設情況嗎?
事情逐漸明朗了起來。但是即便這種拒絕中斷的情況發生了,那么如何才能找到這個拒絕中斷的原因呢?還真沒有這么簡單。不簡單的原因很簡單,硬件中斷本身優先級要高於一般進程和軟中斷,在其被禁用之后自然普通軟件層面的追蹤方法也不起作用了。
所以目前尚無很好的方法在不影響業務的情況下較輕量級地獲得禁用中斷時的內核堆棧。
走到這個地步的時候,那么我們就需要從外露出來的其他指標看看,還有沒有什么解決問題的突破口~
果然系統的內存占用較高,但是並沒有發現明顯的異常程序占用,就感覺憑空少了一塊。
這時候我們可以考慮一下slab的問題。
cat /proc/meminfo |grep -i slab
通過這個命令,我們可以了解總共的slab占用。如果發現顯示出來的數據確實很大,那么我們有必要調用slabtop進一步查看slab相關的占用高的內容。
我們可以看到這個dentry占用極高。dentry是內存中表示目錄與文件的對象,用於鏈接inode。肯定是出現了什么大量打開文件或目錄的情況。
那么,又回到一開始的問題,我們發現了ping的問題,感覺可能和系統禁用中斷有關,現在又發現內存占用高,找到了dentry大量占用資源的事實。這二者之間有必然聯系嗎?
答案是有的。
托大神指導,我們看到了2.6內核的源碼。下面這張圖片內展示的源碼,實現了一個計算slab總量的功能。
我們可以看到內核是通過遍歷鏈表的方式,進行統計計數。而在進入鏈表之前,調用了spin_lock_irq函數。我們再繼續跟進,看看這個函數的相關實現。
至此,真相大白。我們可以確認在統計slab信息的時候,系統的行為是首先禁用中斷,然后遍歷鏈表統計slab,最后再次啟用中斷。那么整個禁用中斷的時間將取決於鏈表中對象的個數,如果其對象數量驚人,很可能就會導致禁用中斷時間過長。
當然,驗證這個關聯是否存在,也是可以簡單實現的。首先,我們在測試機上長ping業務服務器。然后,在業務服務器上執行以下代碼:
cat /proc/slabinfo
系統獲取slabinfo同樣會調用s_show函數,從而觸發禁止中斷。最終,當然發現再次出現了本文開頭一樣的幽靈ping延遲變化。至此,表面原因基本已經找到。
從緩解問題的角度來考慮,此時由於dentry項本身是作為系統緩存而存在,所以利用以下指令釋放緩存,dentry項會被清空,且不影響硬盤上的實際文件。
echo 2 > /proc/sys/vm/drop_caches && sync
至此,問題已經從表面上緩解。
但是,深層次的來說,還要繼續探究為什么會出現這么多的異常文件和目錄打開?這一塊需要繼續從業務層面進行排查。
不過從降低網絡延遲的角度考慮,在目前情境下,設定當slab中dentry比例再次達到某一水平的時候,進行釋放緩存,可以長久自動化維持正常水平,不影響排查工作的進行。