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配额进行匹配，我们可以选择：

1. 增加容器的CPU配额

2. 容器层让容器内的进程看到CPU核数为配额数

3. 根据配额设置正确的GOMAXPROCS

第1个方法：没太大效果，把配额从0.5变成1，没本质的区别（尝试后，问题依旧）。

第2点方法：因为我对Kubernetes不是很熟，待我调研后再来补充。

第3个方法：设置GOMAXPROCS最简单的方法就是启动脚本添加环境变量。

GOMAXPROCS=2 ./svr_bin这种是有效的，但也有不足，如果部署配额大一点的容器，那么脚本没法跟着变。

Uber的库automaxprocs

uber有一个库，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库，会有如下日志：

1. 对于虚拟机或者实体机，8核的情况下：2019/11/07 17:29:47 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined

2. 对于设置了超过1核qusnow boyota的容器，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。

   
   
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

总结

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核数就是分配的配额的话，也可以解决这个问题。这方面我就不太了解了。

讨论

同时文章引起了一些讨论，我这里总结一下：

1. 不仅仅是Go在容器会因为资源没能完整屏蔽有问题，像Java的函数式编程paralle stream底层的fork-join框架会根据CPU数来启动对应的线程，JVM没有设置heap的话，那heap会根据识别的内存大小来自动设置堆大小，Python也会根据CPU数进行一些设置。

2. 在JavaSE8u131+和JDK9支持了对容器资源限制的自动感知能力，在JDK 8u191和JDK 10之后，社区对JVM在容器中运行做了进一步的优化和增强，JVM可以自动感知Docker容器内部的CPU和内存资源限制，Java进程可用CPU核数由cpu sets、cpu shares和cpu quotas等参数计算而来。

3. LXCFS可以在容器内挂载/proc目录，可以解决一部分容器可见性问题。

4. 对于Go来说，在进程启动时osinit方法中使用sched_getaffinity获取CPU个数，如果用户设置GOMAXPROCS环境变量，那么就使用该环境变量来此设置P的个数，否则使用CPU个数设置P，对于Go的话，解决这个问题，最简单的方式就是容器启动前Kubernetes根据分配的cpu quota来设置GOMAXPROCS环境变量，这样也不需要用户去关心了。

5. B站毛老师建议关注一下容器cgroup的CPU，cpuacct下的cpu.stat，里面有容器调度被限制的次数和时间（毛老师说他们已经在SRE上实践了比较久，业务和运维结合比较紧密，也组成团队一起做了很多优化）。

本文转载自公众号：yifhao， 点击查看原文。

Kubernetes入实战培训

Kubernetes入门与实战培训将于2019年11月29日在深圳开课，3天时间带你系统掌握Kubernetes，学习效果不好可以继续学习。本次培训包括：云原生介绍、微服务；Docker基础、Docker工作原理、镜像、网络、存储、数据卷、安全；Kubernetes架构、核心组件、常用对象、网络、存储、认证、服务发现、调度和服务质量保证、日志、监控、告警、Helm、实践案例等等，点击下方图片或者阅读原文链接查看详情。