碼上快樂

相關內容    簡體    繁體

容器中某Go服務GC停頓經常超過100ms排查

本文轉載自   查看原文   2019-11-09 19:46   871    go

容器中某Go服務GC停頓經常超過100ms排查(轉載他人文檔)

 

GC停頓經常超過100ms

現象

有同事反饋說, 最近開始試用公司的k8s, 部署在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停頓的確很嚴重.

  1. 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

  2. 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

  3. 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

  4. 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文件下載到本地看看

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

  2. 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個核, 而線程數又不少.

猜測: 對於linux的cfs(完全公平調度器)來說, 當前容器內所有的線程(輕量級進程)都在一個調度組內. 為了保證效率, 對於每個被運行的task, 除非因為阻塞等原因主動切換, 那么至少保證其運行/proc/sys/kernel/schedmingranularity_ns的時間, 可以看到為4ms.

容器中Go進程沒有正確的設置GOMAXPROCS的個數, 導致可運行的線程過多, 可能出現調度延遲的問題. 正好出現進入gc發起stw的線程把其他線程停止后, 其被調度器切換出去, 很久沒有調度該線程, 實質上造成了stw時間變得很長(正常情況0.1ms的處理過程因為調度延遲變成了100ms級別).

解決方法

解決的方法, 因為可運行的P太多, 導致占用了發起stw的線程的虛擬運行時間, 且CPU配額也不多. 那么我們需要做的是使得P與CPU配額進行匹配. 我們可以選擇:

  1. 增加容器的CPU配額.

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

  3. 根據配額設置正確的GOMAXPROCS

第1個方法: 沒太大效果, 把配額從0.5變成1, 沒本質的區別(嘗試后, 問題依舊). 

第2點方法: 因為我對k8s不是很熟, 待我調研后再來補充. 

第3個方法: 設置GOMAXPROCS最簡單的方法就是啟動腳本添加環境變量 

GOMAXPROCS=2 ./svr_bin 這種是有效的, 但也有不足, 如果部署配額大一點的容器, 那么腳本沒法跟着變.

uber的庫automaxprocs

uber有一個庫, go.uber.org/automaxprocs, 容器中go進程啟動時, 會正確設置GOMAXPROCS. 修改了代碼模板. 我們在go.mod中引用該庫

  1. go.uber.org/automaxprocs v1.2.0

並在main.go中import

  1. import (

  2. _ "go.uber.org/automaxprocs"

  3. )

效果

automaxprocs庫的提示

使用automaxprocs庫, 會有如下日志:

  1. 對於虛擬機或者實體機

    8核的情況下: 2019/11/07 17:29:47 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined

  2. 對於設置了超過1核quota的容器

    2019/11/08 19:30:50 maxprocs: Updating GOMAXPROCS=8: determined from CPU quota

  3. 對於設置小於1核quota的容器

    2019/11/08 19:19:30 maxprocs: Updating GOMAXPROCS=1: using minimum allowed GOMAXPROCS

  4. 如果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. 

 

 

 

  1. 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

  2. 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

  3. 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

  4. 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

  5. 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

  1. ....

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

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

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

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

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

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

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

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

  10. ....

cpuacct,cpu在/sys/fs/cgroup/cpu,cpuacct這個目錄下.

獲取該容器cgroup子目錄

cat /proc/self/cgroup

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

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

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

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

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

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

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

  8. ....

該容器的cpuacct,cpu具體在/kubepods/burstable/pod62f81b5d-xxxx/xxxx92521d65bff8子目錄下

計算quota

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

  2. 50000

  3.  

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

  5. 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

總結

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

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

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

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

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


免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。



猜您在找 服務CPU 100%排查思路 linux中top查看cpu使用率超過100% 對jvm進行gc的時間、數量、jvm停頓時間的監控 Go中http超時問題的排查 【64期】MySQL 服務占用cpu 100%，如何排查問題? 一次服務器CPU占用100%的問題排查 CoreCLR中超過3萬行代碼的gc.cpp文件的來源 java CPU 100% 排查 Go GC機制 線上服務器的cpu使用達到100%了，如何排查、定位和解決該問題？
 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM