记一次生产事故排查——CPU高负载原因排查分析

最近线上一个在线服务发现请求特别慢,接口经常出现超时问题,需要排查定位接口慢的原因。通过对现场和代码进行模拟(毕竟公司代码不太好放上来)总结一下此次排查给经验,尽可能为大家排查线上问题提供一些帮助。

1. 背景描述

大半夜运维打电话反馈请求到服务端接口非常缓慢,并且出现超时、报500现象,严重影响客户使用,需要排查问题原因。

稳住不方,首先看到这样的问题直接去排查 CPU 和内存的情况。线上服务器为16核、64G配置机器,查看内存还有目前仅占用 2.4% ,内存正常。

按理说三台这样配置机器的应该是能够满足当前业务需求的,然后通过 top 命令查看 CPU 负载情况,看了之后直呼好家伙,负载 load 均维持在 20 多,并且单 CPU 使用都到了 80%、90%。根据进程号查看哪一个 java 进程出现负载过高的情况,仔细一问才知道有个客户搞活动,客户端在疯狂请求接口导致 CPU 直接打满。

2. 排查过程

好了,目前初步定为了问题原因——CPU 负载太高导致接口相应变慢,接下来就是要去定位具体是什么原因导致 CPU 负载高。

2.1 定位负载过高的进程

通过 top 命令我们可以看到负载高的进程对应的进程号,如下图所示,可以看到该进程是一个 java 进程。


CPU 负载查看

通过 jps 指令可以查看具体是哪个服务,可以看到出现问题确实为我们模拟出来的这个程序进程,虽然我们能够从接口判断出来是哪个服务导致,但是如果一个环境中部署了多个服务,并且服务存在一定的调用,那么这样查看进程号对应服务名的这一步还是很有必要的。

高负载进程

2.2 进程内运行分析

获取进程中各线程的 CPU 使用情况

首先排查进程内各线程的 CPU 使用情况,命令如下:

ps -mp PID -o THREAD,tid,time
线程运行状态

命令参数说明:
-m:在进程后面显示线程
-p:后面需要跟上进程号列表,通过进程号进行选择。使用 -mp 即筛选出指定的进程号中的线程列表
-o:自定义格式化

线程号处理

我们找到 CPU 占用比较高的一个线程,如 28970这个线程,由于系统中的线程栈使用 16 进制进行记录,因此我们需要将 10 进制的线程号转换为 16 进制的,为下一步排查做准备。这里可以使用计算器,也可以直接使用 linux 指令打印出 28970 转换为 16 进制的结果为 712a。

printf "%x\n" 28970
十六进制线程号

排查进程堆栈信息

通过 jstack 命令可以打印整个进程的线程堆栈信息,在堆栈信息中查找上一步处理的线程号。从日志中可以看到是 RunningMethod.run() 最后执行在这个方法上的 14 行,正好是示例代码中死循环部分。排查其他线程也同样是在这一步阻塞住。一个不够可以多选几个线程进行对比。

jstack 25960|grep 657a -A 10
线程堆栈排查

更进一步排查方法执行耗时

使用 Arthas 进行排查( Arthas 排查线上问题真的好用),通过 trace 命令追踪该方法执行耗时。

trace class-pattern method-pattern

由于测试代码为了模拟使用的死循环,显示 trace 结果效果不太好。在生产环境我们可以根据上一步定位到的类及方法,通过 trace 命令查看该方法调用链中所需耗时。

以官方的 math-game 为例,当我们跟踪 MathGame 的 run 方法时,将打印出该方法的调用链路及每个方法的执行时间,如下图所示:

trace示例

生产环境中执行结果类似,能够根据打印结果定位到具体耗时的方法位置。今后会专门写 Arthas 排查相关博客进行总结。

得出结论

根据以上排查流程结果能够定位到耗时方法、以及执行效率。这次生产事故是由于在解析模板参数时将全量模板及对应参数进行解析导致的,每一次请求均会单独做一次解析,而解析过程又是非常占用资源并耗时的。由于以前并发量不高所以一直没有暴露出问题,这次客户一搞活动就出现了生产事故,由此看出开发这一块的同事并未考虑到并发性能这一块。


2.3 解决方案

紧急方案:

  • 修改 JVM 参数,并增加机器临时应急,这也只是紧急处理方法,熬过当晚活动

短期方案:

  • 添加缓存。由于存在大量重复模板解析因此对解析完成后的模板进行缓存,防止重复操作减轻 CPU 压力
  • 模板瘦身。以前直接一股脑的将全量数据进行解析,因此需要对模板进行瘦身,只解析需要解析的部分,不需要解析的部分不再操作直接替换即可

长期方案:

  • 重构模板解析方法,以前的方法臃肿且不易扩展,需要选用轻量级的解析方案以应对将来的大量请求场景

3. 总结

这次线上事故原因最终还是被定位到了(程序运行导致 CPU 负载过高),定位过程也是比较常规的 CPU 负载过高的排查过程。从问题排查出也暴露出以下几个问题:

  • 开发代码时不仅要实现功能,还需要考虑性能问题
  • 开发完成做好自测以及压力测试
  • 遇到生产问题不能慌,一步步排查总能够找到原因

文章中仅使用了死循环进行模拟,因此并不能够完整的模拟出事故现场,但是整体思路不变,整个流程应用于线上问题定位效果更佳。

4. 代码附录

1   import java.util.concurrent.TimeUnit;
2
3   public class CpuDemo {
4       public static void main(String[] args) {
5           System.out.println("CPU high load start.");
6           for (int i = 0; i < 100; i++) {
7               new Thread(new RunningMethod()).start();
8           }
9       }
10
11      public static class RunningMethod implements Runnable {
12          public void run() {
13
14                  while(true) {
15                  }
16          }
17      }
18
19  }
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 212,332评论 6 493
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,508评论 3 385
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 157,812评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,607评论 1 284
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,728评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,919评论 1 290
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,071评论 3 410
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,802评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,256评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,576评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,712评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,389评论 4 332
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,032评论 3 316
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,798评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,026评论 1 266
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,473评论 2 360
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,606评论 2 350

推荐阅读更多精彩内容