写点什么

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

  • 2020-05-07
  • 本文字数:7858 字

    阅读完需:约 26 分钟

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-05-07 17:361446

评论

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

MatrixOne内核1.0.0-RC1版本正式发布啦!

MatrixOrigin

数据库 云原生 MatrixOrigin MatrixOne 矩阵起源

Alfred 5 for Mac(Mac应用快速启动器) v5.1.2(2145)中文激活版

mac

Alfred 苹果mac Windows软件 快速启动工具

Node与Express后端架构:高性能的Web应用服务

互联网工科生

Web Node Express

买堡垒机成本有哪些?可以产生哪些收益?

行云管家

网络安全 信息安全 堡垒机 堡垒

大数据平台和数据中台的定义、区别以及联系

行云管家

大数据 数据中台 数据仓库 大数据平台

泰山众筹拼团互助模式系统DAPP定制开发

V\TG【ch3nguang】

众筹 拼团

IPQ6010 with QCN9074 Solution|5G and Wi-Fi 6: A Dynamic Duo for the Connected Future

wallyslilly

IPQ6010 QCN9074

链游开发成本是多少

西安链酷科技

区块链游戏 链游 NFT链游

HarmonyOS Codelab 优秀样例——购物应用,体验一次开发多端部署魅力

HarmonyOS开发者

HarmonyOS

共创共赢,天翼云携手用友打造商业创新一体化解决方案!

天翼云开发者社区

云计算 AI 数据治理

鹏云块存储在多副本情况下,如何兼顾数据一致性和效率?

鹏云网络

分布式系统 数据强一致性 副本一致性 分布式存储,

数据科学教学必看!如何最大化利用和鲸的资源与平台赋能教学工作

ModelWhale

人工智能 大数据 数据科学 高等教育 数据资源

怎样快速选择正确的可视化图表?

树上有只程序猿

数据可视化

软件测试/测试开发丨Selenium Web自动化测试基本操作

测试人

Python 软件测试 自动化测试 测试开发 selenium

斩获“年度突破成果”奖!天翼云构建强大AI算力基础,制胜人工智能新时代

天翼云开发者社区

云计算 云服务 云平台

突破连接壁垒,火山引擎边缘云网络的先行之路

火山引擎边缘云

云服务边缘架构 边缘云 边缘云原生

NFTScan 正式上线 Base NFTScan 浏览器和 NFT API 数据服务

NFT Research

NFT\

iOS IPA包的制作和上传步骤详解​

雪奈椰子

ios打包 上架 Windows ios

AI量化交易机器人系统搭建,搬砖套利软件程序开发设计

V\TG【ch3nguang】

量化交易机器人开发 套利

小灯塔系列-中小企业数字化转型系列研究——企业邮箱测评报告

向量智库

阿里云 MSE 助力开迈斯实现业务高增长背后带来的服务挑战

阿里巴巴云原生

阿里云 微服务 云原生

互助系统源码|USDT众筹理财系统模型搭建开发

V\TG【ch3nguang】

USDT承兑支付系统开发 理财系统

英特尔和新思科技深化合作,提供基于英特尔先进制程节点的领先IP

E科讯

iOS IPA包的制作和上传步骤详解​

证书 开发 上架 Windows ios

Docker容器中的Postgresql备份脚本异常解决办法

这我可不懂

Docker k8s postgres

生产制造关键业务模型拆解与平台化演进

华为云开发者联盟

后端 物联网 华为云 华为云开发者联盟 企业号 8 月 PK 榜

CPU突然飙升到300%,Dubbo活动线程数直接飙到1000_语言 & 开发_技术琐话_InfoQ精选文章