一次线上服务占用CPU过高的在线排查过程

故障藐视

接到通知说线上图表的导出功能异常,导出功能是做成服务单独运行的,上面还有定时人任务在跑,上服务器看了下运行日志,日志内功还在更新定时任务的运行日志,只是更新的特别慢,这并不是第一次出现这种情况,重启服务可以解决,但是同样的问题不定时的又会重新出现,这可忍不了。使用top命令查看服务器情况,这个服务所属的进程占用cpu达到了400%多!

通过PID号找到对应的进程名及所在目录,看看出问题的是哪个服务进程
最简单的方法是直接进入pid目录查看,输入命令cd /proc/30219,可以很直观的看到服务启动目录,如下图

初步结果判定

上图可以看到PID为30279的进程占用CPU非常高,这时候我首先就要看看这个进程JVM的gc情况

jstat -gc 30279 5000


下面是对上图中各列的解释

S0C:年轻代中第一个survivor(幸存区)的容量 (字节)
S1C:年轻代中第二个survivor(幸存区)的容量 (字节)
S0U:年轻代中第一个survivor(幸存区)目前已使用空间 (字节)
S1U:年轻代中第二个survivor(幸存区)目前已使用空间 (字节)
EC:年轻代中Eden(伊甸园)的容量 (字节)
EU:年轻代中Eden(伊甸园)目前已使用空间 (字节)
OC:Old代的容量 (字节)
OU:Old代目前已使用空间 (字节)
PC:Perm(持久代)的容量 (字节)
PU:Perm(持久代)目前已使用空间 (字节)
YGC:从应用程序启动到采样时年轻代中gc次数
YGCT:从应用程序启动到采样时年轻代中gc所用时间(s)
FGC:从应用程序启动到采样时old代(full gc)gc次数
FGCT:从应用程序启动到采样时old代(full gc)gc所用时间(s)
GCT:从应用程序启动到采样时gc用的总时间(s)

可以看到老年代的空间十分正常,可是持久代(红框1)的容量已经沾满了,并且不再扩容,想必是已经达到了最大容量,红框2处显示Full GC的次数已经达到了两万多次,并且还在不断增长,但是并没有起到什么作用。
到这里问题就确定了,导致这次服务卡慢的原因是持久代(Perm)溢出导致gc持续运行,持久代的最大空间83968k换算下来也只有82m,解决办法是在启动服务时增大持久代的空间

-XX:PermSize=250m -XX:MaxPermSize=512m

进一步原因探究

上面已经确定了是永久代溢出导致的问题,但是这只是结果,到现在还不知道造成永久代内存溢出的具体原因,如果完全是因为永久代设置过小,承受不了程序日常运行所需开销,那增大永久代空间就可以解决问题,可如果是程序代码本身存在漏洞,那光加大内存也是治标不治本。

根据问题进程id定位问题线程

命令:top -Hp 30279


红框部分的线程全是问题线程,先记录下这些线程的PID,挨个将其转换为16进制

命令:printf "%x\n" 30290 30282 30283 30284 30285 30286 30287 30288 30289

打印问题进程堆栈信息

为方便查看,将堆栈信息答应到文件,每隔5秒打印一份

命令:jstack 30279 > jstack.dump

分析堆栈信息

随便打开一个一个jstack.dump文件,在其中查找刚才转化的十六进制线程id,查找内容如下



印证了开始的判断,全是GC线程。

然后向上翻找,查找与项目有关的代码,分析五个堆栈文件,找到如下堆栈信息



这段代码是系统系统的一个报表导出功能,业务十分复杂,关联资源很多,于是到这里判断是这个导出所需内存资源过大,同时系统永久代内存又过小,多用户同时导出报表就可能撑爆持久代。

到这里,本次线上问题排查就算结束了,并不是程序代码的问题,是项目永久代空间设置过小,不能满足项目所有功能的长时间运行。

额外分享

这里也再记录一次早前项目卡死问题的堆栈问题信息记录,如下


定位到的项目代码如下:

没看错,就是代码在try catch 捕获异常输出的时候采用了e.printStackTrance()进行输出,e.printStackTrance()会将异常堆栈信息存到字符串内存空间中,堆栈信息一旦过长,就很可能导致内存溢出。一般只在测试阶段才使用该方法打印到控制台,上线后就应该使用log对象将错误信息输出到日志文件里去。
在这里分享一篇文章,解释为什么e.printStackTrance()会导致程序锁死:https://blog.csdn.net/hy_coming/article/details/88523988

总结

关注系统运行时的资源需求,分配合适的资源。
避免在上线的项目中出现e.printStackTrance()这样的代码,这可能是刚入门学习时养成的习惯,但是不好的习惯得改!同时在使用其他可能会产生大量字符串的方法时,都得特别注意。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,772评论 6 477
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,458评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,610评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,640评论 1 276
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,657评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,590评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,962评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,631评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,870评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,611评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,704评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,386评论 4 319
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,969评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,944评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,179评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 44,742评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,440评论 2 342

推荐阅读更多精彩内容