公司如今把小贷机器都整理回收了,访问量不大,基本都是用户来查看账户进行还款操作。
现在情况是,我们把很多服务都放在了一台服务器上,那天线上环境改了auth的salt,本地这边是写死的,自动上线已经关闭了通道,没辙,手动替包手动上线,结果没多久运维就喊了,表示cpu飙高到300%。
难得的机会,先用top找出cpu占用最多进程
ps aux|head -1;ps aux|grep -v PID|sort -rn -k +3|head
如果想细看进程信息可以使用ll proc
其实运行完这里的时候,我比较吃惊的是,真正占CPU的并不是部署的几个服务,而是resin容器本身,飚到了99%,从这个角度来讲,其实大部分性能问题都是垃圾回收的锅。
然后利用ps查看到的进程pid找cpu最高线程
top -H -p [pid]
然后拿着线程tid在jstack找,结果在里面找不到,然后上网查JAVA线程无法在jstack里找到的原因
Java thread has no Java stack trace, when
The thread is about to start, and is running pre-start initialization or JVM TI ThreadStart handler.
The thread is about to terminate, and is running post-exit cleanup or JVM TI ThreadEnd handler.
The thread is a JVM TI agent thread, which is running native code.
To find out what these threads are doing, it's not enough to get Java stack trace - you'd need to get native stack traces as well.
On JDK 8 run
jstack -m <pid>
On JDK 11 and later
jhsdb jstack --mixed --pid <pid>
以上大概意思是没找到线程的跟踪栈有三种情况,就是线程启动前的预启动,以及线程退出后的cleanup,第三种就是,利用JVM TI agent运行的线程,这个线程是用来跑本地code的。
******这里面都提到了JVM TI技术,这个技术主要是用来提供虚拟机调用本地方法的接口,可以获取jvm运行情况和提供本地方法的后门一样的接口工具,一些调试和诊断工具都是基于JVM TI来实现的,很多JVM都有自己的TI实现。
当然,这个Stack Over Flow的答案针对的Java线程,我所知道的是,如果导致我们CPU飙高的并不是java线程,那么jstack -F就打不出来。
而这个jstack -m模式,在官方文档里是说,可以打印出所有Java线程和native frames的所有线程。其实到这里是不是隐隐感觉到什么了~~没错,最后真的是垃圾回收的锅。
然后jdk8利用jstack -m找到了,发现里面使用的方法是CMS垃圾回收器的方法
0x00007f0958095152 _ZNK24CompactibleFreeListSpace12block_is_objEPK8HeapWord + 0x32
0x00007f0958099554 _ZN24CompactibleFreeListSpace22prepare_for_compactionEP12CompactPoint + 0xf4
0x00007f09582063ef _ZN10Generation22prepare_for_compactionEP12CompactPoint + 0x2f
0x00007f09581f5d15 _ZN16GenCollectedHeap22prepare_for_compactionEv + 0x45
0x00007f09581f94ca _ZN12GenMarkSweep19invoke_at_safepointEiP18ReferenceProcessorb + 0x20a
0x00007f09580f2249 _ZN12CMSCollector18do_compaction_workEb + 0x229
0x00007f09580f266c _ZN12CMSCollector27acquire_control_and_collectEbb + 0x14c
0x00007f09580f2a4e _ZN29ConcurrentMarkSweepGeneration7collectEbbmb + 0x8e
0x00007f09581f80ba _ZN16GenCollectedHeap13do_collectionEbbmbi + 0x54a
0x00007f09581f88a7 _ZN16GenCollectedHeap18do_full_collectionEbi + 0x47
0x00007f09580902d4 _ZN13CollectedHeap20collect_as_vm_threadEN7GCCause5CauseE + 0x114
0x00007f09586d54b1 _ZN31VM_CollectForMetadataAllocation4doitEv + 0x161
0x00007f09586dd535 _ZN12VM_Operation8evaluateEv + 0x55
0x00007f09586db90a _ZN8VMThread18evaluate_operationEP12VM_Operation + 0xba
0x00007f09586dbc8e _ZN8VMThread4loopEv + 0x1ce
0x00007f09586dc100 _ZN8VMThread3runEv + 0x70
0x00007f0958533268 _ZL10java_startP6Thread + 0x108
讲真,平时只负责上下线,JVM配置只要不出问题很少留意,这个年代了,还在使用CMS吗?嗯,jmap看了下,是CMS。而占用大多CPU也是CMS的特性之一:最小化GC中断,付出的代价便是高CPU负荷。
既然定位到了垃圾回收,那就接着排查垃圾回收吧,pid是18637
就去jstat -gc 18637 5000
jstat -gcold 18637
jstat -gcoldcapacity 18637
发现full gc非常频繁(每五秒输出,发现触发fullGC13次)
(复盘这次的排查问题,发现图片保存少之又少。。)
如此频繁,顺带gccause一下看看最近一次回收的原因
jstat -gccause 18637
结果长这样
从这个结果来看最近一次是Metadata的GC,而触发原因是因为达到了阈值。再细看当前元空间使用率已经接近98%。
到这里不能等了,找运维拿来了jvm参数,有三个参数很亮眼
-XX:MaxMetaspaceSize=128M
-XX:MetaspaceSize=128M
-XX:CMSInitiatingOccupancyFraction=80
老年代的配置属于默认配置,占整个堆内存的2/3,CMS回收要达到80%才会触发,我们还没有达到这个值。
那么根据图1中的显示,metaspace我们已经达到了阈值。
这种情况产生也没毛病,想想一台机器部署了5个web服务和5个微服务的场景吧,虽然没什么人访问,但加载的class信息也足够多了。
主要就是metadata的配置,而有关metadata的配置并没有oracle的官方指导,官方指导上的意思是说metaspace的配置,主要是避免首次启动时对加载的类信息做回收,取决于应用本身,够用就行了,不要太频繁触发full gc就好
Specify a higher value for the option -XX:MetaspaceSize to avoid early garbage collections induced for class metadata. The amount of class metadata allocated for an application is application-dependent and general guidelines do not exist for the selection of -XX:MetaspaceSize. The default size of -XX:MetaspaceSize is platform-dependent and ranges from 12 MB to about 20 MB.
其实调大这metaspace的配置能够大概解决问题,但是最终我选择了切换为G1垃圾回收。
官方文档是这样写的
Applications running today with either the CMS or the ParallelOld garbage collector would benefit switching to G1 if the application has one or more of the following traits.
More than 50% of the Java heap is occupied with live data.The rate of object allocation rate or promotion varies significantly.Undesired long garbage collection or compaction pauses (longer than 0.5 to 1 second)
G1 is planned as the long term replacement for the Concurrent Mark-Sweep Collector (CMS).
首先戳我的点的主要原因是g1最终的目的是要取代cms垃圾回收器,它的回收范围是整个堆,紧跟潮流总不会错的。其次g1取代cms的情况官方也建议了以下几点:
1. 一个是要管理的堆内存大于6g
2. 一个是服务已使用的堆内存超过了50%
3. 一个是对象分配率过高或对象从新生代晋升到老年代速率过快(这里我查了一下资料,意思是对象分配率过高的话其实会导致Minor GC频繁,而这种情况会使对象更快地晋升到老年代,而老年代如果过快地被填充,又会触发FullGC。从设计角度来讲,之所以分代回收,是为了应对对象存活时间而使用不同的回收策略,老年代可不是为了频繁回收而产生的)
4. 垃圾回收导致服务中断时长超过0.5-1s。
这种时候官方就建议把cms换成g1了。
最终cpu骤降,从99%降至一般运行状态下的2%左右。好了。就这样吧,虽然不希望线上出现这种问题,但一旦出问题了,搞一遍还蛮带感的。期待下一次的摸排:DDDDD
后记:
最近在复盘这次垃圾回收,因为这次jvm排查的经历让我对垃圾回收机制和分代回收这一块加深了印象。复盘的时候发现自己思考地还欠缺深入。这次的问题有两个地方值得深思,一个是为什么metaspace会超?如果正常进行GC,为何会超出阈值?其次是没有调大metaspace的前提下,换成G1为什么就没有再频繁FullGC过?
为什么metaspace会超,我经过比对当时留下CMS的jstat数据和G1当前的数据,发现新生代CMS划分区域非常大,是现在G1的十倍。G1是不建议设定新老年代比例的,这样它就可以动态调整新老年代比例,达到最优实践。首先说明metaspace是存储类描述信息的,当堆上分配了对象,就会关联到metaspace里面的类信息,如果堆上的对象不回收,那么metaspace里面的类信息也不会回收。
在配置cms时,我们会设置新生代老年代比例,新生代空间是固定的,如果新生代的空间比较大,回收间隔时间长,那就会导致metaspace里的class信息无法被释放,最终导致未进行youngGC而率先因为metaspace超了跑了FullGC。但G1的新生代空间是根据使用情况动态分配的,它的算法会去回收最有回收价值的region。
就这次修改参数而言,使用G1比CMS时间短很多,就已经执行了717次youngGC,而CMS用了那么久,才52次,侧面也能佐证这个猜测的正确性,解释了为何在相同metaspace的配置下,G1没有产生频繁FullGC的原因:新生代对象回收加快,metaspace空间得到了尽快释放,没有达到阈值,于是不会触发FullGC。
参考文献:
* https://www.oracle.com/java/technologies/javase/hotspot-garbage-collection.html
* https://www.oracle.com/java/technologies/javase/gc-tuning-6.html
* https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/sizing.html
* https://plumbr.io/blog/garbage-collection/what-is-allocation-rate
* https://plumbr.io/blog/garbage-collection/what-is-promotion-rate