while循环cpu占用高排查和优化,线上linux系统故障

2019-10-02 20:53栏目:网络编程
TAG:

Java 自带性能分析工具

命令行工具的功能都很强大,像jmap、jstat、jstack、jps这些,功能和一些收费软件差不多,但是没有GUI看起来就有些费劲。由于使用Windows分析就使用自带的Jmc来用了,只要在命令行输入jmc就可以启动。

图片 1jmc示例图

原文出处: 飒然Hang

《线上linux系统故障排查之一:CPU使用率过高》
《线上linux系统故障排查之二:内存占用过高》

cpu占用排查

由于已经知道cpu占用原因,这里就直接给出错误的示例。如果在服务器上排查需要结合上述命令行工具,具体使用可以参考这里。

  • 错误示例
public class TestCpu { public static void main(String[] args) throws InterruptedException { TaskThread thread = new TaskThread(); thread.setName("Test Cpu"); thread.start(); // 为了让程序不退出,这里休眠一个较长时间 // sleep 在执行后基本不产生性能损耗 Thread.sleep; }}class TaskThread extends Thread { // 由于while循环占用锁导致变量无法观测到变化,可以使用volatile解决,也可以使用并发包下的集合解决 private volatile Queue<Runnable> tasks = new ArrayDeque<>(); public synchronized void add(Runnable runnable) { tasks.add; } @Override public void run() { while  { while (!tasks.isEmpty { Runnable runnable = tasks.remove(); runnable.run(); } } }}

上述代码在运行又占用cpu稳定在15%左右,机器配置为I7 4核8G

  • 使用jcm分析性能消耗先使用飞行记录器记录一段时间的运行情况

    图片 2飞行记录器图片 3线程可以看到测试线程基本占用了所有资源(实际服务器上业务逻辑相对复杂,占有率一般不会占这么高)。但是代码实际只是判断了一个集合是否为空,为什么CPU占用会这么高呢?原因可以参考这里简单解释就是在Windows上如果一个进程得到了 CPU 时间,除非它自己放弃使用 CPU ,否则将完全霸占 CPU。在Linux上相对好一点,因为时基于时间片算法的。在知道原因后就比较好办了,解决方法无非就是在不需要执行无谓的循环的时把CPU释放出来。最简单的做法就是在while循环种调用Thread.sleep方法释放CPU的占用。但这样存在频繁的切换线程调度的问题。

  • 使用wait和notify阻塞和唤醒线程wait和notify的原理可以参考这里。对TaskThread修改代码如下,配合这2个方法可以保证在线程空闲时处于一个挂起状态,CPU占用在空闲时也基本为0了。

class TaskThread extends Thread { private final Deque<Runnable> tasks = new ArrayDeque<>(); public void add(Runnable runnable) { synchronized  { tasks.add; if (tasks.pollFirst() == runnable) { tasks.notify(); } } } @Override public void run() { try { while  { synchronized  { if (tasks.isEmpty { tasks.wait(); } } while (!tasks.isEmpty { Runnable runnable = tasks.remove(); runnable.run(); } } } catch (InterruptedException e) { e.printStackTrace(); } }}

最近看到了大量关于java性能调优、故障排查的文章,自己也写了一篇Java调优经验谈。接着此篇文章,其实一直打算写写一些常用调优工具以及它们的惯常用法的。后来在http://java-performance.info这个站点上看到了类似的一篇博文,自我感觉很有指导意义。于是决定翻译+重组织一下此篇文章:Java server application troubleshooting using JDK tools。

一个应用占用CPU很高,除了确实是计算密集型应用之外,通常原因都是出现了死循环。
下面我们将一步步定位问题,详尽的介绍每一步骤的相关知识。

引言

在Java世界中,我们的很多开发工作从编码、调试到调优都在使用GUI工具。我们经常尝试在本地构建一套和线上一样的环境从而使得问题能够重现,进而使用我们常用的工具来排查定位故障。但不幸的是,很多情况下是无法在本地重现线上问题的。例如,我们没有权限获取真实客户端提交到线上服务端的数据。

由此,很多时候都是需要远程来排查线上服务器上发生的问题。但是如果单单只有一个JRE的话,你也不可能有合适的办法来进行排查。你需要JDK或者第三方的工具。有时候使用JDK提供的工具就是最可取的方案,毕竟,在线上环境使用第三方工具有时候会牵扯到权限的问题。

一般情况下,在线上环境安装JDK发布版本可以让排查进行地更高效。建议安装使用最新的Java7/8 JDK或者构建与线上JRE匹配的一些工具(原文作者不建议安装jdk的发布版本,而是建议根据实际需求逐渐地安装其中的工具)。

一、通过top命令定位占用cpu高的进程

执行top命令得到以下结果:

图片 4

top命令执行结果

通过上图可以明显看出进程PID41843占用cpu过高,明显存在问题,定位到了进程id。当然如果你想只观察进程PID41843的CPU和内存以及负载情况,可以使用以下命令

top -p 41843。

结果如下:

图片 5

top -p 41843命令执行结果

这里顺便解释下上图各个参数的意义,有利于读者更好的排查问题。

  1. 第一行是任务队列信息
    top - 14:06:34 up 537 days, 6 min, 6 users, load average: 0.41, 0.45, 0.43
任务队列信息 含义
14:06:34 当前时间
537 days 系统运行时间
6 min 用户在线时间
6 users 在线用户数
load average: 0.41, 0.45, 0.43 系统负载,即任务队列的平均长度。1分钟前、5分钟前、15分钟前平均负载

2)第二行为进程的信息

进程信息 含义
Tasks: 1 total 进程总数
0 running 正在运行的进程数
1 sleeping 睡眠的进程数
0 stopped 停止的进程数
0 zombie 僵尸进程数
  1. 第三行为cpu信息
cpu信息 含义
6.1% us 用户空间占用CPU百分比
1.5% sy 内核空间占用CPU百分比
0.0% ni 用户进程空间内改变过优先级的进程占用CPU百分比
92.2% id 空闲CPU百分比
0.0% wa 等待输入输出的CPU时间百分比
0.0% hi 硬件中断
0.0% si 软件中断
0.0%st 实时
  1. 第四、五行为内存信息。
    内容如下:
物理内存信息 含义
Mem: 191272k total 物理内存总量
173656k used 使用的物理内存总量
17616k free 空闲内存总量
22052k buffers 用作内核缓存的内存量
交换区信息 含义
Swap: 192772k total 交换区总量
0k used 使用的交换区总量
192772k free 空闲交换区总量
123988k cached 缓冲的交换区总量

问题排查场景

二、通过top命令定位问题进程中每个线程占用cpu情况

通过问题进程中每个线程占用cpu情况使用可以使用如下命令:

top -p 41843 -H

查看进程PID41843的每一个线程占用CPU情况,如图。

图片 6

top -p 41843 -H的执行结果

由上图明显可以发现,线程PID41892CPU占用率最高,接下来定位该线程的代码是否出现异常导致cpu占用过高。

获取正在运行的JVM列表

为了开始排查工作,我们首先需要获取正在运行的jvm进程列表,包括进程id、命令行参数等。有时候仅仅这一步就可以定位到问题,例如,同样的app实例被重复启动在并发做同样的事情(破坏输出文件、重新打开sockets或者其他愚蠢的事情)。

使用jcmd不加任何参数即可获取jvm进程列表

25691 org.apache.catalina.startup.Bootstrap start
20730 org.apache.catalina.startup.Bootstrap start
26828 sun.tools.jcmd.JCmd
3883 org.apache.catalina.startup.Bootstrap start

使用jcmd help能够获取某个jvm进程其他可用的诊断命令。例如:

[root@test-172-16-0-34-ip ~]# jcmd 3883 help
3883:
The following commands are available:
VM.commercial_features
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
Thread.print
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version
help

输入jcmd 可以运行一个诊断命令或者获取到参数错误信息。

[root@test-172-16-0-34-ip ~]# jcmd 3883 GC.heap_dump
3883:
java.lang.IllegalArgumentException: Missing argument for diagnostic command

通过jcmd help 你能够获取此诊断命令更多的信息。如下是GC.heap_dump命令的help。

[root@test-172-16-0-34-ip ~]# jcmd 3883 help GC.heap_dump
3883:
GC.heap_dump
Generate a HPROF format dump of the Java heap.

Impact: High: Depends on Java heap size and content. Request a full GC unless the '-all' option is specified.

Syntax : GC.heap_dump [options] <filename>

Arguments:
    filename :  Name of the dump file (STRING, no default value)

Options: (options must be specified using the <key> or <key>=<value> syntax)
    -all : [optional] Dump all objects, including unreachable objects (BOOLEAN, false)

三、通过jstack 命令定位问题代码

上一步发现PID41892占用的CPU过高,就将这个PID转换成16进制,易知,PID41892转化成16进制为a3a4。使用如下命令命令定位问题代码:

jstack 41892 | grep a3a4

输出如下:

"Thread" prio=10 tid=0x00007f950043e000 nid=0x54ee in test();

可以分析得到: 线程Thread下的wait()函数cpu使用率很高,查看源代码中的test()函数代码如下:

public void test(){
  while(true){
     for(int i = 0 ;i<100;i++);
  }
}

while循环无法结束,一直抢占cpu,导致程序cpu使用过高,修改代码即可。
到此为止,因为代码问题导致的cpu使用过高的故障排查方法就介绍完了。

tips:由于内存的原因,频繁的GC,也可能导致cpu使用过高,内存的解决方案在文章《线上linux系统故障排查之二:内存占用过高》中介绍。

Java堆的DUMP

jcmd提供了输出HPROF格式的堆dump接口。运行jmcd GC.heap_dump 即可。注意这里的FILENAME是相对于运行中的jvm目录来说的,因此避免找不到dump的文件,这里推荐使用绝对路径。此外,也建议使用.hprof作为输出文件的扩展名。

在堆dump完成之后,你可以复制此文件到本地用VisualVM或者用jmc的JOverflow插件打开,进而通过分析堆的状况定位内存问题。

需要注意的两点:

  • 还有很多可以打开hprof文件进行分析的工具:NetBeans, Elipse的MAT,jhat等等。用你最熟悉的即可。
  • 同样可以使用jmap -dump:live,file= 来产生堆dump文件,但是官方文档标注了此工具为unsupported的。虽然我们绝大多数人都会认为JDK中unsupported的特性会永远存在,但是事实并非这样:JEP 240, JEP 241。

四、终极大杀器

笔者是喜欢一、二、三步骤定位cpu使用率过高的问题,但是如果读者觉得以上方法不喜欢或者以上无法定位问题时,可以使用jstack方法获取进程PID41843包含的运行线程的所有状态。使用如下命令:

jstack -l 41843
或者将结果输入在dump.txt文档中:jstack -l 41843 >> dump.txt

首先我们来介绍下,Jstack的输出中,Java线程状态的四种状态的概念:

RUNNABLE 线程运行中或I/O等待
BLOCKED 线程在等待monitor锁(synchronized关键字)
TIMED_WAITING 线程在等待唤醒,但设置了时限
WAITING 线程在无限等待唤醒

接下来用简单的代码模拟这4种状态的发生,同时介绍下问题的排查方法。
1) 让线程一直处于RUNNABLE状态

public static void main(String[] args) {
    printPId();//打印进程id

    runnable();//模拟RUNNABLE状态方法,第14行
}

public static void runnable(){//第19行
    int i = 0;
    while (true) {
        i++;
    }
}

public static void printPId() {
    String name = ManagementFactory.getRuntimeMXBean().getName();
    System.out.println(name.split("@")[0]);
}

执行main函数,使用命令jstack -l PID(pid为printPId函数打印的值),得到以下输出信息:状态为RUNNABLE,程序在Test类的runnable()方法中占用cpu,一般该状态不会出现问题。但是如果多次执行该命令,发现cpu在持续执行该方法,且cpu使用过高,可以排查runnable()方法是否存在死循环等持续占用cpu的情况。

"main" #1 prio=5 os_prio=0 tid=0x00000000023fe000 nid=0x2ab8 runnable [0x0000000
0026df000]
java.lang.Thread.State: RUNNABLE
at Test.runnable(Test.java:19)
at Test.main(Test.java:14)

Locked ownable synchronizers:
-None

2) 让线程一直处于BLOCKED状态(重点关注)

public static void main(String[] args) {
    printPId();//打印进程id

    blocked();//模拟BLOCKED状态方法,第16行
}

public static void blocked(){
    Integer lock = 0;
    new Thread() {
        public void run() {
            synchronized (lock) {
                try {
                    Thread.sleep(1000 * 1000);//26行
                } catch (Exception e) {
                    e.printStackTrace();
                }
            }
        }
    }.start();

    try { Thread.sleep(100); } catch (Exception e) {e.printStackTrace();}

    synchronized (lock) {
        try {
            Thread.sleep(10 * 1000);//第37行
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

public static void printPId() {
    String name = ManagementFactory.getRuntimeMXBean().getName();
    System.out.println(name.split("@")[0]);
}

主线程sleep,先让另外一个线程拿到lock,并长期持有lock(sleep会持有锁,wait不会)。此时主线程会BLOCK住等待lock被释放,此时jstack的输出可以看到main线程状态是BLOCKED。
根据以下输出可以看出:
1)线程状态是 Blocked,阻塞状态。说明线程等待资源超时!
2)“ waiting to lock <0x00000000d6f7a970>”,指该地址被占用了,线程在等待给这个 0x00000000d6f7a970地址上锁。
3)在 dump 日志里查找字符串 0x00000000d6f7a970,如果发现有大量线程都在等待给这个地址上锁。则存在问题。继续查找字符串0x00000000d6f7a970,发现locked <0x00000000d6f7a970> (a java.lang.Integer)给地址上锁,却未释放,查找该出代码问题。
4)“waiting for monitor entry”说明此线程通过 synchronized(obj) {……} 申请进入了临界区。
5)第一行里,"main"是 Thread Name 。tid指Java Thread id。nid指native线程的id。prio是线程优先级。[0x00000000027af000]是线程栈起始地址。

"main" #1 prio=5 os_prio=0 tid=0x000000000244e000 nid=0x2218 waiting for monitor
entry [0x00000000027af000]
java.lang.Thread.State: BLOCKED (on object monitor)
at Test.blocked(Test.java:37)
-waiting to lock <0x00000000d6f7a970> (a java.lang.Integer)
at Test.main(Test.java:16)

Locked ownable synchronizers:
-None

"Thread-0" #10 prio=5 os_prio=0 tid=0x0000000058893800 nid=0x1cc8 waiting on con
dition [0x00000000599ae000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at Test$1.run(Test.java:26)
-locked <0x00000000d6f7a970> (a java.lang.Integer)

Locked ownable synchronizers:
-None

3) 让线程处于TIMED_WAITING状态

public static void main(String[] args) {
   printPId();//打印进程id

   timedWaiting();//模拟TIMED_WAITING状态方法
}

public static void timedWaiting() {
    Integer lock = 0;
    synchronized (lock) {
       try {
           lock.wait(100 * 1000);
       } catch (Exception e) {
           e.printStackTrace();
       }
   }
}

public static void printPId() {
   String name = ManagementFactory.getRuntimeMXBean().getName();
   System.out.println(name.split("@")[0]);
}

根据以下输出可以看出:
1)“TIMED_WAITING ”中的 timed_waiting 指等待状态,但这里指定了时间,到达指定的时间后自动退出等待状态。

"main" #1 prio=5 os_prio=0 tid=0x0000000001c1e000 nid=0x1c78 in Object.wait() [0
x000000000272f000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
-waiting on <0x00000000d6f7a970> (a java.lang.Integer)
at Test.timedWaiting(Test.java:25)
-locked <0x00000000d6f7a970> (a java.lang.Integer)
at Test.main(Test.java:18)

Locked ownable synchronizers:
-None

4) 让线程处于WAITING状态状态

public static void main(String[] args) {
  printPId();//打印进程id

  waiting();//模拟waiting状态方法
}

public static void waiting() {
  Integer lock = 0;
  synchronized (lock) {
      try {
          lock.wait();
      } catch (Exception e) {
          e.printStackTrace();
      }
  }
}

public static void printPId() {
  String name = ManagementFactory.getRuntimeMXBean().getName();
  System.out.println(name.split("@")[0]);
}

无超时的等待,必须等待lock.notify()或lock.notifyAll()或接收到interrupt信号才能退出等待状态。同理,ReentrantLock.lock()的无参方法调用,也会使线程状态变成WAITING。

"main" #1 prio=5 os_prio=0 tid=0x00000000024ce000 nid=0x2b14 in Object.wait() [0
x00000000025ef000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
-waiting on <0x00000000d6f7a970> (a java.lang.Integer)
at java.lang.Object.wait(Unknown Source)
at Test.waiting(Test.java:27)
-locked <0x00000000d6f7a970> (a java.lang.Integer)
at Test.main(Test.java:20)

Locked ownable synchronizers:
-None

掌握各个线程的状态和信息,将无往而不利~~

分析类柱状图

如果正在排查内存泄漏问题,你可能想要知道堆中某种类型的存活对象数目。例如,某一时刻某些类应该只有一个实例(单例模式),但是此类的另外一个或者多个实例却已经到了老年代,但是事实上它们不应该能够被GC roots访问到。

运行以下命令可以打印出类柱状图(同时也打印出存活对象的数目):

jcmd <PID> GC.class_histogram
jmap -histo:live <PID>

输出如下:

    num     #instances         #bytes  class name
----------------------------------------------
   1:         37083       48318152  [B
   2:        235781       22496784  [C
   3:        103958       16069448  <constMethodKlass>
   4:        482361       15435552  java.util.HashMap$Entry
   5:        103958       14152480  <methodKlass>
   6:          9576       11192168  <constantPoolKlass>
   7:        186264       10430784  com.mysql.jdbc.ConnectionPropertiesImpl$BooleanConnectionProperty
   8:        274109        8771488  java.util.Hashtable$Entry
   9:          9576        7210152  <instanceKlassKlass>
  10:          7972        6404256  <constantPoolCacheKlass>
  11:        229637        5511288  java.lang.String
  12:         48471        5428752  java.net.SocksSocketImpl
  13:         21599        3859672  [Ljava.util.HashMap$Entry;

这里的以byte为单位的占用大小是浅尺寸(shallow size),并没有包括子对象的大小。其实这个事实很容易由char[]和String的统计数据注意到:这俩的实例数目是差不多的,但是char[]的占用大小要大很多,就是因为String并未包含下面的char[]的大小。

有了类柱状图信息,你就可以grep/search类的名字从而获取存活实例的数目。如果你发现某些类的实例数量比期望要大很多,你就可以做heap dump,然后用任意的heap分析工具来分析问题。

线程Dump

很多时候,应用会呈现出“卡在那里”的情形。这里有很多种卡住的状况:死锁、cpu密集运算。为了定位到问题所在需要知道线程在做什么、持有了什么锁等等。

Java中有两种锁:基于sychronized和Object.wait/notifyAll方法的原始锁以及java5引入的java.util.concurrent锁。这俩种锁的不同之处主要在于前者是限制在进入synchronized部分的地方的栈帧(stack frame)中的,并且会一直在线程dump中存在。后者却并不限制在栈帧中,你可以在一个方法中进入锁,在另一方法中解锁。因此,thread dump有时候并没有包含这些信息。尽管如此,还是应该使用thread dump来查看线程信息排查问题。

这里有三种方法可以打印应用的thread dump。

kill -3 <PID> #仅限Linux平台
jstack <PID>
jcmd <PID> Thread.print

运行Java飞行记录器(Java Flight Recorder)

上面讲到的工具都是作为快速的查看诊断工具的。如果要深入分析问题,可以选择使用内置的Java飞行记录器:Java Mission Control。

运行JFR需要三步:

  1. 创建一个包含了你自己配置的JFR模板文件。运行jmc, 然后Window->Flight Recording Template Manage菜单。准备好档案后,就可以导出文件,并移动到要排查问题的环境中。
  2. 由于JFR需要JDK的商业证书,这一步需要解锁jdk的商业特性。

     jcmd <PID> VM.unlock_commercial_features
    
  3. 最后你就可以启动JFR。

    jcmd <PID> JFR.start name=test duration=60s settings=template.jfc filename=output.jfr
    

    上述命令立即启动JFR并开始使用templayte.jfc的配置收集60s的JVM信息,输出到output.jfr中。

一旦记录完成之后,就可以复制.jfr文件到你的工作环境使用jmc GUI来分析。它几乎包含了排查jvm问题需要的所有信息,包括堆dump时的异常信息。

后记

本文基本上是对英文原文的翻译,主要描述了几个常见问题的排查场景。

不得不说的是,JDK自带的工具是非常强大的。用好了这些工具其实已经足以应付绝大多数的Java问题排查场景。

版权声明:本文由澳门新葡亰平台游戏发布于网络编程,转载请注明出处:while循环cpu占用高排查和优化,线上linux系统故障