背景说明

陌陌的微服务框架支持Redis协议调用方式， 在使用Redis协议调用MOA服务时， 每个请求会被包装为一个消息， 这个消息会用一个唯一ID来标识，ID是由机器名称+进程ID+消息产生的时间戳组成，当请求消息经过网络到达服务端应用后，MOA框架在处理消息前会先用当前时间减去消息的产生时间，如果差值大于100毫秒则会记录该请求到慢请求文件中。正常请求下该文件几乎不会产生数据，但是最近多名业务侧同学反馈慢请求文件数据较多，导致TP90数据飙高，希望帮忙排查原因。

排查过程

是否是容器问题？

陌陌的应用层全部跑在Docker容器上，为了排查容器自身因素，将该服务的部分实例迁到了VM上，对比发现VM上的实例基本上没有慢请求日志，所有基本确定该问题跟Docker容器相关。

网络不稳？

2018-12-18 12:23:40,822 REQUEST: Command [id=xxxxxxx-kube-node-web-php-

198861545107020.6728, action=/service/xxxx-action-service, source=127.0.0.1, thread=, params={args=[ap6896299708], m=getXxxRecReadNum}]  ### waitedTime: 103 ms

对比消息产生时间和服务端接收到数据包时间可知消息传递的网络耗时几乎可忽略，排除网络不稳定带来的影响。

网卡到socket读缓存区慢了？

通过上面tcpdump结果来说，数据从网卡到ReveiveQ再到用户态获取数据这一个过程也是及时的，为了再次验证这个结论，运维同学通过systemtap工具在tcp_v4_do_rcv调用时，将skb的内容打印出来，并将调用时间打印出来，通过比较系统调用时间和skb中的消息时间比对发现基本一致。 

//probe kernel.statement("tcp_rcv_established@net/ipv4/tcp_input.c:5256") {

probe kernel.function("tcp_v4_do_rcv").return {

	saddr = ip_ntop(@entry($sk->__sk_common->skc_daddr))

	daddr = ip_ntop(@entry($sk->__sk_common->skc_rcv_saddr)){

	if (saddr == "{source Addr}" && daddr == "{target Addr}")

		printf("taptime:%d, pid: %d,  %s:%d --> %s, %s\n",

		gettimeofday_ms(),

		tid(),

		saddr,

		ntohs(@entry($sk->__sk_common->skc_dport)),

		daddr,

		__buffer_data(@entry($skb), 1)

	}

}

Read系统调用不及时？

hack read系统，在read调用时， 对比read触发的时间和read到的消息题中的时间已经延迟较大，这个值几乎跟应用层面记录的waitedTime一致。至此可以确定是发起read调用时就已经出现了时延。

probe syscall.read {

	try {

	   if (pid() == {target Pid}) {

		printf("taptime: %d, data: %s\n", gettimeofday_ms(),

		kernel_string($buf))

	   }

	} catch (msg) {

		println("caught error ", msg)

	}

}

原因分析

一.  Read调用不及时原因

当消息到达Socket ReceiveQ时，epollwait系统调用的阻塞会被唤醒，同时给应用层返回指定socket的readable事件，Netty IO线程响应可读事件进行read调用，但是实际却没有立刻进行read调用。大都数情况下是因为在IO线程中执行了耗时操作，导致worker eventloop group中没有可用线程去拉取数据，但是显然这和MOA的实现机制是冲突的，业务处理逻辑在业务线程中执行，IO线程并没有耗时操作。还有就是GC导致整个应用STW，通过查看应用日志的确找到了相关线索，在实例GC日志上偶尔刷出了100ms+的YoungGC日志，YGC的执行会STW，线上服务使用的是ParNew 并发收集策略，频率基本跟服务耗时突刺吻合。所以问题转变为为什么出现100msGC。

二.  100ms YGC的原因

对比GC日志，发现单次耗时超过100ms的GC与正常较少耗时的YGC相比，GC前后的内存占用情况并没有较大差异，即并不是因为单次GC的内存大导致GC耗时增加。

在一筹莫展之际，运维同事发现了一个现象就是ParallelGCThreads线程数出乎意料的多，调整ParallelGCThreads，限制在4个线程，问题解决！但是这个数字怎么算出来的呢？我们看下 GC 线程数据的计算规则：cpu 核数小于8 gc 线程数等于cpu核数，大于8的时候=8+(cpu数-8)*⅝。同时运维同学给出信息，JDK 8u131 版本开始增加了识别 Docker 资源的改进，但不能识别 cpu shares 或 cpu quotas 配置的 CPU 资源，内存资源的识别也没有默认开启，需指定相关参数，这个问题在JDK 8u191版本得到了改进，能够正确识别 Docker 的 CPU 、内存资源配置信息。至此100msGC的原因得到了确认是因为JDK版本不能正确识别DockerCPU配置，导致整ParallelGCThreads个数异常增大，导致YGC突刺。为什么整ParallelGCThreads个数多导致YGC突刺？

三. ParallelGCThreads个数多导致YGC突刺的原因

发现linkedin同样遇到了这样的问题，并将详细的原因做了描述（详见引用一）

在CFS（引用二）中， 一个cgroup被分配确定的cpu配额（cfs_quota），这些配额快速被活跃的JVM GC多线程用尽，最终导致应用资源被限制。

举例说明：

1. 如果一个应用在一个调度周期内积极的使用CPU资源达到CPU配额，那么这个应用会被限制（没有更多的CPU给它）然后导致在这个应用被暂停在整个调度周期剩余的时间中。
2. 多线程的JVM GC使得问题变的更差，因为cfs_quota是统计这个应用的所有线程，因此CPU配额会被更快的使用掉，JVM GC有多个并行阶段是不会STW (stop the world)的，但是这些运行的多线程会导致CPU配额更快被消耗完而受到cgroup限制，引起应用发生STW。

作者详细举例阐述了上面的内容：

理想情况下，CPU调度程序会调度应用程序在每个CFS周期内稀疏运行，以便应用程序不会长时间暂停。如下图所示，应用程序计划在300毫秒CFS期间运行3次。计划运行之间存在应用程序暂停，预期应用程序暂停为70毫秒（假设应用程序完全使用90毫秒CPU配额）。

第一个问题发生在应用程序耗尽90ms的所有cpu配额时，例如在某些CFS时段的前90ms内。然后，由于配额被占用，在剩余的210ms期间，应用程序暂停，用户经历210ms延迟。请注意，多线程应用程序的问题更严重，因为CPU配额可以更快地用完。

GC STW暂停期间，Java应用程序更严重，因为JVM可以使用多个GC线程并行收集垃圾。

对于流行的JVM垃圾收集器，如CMS和G1，GC有多个阶段; 某些阶段是STW，其它阶段是concurrent（非STW）。尽管并发GC阶段（使用并发GC线程）旨在避免JVM STW，但cgroup的使用完全违背了这个目的。在并发GC阶段使用的CPU时间也会计入cgroup的CPU使用计算，这实际上会导致应用程序遇到更大的STW暂停。

由于JVM GC和CFS调度之间的交互，在Linux cgroup中运行的Java应用程序可能会遇到更长的应用程序暂停。为缓解此问题，作者建议使用以下调整：

a: 充分配置CPU资源（即CFS配额）。显然，分配给cgroup的CPU配额越大，cgroup被限制的可能性就越小。

b: 适当调整GC线程。

结论总结

1. 至此，整个排查过程就结束了，导致应用被暂停执行的根本原因是：因为JVM GC机制和CFS调度的互相影响，导致更长的STW耗时，进而对应用产生影响。
2. 完善公司体系内的Docker容器监控，增加CPU受限监控。

名词解释

MOA   MOA的全称是Momo (Service) Oriented Architecture，是由陌陌技术团队研发的一个RPC服务框架。该框架于2012年底投入使用，目前是陌陌实现远程调用、跨语言通信等最重要的基础框架之一

引用

Application Pauses When Running JVM Inside Linux Control Groups ： 

https://engineering.linkedin.com/blog/2016/11/application-pauses-when-running-jvm-inside-linux-control-groups 

CFS ：

https://www.kernel.org/doc/Documentation/scheduler/sched-bwc.txt