Go 應用服務疑似內存泄露問題排查

作者：SFLYQ

https://juejin.cn/post/7195857732846698557

背景

爲了保障業務的可用性，增加應用服務請求依賴服務（grpc、http）的熔斷降級策略，避免依賴服務不可用的情況下，出現級聯服務故障產生雪崩，通過熔斷降級儘可能把影響縮放到最小。

因此需要在 go 應用服務中接入熔斷組件，組件我們選擇了：阿里開源的 sentinel circuitbreaker，一頓封裝後，項目接入、壓測、驗證併成功上線，同時上線後也進行了跟進了幾個小時，一切正常。

幾天後，在一次常規性的應用服務的資源監控巡查中發現內存資源使用有些異常。

看時間節點就是從熔斷組件集成到項目後，就開始出現了內存的持續增長，看監控數據估算了下，一天增長 10~20MB 左右，還蠻有規律的。

難道是熔斷組件導致的內存泄露？於是就先回滾了熔斷相關內容，繼續觀察內存使用情況，發現內存恢復正常平穩的狀態。已經確定是熔斷問題導致的內存增長的問題。但是還沒定位到具體是什麼原因導致的這個問題，畢竟這個組件是阿里開源，並且在社區中感受好評，不應該有這種問題，還是要給與 respect，帶着這個疑惑，開始了內存泄露的排查之路。

排查

首先在測試環境進行壓測，併發壓測 qps 300+，看資源監控無法復現線上的情況。

組件的使用上也只是對多做了一層的封裝，並沒有做了什麼消耗內存的附加操作，但還是要先自我懷疑，進行了封裝熔斷代碼重新審查，也對一些地方做了改造，通過排除法進行壓測對比，也沒定位到什麼問題。

應用項目加入性能分析採集，使用 pprof 工具進行，對當前使用中（inuse_space）的堆內存進行分析，並且在測試環境中，對發佈和壓測後的 heap 採集進行 diff 對比，也沒發現哪個代碼會導致內存泄露的問題。因爲測試環境無法復現，又將性能分析採集發佈到生產上，跟了幾天，依然無法定位問題。

一直無法定位到問題，於是開始懷疑 Prometheus 裏監控的 k8s pod 內存指標數值的準確性。查閱資料，發現端倪。

container_memory_working_set_bytes 指標統計的內存是包含（RSS+ Cache）其中 cache 包含 file cache，系統內核爲了提高磁盤 IO 的效率，將讀寫過的文件緩存在內存中。file cache 並不會隨着進程退出而釋放，只會當容器銷燬或者系統內存不足時纔會由系統自動回收。

但是因爲應用服務沒有做文件操作，所以也就不以爲然，看看就過去了。

又歷經了幾天的排查，已經毫無思緒，繼續 review 代碼，最終在初始化 sentinel circuitbreaker 代碼中，發現熔斷組件會默認刷日誌到文件。

// NewDefaultConfig creates a new default config entity.
func NewDefaultConfig() *Entity {
 return &Entity{
   // .....
   Log: LogConfig{
    Logger: nil,
    Dir:    GetDefaultLogDir(),
    UsePid: false,
    Metric: MetricLogConfig{
     SingleFileMaxSize: DefaultMetricLogSingleFileMaxSize,
     MaxFileCount:      DefaultMetricLogMaxFileAmount,
     FlushIntervalSec:  DefaultMetricLogFlushIntervalSec,
    },
   },
   // .....
  },
 }
}

然後回想起來 k8s 使用內存監控指標中包含 file cache 的問題。就此真正原因浮出水面了。

讓運維幫忙查看線上日誌：

可以看出每日的日誌文件佔用存儲空間與之前監控的每天增長的內存範圍差不多。

最終代碼改造：

# ....
// sentinel 初始化
conf := config.NewDefaultConfig()
// 設置不刷日誌到文件（注意：k8s的使用內存指標包含:rss + file cache，使用寫日誌文件，會導致k8s pod監控的內存持續增長）
conf.Sentinel.Log.Metric.FlushIntervalSec = 0
# ....

劇終~

番外 - 驗證

k8s 中 memory.usage = working_set = memory.usage_in_bytes \- total_inactive_file 根據 cgroup memory 關係有：memory.usage_in_bytes = memory.kmem.usage_in_bytes + rss + cache

memory.usage_in_bytes的統計數據是包含了所有的 file cache 的，total_active_file和total_inactive_file都屬於 file cache 的一部分。

所以採用memory.usage_in_bytes \- total_inactive_file計算出的結果並不是當前 Pod 中應用程序所佔用的內存，當 Pod 內存資源緊張時total_active_file也是可回收利用的。

Docker 容器內存相關狀態：

cd /sys/fs/cgroup/memory 
cat memory.stat
# 輸出
cache 1470464
rss 35373056
rss_huge 0
mapped_file 864256
swap 0
pgpgin 32152
pgpgout 23157
pgfault 35743
pgmajfault 4
inactive_anon 0
active_anon 35332096
inactive_file 1466368
active_file 4096
unevictable 0
hierarchical_memory_limit 1073741824
hierarchical_memsw_limit 1073741824
total_cache 1470464
total_rss 35373056
total_rss_huge 0
total_mapped_file 864256
total_swap 0
total_pgpgin 0
total_pgpgout 0
total_pgfault 0
total_pgmajfault 0
total_inactive_anon 0
total_active_anon 35332096
total_inactive_file 1466368
total_active_file 4096
total_unevictable 0

通過 shell 腳本，循環寫內容到文件

  s=""
  for ((i=1; i<=500000; i++))
  do
      s=$s$i;
      ns="${s}\r\n";
      # echo $ns;
      echo $ns >> test.log
  done

進過多次的執行 shell，對比

before：

after：

可以明顯看到，每次執行 shell 腳本，循環寫入文件，文件越寫越大，k8s pod 內存監控使用內存不斷地增長，並且沒有釋放掉。

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/ff8gUlpBi6RfRHcnRT-5qA

猜你喜歡