记一次机器内存过高引起的线上故障

最新推荐文章于 2023-11-10 11:55:53 发布

bboyzqh

最新推荐文章于 2023-11-10 11:55:53 发布

阅读量1.4k

点赞数 1

本文链接：https://blog.youkuaiyun.com/zhuqiuhui/article/details/102533824

版权

文章目录

1.案发经过

中午12点时当时在外吃饭，忽然研发群里面炸锅了，到店神器（包括了互动营销的拼团、砍价等活动）的两台机器服务进程没有了，依赖方已经报找不到相应的服务了，由于在外吃饭，在工位的同事帮忙重启了一台机器，服务正常。回去看了一下机器的情况，到店神器在一个集群中有两台机器编号001和编号002，内存、cpu和负载使用情况如下：

编号001机器

在这里插入图片描述

编号002机器
在这里插入图片描述

从上面两幅图可以看出：

机器	时间段	cpu	内存	负载load_1m
编号001机器	11:55:00~11:57:00	6.47%->91.69%	61.79%->71.21%	0.2->6.8
编号002机器	11:55:00~11:56:00	8%->46.94%	60.34%->65.55%	0.13->9.03

编号001机器在11:59:00java进程被杀死，编号002机器在11:58:00java进程被杀死。

2. 故障分析

从刚才表象上看，引起关注的是，编号001机器和编号002机器都是系统负载比较高，且编号002机器高达9.03。从监控平台上看cShareAct接口在事发的近3min中平均RT达10s，于是猜测是不是活动突然开始，导致分享用户量突然增加导致接口超时无法响应呢？查看了一下该接口的监控情况：

接口	调用量	平均RT（ms）	最大RT（ms）	最大QPS
cShareAct	52	10926.2	37308	3

该接口平时的QPS一直很低，3已经很高了，对比一下2019-08-20 11：03~2019-08-23 11：03这3天的该接口监控情况：

接口	调用量	平均RT（ms）	最大RT（ms）	最大QPS
cShareAct	944	1036.31	9821	2

发现该接口RT上涨非常大，且调用量在这3min内确实比平时有所增加，如下图：
在这里插入图片描述

2.1 为什么cShareAct接口一直超时？

从监控上看cShareAct接口平均RT约11s，该接口主要做一件事情：从阿里云上下载图片，并使用awt来合成图片。于是查看了其中一台的日志发现cShareAct接口在11:55:00时开始出现，分享的活动ID是85670、85664，这两个活动是同一家店铺发起的，且这两个活动在今天接近12点开始，所以集中12点附近分享比较多，结合代码和现场日志分析得出cShareAct接口一直超时的结论如下：

活动ID是85670、85664在12点开始，附近时间点分享比较多
cShareAct接口分析90%的时间耗费在从阿里云上下载图片和合成图片过程上
两个活动的主图达4M多（历史活动主图99%小于1M），且是同一张图片（同一个店铺下的两个活动），同时该主图是合成分享图片必须使用的，都是先从阿里云上下载下来，然后再进行合成

2.2 为什么cShare接口调用量突增？

从历史数据上看cShare接口结合活动在12点开始，有可能会出现调用量很高，但这里的很高原因有以下几点：

活动ID是85670、85664在12点开始，附近时间点分享比较多
应用中设置的cShareAct接口默认使用全局的超时配置5s，若cShareAct接口执行过程中超过5s便会产生超时，客户端便会等待结束，而此时服务端依然在执行，客户端感知不到，用户会重复点击，这样就触发了第2次请求，第2次请求再次超时（从日志上分析可以得出），这样就出现了同一个用户出现了多次请求的情况，直接使该接口调用量突然增加。

下图中用户ID是834213在不到2s的时间内同时请求了7次。

在这里插入图片描述

2.3 cpu升高的原因分析

从上面监控上看，现场时间点cpu都达到很高，为了分析原因，于是使用jmeter进行测试环境压测分析，对该分享接口做了一定的限制后，设置50个线程来压测，持续3min，期间cpu轻易达到60~103%之间，并一直居高不下，此时对cpu高的进程分析如下：

第一步：top -Hp 13命令找出当前进程下线程使用cpu情况，如下

 PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                                      
 2231 root      20   0   12.5g   2.1g  15576 S 19.9  2.2   0:55.57 java                                                                                                                         
 2225 root      20   0   12.5g   2.1g  15576 S 12.6  2.2   1:18.39 java                                                                                                                         
 2237 root      20   0   12.5g   2.1g  15576 S 12.3  2.2   2:05.45 java                                                                                                                         
 2234 root      20   0   12.5g   2.1g  15576 S  6.3  2.2   2:02.15 java                                                                                                                         
 2228 root      20   0   12.5g   2.1g  15576 S  5.0  2.2   0:47.25 java                                                                                                                         
 2219 root      20   0   12.5g   2.1g  15576 S  1.3  2.2   1:15.78 java                                                                                                                         
   17 root      20   0   12.5g   2.1g  15576 S  0.3  2.2   0:01.79 java                                                                                                                         
   20 root      20   0   12.5g   2.1g  15576 S  0.3  2.2   0:01.83 java                                                                                                                         
   21 root      20   0   12.5g   2.1g  15576 S  0.3  2.2   0:01.84 java                                                                                                                         
   22 root      20   0   12.5

第二步：jstack -l 13 >> test 保存进程堆栈信息

第三步：找出上面pid是2231（对应16进制8b7）、2225（对应16进制8b1）的堆栈信息，如下

pid是2231的堆栈信息如下

cat test | grep -C200 "8b7"

DubboServerHandler-10.100.2.220:20880-thread-298" #1938 daemon prio=5 os_prio=0 tid=0x00007f4eec0fc000 nid=0x8b7 runnable [0x00007f4d9530a000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
        at org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:197)
        at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:176)
        at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:198)
        at org.apache.http.entity.BasicHttpEntity.writeTo(BasicHttpEntity.java:116)
        at org.apache.http.impl.execchain.ResponseEntityProxy.writeTo(ResponseEntityProxy.java:99)
        at com.yt.cmc.common.util.http.HttpUtil.downloadFile(HttpUtil.java:70)
        at com.yt.cmc.common.util.http.HttpUtil.downloadFile(HttpUtil.java:49)
        at com.yt.cmc.biz.util.PictureOperationUtil.downloadPic(PictureOperationUtil.java:26)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl.downloadPictures(BActServiceImpl.java:2068)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl.setShareActImgDTO(BActServiceImpl.java:2195)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl.shareAct(BActServiceImpl.java:1750)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl$$FastClassBySpringCGLIB$$898f72c0.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:649)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl$$EnhancerBySpringCGLIB$$7bfd05d0.shareAct(<generated>)
        at com.yt.cmc.biz.ao.u2c.CactAOImpl.cShareAct(CactAOImpl.java:236)
        at com.yt.cmc.biz.ao.u2c.CactAOImpl$$FastClassBySpringCGLIB$$c7b011cf.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:718)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
        at com.yt.cmc.biz.aop.GlobalExceptionAspect.doProcess(GlobalExceptionAspect.java:52)
        at sun.reflect.GeneratedMethodAccessor331.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.jav

pid是2225 的堆栈信息如下：

cat test | grep -C200 "8b1"

"DubboServerHandler-10.100.2.220:20880-thread-296" #1932 daemon prio=5 os_prio=0 tid=0x00007f4ee42c1800 nid=0x8b1 waiting on condition [0x00007f4d98336000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000006c5f6a058> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkUntil(LockSupport.java:256)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitUntil(AbstractQueuedSynchronizer.java:2120)
        at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:377)
        at org.apache.http.pool.AbstractConnPool.access$200(AbstractConnPool.java:69)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:245)
        - locked <0x000000076bb64138> (a org.apache.http.pool.AbstractConnPool$2)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:304)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:280)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)
        at com.yt.cmc.common.util.http.HttpUtil.downloadFile(HttpUtil.java:59)
        at com.yt.cmc.common.util.http.HttpUtil.downloadFile(HttpUtil.java:49)
        at com.yt.cmc.biz.util.PictureOperationUtil.downloadPic(PictureOperationUtil.java:26)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl.downloadPictures(BActServiceImpl.java:2068)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl.setShareActImgDTO(BActServiceImpl.java:2195)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl.shareAct(BActServiceImpl.java:1750)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl$$FastClassBySpringCGLIB$$898f72c0.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:649)
        at com.yt.cmc.biz.service.shop.impl.BActServiceImpl$$EnhancerBySpringCGLIB$$7bfd05d0.shareAct(<generated>)
        at com.yt.cmc.biz.ao.u2c.CactAOImpl.cShareAct(CactAOImpl.java:236)
        at com.yt.cmc.biz.ao.u2c.CactAOImpl$$FastClassBySpringCGLIB$$c7b011cf.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)

上面2个进程都在下载一张图片，定位到具体代码发现上面两个一直停留在下载活动的主图过程中，可见cpu升高的原因于此。

2.4 机器负载高的原因

机器负载是根据特定时间段内就绪和正在运行的线程的综合统计情况，由于机器编号001和编号002都是4核的，所以若机器的load average超过4就会说明系统正在超负荷运行，由上面的监控可知，两台机器都在超负荷运行，
编号001机器cpu使用率达91.69%，load_1m达6.8，编号001机器cpu使用率仅46.94%，而load_1m达9.03，在实际运行中机器001在承载的请求量大于002，所以cpu使用率001机器会大于002的。

经上面的分析，cpu偏高的原因在于cShareAct接口下载活动主图比较耗费cpu，在下载过程中会不断地写入磁盘，这样就导致等待磁盘I/O完成的进程过多，而等待执行的进程队列过多，导致机器负载高。

2.5 Java进程为什么会死掉？

java进程为什么会死掉？和横炮同学咨询了一下压测的时候cpu使用率达接近90%负载达到26机器都正常，所以java进程死掉的原因并非cpu使用率和负载过高引起的。后来咨询了一下运维并查看机器运行日志发现两台机器均因内存不足被机器杀死，即触发了机器的OOM-Killer机制。

Linux内核有个机制叫OOM killer（Out-Of-Memory killer），该机制会监控那些占用内存过大，尤其是瞬间很快消耗大量内存的进程，为了防止内存耗尽内核会把该进程杀掉。

上面的监控为什么监测出如002机器内存仅46.94%就死掉了？

阿里云机器监控是15秒之前的，002机器内存一直在增加，未等到当时的内存监控数据就已经死掉了，所以采样结束了。

下面是2台机器的运行日志，从中可以看出，机器001在11:57:17 java进程被杀死，机器002在11:56:25 java进程被杀死。

在这里插入图片描述

2.6 测试环境内存文件分析

同样在测试环境设置50个线程来压测，活动主图仍然是4m，持续3min，测试机器最大堆内存设置为4G

第一步：jmap -heap 13 打印堆内存使用情况，图中显示很快堆内存用光

在这里插入图片描述

第二步：jmap -dump:format=b,file=dumpFile 13 生成堆内存快照

第三步：使用IBM-HeapAnalyzer.jar分析堆内存文件快照，java -jar -Xmx3000m ha456.jar，可以得出确实是图片占了大部分内存空间，如84个PNGImageReader实例占用了堆内存的14.08%，占用内存第1和第2的是在从磁盘读取的图片数据。

在这里插入图片描述

2.7 故障结论

由于活动的主图图片过大，cShareAct接口在下载活动主图时导致cpu飙升，读取该图片和绘制时使该接口RT上涨，用户重复请求过多导致机器负载过高，上面3点原因综合导致jvm堆内存超过设置的堆内存，触发机器的OOM killer机制，最终java进程被杀死，服务消失。

2.8 解决方案

限流

目前已经对cShareAct接口进行了限流，根据历史数据上看该接口最大qps不超过5，平均qps不到1。
图片压缩下载

个人感觉对该接口限流是一个不必要的动作，cShareAct接口的RT主要取决了图片的下载，而图片的大小是决定图片下载时长的关键因素，所以允许用户在创建活动时上传任意大小的图片，而下载时要限制该图片的大小。只要保证该图片的大小便能保证该接口的RT。

如原有的请求url是：https://******/a77bde2f1389bc44db1ce0c.png

可以使用参数对图片进行resize：https://******/a77bde2f1389bc44db1ce0c.png?x-oss-process=image/resize,w_750
超时时间设置

上述请求量过高的一个原因是接口设置了超时时间5s，然后用户重复请求导致，为了增加容错性，对该接口设置了超时时间10s。
缓存设置

对该接口增加缓存
图片绘制

后续优化点，后端绘制图片能力有限，合成图片尽量交付给前端。