一次crash的追踪
前不久上线了一个活动,不久之后,访问就报502.登陆docker查看,进程已经停掉了.又去查看docker后台,程序于22:40点被停掉,但是在日志中该点附近并无相关的错误日志.
程序走势图
从内存走势图看来,程序的内存是一直呈上升趋势的,并在晚间活动高峰期上升明显,当达到接近20%的时候程序就突然崩掉,直觉告诉我,可能是内存泄漏了,于是我检查了一遍代码,把可能造成内存泄漏的地方都改掉了,尽量减少了多余对象的产生(虽然感觉很多地方都没有必要改),我相信强大的GC会给我一个简洁的内存环境.改好代码,又加上的听云的监控后(可恶的听云,居然用不了),重新上线,但是不到一天就又挂了(幸好有两台机器,并未对用户造成影响).于是我查了一下gc日志,日志也并无异常.
不是事发当时的GC日志,此文很多图片并不是事发当时的现场照片,但是保证尽量接近事发当时情况
在gc日志中,只能看到新生代和总内存的变化,并不能看到老年代和永久代的变化,于是我怀疑可能是老年代或者永久代设置过少导致的问题,于是查看了jetty.sh上的jvm参数配置:
JAVA_OPTIONS+=(
"-Djetty.home=$JETTY_HOME"
"-Djetty.base=$JETTY_BASE"
"-Dsun.rmi.transport.tcp.responseTimeout=1000"
"-Djava.io.tmpdir=$TMPDIR"
"-Xloggc:$JETTY_LOGS/gc.log"
"-Dfile.encoding=UTF-8"
"-Xms2560m"
"-Xmx2560m"
"-Xmn768m"
"-XX:PermSize=256m"
"-XX:MaxPermSize=256m"
"-XX:SurvivorRatio=4"
"-Xss256k"
"-Djava.net.preferIPv4Stack=true"
"-XX:+UseParNewGC"
"-XX:+UseAdaptiveSizePolicy"
"-XX:+UseConcMarkSweepGC"
"-XX:CMSInitiatingOccupancyFraction=80"
"-XX:+CMSParallelRemarkEnabled"
"-Djava.awt.headless=true"
"-XX:+PrintGCDateStamps"
"-XX:+PrintGCDetails"
"-XX:ParallelGCThreads=6"
"-XX:+DisableExplicitGC"
"-server")
堆内存初始化2560M!最大堆内存也为2560M!年轻代768M!永久代初始化256M!永久代最大值也为256M!"-XX:SurvivorRatio=4" ,即Eden = 4survivor = 4/6新生代= 512M!栈帧为256K!如此算来老年代应该差不多是1500多M左右! 机器是20多G的内存. 堆初始化和最大堆内存设为相同,可以避免堆内存扩张的时候对性能造成的影响.这个配置可能和博文推荐的配置堆内存为系统内存的1/4与永久代为1/64有些出入,但是应该不至于不够用呀.不管了,既然可能是内存的原因,那就把内存加大试试!于是我就把堆内存改为5120,年轻代改为1024,永久代改为1024.改好以后,又让程序跑起来.
重新上线以后,每隔一段时间我便会登陆docker jstat -gcutil 一下程序,不管docker后台的内存百分比如何,jvm的老年代和永久代都能稳定在30%以下,没毛病呀..但是不幸的是在这种情况下,程序还是又很不小心的挂了.
内存一直比较稳定
这就奇怪了,难道不是内存的原因?我还是不相信不是内存的原因,还是不相信不是内存泄漏,在第三次重启了项目以后,在观察了docker后台内存上升到差不多17%的时候(前两次差不多这个时候挂的),我用jmap -histo 41, 查看了当时的内存对象情况,排名前三甲的还是 byte , char int , 排名前10的都是一些看起来陌生但又熟悉的对象,并没有自己创建类对象的踪影.这让我放弃了内存泄漏的可能性.接着还是挂了.
对象的情况
如果不是内存的原因,那可能是CPU的原因?在经同事提醒以后,我又去后台看了机器的CPU情况,真的有点异常
CPU情况
又一次上线了,我一直开着top,时刻关注着机器CPU的变化,但是早晨没什么用户在,于是我开了一个测试号,模拟器用户操作起来,果然真的,当我操作快了以后,CPU就会飙升到100%以上,难道是某个线程吃掉大部分cpu,当并发实在实在太高的时候,机器就挂了?这种分析很有可能.我又开启了top -Hp 41,观察是哪个线程吃掉的CPU.
果然经过观察,一个86号的线程占用的CPU情况很严重.
事发当时是87号线程的CPU占用率一直在100左右
很有意思,通过 jstack -l 41 | grep "nid=0x56(86的十六进制)",查出是一个TingyunService的线程在作怪,怎么这么熟悉呢?这不是我之前添加的听云监控吗?但是听云是出事以后才添加的,那添加之前是什么情况呀?显然听云不是罪魁祸首.可恶的听云,不仅上传不了数据,还占用CPU.听云一生黑(不知道是不是我配置听云的时候出错了).
在又一次挂掉以后,我陷入了深思,既然不是内存的问题也不是CPU的问题,那会是什么原因呢?我搜了一下"jvm无缘无故挂了",结果搜到有些文章推荐我去看hs_err_pidXXXX.log的日志,这个日志一般在程序的主目录下,如果想修改路径,要到jvm参数配置里面修改.这个日志详细记载了程序crash的那一时刻,jvm的线程,内存,gc的具体内容.我试着到/opt/jetty/jetty/目录下一看,果然是有这么一个日志,打开一看,密密麻麻的不知道写了些什么!!!
日志内容
敏感的同事又翻了几页,然后对我说,你看这里面的线程都被锁住(blocked)了.是不是你的synchronized用的有问题呀?啊!果然翻了几页都是_thread_blocked的thread.难道这就是原因?我们一起review了代码,一般情况下,当高并发的时候,在做一些读写操作的时候,我们都喜欢用synchronize,而且锁的是this,即整个类对象,这就导致明明A用户做的操作,为什么B操作也受到影响了呢?后来我感觉这样子太不合理了,经过试验发现锁用户uid的intern对象也能达到同样的效果,所以后来我一直锁的是用户uid intern后的字符串.同事跟我说不然锁 this试试,虽然我感觉这样子并不能解决问题,但是我还是试了.果然程序还是挂了.
String uid = user.getUid().intern();
synchorized(uid){
dosomething();
}
这一刻,我真的绝望了.但是革命尚未成功,同志仍需努力呀.所以我还是不时会看看日志内容,冥冥之中,我一直感觉应该是线程的问题,一次我突发奇想,想看看这个程序到底有多少被锁的线程,于是
查看被锁线程数量
咦! 相信程序员对于这个数字还是有点感觉的.65536是程序员经常听到的一个数字,而32396刚好接近65535的一半,卧槽, 难道是jvm或者docker或者Linux限制了程序的最大线程数,当程序的线程数超过这个最大线程数的时候就会把这个程序关掉? 这种解释十分合理.而且本身这个一个程序需要开这么多个线程就不太正常.于是我又打开了另外一个项目,用 jstack -l 41 | grep "nid=" | wc -l 查了大概的线程数,才200多个.那就一定是我的项目有问题了.那为什么会有这么多个线程呢?我这个程序里面,能产生线程的地方,除了每次请求进程会生成对应的线程以外,就是线程池里的线程了,但是线程池也就10几20多个固定的线程呀,怎么会有3w多个那么多呢?.我最后再查看了hs_err_pid.log的内容.有了一个惊人的发现.
惊人发现
这里的线程大部分都是pool线程池的线程,这到底怎么回事呢?我怎么会有那么多个线程呢?不对,我怎么会有那么多个线程池呢?在我的代码中,唯一可能产生线程池的地方就是 --->
最主要的一个类的线程池代码
我明明是一个用@Service注解了的单例消息队列bean呀,不可能会产生那么线程池呀!这到底怎么回事?难道这个类不是单例?我在这个消息队列里面把线程名和对象地址都打印出来
log记录
果然每次打印出来的线程名和对象地址都是不一样的.这果然不是单例!!!!!再跟一个同事确认以后,至此,一切问题的答案都出来了.原来这个web的接受消息队列不是单例的,就算你加上@Service也不是单例,我的线程池也不是静态的,每次来一个消息,jvm会创建一个消息队列处理对象,然后会创建一个线程池,然后会创建20个线程,如果反复,线程越累计越多,最后达到了系统/docker/jvm限制的最高线程数,然后把程序给压垮了.那为什么以前不会这样子的呢?因为以前我们service和web是抽离的,处理消息队列都是放在service里面,service接消息队列,他是单例的.后来发现小活动没必要这么搞,搞成两个web就可以了,但是在web上,接受消息队列是不能单例的.所以才出现了这个坑!!
经过这次故障处理,明白了很多道理,也学习了不少:
1.听云有点坑,使用的时候需要确定是否会造成cpu暴增
2.jstat/jmap/jstack/hs_err_pid.log日志在故障处理中作用很大,很有必要学习
3.线程池最好做成静态,整个程序的线程公用一个静态线程池
