Go 中的 HTTP 資源泄漏之謎

我喜歡排查泄露的問題。這是一個智力之謎,我總能在這個過程中學到新東西。

這個謎就像你在電視上讀到或看的一樣:細節是猥瑣的,從不令人沮喪,最後,我們總能得到一個很好的合乎邏輯的解釋。這就是計算機的偉大之處:它們最終是可以預測的,所以我可以安全地扮演偵探角色,因爲我知道我總是能得到我的罪犯。

如果你討厭推理小說或者只想學習參考,你可以跳到關鍵要點 (劇透警告,咄?)。

泄露 Dogfood

在 Coder,我們構建用於管理公共和私有云中的開發工作區的工具。當然,我們在 Coder 上開發 Coder。上週,一位工程師在我們的 dogfood[1] 集羣的主要編碼器服務 coderd(見上圖)中發現了一些可疑的地方。

需要重新啓動是意料之中的事情了,因爲我們非常積極地重新部署以保持接近生產環境,但是同時可以看到每次我們重新啓動時,goroutine 數量都會開始緩慢且穩定的增加。

我們注意到它增加的角度是恆定的,無論白天還是晚上都以相同的速度增加。這個服務是我們的主 API 服務器,它的負載肯定不是恆定的。與大多數服務一樣,它在工作日的負載最大,而在夜間幾乎沒有負載。因此,我們猜測泄漏最有可能發生在一些固定的後臺任務中,而不是 API 處理程序中。

尋找真相

好了,讓我們來了解更多關於泄漏的信息!

幸運的是,我們使用 golang 的 pprof HTTP 端點運行我們的 dogfood 集羣。而且,我們從指標中知道我們有一個 goroutine 泄漏,所以我們可以順着運行 goroutine 的堆棧跟蹤。

在以下信息的行頭能看到,一個 writeLoop 有 822 個 goroutines,一個 readLoop 有 820 個 goroutines。

goroutine profile: total 2020
822 @ 0x5ac2b6 0x5bbfd2 0x94e4b5 0x5dce21
#   0x94e4b4    net/http.(*persistConn).writeLoop+0xf4  /usr/local/go/src/net/http/transport.go:2392

820 @ 0x5ac2b6 0x5bbfd2 0x94d3c5 0x5dce21
#   0x94d3c4    net/http.(*persistConn).readLoop+0xda4  /usr/local/go/src/net/http/transport.go:2213

接着,我們可以讀出涉及 HTTP 的信息。它是一個 persistConn,通過一些代碼閱讀,我們可以看到它用於客戶端的連接池。

一般來說性能 HTTP 客戶端,不會爲每個 HTTP 請求建立一個新連接,而是爲每個主機維護一個連接池。這些連接在空閒時最終超時之前被重複用於多個請求。這增加了向主機發出許多請求的請求和響應吞吐量,這是非常典型的 HTTP 客戶端應用程序。

在我們的代碼中,這些連接似乎產生了泄漏。但是是怎麼泄露的?

讓我們看看 我們掛在 readLoop goroutines 上的那一行。這是一個 select,上面有一個很好的有用的評論。

// Before looping back to the top of this function and peeking on
// the bufio.Reader, wait for the caller goroutine to finish
// reading the response body. (or for cancellation or death)
select {

因此,一些代碼在發出 HTTP 請求後,既不能取消請求,也不能完成讀取響應正文。通常,當調用者沒有調用 response.Body.Close() 時,就會發生這種情況。這也解釋了 writeLoop goroutines,它們是作爲 readLoop 的一併創建的,並且都在等待新的 HTTP 請求。

深究調用堆棧

如果你以爲我們已經結束了,那是可以理解的。我們注意到我們的指標有一個問題,然後使用分析器跟蹤掛起的確切代碼行。我們還沒解開這個謎嗎?

嗯,沒有。我們發現的 goroutine 正在按設計工作:這些 goroutine 是受害者,而不是肇事者。問題是其他一些 goroutine 發出了 HTTP 請求,但未能取消它或關閉響應正文。而且我們知道其他 goroutine 不會繼續那裏等待響應,否則我們會在 pprof 輸出中看到其中的 820 個。它們會繼續執行。

如果能夠看到創建泄漏的 goroutine 的調用堆棧不是很好嗎?你可以在 go race 檢測器中得到這種輸出,因此它在技術上必須是可行的。顯然,在創建 goroutine 時存儲它會增加一些內存開銷,但每個 goroutine 可能只需要幾 kB。也許有一天我們會得到一個包含它的運行時模式,但不幸的是它在這裏沒有幫助。實際上很容易找到開始泄露的 goroutines 的行,因爲它在同一個文件中。但是,請記住,這是一個持久連接,它本身是從它所處理的 HTTP 請求異步啓動的。

我們需要追蹤行爲不當的 HTTP 客戶端代碼。我們知道這個 bug 的基本特徵:發出 HTTP 請求,接收 HTTP 響應,忘記調用 response.Body.Close()。我們的任務是巨大的,因爲簡單地說,HTTP 無處不在。它是應用程序開發協議的首選。審計我們代碼庫中的每個 HTTP 請求 / 響應將花費數週時間。

一切取決於時機

回想一下,我們之前對度量的分析使我們得出結論,它是一個後臺任務,現在我們知道它是一個發出 HTTP 請求的任務。但我們可以通過更仔細地觀察來找到問題細節。

看似直線穩定的增長實際上是階梯式的,儘管數據中有一些噪聲,但我們似乎看到每 1 小時就有一個很大的增長。

事實證明,我們的 coderd 服務每 1 小時運行 4 個後臺作業。我們有四名嫌疑人。會是哪一個呢?會不會不止一個人乾的?幫助我們進行偵察的一個快速修復方法是改變作業運行的週期。我可以一次只做一件任務,但如果我能做一點改變,就能留在原地,不是更好嗎?

選擇 1 小時的間隔是大多數人認爲的 “一個不錯的整數”。但與人不同的是,計算機不關心整數 [2]。1 小時並不是我們所關心的確切值,因此可以將其更改爲接近的值,而不期望系統範圍的行爲受到影響。

最好避免整數,事實上,整數越少越好。我選擇了其中最不四捨五入的數:質數。這使得從數學上講,週期不可能是更頻繁的任務的倍數,所以它們不斷地在同一時間發生。選擇一個基本單位,然後讓作業的質數乘以這個基本單位。我選擇 1 分鐘作爲基本單位,這樣就可以很容易地讀出度量圖表,因爲我們的 Prometheus 指標每 15 秒左右纔會被刪除一次,所以比 1 分鐘更小的度量並不能幫助我們理解度量。所以,1 小時的任務變成了 47、53、59、67 分鐘。

goroutroutine 的峯值現在大多間隔 47 分鐘,儘管仍然有一些噪音。這種額外的噪音使我大喫一驚,並使我懷疑是否不止一個任務要對泄漏負責。但是,選擇質數的能力意味着任務的開始是交錯的,當將峯值與顯示任務開始和停止時間的指標放在一起時,峯值總是與同一任務的開始或停止相關。

因此,我有了我的主要懷疑對象:一個檢查所有工作區容器圖像標記的任務,以便從它們各自的註冊中心獲得更新。它的動機是:向容器鏡像註冊中心發送 HTTP 請求。它是有機會的:我可以一遍又一遍地把它與犯罪時間聯繫起來。

插曲:搜索

上面我已經向你描述了我所做的事情,這些事情實際上在我的調查中取得了進展。在做這些事情的同時,我也在做一件沒有進展的事情:讀代碼。

有了一個好的 IDE,你可以通過調用堆棧向下執行並返回。這很乏味,但我認爲我很擅長理解代碼,這種深度優先搜索錯誤代碼的方法在過去不止一次地爲我找到了錯誤。

但是,正如前面提到的,HTTP 是非常普遍的,因此有很多地方需要覆蓋,並且並不總是清楚何時停止深入執行。另一個 HTTP 請求可能只是另一個層次。可惜的是,這裏不能體現。

Tracking it Down 追蹤它

遊戲仍在繼續!但是,仍然有許多不同的代碼路徑。與容器鏡像註冊表交互是涉及許多 HTTP 請求的複雜交互。

我也花了一些時間去了解受害者。乍一看,他們都是無名氏。我們不知道他們死的時候有什麼要求。但是,仔細檢查傳輸代碼就會發現,泄漏的 readLoop goroutine 有一個 HTTP 請求的引用,它試圖返回響應而失敗。要是我能讀到那個請求就好了!我就知道網址了,這就能讓案子有更大的進展。

如果我把它放在調試器裏,我就能讀取它。

我試圖在一些匆忙構建的單元測試中重現泄漏,但運氣不佳。並不是來自任何註冊表的任何容器鏡像都會導致泄漏。

然後我明白了:我確切地知道再現錯誤的容器鏡像集。是我們 dogfoog 集羣裏的那個。我克隆了數據庫,這樣我的測試就不會中斷其他用戶或刪除任何數據,然後在我自己的工作區中使用調試器針對克隆的數據運行後臺作業。

就這麼幹。

使用調試器逐步檢查該任務,我可以看到泄漏的 goroutine。我能從歷史信息中讀出它的記憶。從請求 URL,我可以知道它是什麼圖像。殭屍不再是無名氏了!但是,事情已經完成了,goroutine 泄露了。我還是得找到兇手。

有了容器鏡像的知識,我再次運行該任務,在頂層添加一些代碼,跳過所有內容,但我知道導致泄漏的代碼除外。我還在 HTTP 傳輸 RoundTripper 中添加了一個斷點,以便在每個 HTTP 請求上中斷。我的斷點已經設好,我埋伏着等待行兇者。我知道我接近了真相。

當 HTTP 請求進來時,我點擊、點擊、點擊我的斷點,等待我知道的確切的 URL 作爲觸發器。然後,我有了它:bug 所在的調用堆棧。

正如我們所懷疑的:一個丟失的 response.Body.Close()。修復的 PR 是一行。花了這麼多精力,只寫一行代碼就有點詩意了。

結果不言自明(google/go-containerregistry 倉庫的一個 bug)。

關鍵要點

雖然每一個泄漏的代碼都以自己的方式泄漏,但許多泄漏探測技術和分析工具都是通用的。

  1. 監控你的服務是否存在泄漏。檢查每個 Go 軟件的關鍵資源包括:a. 內存 b. 協程 c. 文件描述符(打開的文件)

  2. 根據你的應用程序,你可能還需要監視:a. 磁盤空間 b.Inodes c. 子進程 d. 應用程序使用的特殊資源(IP 地址?)

  3. 看看資源泄漏的速度:a. 速率與負載相關嗎? 可能與你的服務的請求路徑相關 b. 速率是否與負載無關? 可能是一份後臺任務

  4. 避免在完全相同的時間間隔上運行所有後臺作業。使用素數以避免作業運行重疊。

  5. 使用監控或日誌記錄後臺作業的開始和結束時間;尋找這些時間和泄漏之間的相關性。

  6. 如果可以,可以導出或克隆真實數據,在 IDE 中重現問題。

最後一點,請注意:

克隆包含外部客戶或用戶數據的生產數據時要小心。如果你完全不確定,請在複製數據之前諮詢你的安全團隊。如果你在受監管的行業(金融、醫療保健等)經營或者是爬蟲,情況就更是如此。

附註:

[1] 使用你自己的產品通俗地稱爲 dogfooding,如 “喫你自己的狗糧”。

[2] 不同人對什麼是圓形有不同的看法。

相關鏈接:

關鍵要點:https://coder.com/blog/go-leak-mysteries#key-takeaways

pprof HTTP 端點:https://pkg.go.dev/net/http/pprof

代碼閱讀:_https://github.com/golang/go/blob/8ed0e51b5e5cc50985444f39dc56c55e4fa3bcf9/src/net/http/transport.go#L98
_

掛在 readLoop goroutines 上的那一行:https://github.com/golang/go/blob/8ed0e51b5e5cc50985444f39dc56c55e4fa3bcf9/src/net/http/transport.go#L2213

都在等待新的 HTTP 請求:https://github.com/golang/go/blob/8ed0e51b5e5cc50985444f39dc56c55e4fa3bcf9/src/net/http/transport.go#L2392

go race 檢測器:https://go.dev/blog/race-detector

開始泄露的 goroutines 的行:https://github.com/golang/go/blob/8ed0e51b5e5cc50985444f39dc56c55e4fa3bcf9/src/net/http/transport.go#L1750

涉及許多 HTTP 請求的複雜交互:https://docs.docker.com/docker-hub/api/latest/

修復的 PR:https://docs.docker.com/docker-hub/api/latest/

原文地址:

https://coder.com/blog/go-leak-mysteries

原文作者:

Spike Curtis

本文永久鏈接:

https:/github.com/gocn/translator/blob/master/2022/w46_HTTP_Resource_Leak_Mysteries_in_Go.md

譯者:Jancd

本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源https://mp.weixin.qq.com/s/2DFzz5Fy3uAI1Qq4xAfvTg