GC停頓經常超過100ms

現象有同事反饋說，最近開始試用公司的Kubernetes，部署在Docker里的Go進程有問題，接口耗時很長，而且還有超時。邏輯很簡單，只是調用了KV存儲，KV存儲一般響應時間<5ms，而且量很少，小于40QPS，該容器分配了0.5個核的配額，日常運行CPU不足0.1個核。復現我找了個容器，踢掉訪問流量，用ab 50并發構造些請求看看。網絡來回延時60ms，但是平均處理耗時200多ms，99%耗時到了679ms。用ab處理時，看了下CPU和內存信息，都沒啥問題。Docker分配的是0.5個核，這里也沒有用到那么多。看了下監控，GC STW(stop the world)超過10ms，50-100ms的都很多，還有不少超過100ms的。Go不是聲稱在1.8后GC停頓基本是小于1ms的嗎？GC信息及trace看看該進程的runtime信息，發現內存很少，gc-pause很大，GOMAXPROCS為76，是機器的核數。export GODEBUG=gctrace=1，重啟進程看看，可以看出GC停頓的確很嚴重。

gc 111 @97.209s 1%: 82+7.6+0.036 ms clock, 6297+0.66/6.0/0+2.7 ms cpu, 9->12->6 MB, 11 MB goal, 76 P

gc 112 @97.798s 1%: 0.040+93+0.14 ms clock, 3.0+0.55/7.1/0+10 ms cpu, 10->11->5 MB, 12 MB goal, 76 P

gc 113 @99.294s 1%: 0.041+298+100 ms clock, 3.1+0.34/181/0+7605 ms cpu, 10->13->6 MB, 11 MB goal, 76 P

gc 114 @100.892s 1%: 99+200+99 ms clock, 7597+0/5.6/0+7553 ms cpu, 11->13->6 MB, 13 MB goal, 76 P

在一臺有go sdk的服務器上對服務跑一下trace，再把trace文件下載到本地看看。

curl -o trace.out 'http://ip:port/debug/pprof/trace?seconds=20'

sz ./trace.out

下圖可見有一個GC的wall time為172ms，而本次GC的兩個stw階段，sweep termination和mark termination都在80多ms的樣子，幾乎占滿了整個GC時間，這當然很不科學。原因及解決方法

原因這個服務是運行在容器里的，容器和母機共享一個內核，容器里的進程看到的CPU核數也是母機CPU核數，對于Go應用來說，會默認設置P(為GOMAXPROCS)的個數為CPU核數。我們從前面的圖也可以看到，GOMAXPROCS為76，每個使用中的P都有一個m與其綁定，所以線程數也不少，上圖中的為171。然而分配給該容器的CPU配額其實不多，僅為0.5個核，而線程數又不少。stw流程Go在開始GC時，需要一個stw，這個stw階段稱為sweep termination。先進入stw，然后執行一些計算和簡單的工作，然后重新啟動其他P，標記和程序并發運行。這個stw的大致流程為一個P發起stw，將其他的P都進入gcstop狀態，其他的P狀態有三種：syscall、idle、running。對于syscall和idle的P，直接設置gcstop即可；而對于running狀態的P，目前為協作式搶占，設置當前P運行的協程的一個標記位，等到協程運行到檢查點時，將P設置為gcstop狀態，其線程停在m.park上。對于Go來說，是無法感知與P綁定的m(線程)是否真正在運行，可能操作系統把該線程切換出去，放在待運行隊列中，而Go還認為這個P是running的，所以這里存在一個問題，只要有一個期望被gcstop的P沒有在運行，而系統遲遲沒有調度，這樣就導致整個完整stw的時間很長，從而使得其他很早就gcstop的P停止了很久，影響了請求。流程代碼stw流程代碼協程搶占處理代碼Go調用大部分函數時都會檢查stack，上面的preemptall方法設置了協程被搶占，同時設置了stack標記位。那么被搶占的協程會執行以下流程，然后最后stopm，把P設置為gcstop狀態。

newstack->gopreempt_m->goschedImpl->schedule->

if sched.gcwaiting != 0 -> gcstopm -> stopm->notesleep(&_g_.m.park)

trace圖go pprof的trace中第一個stw階段的圖表示：從開始告訴其他P要gcstop，執行完一些任務，到把其他P喚醒，這整個過程，如下這個stw大致為70多ms，圖中紅色框起來的表示P10執行handle.func2時進入了gc，開始發起stw。我們可以看到在這個階段，其他的P都沒有執行圖，只有P2一直在running狀態。放大看看，從發起進入gcstop很快的P都進入了gcstop，只花了30us。而唯一的一個時間很長的P進入gcstop，花了72ms。所以就是P2的延遲執行導致了stw的時間很長。原因總結在stw過程中，因為P(或可運行的線程)的個數比較多，就存在這樣一種情況，把一部分P(其線程)停止了，另一部分線程Linux一直沒調度到(可能是被throttle了，也可能是cfs調度本來就有延遲)，也就沒辦法停止自己，遲遲無法達到整體的stw，這樣就導致整個過程時間很長，影響了那些比較早就被stop的P和線程，實質上就造成了服務延時增加很多。解決方法解決的方法，因為可運行的P太多，導致占用了發起stw的線程的虛擬運行時間，且CPU配額也不多。那么我們需要做的是使得P與CPU配額進行匹配，我們可以選擇：

增加容器的CPU配額

容器層讓容器內的進程看到CPU核數為配額數

根據配額設置正確的GOMAXPROCS

第1個方法：沒太大效果，把配額從0.5變成1，沒本質的區別(嘗試后，問題依舊)。第2點方法：因為我對Kubernetes不是很熟，待我調研后再來補充。第3個方法：設置GOMAXPROCS最簡單的方法就是啟動腳本添加環境變量。GOMAXPROCS=2 ./svr_bin這種是有效的，但也有不足，如果部署配額大一點的容器，那么腳本沒法跟著變。Uber的庫automaxprocsuber有一個庫，go.uber.org/automaxprocs，容器中Go進程啟動時，會正確設置GOMAXPROCS，修改了代碼模板，我們在go.mod中引用該庫。

go.uber.org/automaxprocs v1.2.0

并在main.go中import。

import (

_ "go.uber.org/automaxprocs"

)

效果

automaxprocs庫的提示使用automaxprocs庫，會有如下日志：

對于虛擬機或者實體機，8核的情況下：2019/11/07 17:29:47 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined

對于設置了超過1核qusnow boyota的容器，2019/11/08 19:30:50 maxprocs: Updating GOMAXPROCS=8: determined from CPU quota

對于設置小于1核quota的容器，2019/11/08 19:19:30 maxprocs: Updating GOMAXPROCS=1: using minimum allowed GOMAXPROCS

如果Docker中沒有設置quota，2019/11/07 19:38:34 maxprocs: Leaving GOMAXPROCS=79: CPU quota undefined，此時建議在啟動腳本中顯式設置GOMAXPROCS。

請求響應時間設置完后, 再用ab請求看看，網絡往返時間為60ms，99%請求在200ms以下了，之前是600ms，同等CPU消耗下，QPS從差不多提升了一倍。runtime及gc trace信息因為分配的是0.5核，GOMAXPROC識別為1，gc-pause也很低了，幾十us的樣子，同時也可以看到線程數從170多降到了11。

gc 97 @54.102s 1%: 0.017+3.3+0.003 ms clock, 0.017+0.51/0.80/0.75+0.003 ms cpu, 9->9->4 MB, 10 MB goal, 1 P

gc 98 @54.294s 1%: 0.020+5.9+0.003 ms clock, 0.020+0.51/1.6/0+0.003 ms cpu, 8->9->4 MB, 9 MB goal, 1 P

gc 99 @54.406s 1%: 0.011+4.4+0.003 ms clock, 0.011+0.62/1.2/0.17+0.003 ms cpu, 9->9->4 MB, 10 MB goal, 1 P

gc 100 @54.597s 1%: 0.009+5.6+0.002 ms clock, 0.009+0.69/1.4/0+0.002 ms cpu, 9->9->5 MB, 10 MB goal, 1 P

gc 101 @54.715s 1%: 0.026+2.7+0.004 ms clock, 0.026+0.42/0.35/1.4+0.004 ms cpu, 9->9->4 MB, 10 MB goal, 1 P

上下文切換以下為并發50，一共處理8000個請求的perf stat結果對比，默認CPU核數76個P，上下文切換13萬多次，pidstat查看system cpu消耗9%個核。而按照quota數設置P的數量后，上下文切換僅為2萬多次，CPU消耗3%個核。automaxprocs原理解析這個庫如何根據quota設置GOMAXPROCS呢，代碼有點繞，看完后，其實原理不復雜。Docker使用cgroup來限制容器CPU使用，使用該容器配置的cpu.cfsquotaus/cpu.cfsperiodus即可獲得CPU配額，所以關鍵是找到容器的這兩個值。獲取cgroup掛載信息cat /proc/self/mountinfo

....

1070 1060 0:17 / /sys/fs/cgroup ro,nosuid,nodev,noexec - tmpfs tmpfs ro,mode=755

1074 1070 0:21 / /sys/fs/cgroup/memory rw,nosuid,nodev,noexec,relatime - cgroup cgroup rw,memory

1075 1070 0:22 / /sys/fs/cgroup/devices rw,nosuid,nodev,noexec,relatime - cgroup cgroup rw,devices

1076 1070 0:23 / /sys/fs/cgroup/blkio rw,nosuid,nodev,noexec,relatime - cgroup cgroup rw,blkio

1077 1070 0:24 / /sys/fs/cgroup/hugetlb rw,nosuid,nodev,noexec,relatime - cgroup cgroup rw,hugetlb

1078 1070 0:25 / /sys/fs/cgroup/cpu,cpuacct rw,nosuid,nodev,noexec,relatime - cgroup cgroup rw,cpuacct,cpu

1079 1070 0:26 / /sys/fs/cgroup/cpuset rw,nosuid,nodev,noexec,relatime - cgroup cgroup rw,cpuset

1081 1070 0:27 / /sys/fs/cgroup/net_cls rw,nosuid,nodev,noexec,relatime - cgroup cgroup rw,net_cls

....

cpuacct，cpu在/sys/fs/cgroup/cpu,cpuacct這個目錄下。獲取該容器cgroup子目錄cat /proc/self/cgroup

10:net_cls:/kubepods/burstable/pod62f81b5d-xxxx/xxxx92521d65bff8

9:cpuset:/kubepods/burstable/pod62f81b5d-xxxx/xxxx92521d65bff8

8:cpuacct,cpu:/kubepods/burstable/pod62f81b5d-xxxx/xxxx92521d65bff8

7:hugetlb:/kubepods/burstable/pod62f81b5d-5ce0-xxxx/xxxx92521d65bff8

6:blkio:/kubepods/burstable/pod62f81b5d-5ce0-xxxx/xxxx92521d65bff8

5:devices:/kubepods/burstable/pod62f81b5d-5ce0-xxxx/xxxx92521d65bff8

4:memory:/kubepods/burstable/pod62f81b5d-5ce0-xxxx/xxxx92521d65bff8

....

該容器的cpuacct，CPU具體在/kubepods/burstable/pod62f81b5d-xxxx/xxxx92521d65bff8子目錄下。計算quota

cat /sys/fs/cgroup/cpu,cpuacct/kubepods/burstable/pod62f81b5d-5ce0-xxxx/xxxx92521d65bff8/cpu.cfs_quota_us

50000

cat /sys/fs/cgroup/cpu,cpuacct/kubepods/burstable/pod62f81b5d-5ce0-xxxx/xxxx92521d65bff8/cpu.cfs_period_us

100000

兩者相除得到0.5，小于1的話，GOMAXPROCS設置為1，大于1則設置為計算出來的數。核心函數automaxprocs庫中核心函數如下所示，其中CG為解析出來的cgroup的所有配置路徑，分別讀取cpu.cfs_quota_us和cpu.cfs_period_us，然后計算。官方issue谷歌搜了下, 也有人提過這個問題：runtime: long GC STW pauses (≥80ms) #19378?https://github.com/golang/go/issues/19378總結

容器中進程看到的核數為母機CPU核數，一般這個值比較大>32，導致Go進程把P設置成較大的數，開啟了很多P及線程。

一般容器的quota都不大，0.5-4，Linux調度器以該容器為一個組，里面的線程的調度是公平，且每個可運行的線程會保證一定的運行時間，因為線程多，配額小，雖然請求量很小，但上下文切換多，也可能導致發起stw的線程的調度延遲，引起stw時間升到100ms的級別，極大的影響了請求。

通過使用automaxprocs庫，可根據分配給容器的cpu quota，正確設置GOMAXPROCS以及P的數量，減少線程數，使得GC停頓穩定在<1ms了，且同等CPU消耗情況下，QPS可增大一倍，平均響應時間由200ms減少到100ms，線程上下文切換減少為原來的1/6。

同時還簡單分析了該庫的原理，找到容器的cgroup目錄，計算cpuacct，CPU下cpu.cfs_quota_us/cpu.cfs_period_us，即為分配的CPU核數。

當然如果容器中進程看到CPU核數就是分配的配額的話，也可以解決這個問題。這方面我就不太了解了。

討論

同時文章引起了一些討論，我這里總結一下：

不僅僅是Go在容器會因為資源沒能完整屏蔽有問題，像Java的函數式編程paralle stream底層的fork-join框架會根據CPU數來啟動對應的線程，JVM沒有設置heap的話，那heap會根據識別的內存大小來自動設置堆大小，Python也會根據CPU數進行一些設置。

在JavaSE8u131+和JDK9支持了對容器資源限制的自動感知能力，在JDK 8u191和JDK 10之后，社區對JVM在容器中運行做了進一步的優化和增強，JVM可以自動感知Docker容器內部的CPU和內存資源限制，Java進程可用CPU核數由cpu sets、cpu shares和cpu quotas等參數計算而來。

LXCFS可以在容器內掛載/proc目錄，可以解決一部分容器可見性問題。

對于Go來說，在進程啟動時osinit方法中使用sched_getaffinity獲取CPU個數，如果用戶設置GOMAXPROCS環境變量，那么就使用該環境變量來此設置P的個數，否則使用CPU個數設置P，對于Go的話，解決這個問題，最簡單的方式就是容器啟動前Kubernetes根據分配的cpu quota來設置GOMAXPROCS環境變量，這樣也不需要用戶去關心了。

B站毛老師建議關注一下容器cgroup的CPU，cpuacct下的cpu.stat，里面有容器調度被限制的次數和時間(毛老師說他們已經在SRE上實踐了比較久，業務和運維結合比較緊密，也組成團隊一起做了很多優化)。

本文轉載自公眾號：yifhao，點擊查看原文。Kubernetes入實戰培訓

Kubernetes入門與實戰培訓將于2019年11月29日在深圳開課，3天時間帶你系統掌握Kubernetes，學習效果不好可以繼續學習。本次培訓包括：云原生介紹、微服務；Docker基礎、Docker工作原理、鏡像、網絡、存儲、數據卷、安全；Kubernetes架構、核心組件、常用對象、網絡、存儲、認證、服務發現、調度和服務質量保證、日志、監控、告警、Helm、實踐案例等等，點擊下方圖片或者閱讀原文鏈接查看詳情。

總結

以上是生活随笔為你收集整理的vs 服务容器中已存在服务_容器中某Go服务GC停顿经常超过100ms排查的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。