GC暂停时间过长—

告警

本次GC日志分析

2022-11-17T17:58:50.518+0800: 1217960.132: [GC (Allocation Failure) 2022-11-17T17:58:50.518+0800: 1217960.132: [ParNew: 1382400K->153600K(1382400K), 0.
5626158 secs] 3419277K->2410488K(4040704K), 0.5628652 secs] [Times: user=1.07 sys=0.00, real=0.56 secs]
2022-11-17T17:58:51.084+0800: 1217960.698: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2256888K(2658304K)] 2419662K(4040704K), 0.0349632 secs] [Times:
user=0.05 sys=0.00, real=0.03 secs]
2022-11-17T17:58:51.119+0800: 1217960.734: [CMS-concurrent-mark-start]
2022-11-17T17:58:51.626+0800: 1217961.240: [CMS-concurrent-mark: 0.506/0.506 secs] [Times: user=1.03 sys=0.00, real=0.51 secs]
2022-11-17T17:58:51.626+0800: 1217961.240: [CMS-concurrent-preclean-start]
2022-11-17T17:58:51.634+0800: 1217961.248: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2022-11-17T17:58:51.634+0800: 1217961.248: [CMS-concurrent-abortable-preclean-start]CMS: abort preclean due to time 2022-11-17T17:58:56.994+0800: 1217966.608: [CMS-concurrent-abortable-preclean: 4.854/5.360 secs] [Times: user=5.29 sys
=0.03, real=5.36 secs]
2022-11-17T17:58:56.997+0800: 1217966.611: [GC (CMS Final Remark) [YG occupancy: 629022 K (1382400 K)]2022-11-17T17:58:56.997+0800: 1217966.611: [Resca
n (parallel) , 0.0937759 secs]2022-11-17T17:58:57.091+0800: 1217966.705: [weak refs processing, 0.0002312 secs]2022-11-17T17:58:57.091+0800: 1217966.70
5: [class unloading, 0.0450819 secs]2022-11-17T17:58:57.136+0800: 1217966.750: [scrub symbol table, 0.0198218 secs]2022-11-17T17:58:57.156+0800: 121796
6.770: [scrub string table, 0.0021679 secs][1 CMS-remark: 2256888K(2658304K)] 2885910K(4040704K), 0.1613101 secs] [Times: user=0.26 sys=0.00, real=0.16secs]
2022-11-17T17:58:57.159+0800: 1217966.773: [CMS-concurrent-sweep-start]
2022-11-17T17:58:58.567+0800: 1217968.181: [CMS-concurrent-sweep: 1.398/1.409 secs] [Times: user=1.44 sys=0.00, real=1.41 secs]
2022-11-17T17:58:58.567+0800: 1217968.182: [CMS-concurrent-reset-start]
2022-11-17T17:58:58.576+0800: 1217968.190: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

STW的两个阶段，共耗时 0.19s

初始标记 CMS Initial Mark: 耗时0.03s
重新标记 CMS Final Remark: 耗时0.16s

并发阶段，耗时

并发标记 CMS-concurrent-mark: 耗时0.51s
并发预清理 CMS-concurrent-preclean：耗时0.01s
并发可中断预清理 CMS-concurrent-abortable-preclean: 耗时5.36s
并发清理 CMS-concurrent-sweep：1.41s

告警和监控的问题

经过对gc日志的分析，发现，实际暂停时间和告警内容不符，查看监控，也发现了这个问题

和运维确认后，监控和告警的指标，并不是gc暂停时间，而是gc总时长。
因此，运维侧，需要优化，告警、监控相关说明
监控最好能够添加暂停时长的指标 @运维同鞋

有内存不足的表现

查看堆监控发现，

eden去和s区经常被打满，对象进入老年代
使得fullgc较为频繁
没有内存泄露的表现（没有持续增长，无法回收），不需要再dump分析

老年代够用，但新生代小了

结论与方案

gc暂停时间并不长，只是gc整个过程较长
告警中的时间并不是gc暂停时间，运维侧需要调整告警内容与监控的指标，细化暂停时长的监控@运维同鞋
堆内存，老年代够用，但新生代小了，建议老年代保持不变，新生代加内存，
- 当前是堆内存共4GB，新生代为1500m
- 新生代加到2500m，然后持续观察

GC暂停时间过长——排查分析相关推荐

Mp4视频首帧加载时间过长问题分析
一.背景说明用户反映某课程视频(mp4格式)从打开播放器到第一帧画面显示,加载时间过长,影响观看体验. 二.时间埋点 1.定位耗时问题,最直接的方法是在关键节点埋点,打印时间戳,找出耗时操作.项目使 ...
linux启动tomcat不停的触发gc,tomcat的rmi触发的full gc的时间过长的优化
生产上发现每次full gc都会花上5~20s的时间,查看了下,发现每一个小时都会触发一次full gc,查了下资料是rmi导致的. 但是zabbix监控需要开启rmi,不想关闭.查了下资料发现可以通 ...
如何获取GC(垃圾回收器)的STW(暂停)时间?
前言在现代的容器化和微服务应用中,因为分布式的环境和错综复杂的调用关系,APM(Application Performance Monitoring 应用性能监控)显得尤为重要,它通过采集应用程序各 ...
jvmti_JVMTI标记如何影响GC暂停
jvmti 这篇文章分析了为什么Plumbr Agents在某些情况下以及如何延长GC暂停的时间. 对基本问题进行故障诊断揭示了有关在GC暂停期间如何处理JVMTI标记的有趣见解. 发现问题我们的一 ...
JVMTI标记如何影响GC暂停
这篇文章分析了为什么Plumbr Agents在某些情况下以及如何延长GC暂停的时间. 对基本问题进行故障诊断揭示了有关在GC暂停期间如何处理JVMTI标记的有趣见解. 发现问题我们的一位客户抱怨说 ...
JVM 问题排查分析下篇（案例实战）
GC 问题排查实战案例这一部分,我们来看一个实际的案例. 假设我们有一个提供高并发请求的服务,系统使用 Spring Boot 框架,指标采集使用 MicroMeter,监控数据上报给 Datado ...
牛逼了！JDK 16 ZGC 实现最大暂停时间不超过1ms
点击上方"芋道源码",选择"设为星标" 管她前浪,还是后浪? 能浪的浪,才是好浪! 每天 8:55 更新文章,每天掉亿点点头发... 源码精品专栏原创 | J ...
GC一些长时间停顿问题排查及解决办法
对于许多企业级应用,尤其是OLTP应用来说,长暂停很可能导致服务超时,而对这些运行在JVM上的应用来说,垃圾回收(GC)可能是长暂停最主要的原因.本文将描述一些可能碰到GC长暂停的不同场景,以及说明我 ...
频繁GC (Allocation Failure)及young gc时间过长分析
序本文主要分析一个频繁GC (Allocation Failure)及young gc时间过长的case. 症状 gc throughput percent逐步下降,从一般的99.96%逐步下降,跌 ...

GC暂停时间过长——排查分析

告警

本次GC日志分析

告警和监控的问题

有内存不足的表现

结论与方案

GC暂停时间过长——排查分析相关推荐

最新文章

热门文章