写点什么

CPU突然飙升到300%,Dubbo活动线程数直接飙到1000

2020 年 5 月 07 日

CPU突然飙升到300%,Dubbo活动线程数直接飙到1000

新功能开发测试完成后,准备发布上线,当发布完第三台机器时,监控显示其中一台机器CPU突然飙升到300%,Dubbo活动线程数直接飙到1000+,不得不停止发布,立马回滚出问题的机器,回滚之后恢复正常;继续观察另外两台已经发布的机器,最终,无一幸免,只能全部回滚了。


下面是我的故障排查过程:


监控日志分析


首先查看故障时间点的应用日志,发现大量方法耗时较久,其中 filterMission 方法尤为显著,耗时长达 30S+。说明下,filterMission 是当前服务中 QPS 较高的接口(日均调用量 2 个亿),所以导致故障的可能性也较高。于是重新 review 了一遍 filterMission 的实现,其中并无复杂的计算逻辑,没有大量数据的处理逻辑,也不存在锁的争用,本次需求更是不涉及 filterMission 的改造,排除 filterMission 导致故障发生。


从日志中也可以发现,大量请求发生超时,这些都只能说明系统负载过重,并不能定位问题的症结所在。


Code Review


从应用日志找不到原因所在,只能再做一次 code review 了。首先检查系统中是否存在同步代码逻辑的使用,主要是为了排除发生死锁的可能;检查具有复杂运算逻辑的代码;同时,将本次修改的代码和上一版本进行比对,也没找出什么问题。(事实证明,Review 不够仔细)


线程 Dump 分析


到此,从日志中暂时也分析不出问题,盲目看代码也无法具体定位问题了,现在只能重新发布一台机器,出现问题时让运维将应用程序的线程堆栈 dump 出来,分析 jstack 文件。开始分析 dump 文件前,先巩固下基础吧。


线程状态



图中各状态说明:


New: 新建状态,当线程对象创建时存在的状态;


Runnable:ready-to-run,可运行状态,调用 thread.start()后,线程变成为 Runnable 状态,还需要获得 CPU 才能运行;


Running:正在运行,当调用 Thread.yield()或执行完时间片,CPU 会重新调度;注意:Thread.yield()调用之后,线程会释放 CPU,但是 CPU 重新调度可能让线程重新获得时间片。


Waiting:调用 thread.join()、object.wait()和 LockSupport.park()线程都会进入该状态,表明线程正处于等待某个资源或条件发生来唤醒自己;thread.join()、object.wait()需要 Object 的 notify()/notifyAll()或发生中断来唤醒,LockSupport.park()需要 LockSupport.unpark()来唤醒,这些方法使线程进入 Runnable 状态,参与 CPU 调度。


thread.join():作用是等待线程 thread 终止,只有等 thread 执行完成后,主线程才会继续向下执行;从 join()实现可知,主线程调用 thread.join()之后,只有 thread.isAlive()返回 true,才会调用 object.wait()使主线程进入等待状态,也就是说,thread.start()未被调用,或 thread 已经结束,object.wait()都不会被调用。也就是说,必须先启动线程 thread,调用 thread.join()才会生效;若主线程在 waiting 状态被唤醒,会再次判断 thread.isAlive(),若为 true,继续调用 object.wait()使进入 waiting 状态,直到 thread 终止,thread.isAlive()返回 false。


object.wait():作用是使线程进入等待状态,只有线程持有对象上的锁,才能调用该对象的 wait(),线程进入等待状态后会释放其持有的该对象上的锁,但会仍然持有其它对象的锁。若其他线程想要调用 notify()、notifyAll()唤醒该线程,也需要持有该对象的锁。


LockSupport.park():挂起当前线程,不参与线程调度,除非调用 LockSupport.unpark()重新参与调度。


Timed_Waiting:调用 Thread.sleep(long)、LockSupport.parkNanos(long)、thread.join(long)或 obj.wait(long)等都会使线程进入该状态,与 Waiting 的区别在于 Timed_Waiting 的等待有时间限制;


Thread.sleep():让当前线程停止运行指定的毫秒数,该线程不会释放其持有的锁等资源。


Blocked:指线程正在等待获取锁,当线程进入 synchronized 保护的代码块或方法时,没有获取到锁,则会进入该状态;或者线程正在等待 I/O,也会进入该状态。注意,java 中 Lock 对象不会使线程进入该状态。


Dead:线程执行完毕,或者抛出了未捕获的异常之后,会进入 dead 状态,表示该线程结束。


上图中某些状态只是为了方便说明,实际并不存在,如 running/sleeping,java 中明确定义的线程状态值有如下几个:


NEW、RUNNABLE、BLOCKED、WAITING、TIMED_WAITING、TERMINATED


分析 jstack 日志


  • 大量dubbo线程处于WAITING状态,看日志:


"DubboServerHandler-172.24.16.78:33180-thread-1220" #1700 daemon prio=5 os_prio=0 tid=0x00007f3394988800 nid=0x4aae waiting on condition [0x00007f32d75c0000]   java.lang.Thread.State: WAITING (parking)  at sun.misc.Unsafe.park(Native Method)  - parking to wait for  <0x00000000866090c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  at java.lang.Thread.run(Thread.java:745)
复制代码


由日志可知道,线程“DubboServerHandler-172.24.16.78:33180-thread-1220”处于 WAITING 状态,主要原因是线程从线程池队列中取任务来执行,但线程池为空,最终调用了 LockSupport.park 使线程进入等待状态,需要等待队列非空的通知。


设想一下,什么时候会新创建新线程来处理请求?结合 jdk 线程池实现可知,当新请求到来时,若池中线程数量未达到 corePoolSize,线程池就会直接新建线程来处理请求。


根据 jstack 日志,有 195 个 dubbo 线程从 ScheduledThreadPoolExecutor 中取任务导致处于 WAITING 状态,按理这些 dubbo 线程只负责处理客户端请求,不会处理调度任务,为什么会去调度任务线程中取任务呢?这里暂时抛出这个问题吧,我也不知道答案,希望有大神帮忙解答。


  • 还有另外一部分WAITING状态的线程,看日志:


"DubboServerHandler-172.24.16.78:33180-thread-1489" #1636 daemon prio=5 os_prio=0 tid=0x00007f33b0122800 nid=0x48ec waiting on condition [0x00007f32db600000]   java.lang.Thread.State: WAITING (parking)  at sun.misc.Unsafe.park(Native Method)  - parking to wait for  <0x0000000089d717a8> (a java.util.concurrent.SynchronousQueue$TransferStack)  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)  at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)  at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)  at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:924)  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  at java.lang.Thread.run(Thread.java:745)
复制代码


这部分 dubbo 线程主要是因为从 ThreadPoolExecutor 取任务来执行时被挂起(309 个线程),这些线程正常处理完第一个请求后,就会回到线程池等待新的请求。由于这里使用 newFixedThreadPool 作为 dubbo 请求处理池,因此每个新请求默认都会创建新线程来处理,除非达到池的限定值。只有达到线程池最大线程数量,新的请求来临才会被加入任务队列,哪些阻塞在 getTask()的线程才会得到复用。


  • 此外,还有大量dubbo线程处于BLOCKED状态,看日志:


"DubboServerHandler-172.24.16.78:33180-thread-236" #1727 daemon prio=5 os_prio=0 tid=0x00007f336403b000 nid=0x4b8b waiting for monitor entry [0x00007f32d58a4000]   java.lang.Thread.State: BLOCKED (on object monitor)  at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:149)  - waiting to lock <0x0000000085057998> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager)  at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:88)  at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)  at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)  at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)  at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)  at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:349)  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)  at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)  at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1993)  at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1852)  at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:179)  at com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger.info(Slf4jLogger.java:42)  at com.alibaba.dubbo.common.logger.support.FailsafeLogger.info(FailsafeLogger.java:93)  at com.dianwoba.universe.dubbo.filter.ResponseFilter$1.run(ResponseFilter.java:116)  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)  at java.util.concurrent.FutureTask.run(FutureTask.java:266)  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  at java.lang.Thread.run(Thread.java:745)
复制代码


waiting for monitor entry :说明当前线程正处于 EntryList 队列中,等待获取监视器锁。


说明:Java 中 synchronized 的同步语义主要基于 Java 对象头和 monitor 实现,每个 monitor 同一时间只能由一个线程拥有,其他想要获取该 monitor 只能等待,其中 monitor 具有两个队列:WaitSet 和 EntryList。当某个线程在拥有 monitor 时,调用了 Object.wait(),则会释放 monitor,进入 WaitSet 队列等待,此时线程状态为 WAITING,WaitSet 中的等待的状态是 “in Object.wait()”。当其他线程调用 Object 的 notify()/notifyAll()唤醒该线程后,将会重新竞争 monitor;当某个线程尝试进入 synchronized 代码块或方法时,获取 monitor 失败则会进入 EntryList 队列,此时线程状态为 BLOCKED,EntryList 中等待的状态为“waiting for monitor entry”。


根据 jstack 日志,有 377 个 dubbo 线程在等待锁定资源“0x0000000085057998”,从堆栈可知,这些线程都在竞争 RollingRandomAccessFileManager 的 monitor,让我们看看那个线程拥有了该监视器,看日志:


"DubboServerHandler-172.24.16.78:33180-thread-429" #553 daemon prio=5 os_prio=0 tid=0x00007f339c09f800 nid=0x4467 waiting for monitor entry [0x00007f331f53a000]   java.lang.Thread.State: BLOCKED (on object monitor)  at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:149)  - locked <0x0000000085057998> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager)  at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:88)  at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)  at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)  at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)  at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)  at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)  at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:349)  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)  at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)  at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1993)  at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1852)  at org.apache.logging.slf4j.Log4jLogger.warn(Log4jLogger.java:239)  at com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger.warn(Slf4jLogger.java:54)  at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:107)  at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:48)  at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)  at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)  at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)  at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:60)  at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)  at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:112)  at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)  at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)  at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)  at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)  at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)  at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:108)  at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)  at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)  at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)  at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  at java.lang.Thread.run(Thread.java:745)
复制代码


看到该线程的堆栈就一脸懵 b 了,它已经锁定了资源“0x0000000085057998”,但仍然处于 BLOCKED 状态,是不是有死锁的味道?但是这里不是死锁,最可能的原因是:


  • 线程没有获得运行所需的资源;

  • JVM正在进行fullGC

  • 从这部分日志可知,大部分线程阻塞在打印监控日志的过程中,所以很多请求出现超时。主要原因可能是CPU占用率高,持有锁的线程处理过程非常慢,导致越来越多的线程在锁竞争中被阻塞,整体性能下降。


到此,仍然没有找到问题的原因,再一次观察资源占用情况,发现当出现问题时,内存占用持续增长,且无下降痕迹,然后找运维 dump 了一份 GC 日志,发现 JVM 一直在做 fullGC,而每次 GC 之后内存基本没变化,说明程序中发生了内存泄漏。最后定位到发生内存泄漏的地方是一个分页查询接口,SQL 语句中漏掉了 limit,offset,够初心大意了。


这尼玛一次性将整张表的数据查出来(300 万),还要对 300 万记录循环处理一遍,这内存不爆掉就怪了。正是因为该原因,导致内存长时间没有释放,JVM 执行 fullGC 无法回收内存,导致持续做 fullGC,CPU 被耗尽,无法处理应用请求。


综上,罪魁祸首是发生了内存泄漏,JVM 一直做 fullGC,导致 CPU 突然飙升,Dubbo 活动线程数增大,锁竞争严重,请求处理超时。根据以上分析,同时也暴露了另外一个不合理的问题:dubbo 线程池数量配置过大,最大值为 1500,也就是说最终线程池中会有 1500 个线程来处理用户请求,当并发量高时,活动线程数增加,CPU 频繁进行上下文切换,系统的吞吐率并不会太高。这是一个优化点。


本文记录该过程,一方面是为了记录曾经踩过的坑,同时提高自己的故障分析和处理能力。当需要问题时,一定不要着急,学会分析问题,一步步找到问题所在。尤其是遇到线上问题时,由于无法调试,一定要在应用中做监控,当出现问题时,一定要结合日志来分析,业务中的问题结合业务日志,性能问题结合内存 dump 日志和线程 dump 日志等等。


本文转载自技术锁话公众号。


原文链接:https://mp.weixin.qq.com/s/-lSiVDfqYrKk_w-xitYBhA


2020 年 5 月 07 日 17:36209

评论

发布
暂无评论
发现更多内容

面试大厂的尖兵利器!超全算法笔试模拟题精解合集,这份《程序员面试宝典》简直太牛了

Java成神之路

Java 程序员 架构 面试 编程语言

GaussDB(DWS)应用实践丨负载管理与作业排队处理方法

华为云开发者社区

数据 负载 GaussDB

有道逻辑英语-时态新发现笔记

Leo

学习 前端进阶训练营 笔记 时态

深入浅出理解视频编解码技术

拍乐云Pano

音视频 RTC 拍乐云 视频编解码 视频算法

看到Mybatis源码就感到烦躁,怎么办?

田维常

mybatis

云小课 | 需求任务还未分解,该咋整!项目管理Scrum项目工作分解的心酸谁能知?

华为云开发者社区

项目管理 敏捷 devcloud

ICT芯矿链挖矿矿机系统开发平台丨ICT芯矿链源码案例

系统开发咨询1357O98O718

ICT芯矿链矿机系统开发

投行工作的本质 | 读《投行职业进阶指南:从新手到合伙人》

邓瑞恒Ryan

读书笔记 投资 金融 投行 职业第二曲线

快来!开源一份阿里微服务指导手册:SpringBoot+SpringCloud+消息中间件

Java架构追梦

Java 架构 面试 微服务

Norvarm波场链系统开发方案丨Norvarm波场源码功能

系统开发咨询1357O98O718

Norvarm波场链系统开发

云原生体系下的技海浮沉与理论探索

阿里巴巴云原生

Serverless 容器 微服务 云原生 k8s

【涂鸦物联网足迹】物联网常见通信协议

IoT云工坊

物联网 HTTP 通信协议 mqtt coap

第八周大作业

小兵

忒棒了!阿里P8大牛用这份技术点直接带你玩转高可用服务架构

比伯

Java 编程 架构 互联网 程序人生

产品推荐 | 还在自研?快来解锁拍乐云互动白板

拍乐云Pano

音视频 在线教育 RTC 互动白板

《微信小程序开发入门与实践》.pdf

田维常

公安大数据分析系统开发,情报研判系统搭建

t13823115967

智慧公安

熬夜整理10 万字节详细面试笔记(带完整目录) 良心分享

Crud的程序员

Java 编程 程序员 架构 java面试

Gemini双子新约交易所系统软件APP开发

开發I852946OIIO

系统开发

探究神秘的SpringMVC,寻找遗失的web.xml踪迹

996小迁

Java 编程 程序员 架构 面试

H3C核心交换机故障处理通用流程

网络技术平台

我看技术人的成长路径

阿里巴巴云原生

开发者 云原生 技术人 自我思考 职场成长

太牛皮了!这份神仙级面试笔记把所有Java知识面试题都详解出来了。免费分享PDF文档,先到先得。

Java成神之路

Java 程序员 架构 面试 编程语言

构建一张音视频全球大网究竟需要多少个节点?Pano Backbone技术探秘

拍乐云Pano

音视频 RTC 实时音视频 音视频算法 拍乐云

区块链应用落地,物流供应链平台搭建

t13823115967

区块链应用

北京天源迪科与重庆邮电大学移通学院成功签约

DT极客

五年Java开发经验,从传统企业月薪20k到互联网大厂月薪50k,我只做了这一件事!

Java成神之路

Java 程序员 架构 面试 编程语言

BMEX交易所系统软件开发|BMEX交易所APP开发

开發I852946OIIO

系统开发

喜讯 | 拍乐云荣登2020「年度最具投资价值创新企业TOP20」榜单

拍乐云Pano

音视频 实时音视频 音视频算法 拍乐云

连续肝了好几个晚上,终于把网络相关知识和计算机底层操作系统知识总结整理出来了,两份文档资料分享给你!

Java成神之路

Java 程序员 架构 面试 编程语言

巨头们为什么要开源自己的技术?解析科技企业对软件开源的态度

Marilyn

开源 敏捷开发

CPU突然飙升到300%,Dubbo活动线程数直接飙到1000-InfoQ