从阿里大促中,我理出的CPU与Load异常排查思路

DBAplus社群 2020-10-12 18:08:00
前言

 

大家都知道服务器在大促期间由于流量的增加势必导致机器的cpu与load变高,本文将与大家一起巩固cpu和load的概念,为今年各种大促做准备的同时也是增加自己的技能储备。

 

不过cpu和load这块真的还是很需要积累的,笔者经验尚浅,感觉还是有许多写得不到位或不恰当的地方,如果有错误,希望大家可以帮助指正。
 

一、top命令

 

既然说了cpu和load,那总需要监控吧,没有监控就不知道cpu和load,后面的一切也就无从谈起了。

 

top命令是最常见的查看cpu和load的命令,拿我自己虚拟机上装的ubuntu系统执行一下top命令(默认3秒刷1次,-d可指定刷新时间):

 

 

做了一张表格比较详细地解释了每一部分的含义,其中重要属性做了标红加粗:

 

 

内存与SWAP输出格式是一样的,因此放在了一起写。

 

二、cpu如何计算

 

当我们执行top命令的时候,看到里面的值(主要是cpu和load)是一直在变的,因此有必要简单了解一下Linux系统中cpu的计算方式。

 

cpu分为系统cpu和进程、线程cpu,系统cpu的统计值位于/proc/stat下(以下的截图未截全):

 

 

cpu、cpu0后面的这些数字都和前面的us、sy、ni这些对应,具体哪个对应哪个值不重要,感兴趣的可以网上查一下文档。

 

进程cpu的统计值位于/proc/{pid}/stat下:

 

 

线程cpu的统计值位于/proc/{pid}/task/{threadId}/stat下: 

 

 

这里面的所有值都是从系统启动时间到当前时间的一个值。因此,对于cpu的计算的做法是,采样两个足够短的时间t1、t2:

 

  • 将t1的所有cpu使用情况求和,得到s1;

  • 将t2的所有cpu使用情况求和,得到s2;

  • s2 - s1得到这个时间间隔内的所有时间totalCpuTime;

  • 第一次的空闲idle1 - 第二次的空闲idle2,获取采样时间内的空闲时间;

  • cpu使用率 = 100 * (totalCpuTime - idle) / totalCpuTime。

 

其他时间例如us、sy、ni都是类似的计算方式,总结起来说,cpu这个值反应的是某个采样时间内的cpu使用情况。因此有时候cpu很高,但是打印线程堆栈出来发现高cpu的线程在查询数据库等待中,不要觉得奇怪,因为cpu统计的是采样时间内的数据。

 

假设top观察某段时间用户空间cpu一直很高,那么意味着这段时间用户的程序一直在占据着cpu做事情。

 

三、对load的理解

 

关于load的含义,其实有些文章把它跟行车过桥联系在一起是比较恰当和好理解的:

 

一个单核的处理器可以形象得比喻成一条单车道,车辆依次行驶在这条单车道上,前车驶过之后后车才可以行驶。

 

如果前面没有车辆,那么你顺利通过;如果车辆众多,那么你需要等待前车通过之后才可以通过。

 

因此,需要些特定的代号表示目前的车流情况,例如:

 

  • 等于0.00,表示目前桥面上没有任何的车流。实际上这种情况0.00和1.00之间是相同的,总而言之很通畅,过往的车辆可以丝毫不用等待的通过;

  • 等于1.00,表示刚好是在这座桥的承受范围内。这种情况不算糟糕,只是车流会有些堵,不过这种情况可能会造成交通越来越慢;

  • 大于1.00,那么说明这座桥已经超出负荷,交通严重的拥堵。那么情况有多糟糕? 例如2.00的情况说明车流已经超出了桥所能承受的一倍,那么将有多余过桥一倍的车辆正在焦急的等待。

 

但是比喻终归是比喻,从比喻中我们了解了,load表示的是系统的一个能力,但是我们却不知道什么样的任务会被归到load的计算中。关于具体怎么样的任务会被归到load的计算中,可以使用man uptime命令看一下Linux对于load的解释:

 

 

大致意思就是说,系统load是处于运行状态或者不可中断状态的进程的平均数(标红部分表示被算入load的内容)。一个处于运行状态的进程表示正在使用cpu或者等待使用cpu,一个不可中断状态的进程表示正在等待IO,例如磁盘IO。load的平均值通过3个时间间隔来展示,就是我们看到的1分钟、5分钟、15分钟,load值和cpu核数有关,单核cpu的load=1表示系统一直处在负载状态,但是4核cpu的load=1表示系统有75%的空闲。

 

特别注意,load指的是所有核的平均值,这和cpu的值是有区别的。

 

还有一个重要的点是,查了资料发现,虽然上面一直强调的是"进程",但是进程中的线程数也是会被当作不同的进程来计算的,假如一个进程产生1000个线程同时运行,那运行队列的长度就是1000,load average就是1000。

 

四、请求数和load的关系

 

之前我自己一直有个误区:当成千上万的请求过来,且在排队的时候,后面的请求得不到处理,load值必然会升高。认真思考之后,这个观点可真是大错特错,因此特别作为一段写一下,和大家分享。

 

以Redis为例,我们都知道Redis是单线程模型的,这意味着同一时间可以有无数个请求过来,但是同一时间只有一个命令会被处理。

 

图片来源:https://www.processon.com/view/5c2ddab0e4b0fa03ce89d14f

 

单独的一条线程接到就绪的命令之后,会将命令转给事件分发器,事件分发器根据命令的类型执行对应的命令处理逻辑。由于只有一条线程,只要后面排队的命令足够多到让这条线程一个接一个不停地处理命令,那么load表现就等于1。

 

整个过程中,回看load这个值,它和请求数没有任何关系,真正和load相关的是工作线程数量,main线程是工作线程、Timer是工作线程、GC线程也是工作线程,load是以线程/进程作为统计指标,无论请求数是多少,最终都需要线程去处理,而工作线程的处理性能直接决定了最终的load值。

 

举个例子,假设一个服务中有一个线程池,线程池中线程数量固定为64:

 

  • 正常来说一个任务执行时间为10ms,线程拿到任务10ms处理完,很快回归线程池等待下一个任务到来,自然很少有处于运行状态或者等待IO的线程,从一个统计周期来看load表现为很低;

  • 某段时间由于系统问题,一个任务10s都处理不完,相当于线程一直在处理任务,在load的统计周期里面就体现出的值=64(不考虑这64条线程外的场景)。

 

因此,总而言之,搞清楚load值和请求数、线程数的关系非常重要,想清楚这些才能正确地进行下一步的工作。

 

五、load高、cpu高的问题排查思路

 

首先抛出一个观点:cpu高不是问题,由cpu高引起的load高才是问题,load是判断系统能力指标的依据

 

为什么这么说呢,以单核cpu为例,当我们日常cpu在20%、30%的时候其实对cpu资源是浪费的,这意味着绝大多数时候cpu并没有在做事,理论上来说一个系统极限cpu利用率可以达到100%,这意味着cpu完全被利用起来了处理计算密集型任务,例如for循环、md5加密、new对象等等。但是实际不可能出现这种情况,因为应用程序中不消耗cpu的IO不存在是几乎不可能的,例如读取数据库或者读取文件,因此cpu不是越高越好,通常75%是一个需要引起警戒的经验值。

 

注意前面提到的是"引起警戒",意味着cpu高不一定是问题,但是需要去看一下,尤其是日常的时候,因为通常日常流量不大,cpu是不可能打到这么高的。如果只是普通的代码中确实在处理正常业务那没问题,如果代码里面出现了死循环(例如JDK1.7中经典的HashMap扩容引发的死循环问题),那么几条线程一直占着cpu,最后就会造成load的增高。

 

在一个Java应用中,排查cpu高的思路通常比较简单,有比较固定的做法:

 

  • ps -ef | grep java,查询Java应用的进程pid;

  • top -H -p pid,查询占用cpu最高的线程pid;

  • 将10进制的线程pid转成16进制的线程pid,例如2000=0x7d0;

  • jstack 进程pid | grep -A 20 '0x7d0',查找nid匹配的线程,查看堆栈,定位引起高cpu的原因。

 

网上有很多文章写到这里就停了,实践过程中并不是这样。因为cpu是时间段内的统计值、jstack是一个瞬时堆栈只记录瞬时状态,两个根本不是一个维度的事,因此完全有可能从打印出来的堆栈行号中看到代码停留在以下地方:

 

  • 不消耗cpu的网络IO;

  • for (int i = 0, size = list.size(); i < size; i++) {...};

  • 调用native方法。

 

如果完全按照上面那一套步骤做的话碰到这种情况就傻眼了,冥思苦想半天却不得其解,根本不明白为什么这种代码会导致高cpu。针对可能出现的这种情况,实际排查问题的时候jstack建议打印5次至少3次,根据多次的堆栈内容,再结合相关码段进行分析,定位高cpu出现的原因,高cpu可能是代码段中某个bug导致的而不是堆栈打印出来的那几行导致的

 

另外,cpu高的情况还有一种可能的原因,假如一个4核cpu的服务器我们看到总的cpu达到了100%+,按1之后观察每个cpu的us,只有一个达到了90%+,其他都在1%左右(下图只是演示top按1之后的效果并非真实场景):

 

 

这种情况下可以重点考虑是不是频繁FullGC引起的。因为我们知道FullGC的时候会有Stop The World这个动作,多核cpu的服务器,除了GC线程外,在Stop The World的时候都是会挂起的,直到Stop The World结束。以几种老年代垃圾收集器为例:

 

  • Serial Old收集器,全程Stop The World;

  • Parallel Old收集器,全程Stop The World;

  • CMS收集器,它在初始标记与并发标记两个过程中,为了准确标记出需要回收的对象,都会Stop The World,但是相比前两种大大减少了系统停顿时间。

 

无论如何,当真正发生Stop The World的时候,就会出现GC线程在占用cpu工作而其他线程挂起的情况,自然表现也就为某个cpu的us很高而且他cpu的us很低。

 

针对FullGC的问题,排查思路通常为:

 

  • ps -ef | grep java,查询Java应用的进程pid;

  • jstat -gcutil pid 1000 1000,每隔1秒打印一次内存情况共打印1000次,观察老年代(O)、MetaSpace(MU)的内存使用率与FullGC次数;

  • 确认有频繁的FullGC的发生,查看GC日志,每个应用GC日志配置的路径不同;

  • jmap -dump:format=b,file=filename pid,保留现场;

  • 重启应用,迅速止血,避免引起更大的线上问题;

  • dump出来的内容,结合MAT分析工具分析内存情况,排查FullGC出现的原因。

 

如果FullGC只是发生在老年代区,比较有经验的开发人员还是容易发现问题的,一般都是一些代码bug引起的。MetaSpace发生的FullGC经常会是一些诡异、隐晦的问题,很多和引入的第三方框架使用不当有关或者就是第三方框架有bug导致的,排查起来就很费时间。

 

那么频繁FullGC之后最终会导致load如何变化呢?这个我没有验证过和看过具体数据,只是通过理论分析,如果所有线程都是空闲的,只有GC线程在一直做FullGC,那么load最后会趋近于1。但是实际不可能,因为如果没有其他线程在运行,怎么可能导致频繁FullGC呢。所以,在其他线程处理任务的情况下Stop The World之后,cpu挂起,任务得不到处理,更大可能的是load会一直升高。

 

最后顺便提一句,前面一直在讲FullGC,频繁的YoungGC也是会导致load升高的,之前看到过的一个案例是,Object转xml,xml转Object,代码中每处都new XStream()去进行xml序列化与反序列化,回收速度跟不上new的速度,YoungGC次数陡增。

 

六、load高、cpu低的问题排查思路

 

关于load的部分,我们可以看到会导致load高的几个因素:

 

  • 线程正在使用cpu;

  • 线程正在等待使用cpu;

  • 线程在执行不可被打断的IO操作。

 

既然cpu不高,load高,那么线程要么在进行io要么在等待使用cpu。不过对于后者"等待使用cpu"我这里存疑,比如线程池里面10个线程,任务来的很慢,每次只会用到1个线程,那么9个线程都是在等待使用cpu,但是这9个线程明显是不会占据系统资源的,因此我认为自然也不会消耗cpu,所以这个点不考虑。

 

因此,在cpu不高的情况下假如load高,大概率io高才是罪魁祸首,它导致的是任务一直在跑,迟迟处理不完,线程无法回归线程池中。首先简单讲讲磁盘io,既然wa表示的是磁盘io等待cpu的百分比,那么我们可以看下wa确认下是不是磁盘io导致的:

 

 

如果是,那么按照cpu高同样的方式打印一下堆栈,查看文件io的部分进行分析,排查原因,例如是不是多线程都在读取本地一个超大的文件到内存。

 

磁盘io导致的load高,我相信这毕竟是少数,因为Java语言的特点,应用程序更多的高io应当是在处理网络请求,例如:

 

  • 从数据库中获取数据;

  • 从Redis中获取数据;

  • 调用Http接口从支付宝获取数据;

  • 通过dubbo获取某服务中的数据。

 

针对这种情况,我觉得首先我们应该对整个系统架构的依赖比较熟悉,例如我画一个草图:

 

 

对依赖方的调用任何一个出现比较高的耗时都会增加自身系统的load,出现load高的建议排查方式为:

 

  • 查日志,无论是HBase、MySql、Redis调用还是通过http、dubbo调用接口,调用超时,拿连接池中的连接超时,通常都会有错误日志抛出来,只要系统里面没有捕获异常之后不打日志直接吞掉一般都能查到相关的异常;

  • 对于dubbo、http的调用,建议做好监控埋点,输出接口名、方法入参(控制大小)、是否成功、调用时长等必要参数,有些时候可能没有超时,但是调用2秒、3秒一样会导致load升高,所以这种时候需要查看方法调用时长进行下一步动作。

 

如果上面的步骤还是没用或者没有对接口调用做埋点,那么还是万能的打印堆栈吧,连续打印五次十次,看一下每次的堆栈是否大多都指向同一个接口的调用,网络io的话,堆栈的最后几行一般都有at java.net.SocketInputStream.read(SocketInputStream.java:129)。

 

七、Java应用load高的几种原因总结

 

前面说了这么多,这里总结一下load高可能的一些原因:

 

  • 死循环或者不合理的大量循环操作,如果不是循环操作,按照现代cpu的处理速度来说处理一大段代码也就一会会儿的事,基本对能力无消耗;

  • 频繁的YoungGC;

  • 频繁的FullGC;

  • 高磁盘IO;

  • 高网络IO。

 

系统load高通常都是由于某段发布的代码有bug或者引入某些第三方jar而又使用不合理导致的,因此注意首先区分load高,是由于cpu高导致的还是io高导致的,根据不同的场景采取不同定位问题的方式。

 

当束手无策时,jstack打印堆栈多分析分析吧,或许能灵光一现能找到错误原因。

 

结语

 

先有理论,把理论想透了,实战碰到问题的时候才能头脑清楚。

 

坦白讲,cpu和load高排查是一个很偏实战的事情,这方面我还也有很长一条路需要走,身边在这块经验比我丰富的同事多得很。很多人问过我,项目比较简单,根本没有这种线上问题需要我去排查怎么办?这个问题只能说,平时多积累、多实战是唯一途径,假如没有实战机会,那么推荐三种方式:

 

  • 自己通过代码模拟各种异常,例如FullGC、死锁、死循环,然后利用工具去查,可能比较简单,但是万丈高楼平地起,再复杂的东西都是由简单的变化过来的;

  • 多上服务器上敲敲top、sar、iostat这些命令,熟记每个命令的作用及输出参数的含义;

  • 去网上找一下其他人处理FullGC、CPU高方法的文章,站在巨人的肩膀上,看看前人走过的路,总结记录一些实用的点。

 

当真的有实战机会来的时候把握住,即使是同事排查的问题,也可以在事后搞清楚问题的来龙去脉,久而久之自然这方面的能力就会提高上去。

 

作者丨五月的仓颉
来源丨五月的仓颉(ID:gh_6b7a3f664e7d)
dbaplus社群欢迎广大技术人员投稿,投稿邮箱:editor@dbaplus.cn
 
最新评论
访客 2024年04月08日

如果字段的最大可能长度超过255字节,那么长度值可能…

访客 2024年03月04日

只能说作者太用心了,优秀

访客 2024年02月23日

感谢详解

访客 2024年02月20日

一般干个7-8年(即30岁左右),能做到年入40w-50w;有…

访客 2023年08月20日

230721

活动预告