背景说明

陌陌的微服务框架支持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多线程用尽，最终导致应用资源被限制。

举例说明：

如果一个应用在一个调度周期内积极的使用CPU资源达到CPU配额，那么这个应用会被限制（没有更多的CPU给它）然后导致在这个应用被暂停在整个调度周期剩余的时间中。
多线程的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线程。

结论总结

至此，整个排查过程就结束了，导致应用被暂停执行的根本原因是：因为JVM GC机制和CFS调度的互相影响，导致更长的STW耗时，进而对应用产生影响。
完善公司体系内的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

服务频繁出现100毫秒的延迟，原因是什么？相关推荐

MySQL主从复制延迟原因及处理思路
简单概述一下复制逻辑: 1.主库将对数据库实例的变更记录到binlog中. 2.主库会有binlog dump线程实时监测binlog的变更并将这些新的events推给从库(Master has se ...
STM32定时器实现100毫秒保存一次数据到SD卡
假设使用定时器3每1毫秒定时:保存至SD卡的函数是StartSave(); 第一种情况:定时器快,主循环慢 1.代码设计1(错误的设计) int cnt = 0; //计数 //TIM3中断处理函数 ...
每一次new InitialContext()方法花费大概100毫秒到200毫秒之间，而每一次lookup()大概要花10毫秒到30毫秒之间
最近因为工作需要开始学习Ejb3,遇到了一个让我很郁闷的事情,做一下小小的总结--小心new InitialContext(). 在做客户端的时候,发现连接服务器,搜索数据库,然后返回结果集.每一次执 ...
MySQL 常见主从延迟原因分析
MySQL 常见主从延迟原因分析更新时间:2022-10-30 文章目录 MySQL 常见主从延迟原因分析 MySQL 主从复制简介主从延迟时间计算方式主从延迟问题影响常见主从延迟原因分析 M ...
微服务架构中的雪崩问题产生原因及解决办法
微服务架构中的雪崩问题产生原因及解决办法参考文章: (1)微服务架构中的雪崩问题产生原因及解决办法 (2)https://www.cnblogs.com/panchanggui/p/10330924 ...
提示“Web打印服务CLodop未安装启动”的各种原因和解决方法
提示"Web打印服务CLodop未安装启动"的各种原因和解决方法参考文章: (1)提示"Web打印服务CLodop未安装启动"的各种原因和解决方法 (2)ht ...
mysql主从复制延时性问题_MySQL主从同步延迟原因及解决办法
MySQL主从延迟原因以及解决方案:谈到MySQL数据库主从同步延迟原理,得从mysql的数据库主从复制原理说起,mysql的主从复制都是单线程的操作(mysql5.6版本之前),主库对所有DDL和D ...
mysql单机在线迁移_MySQL 不停服务在线进行100亿数据迁移切换
MySQL 不停服务在线进行100亿数据迁移切换背景: 促销库压力巨大,单实例已经不足以提供写入性能,虽然有256个分表,但是经常io打满,总数据量已经达到100亿,单实例io已经支撑不住,所以方 ...
java 计时 timeclock_用 java 写一个clock的类，100毫秒的时钟求代码。。越简单越好。。最好有注释...
展开全部这里有一个时钟的类,你看一下吧,不明白你的 100毫秒的时钟是什么意思. import java.awt.BasicStroke; import java.awt.BorderLayout ...

服务频繁出现100毫秒的延迟，原因是什么？