记一次线上机器CPU飙高的排查过程

        公司如今把小贷机器都整理回收了,访问量不大,基本都是用户来查看账户进行还款操作。

        现在情况是,我们把很多服务都放在了一台服务器上,那天线上环境改了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


图1

jstat -gcold 18637

jstat -gcoldcapacity 18637

发现full gc非常频繁(每五秒输出,发现触发fullGC13次)

(复盘这次的排查问题,发现图片保存少之又少。。)

如此频繁,顺带gccause一下看看最近一次回收的原因

jstat -gccause 18637

结果长这样


图2

从这个结果来看最近一次是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

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

推荐阅读更多精彩内容