频繁GC引起卡顿问题排查与解决

这篇具有很好参考价值的文章主要介绍了频繁GC引起卡顿问题排查与解决。希望对大家有所帮助。如果存在错误或未考虑完全的地方,请大家不吝赐教,您也可以点击"举报违法"按钮提交疑问。

频繁GC引起卡顿问题排查与解决

一  问题描述

今天测试组更新测试环境后发现系统卡顿,无法办理任何业务,重启系统后问题仍然存在。已经到项目后期,迭代测试时间十分紧张。此问题直接影响到项目进度

二 排查过程

1.查看进程资源占用情况

Linux 下常用top命令显示系统中各个进程的资源占用状况,查看资源发现PID26799进程信息中

CPU使用率达到了333%。详细信息如下

root@10.0.254.59 15:57:17 /data/jboss-4.2.3-9.0.0-8078/bin  # top
top - 16:01:10 up 241 days, 22:37,  6 users,  load average: 8.83, 3.23, 2.69
Tasks: 207 total,   1 running, 206 sleeping,   0 stopped,   0 zombie
%Cpu(s): 84.0 us,  0.7 sy,  0.0 ni, 15.2 id,  0.0 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem : 16266800 total,   170440 free,  9203876 used,  6892484 buff/cache
KiB Swap:  4194300 total,  4066812 free,   127488 used.  6589968 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                                                                                   
26799 root      20   0 8730000   4.6g  28024 S 333.0 29.9  11:09.94 java                                                                                                                                                                                                      
27727 root      20   0 8728572   2.3g  36332 S   1.0 14.6  12:27.05 java                                                                                                                                                                                                      
21841 root      20   0 5464404   1.6g  16284 S   0.7 10.2 145:29.47 java                                                                                                                                                                                                      
    9 root      20   0       0      0      0 S   0.3  0.0  11:51.47 rcu_sched                                                                                                                                                                                                 
13985 root      20   0  162148   2408   1588 R   0.3  0.0   0:00.01 top                                                                                                                                                                                                       
24029 root      20   0  162856   3156   1608 S   0.3  0.0   0:45.30 top                                                                                                                                                                                                       
    1 root      20   0  193640   4364   2832 S   0.0  0.0  19:42.60 systemd                                                                                                                                                                                                   
    2 root      20   0       0      0      0 S   0.0  0.0   0:01.32 kthreadd                                                                                                                                                                                                  
    3 root      20   0       0      0      0 S   0.0  0.0   0:28.28 ksoftirqd/0                                                                                                                                                                                               
                 

2. 查看进程中占用线程情况

使用top -Hp命令查找该进程中CPU使用最高的线程,发现26801、26802、26803、28604线程CPU使用都达到了100%

root@10.0.254.59 16:01:15 /data/jboss-4.2.3-9.0.0-8078/bin  # top -Hp 26799
top - 16:01:25 up 241 days, 22:37,  6 users,  load average: 8.14, 3.35, 2.74
Threads: 553 total,   4 running, 549 sleeping,   0 stopped,   0 zombie
%Cpu(s): 98.5 us,  1.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 16266800 total,   169656 free,  9204352 used,  6892792 buff/cache
KiB Swap:  4194300 total,  4066812 free,   127488 used.  6589608 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                                                                                                                    
26801 root      20   0 8730000   4.6g  28024 R 99.9 29.9   1:06.08 java                                                                                                                                                                                                       
26803 root      20   0 8730000   4.6g  28024 R 99.9 29.9   1:06.22 java                                                                                                                                                                                                       
26804 root      20   0 8730000   4.6g  28024 R 99.9 29.9   1:06.30 java                                                                                                                                                                                                       
26802 root      20   0 8730000   4.6g  28024 R 99.9 29.9   1:06.11 java                                                                                                                                                                                                       
26799 root      20   0 8730000   4.6g  28024 S  0.0 29.9   0:00.00 java                                                                                                                                                                                                       
26800 root      20   0 8730000   4.6g  28024 S  0.0 29.9   0:00.05 java                                                                                                                                                                                                       
26805 root      20   0 8730000   4.6g  28024 S  0.0 29.9   0:08.64 java                                                                                                                                                                                                       
26806 root      20   0 8730000   4.6g  28024 S  0.0 29.9   0:00.01 java                                                                                                                                                                                                       
                                                                                                                                                                                                    

3. 获取进程的栈信息

使用jstack将PID26799进程的栈信息导出到临时文件以便分析

root@10.0.254.59 16:01:58 /data/jboss-4.2.3-9.0.0-8078/bin  # jstack 26799 >pid26799.txt

4. 执行printf 将线程号格式化为16进制

26801、26802、26803、28604分别对应十六进制数068b1,、068b2、068b3、068b4

例如:

root@10.0.254.59 16:02:59 /data/jboss-4.2.3-9.0.0-8078/bin  # printf "0%x\n" 26802

068b2

5. 查找线程的栈信息

通过占用转换后的十六进制数去导出的pid26799.txt中查找栈信息。发现4个线程都是GC任务

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007faef408e800 nid=0x68b6 in Object.wait() [0x00007faee1603000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x00000006c043d188> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Thread" os_prio=0 tid=0x00007faef4085000 nid=0x68b5 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007faef4020000 nid=0x68b1 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007faef4022000 nid=0x68b2 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007faef4024000 nid=0x68b3 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007faef4025800 nid=0x68b4 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007faef40d4800 nid=0x68bd waiting on condition 

6.查看GC垃圾回收

发现YGC(年轻代回收次数) 和FGC(老年代垃圾回收次数) 都比较大,且YGCT(年轻代回收消耗时间) 和FGCT(老年代垃圾回收消耗时间)都比较长,说明系统因为GC才出现的卡顿现象。因为,在执行垃圾收集算法时,Java应用程序的其他所有线程都被挂起,在Java中的这个现象叫做Stop-The-World机制简称STW。 这是一种全局暂停现象。

root@10.0.254.59 16:05:45 /data/STARSMS/jboss-4.2.3-9.0.0-8078/bin  # jstat -gc 26799 5000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709387.4  180608.0 166270.8 22400.0 18766.9     61   17.137  33    394.263  411.400
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709387.4  180608.0 166270.8 22400.0 18766.9     61   17.137  33    394.263  411.400
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709387.2  180608.0 166292.3 22400.0 18766.9     61   17.137  34    409.916  427.052
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709387.2  180608.0 166292.3 22400.0 18766.9     61   17.137  34    409.916  427.052
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709387.2  180608.0 166292.3 22400.0 18766.9     61   17.137  34    409.916  427.052
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709236.9  180608.0 166306.0 22400.0 18769.6     61   17.137  35    426.082  443.219
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709236.9  180608.0 166306.0 22400.0 18769.6     61   17.137  35    426.082  443.219
200192.0 211456.0  0.0    0.0   919552.0 919552.0 2796544.0  2709236.9  180608.0 166306.0 

7. 堆转储,分析dump.hprof 文件

先通过  arhtas  的heapdump命令得到hprof文件。( 参考:arthas)通过浏览器下载: http://localhost:8563/arthas-output/ 

[arthas@9312]$ heapdump arthas-output/dump.hprof
Dumping heap to arthas-output/dump.hprof ...
Heap dump file created

 频繁GC引起卡顿问题排查与解决

然后分析hprof文件, 分析方法有很多中我使用的是JDK自带的bin/jvisualvm.exe 分析

文件- 装入-选择下载的dump.hprof文件

频繁GC引起卡顿问题排查与解决

因为SWT时线程被挂起,所以泄露的程序应该有线程信息, 根据对象和线程栈发现了可疑程序

"autoArrivalTimeChangeQuartzSchedule_Worker-1" #361 prio=5 os_prio=0 tid=0x00007fae4419c800 nid=0x6e97 runnable [0x00007fae36f2d000]
   java.lang.Thread.State: RUNNABLE
	at java.text.DateFormatSymbols.<init>(DateFormatSymbols.java:145)
	at sun.util.locale.provider.DateFormatSymbolsProviderImpl.getInstance(DateFormatSymbolsProviderImpl.java:85)
	at java.text.DateFormatSymbols.getProviderInstance(DateFormatSymbols.java:364)
	at java.text.DateFormatSymbols.getInstance(DateFormatSymbols.java:340)
	at java.util.Calendar.getDisplayName(Calendar.java:2110)
	at java.text.SimpleDateFormat.subFormat(SimpleDateFormat.java:1125)
	at java.text.SimpleDateFormat.format(SimpleDateFormat.java:966)
	at java.text.SimpleDateFormat.format(SimpleDateFormat.java:936)
	at java.text.DateFormat.format(DateFormat.java:345)
	at com.star.sms.business.customer.job.GwNpDealContext.getDateList(GwNpDealContext.java:277)

8.分析线上代码

使用arhtas 的jad命令查看线上代码,发现275-279行提交的代码存在死循环。至此找到内存泄露代码

[arthas@9312]$ jad com.star.sms.business.customer.job.GwNpDealContext getDateList

ClassLoader:
+-org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader@105c375d[stariboss-customer:1.0.0(id=130)]
  +-org.eclipse.osgi.baseadaptor.BaseAdaptor$1@d280fb

Location:
/E:/Jboss/jboss-4.2.3-9.0.0R1-8089-hebei-dev/server/default/tmp/stariboss_configuration/org.eclipse.osgi/bundles/130/1/bundlefile

        public List<String> getDateList(String startTime, String endTime, GwNpUserType type) {
            ArrayList<String> dateList = new ArrayList<String>();
/*246*/     SimpleDateFormat format = null;
/*247*/     int calendarField = 0;
/*248*/     if (type.equals((Object)GwNpUserType.HOR)) {
                format = new SimpleDateFormat("yyyyMMddHH");
/*250*/         calendarField = 11;
/*251*/     } else if (type.equals((Object)GwNpUserType.DAY)) {
                format = new SimpleDateFormat("yyyyMMdd");
/*253*/         calendarField = 5;
/*254*/     } else if (type.equals((Object)GwNpUserType.MONTH)) {
                format = new SimpleDateFormat("yyyyMM");
/*256*/         calendarField = 2;
            } else {
/*258*/         this.log.info((Object)"=====GwNpUserType is INVALID======");
/*259*/         return dateList;
            }
            try {
/*263*/         Date startTime1 = null;
/*264*/         Date endTime1 = null;
/*265*/         if (StringUtils.hasText((String)startTime)) {
/*266*/             startTime1 = format.parse(startTime);
/*267*/             endTime1 = format.parse(endTime.substring(0, startTime.length()));
                } else {
/*269*/             startTime = this.assigStartTime(startTime, calendarField);
/*270*/             startTime1 = DateFormatUtil.parseStrToDate4((String)startTime);
/*271*/             endTime1 = DateFormatUtil.parseStrToDate4((String)endTime);
                }
/*274*/         Calendar tempStart = Calendar.getInstance();
/*275*/         tempStart.setTime(startTime1);
                while (endTime1.getTime() >= startTime1.getTime()) {
/*277*/             dateList.add(format.format(startTime1));
/*279*/             startTime1 = tempStart.getTime();
                }
            }
            catch (Exception e) {
                // empty catch block
            }
/*284*/     return dateList;
        }

三 问题总结

本问题是因为开发提交了几行未经测试的代码引起, 此代码直接引起内存泄露,系统频繁GC。这也是提交未测试代码引起故障的典型案例。


 上一篇:了解高可用文章来源地址https://www.toymoban.com/news/detail-422900.html


到了这里,关于频繁GC引起卡顿问题排查与解决的文章就介绍完了。如果您还想了解更多内容,请在右上角搜索TOY模板网以前的文章或继续浏览下面的相关文章,希望大家以后多多支持TOY模板网!

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处: 如若内容造成侵权/违法违规/事实不符,请点击违法举报进行投诉反馈,一经查实,立即删除!

领支付宝红包 赞助服务器费用

相关文章

  • 【Android】 频繁刷新 RecyclerView导致View 对象引用过多引起的Native 内存占用过大解决办法

    在 RecyclerView 中,如果频繁刷新 RecyclerView,可能会导致 Native 内存中有大量的 TextView 对象,从而导致内存占用过多的问题。以下是一些可能导致该问题的原因和解决方法: 使用 ViewHolder 在 RecyclerView 中,使用 ViewHolder 可以避免频繁创建和销毁 View 对象,从而减少内存占用。可

    2024年02月08日
    浏览(83)
  • CGLIB动态代理对象GC问题排查

    最近有个新系统开发完成后要上线,由于系统调用量很大,所以先对核心接口进行了一次压力测试,由于核心接口中基本上只有纯内存运算,所以预估核心接口的压测QPS能够达到上千。 压测容器配置:4C8G 先从10个并发开始进行发压,结果cpu一下就飙升到了100%,但是核心接口

    2024年02月14日
    浏览(40)
  • 现场问题排查-k8s(docker)上某服务pod频繁自动重启

    根因:应用内存占用不合理(个人认为)+现场配置内存不够导致频繁触发OOM引发该现象。 为啥要写这个文章? 之前没有k8s下pod频繁重启的问题处理经验,这次实战沉淀思路及过程,供后续自己处理相同问题提供参考资料 为其他遇到类似问题的人提供一些排查思路 现场反馈

    2024年02月03日
    浏览(43)
  • 安防监控视频云存储平台EasyNVR通道频繁离线的原因排查与解决

    安防视频监控汇聚EasyNVR视频集中存储平台,是基于RTSP/Onvif协议的安防视频平台,可支持将接入的视频流进行全平台、全终端分发,分发的视频流包括RTSP、RTMP、HTTP-FLV、WS-FLV、HLS、WebRTC等格式。为了满足用户的集成与二次开发需求,我们也提供了丰富的API接口供用户调用。有

    2024年02月12日
    浏览(80)
  • 【FAQ】安防监控视频云存储平台EasyNVR频繁离线的原因排查与解决

    有用户反馈,在使用EasyNVR时会出现通道频繁离线的情况。针对该反馈我们立即进行了排查。 安防视频监控汇聚EasyNVR视频集中存储平台,是基于RTSP/Onvif协议的安防视频平台,可支持将接入的视频流进行全平台、全终端分发,分发的视频流包括RTSP、RTMP、HTTP-FLV、WS-FLV、HLS、W

    2024年02月12日
    浏览(149)
  • 小程序canvas画画板签字版,touchmove时卡顿的问题(根本原因是因为vue语法中page.data导致视图层和逻辑层的频繁通讯导致)

    因为要做一个画画板的功能,所以使用了canvas组件,一开始好多人说小程序canvas性能特别差,也没太注意,做出来之后确实有点卡,而且每一笔touchmove时间越长越卡,最终导致页面卡到无法使用,起初我也以为是canvas卡。 第一步肯定是先找一下canvas的问题,网上搜到一些材料

    2024年02月10日
    浏览(45)
  • 年轻代频繁GC ParNew导致http变慢

    某日下午大约四点多,接到合作方消息,线上环境,我这边维护的某http服务突然大量超时(对方超时时间设置为300ms),我迅速到鹰眼平台开启采样,发现该服务平均QPS到了120左右,平均RT在2秒多到3秒,部分毛刺高达5到6秒(正常时候在60ms左右)。 qps情况: rt情况 该服务是

    2024年02月13日
    浏览(53)
  • 【Azure】office365邮箱测试的邮箱账号因频繁连接邮箱服务器而被限制连接 引起邮箱显示异常

    azure微软office365邮箱会对频繁连接自身邮箱服务器的IP地址进行,连接邮箱服务器IP限制,也就是黑名单,释放时间不确定,但至少一天及以上。 解决办法,换一个IP,或者新注册一个office365邮箱再重试。 以上连接失败会出现code = 5或者code = 22

    2024年02月13日
    浏览(36)
  • 将非受信数据作为参数传入,可能引起xml 注入,引起数据覆盖,这个问题咋解决

    当将非受信数据作为参数传入时,确实存在XML注入(XML Injection)的风险,攻击者可以通过构造恶意的XML数据来修改XML文档结构或执行意外的操作。为了解决这个问题,你可以采取以下措施: 输入验证和过滤:对于接收到的非受信数据,进行输入验证和过滤,确保只接受符合

    2024年02月13日
    浏览(45)
  • 解决云服务器访问问题:发现和解决 Cloudflare WARP 引起的 IP 问题

    最近在配置我的云服务器时,我遇到了一个有趣的网络问题。虽然能够通过 SSH 连接到服务器,也可以通过域名访问服务,但是在尝试通过 IP 地址和端口直接访问服务器上的服务时,却无法成功。一开始,我对这个问题感到困惑,但最终通过一系列的调试步骤找到了原因并解

    2024年01月24日
    浏览(46)

觉得文章有用就打赏一下文章作者

支付宝扫一扫打赏

博客赞助

微信扫一扫打赏

请作者喝杯咖啡吧~博客赞助

支付宝扫一扫领取红包,优惠每天领

二维码1

领取红包

二维码2

领红包