事情就发生在前几天，大家正在愉快的等下班的时候，突然收到上游系统反馈的告警邮件~
背景
先介绍一下背景，该系统平时调用量就比较大，所以部署的机器也多，一个机房大概有40台左右，单台虚机分配到的资源为4核8g，RPC框架用的是中间件魔改过的dubbo。系统比较老，还是用的原始的java6（升java8在计划中，不用问了）。
资源嘛，一般都是过剩的，毕竟分配资源都是按应用的上限来算，每次到服务器上用top命令看的时候都痛心疾首，负载竟然只有0.0几。
故事开始
上游发来的邮件里面信息很明确，调我们系统的服务在1分钟内出现了大量RPC异常，通过服务端打点监控很快就发现了所有的rpc异常的一个共同点：他们调用服务的提供者都是我们的同一台机器（还好只是一台机器）。
到这个时候，故障已经自行恢复了，持续了大概2分钟左右。
排查
故障已经自行恢复，现在留给我们的只有监控和日志。
当时的zabbix监控大概长这样(灵魂画手 哈哈)：
随后去看了眼gc日志，给我吓一跳：
2020-03-04T17:40:49.519+0800:6529953.133:[GC 6529953.133:[ParNew:634975K->36373K(707840K),58.1656230 secs]
969763K->371752K(2018560K),58.1660390 secs][Times:user=0.20 sys=0.03,real=58.16 secs]
Total time for which application threads were stopped: 58.1656230 seconds
一个长达一分钟的stop the world。
迅速把发生时间段前后的gc日志看了一遍，gc发生的频率还算正常，而且也没有出现有大对象回收不掉的情况，只有一个时间很诡异，[Times:user=0.20 sys=0.03,real=58.16 secs]。当时的第一反应就是：gc线程在等，或者是阻塞了。
user：进程执行用户态代码所耗费的处理器时间。
sys：进程执行核心态代码所耗费的处理器时间。
real：执行动作从开始到结束耗费的时钟时间。
user和sys代表的是线程占用一个处理器核心的耗时计数，如果是多核环境，同一时间有多少个处理器在工作，就会有多少倍的时间被记录下来。而时钟时间指的的是自然界中的时间计数，即从处理开始，到处理结束的时间差。
安全点
最初是怀疑在准备gc的过程中，有线程迟迟没有进入安全点，导致gc线程一直在自旋等待。
不过这个猜测很快就被否定了。等待安全点而引起的长停顿在gc日志上的表现并不是这样。
如果是由安全点导致的话，在时间上应该是real时间正常，但是整个应用程序停下的时间过长。这两个时间的差值，就是TTSP(Time To Safepoint)。
如果是安全点引起的话，可以通过加jvm参数来打印进入安全点超时的线程名称来定位问题：
-XX:+SafepointTimeout
-XX:+SafepointTimeoutDelay=2000
资源
另外一种可能是gc线程抢不到计算资源，从而导致gc迟迟不能进行
随后联系运维，在确认物理机没有出现故障，且当时没有人工做其他操作后，帮忙拉去了部署在这台物理机机上的所有应用列表。
单台物理机上使用kvm虚出来12台4核8g的虚机，在拿到每个应用的监控后，发现有一个应用当时cpu&io占用异常的高，达到了100%(我们最高也就70%上下)。
这样，该应用就很可疑了。
哈哈哈，不知道当时他们有没有发现自己的应用把cpu给飚满了
转到看该应用的打点监控：调用量不大，单台机器每小时只有6000+的调用量，而且也是只有这一台应用出现了占用大量cpu的情况。
看了调度平台，发现有一个调度的分片恰好在这台机器上。
该调度为每5分钟触发一次，统计了下他们的业务日志，数据量不大，而且历史上cpu也比较平稳。不至于吃满cpu。
(虽然看不到他们的代码，不过接入的调度平台日志有关键字可以查，大概估算下数据量吧)
翻日志的过程中，看到了有些解密失败的报错
难道是有大批量加解密请求占满了cpu？跟着日志一路找到接口，很遗憾，人家只是做了个sha1解密，才200多次，占满cpu是不可能的。
这时候也实在没了思路，主要是现场没了。。。如果现场还在的话，直接top -H -p找出占cpu的线程，再来一顿操作，分分钟找出罪魁祸首。
功夫不负有心人
没办法，之前都按关键字看应用日志，现在我也不关键字了，跳到cpu占用开始上升的时间点，批量往下翻日志看，一边翻一边吐槽，他们打的日志真不怎么样，都是大段大段的json，也不知道什么业务。
也是有意思了，如果我的zless命令竟然有点小卡，我尼玛这日志打的什么鬼东西，怎么这么长，卧槽？竟然还找不到底？MD，不会是他们在日志里面打一个巨长的json把io全给抢过去了吧？赶紧复制一个关键字：
$ zgrep -C 10 '2020-03-04 17:40:11.447' XX.log.zip | wc -L
2278281
这时候基本上已经实锤了，他这一行日志实在是太长了，就算他log4j配置的异步打印，这么大一个内容一次刷到文件换谁谁也受不了。
结束
自己也没想到，问题竟然出在日志打印上。
不过，虚机的隔离还是有待提升啊，竟然被同一物理机上的其他应用影响。不过，貌似io也很难完全隔离？
问题已经通知对方，但是我们已经怕了，已经把应用移到其他物理机上了 哈哈哈😃。
