Java常见的性能问题和排查

CPU占满,内存泄露,死锁等问题

Posted by Haiming on April 29, 2020

参考文章:https://mp.weixin.qq.com/s/fcYbt3wUhcZlBeZy0RfgGQ

本文主要梳理四种情况:CPU 100%,内存泄露OOM,死锁——无法创建新线程和线程频繁切换导致系统性能下降。

0. 工具梳理

0.1 top

top命令是我们最常用的Linux命令之一,它可以实时的显示当前正在执行的进程的CPU使用率,内存使用率等系统信息。top -Hp pid 可以查看线程的系统资源使用情况。

基本上第一步都是top先,之后找到进程id再做打算。

0.2 vmstat

是在OS之中观察OS的周期和采集次数的虚拟内存检测工具。可以统计内存,CPU,swap等等的使用情况。

在我们本文之中主要是用来看进程的上下文切换。

  • r: 运行队列中进程数量(当数量大于CPU核数表示有阻塞的线程)
  • b: 等待IO的进程数量
  • swpd: 使用虚拟内存大小
  • free: 空闲物理内存大小
  • buff: 用作缓冲的内存大小(内存和硬盘的缓冲区)
  • cache: 用作缓存的内存大小(CPU和内存之间的缓冲区)
  • si: 每秒从交换区写到内存的大小,由磁盘调入内存
  • so: 每秒写入交换区的内存大小,由内存调入磁盘
  • bi: 每秒读取的块数
  • bo: 每秒写入的块数
  • in: 每秒中断数,包括时钟中断。
  • cs: 每秒上下文切换数。
  • us: 用户进程执行时间百分比(user time)
  • sy: 内核系统进程执行时间百分比(system time)
  • wa: IO等待时间百分比
  • id: 空闲时间百分比

0.3 pidstat

我们上面提到了两个:top和vmstat,都是检测进程的内存,CPU,I/O等等。但是pidstat的粒度更细,可以检测到线程级别。pidstat命令字段:

  • UID :被监控任务的真实用户ID。
  • TGID :线程组ID。
  • TID:线程ID。
  • cswch/s:主动切换上下文次数,这里是因为资源阻塞而切换线程,比如锁等待等情况。
  • nvcswch/s:被动切换上下文次数,这里指CPU调度切换了线程。

0.4 jstack

分析线程的堆栈,最常用的是jstack pid来查看线程的堆栈信息,也经常排除死锁情况。

0.5 jstat

检测java运行的实时情况,包括堆内存信息和GC信息。常用来看GC的情况。

0.6 MAT内存工具

MAT(Memory Analyzer Tool)工具是eclipse的一个插件(MAT也可以单独使用),它分析大内存的dump文件时,可以非常直观的看到各个对象在堆空间中所占用的内存大小、类实例数量、对象引用关系、利用OQL对象查询,以及可以很方便的找出对象GC Roots的相关信息。

idea中也有这么一个插件,就是JProfiler

1. CPU占满

直接写一个死循环:

/**
     * 模拟CPU占满
     */
    @GetMapping("/cpu/loop")
    public void testCPULoop() throws InterruptedException {
        System.out.println("请求cpu死循环");
        Thread.currentThread().setName("loop-thread-cpu");
        int num = 0;
        while (true) {
            num++;
            if (num == Integer.MAX_VALUE) {
                System.out.println("reset");
            }
            num = 0;
        }

    }

怎么处理?

先top看Java的进程id:pid是哪个,然后再使用 top -Hp pid来查看相应的Java线程情况。找到使用率最高的CPU(比如99.9%)的pid——此处为线程号。之后再将其转换成16进制,执行jstack 进程id | grep -A 20 16进制的线程id得到dump信息,其可以定位到代码行,就定位出了CPU占满的问题。

2. 内存泄露——OOM

其借助了ThreadLocal来完成模拟过程。因为ThreadLocal是使用Thread之中的ThreadLocalMap实现的,我们一般使用线程池,可能一个线程会存在很久。ThreadLocalMap的Entry继承的是WeakReference,而Entry的Key是WeakReference的封装:

    static class ThreadLocalMap {

        /**
         * The entries in this hash map extend WeakReference, using
         * its main ref field as the key (which is always a
         * ThreadLocal object).  Note that null keys (i.e. entry.get()
         * == null) mean that the key is no longer referenced, so the
         * entry can be expunged from table.  Such entries are referred to
         * as "stale entries" in the code that follows.
         */
        static class Entry extends WeakReference<ThreadLocal<?>> {
            /** The value associated with this ThreadLocal. */
            Object value;

            Entry(ThreadLocal<?> k, Object v) {
                super(k);
                value = v;
            }
        }

那么每次GC的时候,都会被回收。如果ThreadLocal在set之后不进行后续的操作,那么GC就会将key清除掉,但是Value因为线程还存活,所以Value一直存在,直到最后OOM。

上面讲到了,这个问题出在GC上面,那么如何看GC?就是jstat。启动时候我们可以选择保存堆dump文件,将这个文件直接导出到MAT工具,就能看到谁用了最大的内存,其GCRoot是什么,最大的内存块在哪等等。

3. 死锁

死锁的话就是内存占用升高,CPU不一定有影响。但是如果直接new线程,会报无法创建线程的错误。这里也体现了一点线程池的好处——毕竟还有拒绝策略。

直接通过ps -ef | grep java来找到java的进程pid,执行jstack pid就可出现java的堆栈信息。直接看死锁情况,比如

Java stack information for the threads listed above:
===================================================
"pool-1-thread-2":
        at top.luozhou.analysisdemo.controller.DeadLockThread2.run(DeadLockThread.java:30)
        - waiting to lock <0x00000000f8387d98> (a java.lang.Object)
        - locked <0x00000000f8387d88> (a java.lang.Object)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
"pool-1-thread-1":
        at top.luozhou.analysisdemo.controller.DeadLockThread1.run(DeadLockThread.java:30)
        - waiting to lock <0x00000000f8387d88> (a java.lang.Object)
        - locked <0x00000000f8387d98> (a java.lang.Object)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
          
 Found 5 deadlocks

4. 线程频繁切换

上下文切换会导致CPU将大量的时间浪费在线程的保存和恢复上面,那么系统的整体性能就会下降。当发现系统的性能明显下降的时候,要考虑是否发生了大量的线程切换。

 @GetMapping(value = "/thread/swap")
    public String theadSwap(int num) {
        System.out.println("模拟线程切换");
        for (int i = 0; i < num; i++) {
            new Thread(new ThreadSwap1(new AtomicInteger(0)),"thread-swap"+i).start();
        }
        return "ok";
    }
public class ThreadSwap1 implements Runnable {
    private AtomicInteger integer;

    public ThreadSwap1(AtomicInteger integer) {
        this.integer = integer;
    }

    @Override
    public void run() {
        while (true) {
            integer.addAndGet(1);
            Thread.yield(); //让出CPU资源
        }
    }
}

这里创建多个线程取执行基础的原子+1,然后就去让出CPU资源。

多次请求之后看vmstat 1 10

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
101  0 128000 878384    908 468684    0    0     0     0 4071 8110498 14 86  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4065 8312463 15 85  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4107 8207718 14 87  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4083 8410174 14 86  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4083 8264377 14 86  0  0  0
100  0 128000 878384    908 468688    0    0     0   108 4182 8346826 14 86  0  0  0
  1. r: 等待的进程数量,100,有阻塞
  2. cs=800多万,每秒进程切换了800万次
  3. us=14,用户态占用了14%时间片
  4. sy=86,内核态占用了86%时间片

先top之后发现java进程将CPU吃满了,那么再top -Hp pid来得到相应的线程的情况。发现线程的CPU使用蛮平均,没有一个将CPU吃满的情况。

那么就要进入线程内部排查了:

直接执行pidstat,可以得到数据:

11:04:30 PM   UID       TGID       TID   cswch/s nvcswch/s  Command
11:04:30 PM     0         -     87128      0.00     16.07  |__java
11:04:30 PM     0         -     87129      0.00     15.60  |__java
11:04:30 PM     0         -     87130      0.00     15.54  |__java
11:04:30 PM     0         -     87131      0.00     15.60  |__java
11:04:30 PM     0         -     87132      0.00     15.43  |__java
11:04:30 PM     0         -     87133      0.00     16.02  |__java
11:04:30 PM     0         -     87134      0.00     15.66  |__java
11:04:30 PM     0         -     87135      0.00     15.23  |__java
11:04:30 PM     0         -     87136      0.00     15.33  |__java
11:04:30 PM     0         -     87137      0.00     16.04  |__java

那么可以看到,java的线程每秒切换15次左右,正常情况应该是个位甚至小数,所以可以断定是线程开启过多,导致频繁上下文切换,最终影响了整体性能。