jstack排查日记-cpu高耗却不处理业务，搞事情？

1. 问题描述

背景

基本信息

机器资源4c8g
jdk1.7
使用log4j2
业务流程中需要访问一次mysql
业务流程是一系列计算，记了比较详细的日志
业务流程必须在60s内做完，否则超时之后，会重试整套业务流程

现象

应用进程cpu占用200%+，业务无法成功执行完成，并在达到超时时间后不断触发重试，导致堆积大量待处理的消息。

2. 基本分析

虽然每个应用的业务不尽相同，但是排查的套路大体是一致的：

如果日志中有异常，则根据异常信息排查解决即可
如果内存占用很高，可能需要观察gc日志，必要时要dump出内存快照，结合内存诊断工具分析。这里推荐一款比较好的工具，eclipse Memory Analyzer，也就是java程序员熟知的mat，链接在下方。mat可以对内存快照进行分析，同时推断出可能出现内存泄漏的地方，可以很好的辅助诊断
如果cpu占用很高，则需要排查是什么占据了那么高的cpu。java自带的jstack就是比较好的工具。

由于我的应用没有异常日志，比较明显的是cpu占用很高，因此首先利用jstack去排查到底是谁耗用了那么高的cpu。

3. jstack分析

首先，查看当前应用的进程id

ds_dfpas@dev22162:~> jps
6741 supervisor
3070 LogWriter
3086 worker
2787 LogWriter
25301 Kafka
19411 QuorumPeerMain
2155 worker
2139 LogWriter
2804 worker
3562 Jps

假设这里是3086这个进程有问题，接着

 top -Hp 3086

top -Hp可以看到该进程内线程的cpu占用情况，按照从高往低排列。和我们看top -p pid的时候差不多

线程占用cpu

我们可以看到，id为3097的线程占用了22%的cpu，那么它在做什么？是什么线程呢？

这时候，我们需要做的就是将这个进程执行的stack dump出来，然后根据线程id去找这个线程的执行栈。

首先，利用jstack快照线程堆栈，

jstack 3086 > stack.log

接着我们需要将刚才的线程id转换为十六进制数字，因为在stack中是用16进制标识线程id的

ds_dfpas@dev22162:~> printf "%x\n" 30979 
7903

然后，根据这个结果，去刚才的stack.log里找对应的线程，nid=0x7903

"Thread-482" prio=10 tid=0x00000000022b5000 nid=0x7903 runnable [0x00007f27f48c7000]
   java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:345)
        at java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:253)
        at java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:211)
        at java.util.zip.GZIPOutputStream.write(GZIPOutputStream.java:146)
        - locked <0x00000007abd7bab0> (a java.util.zip.GZIPOutputStream)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.write(BufferedOutputStream.java:126)
        - locked <0x00000007abd7bad0> (a java.io.BufferedOutputStream)
        at org.apache.logging.log4j.core.appender.rolling.action.GzCompressAction.execute(GzCompressAction.java:102)
        at org.apache.logging.log4j.core.appender.rolling.action.GzCompressAction.execute(GzCompressAction.java:78)
        at org.apache.logging.log4j.core.appender.rolling.RollingFileManager$AsyncAction.execute(RollingFileManager.java:226)
        at org.apache.logging.log4j.core.appender.rolling.action.AbstractAction.run(AbstractAction.java:65)
        - locked <0x00000007abd65e58> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager$AsyncAction)
        at java.lang.Thread.run(Thread.java:745)

可以看到，nid=0x7903的线程，处于runnable状态，其是log4j的记日志的线程。其实到这里，大致就知道为何该线程占用cpu这么高了，因为日志记录的太平凡。而且这里是在做压缩。联系到实际业务，我的确打了大量的日志，且日志配置了没100M滚动一次，并且执行压缩。

于是，对于刚才看到的这个比较耗cpu的线程，算是找到原因了。那么解决方式也很好办，就是我关闭了所有的日志，然后继续排查。

关闭日志很简单，就是log4j的配置文件调整成为error级别，我没有打印error级别的日志，因此不会再有日志输出。不过我这里使用的是log4j2，可以动态加载配置。

之所以说继续排查，是因为我们只是找到 cpu占用高的一个线程，或者是某一类线程，但是理论上这不会导致业务流程走不下去，顶多是慢，但也应该缓慢执行成功一部分。

紧接着，继续结合top和top -Hp观察进程和线程的cpu占用情况，发现cpu占用问题有效缓解，基本处于正常状态（70%多），top -Hp也未发现比较异常的线程。但是业务还是没有执行成功，仍然在不停的重试。

这时候我怀疑是流程走到某个地方就走不下去了导致的，就没有再去抓个别线程来，而是干脆直接再次dump出执行栈。

其实这个过程需要结合自己的应用分析，比如是不是外部访问太慢导致，是不是自己某个地方没有打印出来异常，是不是某个地方有死循环等等，如果都没有明显的结论，那么至少有两种途径可以继续排查，一个是阅读堆栈信息，一个是查看gc情况，是不是频繁的fullgc倒是stw。其实我是怀疑过fullgc的，也dump出来了内存快照，结合mat分析过。mat给出了一些疑点，但是结合代码和应用排除了，因此我只有选择尝试一下阅读stack

继续

jstack 3086 > stack.log

然后仔细阅读一下stack，于是我发现了一个重要的信息


"Thread-215-AndroidDfpSimilarityBolt-executor[113 113]" prio=10 tid=0x0000000000f3c800 nid=0x2927 waiting for monitor entry [0x00007f38bc03f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
        at com.cup.dcs.storm.persistence.DbDao.queryFromDB5Times(DbDao.java:260)
        at com.cup.dcs.storm.persistence.DbDao.zrangeFixLen(DbDao.java:222)
        at com.cup.dcs.storm.persistence.PersistenceDao.zrange(PersistenceDao.java:145)
        at com.cup.dcs.storm.bolt.dfp.AndroidDfpSimilarityCalBolt.execute(AndroidDfpSimilarityCalBolt.java:117)
        at org.apache.storm.daemon.executor$fn__7953$tuple_action_fn__7955.invoke(executor.clj:728)
        at org.apache.storm.daemon.executor$mk_task_receiver$fn__7874.invoke(executor.clj:461)
        at org.apache.storm.disruptor$clojure_handler$reify__7390.onEvent(disruptor.clj:40)
        at org.apache.storm.utils.DisruptorQueue.consumeBatchToCursor(DisruptorQueue.java:439)
        at org.apache.storm.utils.DisruptorQueue.consumeBatchWhenAvailable(DisruptorQueue.java:418)
        at org.apache.storm.disruptor$consume_batch_when_available.invoke(disruptor.clj:73)
        at org.apache.storm.daemon.executor$fn__7953$fn__7966$fn__8019.invoke(executor.clj:847)
        at org.apache.storm.util$async_loop$fn__625.invoke(util.clj:484)
        at clojure.lang.AFn.run(AFn.java:22)
        at java.lang.Thread.run(Thread.java:745)

这是一个重要的信息，我的应用的某些线程被BLOCKED住了，继续搜索BLOCKED发现，大量的线程被卡在类似的地方（JdbcPool.getConnection），

ds_dfpas@dev22161:~> grep -A2 BLOCKED stack.log.blocked  
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
--
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:69)
        - waiting to lock <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)

大家都在等着锁住0x000000078194d320，去搜索0x000000078194d320，发现罪魁祸首：

"Thread-185-AndroidDfpSimilarityBolt-executor[83 83]" prio=10 tid=0x00000000017fa800 nid=0x2909 runnable [0x00007f38bde5b000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:152)
        at java.net.SocketInputStream.read(SocketInputStream.java:122)
        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:112)
        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:159)
        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:187)
        - locked <0x00000007e25e67b8> (a com.mysql.jdbc.util.ReadAheadInputStream)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3158)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3615)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3604)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4149)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2615)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2776)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2834)
        - locked <0x00000007fda34988> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2783)
        at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1569)
        - locked <0x00000007fda34988> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.ConnectionImpl.loadServerVariables(ConnectionImpl.java:4219)
        at com.mysql.jdbc.ConnectionImpl.initializePropsFromServer(ConnectionImpl.java:3614)
        at com.mysql.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:2370)
        at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2328)
        - locked <0x00000007fda34988> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:832)
        at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:46)
        at sun.reflect.GeneratedConstructorAccessor36.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:408)
        at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:417)
        at com.mysql.jdbc.LoadBalancingConnectionProxy.createConnectionForHost(LoadBalancingConnectionProxy.java:382)
        - locked <0x0000000781ef6618> (a com.mysql.jdbc.LoadBalancingConnectionProxy)
        at com.mysql.jdbc.RandomBalanceStrategy.pickConnection(RandomBalanceStrategy.java:75)
        at com.mysql.jdbc.LoadBalancingConnectionProxy.pickNewConnection(LoadBalancingConnectionProxy.java:693)
        - locked <0x0000000781ef6618> (a com.mysql.jdbc.LoadBalancingConnectionProxy)
        at com.mysql.jdbc.LoadBalancingConnectionProxy.<init>(LoadBalancingConnectionProxy.java:335)
        at com.mysql.jdbc.NonRegisteringDriver.connectLoadBalanced(NonRegisteringDriver.java:393)
        at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:326)
        at java.sql.DriverManager.getConnection(DriverManager.java:571)
        at java.sql.DriverManager.getConnection(DriverManager.java:215)
        at com.cup.dcs.storm.persistence.JdbcPool.getNewConnection(JdbcPool.java:116)
        at com.cup.dcs.storm.persistence.JdbcPool.getConnection(JdbcPool.java:95)
        - locked <0x000000078194d320> (a com.cup.dcs.storm.persistence.JdbcPool)
        at com.cup.dcs.storm.persistence.DbDao.queryFromDB5Times(DbDao.java:260)
        at com.cup.dcs.storm.persistence.DbDao.zrangeFixLen(DbDao.java:222)
        at com.cup.dcs.storm.persistence.PersistenceDao.zrange(PersistenceDao.java:145)
        at com.cup.dcs.storm.bolt.dfp.AndroidDfpSimilarityCalBolt.execute(AndroidDfpSimilarityCalBolt.java:117)
        at org.apache.storm.daemon.executor$fn__7953$tuple_action_fn__7955.invoke(executor.clj:728)
        at org.apache.storm.daemon.executor$mk_task_receiver$fn__7874.invoke(executor.clj:461)
        at org.apache.storm.disruptor$clojure_handler$reify__7390.onEvent(disruptor.clj:40)
        at org.apache.storm.utils.DisruptorQueue.consumeBatchToCursor(DisruptorQueue.java:439)
        at org.apache.storm.utils.DisruptorQueue.consumeBatchWhenAvailable(DisruptorQueue.java:418)
        at org.apache.storm.disruptor$consume_batch_when_available.invoke(disruptor.clj:73)
        at org.apache.storm.daemon.executor$fn__7953$fn__7966$fn__8019.invoke(executor.clj:847)
        at org.apache.storm.util$async_loop$fn__625.invoke(util.clj:484)
        at clojure.lang.AFn.run(AFn.java:22)
        at java.lang.Thread.run(Thread.java:745)

该线程持有着0x000000078194d320的锁～根据堆栈信息和代码，可以知道这里实在获取新的数据库连接。那么问题就比较清楚了，获取连接的时候除了问题，导致锁被独占，其他的线程都在等着。而该线程一直获取不到连接，因此整个应用都被卡住了。

为了验证这个连接的问题，用mysql客户端手动连接了一下数据库，果然有问题，执行连接命令之后，既不成功，也不返回refused等信息，而是一直hang在那里～这可能和我们使用了某个不成熟的代理有关，咨询了相关同事后，重启了代理，连接可以正常拿到，业务恢复正常，问题解决！！！

问题找到之后发现其实问题很简单，就是mysql的代理出问题了，但是坑的是，这个代理并没有立刻拒绝或者超时返回，也没有抛出异常，而笔者又没有立刻怀疑到mysql的问题，因此有了前面一堆的猜想和验证。不过虽然饶了些路，但是排查的过程还是有意义的，毕竟真理虽然至简，但是发现真理的道路确实复杂、困难的。

4. 小结

在前面也说过，一般出了问题，可以先结合日志分析，如果日志没有信息，则可以怀疑一下关键路径，比如外部服务、数据库、缓存等，如果这些都无法得出重要信息，那就祭出最直接的工具吧，要么jstack分析栈执行情况，要么结合gc和jmap来分析内存使用情况。

另外，在使用jstack结合top -Hp的时候，需要注意的是，动作要快！因为不同时期，stack快照出的线程堆栈信息是不完全相同的，如果方法执行完了，那么方法栈就会结束。因此一般建议的方式是

首先

top -Hp pid

观察线程执行和cpu占用情况，发现需要跟踪的线程时，立刻摁q退出观察，然后迅速执行

jstack pid > stack.log

导出之后再去进行线程id的十六进制转换和grep，比较容易成功抓到。

另如果是64位机器，可能需要在jstack的时候添加-J-d64

最后编辑于：2018.10.25 22:20:38

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 196,165评论 5赞 462
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 82,503评论 2赞 373
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 143,295评论 0赞 325
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 52,589评论 1赞 267
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 61,439评论 5赞 358
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 46,342评论 1赞 273
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 36,749评论 3赞 387
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 35,397评论 0赞 255
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 39,700评论 1赞 295
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 34,740评论 2赞 313
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 36,523评论 1赞 326
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 32,364评论 3赞 314
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 37,755评论 3赞 300
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 29,024评论 0赞 19
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 30,297评论 1赞 251
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 41,721评论 2赞 342
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 40,918评论 2赞 336

jstack排查日记-cpu高耗却不处理业务，搞事情？

1. 问题描述

2. 基本分析

3. jstack分析

4. 小结

推荐阅读更多精彩内容