摘要:最近工作遇到了記憶體洩漏問題,運維同學緊急呼叫解決,于是在解決問題之餘也系統記錄了下記憶體洩漏問題的常見解決思路。
最近工作遇到了記憶體洩漏問題,運維同學緊急呼叫解決,于是在解決問題之餘也系統記錄了下記憶體洩漏問題的常見解決思路。
首先搞清楚了本次問題的現象:
1. 服務在13号上線過一次,而從23号開始,出現記憶體不斷攀升問題,達到預警值重新開機執行個體後,攀升速度反而更快。
2. 服務分别部署在了A、B 2種晶片上,但除模型推理外,幾乎所有的預處理、後處理共享一套代碼。而B晶片出現記憶體洩漏警告,A晶片未出現任何異常。
思路一:研究新舊源碼及二方庫依賴差異
根據以上兩個條件,首先想到的是13号的更新引入的問題,而更新可能來自兩個方面:
1. 自研代碼
2. 二方依賴代碼
從上述兩個角度出發:
- 一方面,分别用Git曆史資訊和BeyondCompare工具對比了兩個版本的源碼,并重點走讀了下A、B兩款晶片代碼單獨處理的部分,均未發現任何異常。
- 另一方面,通過pip list指令對比兩個鏡像包中的二方包,發現僅有pytz時區工具依賴的版本有變化。
經過研究分析,認為此包導緻的記憶體洩漏的可能性不大,是以暫且放下。
至此,通過研究新舊版本源碼變化找出記憶體洩漏問題這條路,似乎有點走不下去了。
思路二:監測新舊版本記憶體變化差異
目前python常用的記憶體檢測工具有pympler、objgraph、tracemalloc 等。
首先,通過objgraph工具,對新舊服務中的TOP50變量類型進行了觀察統計
objraph常用指令如下:
\# 全局類型數量
objgraph.show\_most\_common\_types(limit=50)
\# 增量變化
objgraph.show\_growth(limit=30)
複制
這裡為了更好的觀測變化曲線,我簡單做了個封裝,使資料直接輸出到了csv檔案以便觀察。
stats = objgraph.most\_common\_types(limit=50)
stats\_path = "./types\_stats.csv"
tmp\_dict = dict(stats)
req\_time = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime())
tmp\_dict\['req\_time'\] = req\_time
df = pd.DataFrame.from\_dict(tmp\_dict, orient='index').T
if os.path.exists(stats\_path):
df.to\_csv(stats\_path, mode='a', header=True, index=False)
else:
df.to\_csv(stats\_path, index=False)
複制
如下圖所示,用一批圖檔在新舊兩個版本上跑了1個小時,一切穩如老狗,各類型的數量沒有一絲波瀾。
此時,想到自己一般在轉測或上線前都會将一批異常格式的圖檔拿來做個邊界驗證。
雖然這些異常,測試同學上線前肯定都已經驗證過了,但死馬當成活馬醫就順手拿來測了一下。
平靜資料就此被打破了,如下圖紅框所示:dict、function、method、tuple、traceback等重要類型的數量開始不斷攀升。
而此時鏡像記憶體亦不斷增加且毫無收斂迹象。
由此,雖無法确認是否為線上問題,但至少定位出了一個bug。而此時回頭檢查日志,發現了一個奇怪的現象:
正常情況下特殊圖檔導緻的異常,日志應該輸出如下資訊,即check_image_type方法在異常棧中隻會列印一次。
但現狀是check_image_type方法循環重複列印了多次,且重複次數随着測試次數在一起變多。
重新研究了這塊兒的異常處理代碼。
異常聲明如下:
抛異常代碼如下:
問題所在
思考後大概想清楚了問題根源:
這裡每個異常執行個體相當于被定義成了一個全局變量,而在抛異常的時候,抛出的也正是這個全局變量。當此全局變量被壓入異常棧處理完成之後,也并不會被回收。
是以随着錯誤格式圖檔調用的不斷增多,異常棧中的資訊也會不斷增多。而且由于異常中還包含着請求圖檔資訊,是以記憶體會呈MB級别的增加。
但這部分代碼上線已久,線上如果真的也是這裡導緻的問題,為何之前沒有任何問題,而且為何在A晶片上也沒有出現任何問題?
帶着以上兩個疑問,我們做了兩個驗證:
首先,确認了之前的版本以及A晶片上同樣會出現此問題。
其次,我們檢視了線上的調用記錄,發現最近剛好新接入了一個客戶,而且出現了大量使用類似問題的圖檔調用某局點(該局點大部分為B晶片)服務的現象。我們找了些線上執行個體,從日志中也觀測到了同樣的現象。
由此,以上疑問基本得到了解釋,修複此bug後,記憶體溢出問題不再出現。
進階思路
講道理,問題解決到這個地步似乎可以收工了。但我問了自己一個問題,如果當初沒有列印這一行日志,或者開發人員偷懶沒有把異常棧全部打出來,那應該如何去定位?
帶着這樣的問題我繼續研究了下objgraph、pympler 工具。
前文已經定位到了在異常圖檔情況下會出現記憶體洩漏,是以重點來看下此時有哪些異樣情況:
通過如下指令,我們可以看到每次異常出現時,記憶體中都增加了哪些變量以及增加的記憶體情況。
1. 使用objgraph工具objgraph.show_growth(limit=20)
2. 使用pympler工具
from pympler import tracker
tr = tracker.SummaryTracker()
tr.print\_diff()
複制
通過如下代碼,可以列印出這些新增變量來自哪些引用,以便進一步分析。
gth = objgraph.growth(limit=20)
for gt in gth:
logger.info("growth type:%s, count:%s, growth:%s" % (gt\[0\], gt\[1\], gt\[2\]))
if gt\[2\] > 100 or gt\[1\] > 300:
continue
objgraph.show\_backrefs(objgraph.by\_type(gt\[0\])\[0\], max\_depth=10, too\_many=5,
filename="./dots/%s\_backrefs.dot" % gt\[0\])
objgraph.show\_refs(objgraph.by\_type(gt\[0\])\[0\], max\_depth=10, too\_many=5,
filename="./dots/%s\_refs.dot" % gt\[0\])
objgraph.show\_chain(
objgraph.find\_backref\_chain(objgraph.by\_type(gt\[0\])\[0\], objgraph.is\_proper\_module),
filename="./dots/%s\_chain.dot" % gt\[0\]
)
複制
通過graphviz的dot工具,對上面生産的graph格式資料轉換成如下圖檔:
dot -Tpng xxx.dot -o xxx.png
複制
這裡,由于dict、list、frame、tuple、method等基本類型數量太多,觀測較難,是以這裡先做了過濾。
記憶體新增的ImageReqWrapper的調用鍊
記憶體新增的traceback的調用鍊:
雖然帶着前面的先驗知識,使我們很自然的就關注到了traceback和其對應的IMAGE_FORMAT_EXCEPTION異常。
但通過思考為何上面這些本應在服務調用結束後就被回收的變量卻沒有被回收,尤其是所有的traceback變量在被IMAGE_FORMAT_EXCEPTION異常調用後就無法回收等這些現象;同時再做一些小實驗,相信很快就能定位到問題根源。
至此,我們可以得出結論如下:
由于抛出的異常無法回收,導緻對應的異常棧、請求體等變量都無法被回收,而請求體中由于包含圖檔資訊是以每次這類請求都會導緻MB級别的記憶體洩漏。
另外,研究過程中還發現python3自帶了一個記憶體分析工具tracemalloc,通過如下代碼就可以觀察代碼行與記憶體之間的關系,雖然可能未必精确,但也能大概提供一些線索。
import tracemalloc
tracemalloc.start(25)
snapshot = tracemalloc.take\_snapshot()
global snapshot
gc.collect()
snapshot1 = tracemalloc.take\_snapshot()
top\_stats = snapshot1.compare\_to(snapshot, 'lineno')
logger.warning("\[ Top 20 differences \]")
for stat in top\_stats\[:20\]:
if stat.size\_diff < 0:
continue
logger.warning(stat)
snapshot = tracemalloc.take\_snapshot()
複制