小工具      在线工具  汉语词典  css  js  c++  java

CPU飙高及Full GC次数过多怎么排查?

Java 额外说明

收录于:97天前

处理过线上问题的同学基本上都会遇到系统突然运行缓慢、CPU 100%、Full GC 次数过多等问题。当然,这些问题造成的最终直观的现象就是系统运行缓慢、出现大量报警。本文主要针对系统运行缓慢的问题,提供该问题的排查思路,从而定位问题的代码点,进而提供解决问题的思路。

如果问题导致线上系统不可用,首先需要导出jstack和内存信息,然后重新启动系统,以尽快保证系统的可用性。造成这种情况的原因主要有两个:

  • 代码中某个位置读取大量数据,导致系统内存耗尽,导致Full GC次数过多,系统变慢;

  • 代码中存在CPU比较密集的操作,导致CPU过高,系统运行缓慢;

相对来说,这是最常见的两个线上问题,它们会直接导致系统不可用。还有几种情况会导致某个功能运行缓慢,但不会导致系统不可用:

  • 代码的某个位置存在阻塞操作,导致函数调用整体比较耗时,但出现比较随机;

  • 线程由于某种原因进入 WAITING 状态。此时整个功能不可用,但无法复现;

  • 锁使用不当会导致多个线程进入死锁状态,导致整个系统变慢。

对于这三种情况,通过检查CPU和系统内存是无法找出具体问题的,因为它们都是比较阻塞的操作,CPU和系统内存占用率不高,但功能却很慢。接下来我们通过查看系统日志来逐步排查上述问题。

1Full GC 次数过多

相对而言,这种情况是最容易出现的,尤其是新功能上线的时候。对于Full GC次数较多的情况,主要有以下两个特点:

  • 多个在线线程CPU利用率超过100%。通过jstack命令可以看到这些线程主要是垃圾回收线程。

  • 通过jstat命令监控GC情况。可以看到Full GC的次数非常多,并且数量还在不断增加。

       首先我们可以使用top命令查看系统CPU的占用情况,如下是系统CPU较高的一个示例:

top - 08:31:10 up 30 min,  0 users,  load average: 0.73, 0.58, 0.34
KiB Mem:   2046460 total,  1923864 used,   122596 free,    14388 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192352 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
    9 root      20   0 2557160 288976  15812 S  98.0 14.1   0:42.60 java

       可以看到,有一个Java程序此时CPU占用量达到了98.8%,此时我们可以复制该进程id9,并且使用如下命令查看呢该进程的各个线程运行情况:

top -Hp 9

该进程下各个线程的运行状态如下:

top - 08:31:16 up 30 min,  0 users,  load average: 0.75, 0.59, 0.35
Threads:  11 total,   1 running,  10 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.5 us,  0.6 sy,  0.0 ni, 95.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   2046460 total,  1924856 used,   121604 free,    14396 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192532 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
   10 root      20   0 2557160 289824  15872 R 79.3 14.2   0:41.49 java
   11 root      20   0 2557160 289824  15872 S 13.2 14.2   0:06.78 java

       可以看到,在进程为9的Java程序中各个线程的CPU占用情况,接下来我们可以通过jstack命令查看线程id为10的线程为什么耗费CPU最高。需要注意的是,在jsatck命令展示的结果中,线程id都转换成了十六进制形式。可以用如下命令查看转换结果,也可以找一个科学计算器进行转换:

root@a39de7e7934b:/# printf "%x\n" 10
a

       这里打印结果说明该线程在jstack中的展现形式为0xa,通过jstack命令我们可以看到如下信息:

"main" #1 prio=5 os_prio=0 tid=0x00007f8718009800 nid=0xb runnable [0x00007f871fe41000]
   java.lang.Thread.State: RUNNABLE
	at com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)

"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable

       这里的VM Thread一行的最后显示nid=0xa,这里nid的意思就是操作系统线程id的意思。而VM Thread指的就是垃圾回收的线程。这里我们基本上可以确定,当前系统缓慢的原因主要是垃圾回收过于频繁,导致GC停顿时间较长。我们通过如下命令可以查看GC的情况:

root@8d36124607a0:/# jstat -gcutil 9 1000 10
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00   0.00  75.07  59.09  59.60   3259    0.919  6517    7.715    8.635
  0.00   0.00   0.00   0.08  59.09  59.60   3306    0.930  6611    7.822    8.752
  0.00   0.00   0.00   0.08  59.09  59.60   3351    0.943  6701    7.924    8.867
  0.00   0.00   0.00   0.08  59.09  59.60   3397    0.955  6793    8.029    8.984

可以看到这里的FGC指的是Full GC的次数,高达6793次,并且还在不断增长。这进一步证实了系统缓慢是由于内存溢出造成的。那么到这里内存溢出就确认了,但是如何检查是哪些对象导致了内存溢出呢?可以dump内存日志,然后通过eclipse的mat工具查看。下面是显示的对象树结构:

图片

       经过mat工具分析之后,我们基本上就能确定内存中主要是哪个对象比较消耗内存,然后找到该对象的创建位置,进行处理即可。这里的主要是PrintStream最多,但是我们也可以看到,其内存消耗量只有12.2%。也就是说,其还不足以导致大量的Full GC,此时我们需要考虑另外一种情况,就是代码或者第三方依赖的包中有显示的System.gc()调用。这种情况我们查看dump内存得到的文件即可判断,因为其会打印GC原因:

[Full GC (System.gc()) [Tenured: 262546K->262546K(349568K), 0.0014879 secs] 262546K->262546K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0015151 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 2795K->0K(157248K), 0.0001504 secs][Tenured: 262546K->402K(349568K), 0.0012949 secs] 265342K->402K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0014699 secs] [Times: user=0.00

       比如这里第一次GC是由于System.gc()的显示调用导致的,而第二次GC则是JVM主动发起的。总结来说,对于Full GC次数过多,主要有以下两种原因:

  • 代码中一次性获取大量对象,导致内存溢出。这时候可以使用eclipse的mat工具来查看哪些对象在内存中较多;

  • 内存占用不高,但是Full GC次数还是比较多,此时可能是显示的System.gc()调用导致GC次数过多,这可以通过添加-XX:+DisableExplicitGC来禁用JVM对显示GC的响应。

2CPU 太高

       在前面第一点中,我们讲到,CPU过高可能是系统频繁的进行Full GC,导致系统缓慢。而我们平常也肯能遇到比较耗时的计算,导致CPU过高的情况,此时查看方式其实与上面的非常类似。首先我们通过top命令查看当前CPU消耗过高的进程是哪个,从而得到进程id;然后通过top -Hp <pid>来查看该进程中有哪些线程CPU过高,一般超过80%就是比较高的,80%左右是合理情况。这样我们就能得到CPU消耗比较高的线程id。接着通过该线程id的十六进制表示jstack日志中查看当前线程具体的堆栈信息。

       在这里我们就可以区分导致CPU过高的原因具体是Full GC次数过多还是代码中有比较耗时的计算了。如果是Full GC次数过多,那么通过jstack得到的线程信息会是类似于VM Thread之类的线程,而如果是代码中有比较耗时的计算,那么我们得到的就是一个线程的具体堆栈信息。如下是一个代码中有比较耗时的计算,导致CPU过高的线程信息:

图片

这里可以看到,在请求UserController时,线程的CPU一直处于100%,因为Controller进行了耗时的调用。我们可以根据堆栈信息直接定位到UserController的第34行,看看具体是什么原因导致代码中计算量较大。

3时不时出现的界面耗时现象

对于这种情况,一个典型的例子就是访问我们的一个接口往往需要2到3秒才能返回。这是一个麻烦的情况,因为一般来说,它不会消耗太多CPU,也不会占用大量内存。也就是说,我们无法通过上述两种方法来解决这个问题。而且由于这样的界面比较耗时,所以时有发生。这意味着即使我们通过jstack命令获取了线程访问的堆栈信息,也无法判断哪个线程正在执行耗时操作。溃败。

对于时不时出现的接口耗时严重的问题,我们的定位思路基本是:首先找到接口,通过压测工具不断增加访问量。如果界面中某个位置比较耗时,由于我们访问的频率非常高,所以大多数线程最终都会阻塞在这个阻塞点。这样,通过多个线程具有相同的堆栈日志,我们基本上可以定位到界面中比较耗时的代码。地点。以下是通过压力测试工具针对代码中的一个耗时的阻塞操作得到的线程堆栈日志:

"http-nio-8080-exec-2" #29 daemon prio=5 os_prio=31 tid=0x00007fd08cb26000 nid=0x9603 waiting on condition [0x00007000031d5000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at java.lang.Thread.sleep(Thread.java:340)
	at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
	at com.aibaobei.user.controller.UserController.detail(UserController.java:18)

"http-nio-8080-exec-3" #30 daemon prio=5 os_prio=31 tid=0x00007fd08cb27000 nid=0x6203 waiting on condition [0x00007000032d8000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at java.lang.Thread.sleep(Thread.java:340)
	at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
	at com.aibaobei.user.controller.UserController.detail(UserController.java:18)

"http-nio-8080-exec-4" #31 daemon prio=5 os_prio=31 tid=0x00007fd08d0fa000 nid=0x6403 waiting on condition [0x00007000033db000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at java.lang.Thread.sleep(Thread.java:340)
	at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
	at com.aibaobei.user.controller.UserController.detail(UserController.java:18)

从上面的日志中可以看到UserController的第18行有多个线程被阻塞,说明这是一个阻塞点,这也是界面比较慢的原因。

4线程进入WAITING状态

对于这种情况来说,这是比较少见的情况,但是也是有可能的,而且由于它具有一定程度的“不可再现性”,所以我们在排查问题的时候很难发现。笔者也遇到过类似的情况。具体场景是,使用CountDownLatch时,每个并行任务完成后都需要唤醒主线程继续执行。当时我们使用CountDownLatch来控制多线程连接,导出用户的Gmail邮箱数据。其中一个线程连接到用户的邮箱,但该连接被服务器挂起,导致该线程等待服务器的响应。最终,我们的主线程和其他几个线程都处于 WAITING 状态。

       对于这样的问题,查看过jstack日志的读者应该都知道,正常情况下,线上大多数线程都是处于TIMED_WAITING状态,而我们这里出问题的线程所处的状态与其是一模一样的,这就非常容易混淆我们的判断。解决这个问题的思路主要如下:

  • 通过grep在jstack日志中找出所有的处于TIMED_WAITING状态的线程,将其导出到某个文件中,如a1.log,如下是一个导出的日志文件示例:

"Attach Listener" #13 daemon prio=9 os_prio=31 tid=0x00007fe690064000 nid=0xd07 waiting on condition [0x0000000000000000]
"DestroyJavaVM" #12 prio=5 os_prio=31 tid=0x00007fe690066000 nid=0x2603 waiting on condition [0x0000000000000000]
"Thread-0" #11 prio=5 os_prio=31 tid=0x00007fe690065000 nid=0x5a03 waiting on condition [0x0000700003ad4000]
"C1 CompilerThread3" #9 daemon prio=9 os_prio=31 tid=0x00007fe68c00a000 nid=0xa903 waiting on condition [0x0000000000000000]
  • 等待一段时间,比如10s,再次grep jstack日志,导出到另一个文件,比如a2.log。结果如下:

"DestroyJavaVM" #12 prio=5 os_prio=31 tid=0x00007fe690066000 nid=0x2603 waiting on condition [0x0000000000000000]
"Thread-0" #11 prio=5 os_prio=31 tid=0x00007fe690065000 nid=0x5a03 waiting on condition [0x0000700003ad4000]
"VM Periodic Task Thread" os_prio=31 tid=0x00007fe68d114000 nid=0xa803 waiting on condition
  • 重复步骤2。导出3~4个文件后,我们对导出的文件进行比较,找出这些文件中一直存在的用户线程。这个线程基本上可以确认它包含处于等待状态的文件。有问题的线程。因为正常的请求线程在20~30s后就不会处于等待状态了。

  • 检查完这些线程后,我们可以继续检查它们的堆栈信息。如果线程本身应该处于等待状态,比如用户创建的线程池中的空闲线程,那么这个线程的堆栈信息不会包含用户定义的类。这些都可以排除掉,剩下的线程基本上就可以确认是我们要找的有问题的线程了。通过它的堆栈信息,我们可以找出导致线程处于等待状态的代码在哪里。

       这里需要说明的是,我们在判断是否为用户线程时,可以通过线程最前面的线程名来判断,因为一般的框架的线程命名都是非常规范的,我们通过线程名就可以直接判断得出该线程是某些框架中的线程,这种线程基本上可以排除掉。而剩余的,比如上面的Thread-0,以及我们可以辨别的自定义线程名,这些都是我们需要排查的对象。

       经过上面的方式进行排查之后,我们基本上就可以得出这里的Thread-0就是我们要找的线程,通过查看其堆栈信息,我们就可以得到具体是在哪个位置导致其处于等待状态了。如下示例中则是在SyncTask的第8行导致该线程进入等待了。

"Thread-0" #11 prio=5 os_prio=31 tid=0x00007f9de08c7000 nid=0x5603 waiting on condition [0x0000700001f89000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
	at com.aibaobei.chapter2.eg4.SyncTask.lambda$main$0(SyncTask.java:8)
	at com.aibaobei.chapter2.eg4.SyncTask$$Lambda$1/1791741888.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)

5
僵局

对于死锁来说,这种情况基本上很容易发现,因为jstack可以帮助我们检查是否有死锁,并在日志中打印具体的死锁线程信息。以下是产生死锁的 jstack 日志示例:

图片

可以看到在jstack日志的最下面,它直接帮助我们分析日志中存在哪些死锁,以及每个死锁的线程堆栈信息。这里我们有两个用户线程互相等待对方释放锁,阻塞的位置都在ConnectTask的第5行。这时候我们就可以直接定位位置,进行代码分析,找到死锁的原因。原因。

6概括

本文主要讲解了网上可能出现的五种导致系统缓慢的情况,并详细分析了每种情况出现时的现象。根据这个现象,我们已经找到了定位该原因导致的系统缓慢的方法。简单来说,我们在进行在线日志分析时,可以分为以下几个步骤:

  • 通过top命令查看CPU情况,如果CPU比较高,则通过top -Hp <pid>命令查看当前进程的各个线程运行情况,找出CPU过高的线程之后,将其线程id转换为十六进制的表现形式,然后在jstack日志中查看该线程主要在进行的工作。这里又分为两种情况

    • 如果是普通用户线程,则利用该线程的堆栈信息来查看用户代码运行在哪里,比较消耗CPU;

    • 如果该线程是VM Thread,则通过jstat -gcutil <pid> <period> <times>命令监控当前系统的GC状况,然后通过jmap dump:format=b,file=<filepath> <pid>导出系统当前的内存数据。导出之后将内存情况放到eclipse的mat工具中进行分析即可得出内存中主要是什么对象比较消耗内存,进而可以处理相关代码;

  • 如果通过top命令看到CPU并不高,并且系统内存占用率也比较低。此时就可以考虑是否是由于另外三种情况导致的问题。具体的可以根据具体情况分析:

    • 如果是接口调用比较耗时,并且是不定时出现,则可以通过压测的方式加大阻塞点出现的频率,从而通过jstack查看堆栈信息,找到阻塞点;

    • 如果是某个功能突然出现停滞的状况,这种情况也无法复现,此时可以通过多次导出jstack日志的方式对比哪些用户线程是一直都处于等待状态,这些线程就是可能存在问题的线程;

    • 如果通过jstack可以查看到死锁状态,则可以检查产生死锁的两个线程的具体阻塞点,从而处理相应的问题。

本文主要提出导致上线功能缓慢的五个常见问题,以及排查思路。当然,网络问题的出现形式多种多样,并不一定仅限于这几种情况。如果我们能够仔细分析这些问题发生的场景,就可以根据具体情况进行分析,解决相应的问题。

https://mp.weixin.qq.com/s/ebVcV4N-Lw-vGyMZc9SNtg

. . .

相关推荐

额外说明

VS Code中将 “ .art “ 文件识别为 “ .html “ 文件

例如: 解决方法: (1) " ctrl+shift+p "打开搜索面板; (2)输入 " open settings (json) ";   (3)在 " settings.json "文件中添加代码: "files.associations": { 

额外说明

实战篇:Oracle 配置透明网关访问 MySQL 详细教程

前言 从 Oracle 无法直接访问 Mysql 数据库,需要配置透明网关后通过 DBLink 实现访问。 今天搞了一下午透明网关配置,流程比较复杂,并且有一些坑,这不立刻来给大家排排坑,说不定以后就用的着呢! 废话不多说,直接实战走起~ 一、环境准备

额外说明

【Unity3D日常开发】Unity3D中控制人物移动

一、前言 网上关于角色移动的文章太多太多了,就我自己整理的时候都发现写了好多篇(因为有不同的方案),今天就将目前已知的移动角色的方案总结出来,毕竟是一个资源整合的时代,谁也不想找个角色移动的脚本都要找好几篇文章对吧 目前可以划分为三个方面 角色移动到鼠标

额外说明

MySQL数据库设计:简单的大学教务系统数据库设计(入门向)

简单的教务系统数据库可以由如下六个表组成。下面给出了各个表格的主键与外键。 学生表 主键为学号,无外键 课程表 主键为课程编号,无外键 老师表 主键为教师工号,无外键 开课表 主键为教师工号、课程编号、学期(老师可以在不同学期开相同的课程)、课程班级(老

额外说明

从业务层的代码出发,去排查通用框架代码崩溃的问题

目录 1、问题说明 1.1、Release下崩溃,Debug下很难复现 1.2、用Windbg打开dump文件,发现崩溃在通用的框架代码中

额外说明

当AI遇到IoT:开启智能生活的无限可能

文章目录 1. AI和IoT的融合 1.1 什么是人工智能(AI)? 1.2 什么是物联网(IoT)? 1.3 AI和IoT的融合 2. 智能家居 2.1 智能家居安全 2.2 智能家居自动化 3. 医疗保健 3.1 远程监护 3.2 个性化医疗 4.

额外说明

MySQL数据库迁移:拷贝data目录

其实迁移数据库,一般用sql文件就行,把A服务器数据库的表结构和数据等等导出,然后导入到B服务器数据库, 但是这次数据文件过大,大约有40个G,使用命令行导入,效果不是很好,经常在执行过程中报错、卡死。 最后参考网上的帖子,复制源数据库的data目录下的

额外说明

Vue2 改变列表排序:上移,下移,置顶,置底

概述 技术上使用 Vue2、 ElementUI。对列表做上移,下移,置顶,置底等操作。 效果 实现 HML <template> <div> <div class="rows" v-for="(item,index) in ro

额外说明

SpringBoot设置允许跨域请求

跨域 一个资源会发起一个跨域HTTP请求(Cross-site HTTP request), 当它请求的一个资源是从一个与它本身提供的第一个资源的不同的域名时 。比如说,域名A(http://domaina.example)的某 Web 应用程序中通过标

额外说明

Kubernetes安装Mysql集群

Kubernetes安装Mysql集群 默认已配置好kubernetes与storageClass(本文使用directpv-min-io) 文章部署未使用helm和operator,慎用 kubernetes1.25 mysql5.7 1、namsSp

ads via 小工具