線上服務被幹爆了,竟然是日誌的鍋!!

HollisChuang發表於2020-12-07

本文要介紹的是一個發生在我們線上環境的真實案例,問題發生在某次大促期間,對我們的線上叢集造成了比較大的影響,這篇文章簡單覆盤一下這個問題。問了方便大家理解,實際排查和解決過程可能和本文描述的並不完全一致,但是思路是一樣的。

問題過程

某次大促期間,某一個線上應用突然發生大量報警,提示磁碟佔用率過高,一度達到了80%多。

這種情況我們第一時間登入線上機器,檢視線上機器的磁碟使用情況。使用命令:df檢視磁碟佔用情況。

$df
Filesystem     1K-blocks    Used Available Use% Mounted on
/               62914560 58911440 4003120  93% /
/dev/sda2       62914560 58911440 4003120   93% /home/admin

發現機器磁碟確實耗費的比較嚴重,因為大促期間請求量比較多,於是我們最先開始懷疑是不是日誌太多了,導致磁碟耗盡。

這裡插播一個背景,我們的線上機器是配置了日誌的自動壓縮和清理的,單個檔案達到一定的大小,或者機器內容達到一定的閾值之後,就會自動觸發。

但是大促當天並沒有觸發日誌的清理,導致機器磁碟一度被耗盡。

經過排查,我們發現是應用的某一些Log檔案,佔用了極大的磁碟空間,並且還在不斷的增大。

du -sm * | sort -nr
512 service.log.20201105193331
256 service.log
428 service.log.20201106151311
286 service.log.20201107195011
356 service.log.20201108155838

du -sm * | sort -nr :統計當前目錄下檔案大小,並按照大小排序

於是經過和運維同學溝通,我們決定進行緊急處理。

首先採取的手段就是手動清理日誌檔案,運維同學登入到伺服器上面之後,手動的清理了一些不太重要的日誌檔案。

rm service.log.20201105193331

但是執行了清理命令之後,發現機器上面的磁碟使用率並沒有減少,而且還是在不斷的增加。

$df
Filesystem     1K-blocks    Used Available Use% Mounted on
/               62914560 58911440 4003120  93% /
/dev/sda2       62914560 58911440 4003120  93% /home/admin

於是我們開始排查為什麼日誌被刪除之後,磁碟空間沒有被釋放,通過命令,我們查到了是有一個程式還在對檔案進行讀取。

lsof |grep deleted
SLS   11526  root   3r   REG   253,0 2665433605  104181296 /home/admin/****/service.log.20201205193331 (deleted)

lsof |grep deleted 的作用是:檢視所有已開啟檔案並篩選出其中已刪除狀態的檔案

經過排查,這個程式是一個SLS程式,在不斷的從機器上讀取日誌內容。

SLS是阿里的一個日誌服務,提供一站式提供資料收集、清洗、分析、視覺化和告警功能。簡單點說就是會把伺服器上面的日誌採集到,持久化,然後供查詢、分析等。

我們線上日誌都會通過SLS進行採集,所以,通過分析,我們發現磁碟空間沒釋放,和SLS的日誌讀取有關。

到這裡,問題基本已經定位到了,那麼我們插播一下原理,介紹一下這背後的背景知識。

背景知識

Linux系統中是通過link的數量來控制檔案刪除的,只有當一個檔案不存在任何link的時候,這個檔案才會被刪除。

一般來說,每個檔案都有2個link計數器:i_count 和 i_nlink,也就是說:Linux系統中只有i_nlink及i_count都為0的時候,這個檔案才會真正被刪除。   

  • i_count表示當前檔案使用者(或被呼叫)的數量
  • i_nlink表示介質連線的數量(硬連結的數量);
  • 可以理解為i_count是記憶體引用計數器,i_nlink是磁碟的引用計數器。   

當一個檔案被某一個程式引用時,對應i_count數就會增加;當建立檔案的硬連結的時候,對應i_nlink數就會增加。

在Linux或者Unix系統中,通過rm或者檔案管理器刪除檔案,只是將它會從檔案系統的目錄結構上解除連結(unlink),實際上就是減少磁碟引用計數i_nlink,但是並不會減少i_count數。

如果一個檔案正在被某個程式呼叫,使用者使用rm命令把檔案"刪除"了,這時候通過ls等檔案管理命令就無法找到這個檔案了,但是並不意味著這個檔案真正的從磁碟上刪除了。

因為還有一個程式在正常的執行,在向檔案中讀取或寫入,也就是說檔案其實並沒有被真正的"刪除",所以磁碟空間也就會一直被佔用。

而我們的線上問題就是這個原理,因為有一個程式正在對日誌檔案進行操作,所以其實rm操作並沒有將檔案真正的刪除,所以磁碟空間並未釋放。

問題解決

在瞭解了線上的問題現象以及以上的相關背景知識之後,我們就可以想到辦法來解決這個問題了。

那就是想辦法把SLS程式對這個日誌檔案的引用幹掉,檔案就可以真正的被刪除,磁碟空間就能真正的被釋放掉了。

kill -9 11526
$df
Filesystem     1K-blocks    Used Available Use% Mounted on
/               62914560 50331648 12582912  80% /
/dev/sda2       62914560 50331648 12582912  80% /home/admin

特別提醒下,在執行kill -9 之前,一定要考慮下執行的後果是什麼,背後原理可以參考:我到伺服器執行kill -9後,就被通知第二天別來了!

事後,我們經過覆盤,發現之所以出現這樣的問題,主要有兩個原因:

  • 1、線上日誌列印太多,太頻繁
  • 2、SLS日誌拉取速度太慢

深入分析後我們發現,這個應用列印了很多過程日誌,最初日誌列印是為了方便排查線上的問題,或者做資料分析用的,但是大促期間日誌量激增,導致磁碟空間佔用極速上升。

另外,因為該應用和幾個其他的大應用共用了一份SLS的project,導致SLS拉取速度被拉低,進而導致程式一直無法結束。

事後,我們也總結了一些改進項,對於第二個問題,我們對於該應用的SLS配置做拆分,獨立出來進行管理。

對於第一個問題,那就是大促期間引入日誌降級的策略,一旦發生磁碟爆滿,就是將日誌降級掉。

關於日誌降級,我開發了一個通用的工具,就是通過配置的方式,動態推送日誌級別,動態修改線上的日誌輸出級別。並且把這份配置的修改配置到我們的預案平臺上,大促期間進行定時或者緊急預案處理,即可避免這個問題。

關於日誌降級工具的開發思路和相關程式碼,下一篇文章中給大家分享。

思考

每次大促之後我們覆盤,都會發現其實大多數問題都是由幾個不起眼的小問題堆積到一起而引發的。

在問題分析過程中往往會需要運用到很多非開發技能相關的知識,如作業系統、計算機網路、資料庫、甚至硬體相關的知識。

所以我一直認為,判斷一個程式設計師是否牛X,就看他的解決問題的能力!

相關文章