1. 程式人生 > >某Python程序出現執行緒卡住情況的排查記錄

某Python程序出現執行緒卡住情況的排查記錄

現象:

需要排查的程序同時執行多個執行緒,其中一個執行緒的日誌停留在數日前,而其他執行緒可以正常執行,日誌正常列印

排查:

觀察執行緒資訊:

可以使用top -H -p {程序id}命令獲得該程序執行緒資訊。

排查當天15:09執行緒資訊:
出問題伺服器:
這裡寫圖片描述
正常伺服器(為了方便對比):
這裡寫圖片描述
16:36執行緒資訊:
出問題伺服器:
這裡寫圖片描述
正常伺服器:
這裡寫圖片描述
經過一番努力觀察,發現出問題伺服器3914這個執行緒的TIME+列的值保持不變,而通過正常伺服器的資訊對比得知,如果正常執行這個值應該是會變的。

TOP TIME+ Total CPU time the task has used since it started – man top

導致執行緒cpu時間不再增加的可能的原因就是在等待io,說明3914這個執行緒某個io卡住了

觀察執行緒程序佔用檔案情況

lsof 命令可以檢視當前系統檔案被開啟情況,lsof -p {程序id} 可以看到

出問題伺服器:
這裡寫圖片描述

正常伺服器1:
這裡寫圖片描述

正常伺服器2 :
這裡寫圖片描述

對比正常的兩臺伺服器,可以發現有問題的程序lsof出來的結果還是很不一樣的,其中一個TCP連線十分可疑, 繼續用lsof -i 命令追蹤得知這tcp請求來之問題執行緒程式碼裡的對郵件介面的請求,那麼問題原因就很清楚了:一次對郵件藉口的請求無限卡住了,導致執行緒無法繼續往下跑

反思:

實際排查的時候並沒如上面步驟那麼明瞭,一開始沒怎麼看程式碼只往檔案io方面排查,所以根本沒留意到那個異常的tcp連線,之後某次看程式碼才發現還有網路io才注意到。