java中WAITING状态的线程为啥还会消耗CPU

时间  2021-08-14
标签 java node 正则表达式 api bash 服务器 markdown 并发 app 框架 栏目 Java 繁體版
原文   原文链接

背景

刚刚过去的双十一, 公司订单量又翻了一倍. 就在老板坐在办公室里面偷偷笑的同时,坐在工位上的咱们倒是一直瑟瑟发抖. 面对zabbix里面时不时蹦出来的一条条CPU告警,默默地祈祷着不要出问题.java

固然, 祈祷是解决不了问题的, 即便是开过光的服务器也不行. CPU告警了, 还得老老实实地去看为啥CPU飚起来了.node

接下来就是CPU排查三部曲正则表达式

1. top -Hp $pid 找到最耗CPU的线程. 
2. 将最耗CPU的线程ID转成16进制
3. 打印jstack, 到jstack里面查这个线程在干吗
复制代码

固然 若是你线上环境有装arthas等工具的话, 直接thread -n就能够打印出最耗cpu的n个线程的堆栈,三个步骤一块儿帮你作了.api

最后找到最耗cpu的线程堆栈以下:bash

"operate-api-1-thread-6" #1522 prio=5 os_prio=0 tid=0x00007f4b7006f800 nid=0x1b67c waiting on condition [0x00007f4ac8c4a000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c10828c8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
	at ch.qos.logback.classic.Logger.info(Logger.java:579)
	...

复制代码

值得一提的是, 相似的线程还有800多个... 只是部分没有消耗CPU而已服务器

问题

很明显, 这是由于logback打印日志太多了形成的(此时应有一个尴尬而不失礼貌的假笑).markdown

当你们都纷纷转向讨论接下来如何优化logback和打日志的时候. 我却眉头一皱, 以为事情并无那么简单:并发

这个线程不是被LockSupport.park挂起了, 处于WAITING状态吗? 被挂起即表明放弃占用CPU了, 那为啥还会消耗CPU呢?app

来看一下LockSupport.park的注释, 明确提到park的线程不会再被CPU调度了的:框架

/**
     * Disables the current thread for thread scheduling purposes unless the
     * permit is available.
     *
     * <p>If the permit is available then it is consumed and the call
     * returns immediately; otherwise the current thread becomes disabled
     * for thread scheduling purposes and lies dormant until one of three
     * things happens:
     *
     */
    public static void park() {
        UNSAFE.park(false, 0L);
    }
复制代码

实验见真知

带着这个疑问, 我在stackoverflow搜索了一波, 发现还有很多人有这个疑问

  1. stackoverflow.com/questions/1…

  2. stackoverflow.com/questions/5…

  3. stackoverflow.com/questions/1…

  4. stackoverflow.com/questions/3…

  5. stackoverflow.com/questions/5…

上面好几个问题内容有点多, 我也懒得翻译了, 直接总结结论:

1. 处于waittig和blocked状态的线程都不会消耗CPU
2. 线程频繁地挂起和唤醒须要消耗CPU, 并且代价颇大
复制代码

但这是别人的结论, 究竟是不是这样的呢. 下面咱们结合visualvm来作一下实验.

有问题的代码

首先来看一段确定会消耗100%CPU的代码:

package com.test;

public class TestCpu {
    public static void main(String[] args) {
         while(true){

         }
    }
}
复制代码

visualvm显示CPU确实消耗了1个核, main线程也是占用了100%的CPU:

image

image

被park的线程

而后来看一下park的线程是否会消耗cpu

代码:

import java.util.concurrent.locks.LockSupport;

public class TestCpu {
    public static void main(String[] args) {
        while(true){
            LockSupport.park();
        }
    }
}
复制代码

visualvm显示一切波澜不惊,CPU毫无压力 :

image

image

发生死锁的线程

再来看看blocked的线程是否消耗CPU. 并且咱们此次玩大一点, 看看出现了死锁的话,会不会形成CPU飙高.(死锁就是两个线程互相block对方)

死锁代码以下:

package com.test;

public class DeadLock {

    static Object lock1 = new Object();
    static Object lock2 = new Object();

    public static class Task1 implements Runnable {

        @Override
        public void run() {
            synchronized (lock1) {
                System.out.println(Thread.currentThread().getName() + " 得到了第一把锁!!");
                try {
                    Thread.sleep(50);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (lock2) {
                    System.out.println(Thread.currentThread().getName() + " 得到了第二把锁!!");
                }
            }
        }
    }

    public static class Task2 implements Runnable {

        @Override
        public void run() {
            synchronized (lock2) {
                System.out.println(Thread.currentThread().getName() + " 得到了第二把锁!!");
                synchronized (lock1) {
                    System.out.println(Thread.currentThread().getName() + " 得到了第一把锁!!");
                }
            }
        }
    }

    public static void main(String[] args) throws InterruptedException {
        Thread thread1 = new Thread(new Task1(), "task-1");
        Thread thread2 = new Thread(new Task2(), "task-2");
        thread1.start();
        thread2.start();

        thread1.join();
        thread2.join();
        System.out.println(Thread.currentThread().getName() + " 执行结束!");
    }
}
复制代码

image

image

image

也是能够看到虽然visualVm能检测到了死锁, 可是整个JVM消耗的CPU并无什么大的起伏的. 也就是说就算是出现了死锁,理论上也不会影响到系统CPU.

固然,虽然死锁不会影响到CPU, 可是一个系统的资源并不仅有CPU这一种, 死锁的出现仍是有可能致使某种资源的耗尽,而最终致使服务不可用, 因此死锁仍是要避免的.

频繁切换线程上下文的场景

最后, 来看看大量线程切换是否会影响到JVM的CPU.

咱们先生成数2000个线程, 利用jdk提供的LockSupport.park()不断挂起这些线程. 再使用LockSupport.unpark(t)不断地唤醒这些线程. 唤醒以后又立马挂起. 以此达到不断切换线程的目的.

代码以下:

package com.test;

import java.util.ArrayList;
import java.util.List;
import java.util.Random;
import java.util.concurrent.locks.LockSupport;

public class TestCpu {
    public static void main(String[] args) {
        int  threadCount = 2000;
        if(args.length > 0){
            threadCount = Integer.parseInt(args[0].trim());
        }
        final List<Thread> list = new ArrayList<>(threadCount);

        // 启动threadCount个线程, 不断地park/unpark, 来表示线程间的切换
        for(int i =0; i<threadCount; i++){
            Thread thread = new Thread(()->{
                while(true){
                    LockSupport.park();
                    System.out.println(Thread.currentThread() +" was unpark");
                }
            });
            thread.setName("cpuThread" + i);
            list.add(thread);
            thread.start();
        }

        // 随机地unpark某个线程
        while(true){
            int i = new Random().nextInt(threadCount);
            Thread t = list.get(i);
            if(t != null){
                LockSupport.unpark(t);
            }
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }finally {
            }
        }
    }
}

复制代码

再观察visualVm, 发现整个JVM的CPU的确开始升高了, 可是具体到线程级别, 会发现每一个线程都基本不耗CPU. 说明CPU不是这些线程自己消耗的. 而是系统在进行线程上下文切换时消耗的:

jvm的cpu状况:

image

每一个线程的占用cpu状况:

image

分析和总结

再回到咱们文章开头的线程堆栈(占用了15%的CPU):

"operate-api-1-thread-6" #1522 prio=5 os_prio=0 tid=0x00007f4b7006f800 nid=0x1b67c waiting on condition [0x00007f4ac8c4a000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c10828c8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
	at ch.qos.logback.classic.Logger.info(Logger.java:579)
	...
复制代码

上面论证过了,WAITING状态的线程是不会消耗CPU的, 因此这里的CPU确定不是挂起后消耗的, 而是挂起前消耗的.

那是哪段代码消耗的呢? 答案就在堆栈中的这段代码:

at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
复制代码

众所周知, ReentrantLock的底层是使用AQS框架实现的. AQS你们可能都比较熟悉, 若是不熟悉的话这里能够大概描述一下AQS:

1. AQS有个临界变量state,当一个线程获取到state==0时, 表示这个线程进入了临界代码(获取到锁), 并原子地把这个变量值+1
2. 没能进入临界区(获取锁失败)的线程, 会利用CAS的方式添加到到CLH队列尾去, 并被LockSupport.park挂起.
3. 当线程释放锁的时候, 会唤醒head节点的下一个须要唤醒的线程(有些线程cancel了就不须要唤醒了)
4. 被唤醒的线程检查一下本身的前置节点是否是head节点(CLH队列的head节点就是以前拿到锁的线程节点)的下一个节点,
若是不是则继续挂起, 若是是的话, 与其余线程从新争夺临界变量,即重复第1步
复制代码

CAS

在AQS的第2步中, 若是竞争锁失败的话, 是会使用CAS乐观锁的方式添加到队列尾的, 核心代码以下:

/**
     * Inserts node into queue, initializing if necessary. See picture above.
     * @param node the node to insert
     * @return node's predecessor */ private Node enq(final Node node) { for (;;) { Node t = tail; if (t == null) { // Must initialize if (compareAndSetHead(new Node())) tail = head; } else { node.prev = t; if (compareAndSetTail(t, node)) { t.next = node; return t; } } } } 复制代码

看上面的这段代码, 设想在极端状况下(并发量很是高的状况下), 每一次执行compareAndSetTail都失败(即返回false)的话,那么这段代码就至关是一个while(true)死循环.

在咱们的实际案例中, 虽然不是极端状况, 可是并发量也是极高的(每个线程每时每刻都在调用logback打日志), 因此在某些状况下, 个别线程会在这段代码自旋太久而长期占用CPU, 最终致使CPU告警

CAS也是一种乐观锁, 所谓乐观就是认为竞争状况比较少出现. 因此CAS是不适合用于锁竞争严重的场景下的,锁竞争严重的场景更适合使用悲观锁, 那样线程被挂起了,会更加节省CPU

AQS中线程上下文切换

在实际的环境中, 若是临界区的代码执行时间比较短的话(logback写日志够短了吧), 上面AQS的第3,第4步也是会致使CLH队列的线程被频繁唤醒,而又因为抢占锁失败频繁地被挂起. 所以也会带来大量的上下文切换, 消耗系统的cpu资源.

从实验结果来看, 我以为这个缘由的可能性更高.

延伸思考

所谓cpu偏高就是指"cpu使用率"太高. 举例说1个核的机器,CPU使用100%, 8个核使用了800%,都表示cpu被用满了.那么1核的90%, 8核的700%均可以认为cpu使用率太高了.

cpu被用满的后果就是操做系统的其余任务没法抢占到CPU资源. 在window上的体现就是卡顿,鼠标移动很是不流畅.在服务器端的体现就是整个JVM没法接受新的请求, 当前的处理逻辑也没法进行而致使超时,对外的表现就是整个系统不可用.

CPU% = (1 - idleTime / sysTime) * 100

idleTime: CPU空闲时间
sysTime: CPU在用户态和内核态的使用时间之和
复制代码

cpu是基于时间片调度的. 理论上无论一个线程处理时间有多长, 它能运行的时间也就是一个时间片的时间, 处理完后就得释放cpu. 然而它释放了CPU后, 仍是会立马又去抢占cpu,并且抢到的几率是同样的. 因此从应用层面看, 有时仍是能够看到这个线程是占用100%的

最后,从经验来看, 一个JVM系统的CPU偏高通常就是如下几个缘由:

  1. 代码中存在死循环
  2. JVM频繁GC
  3. 加密和解密的逻辑
  4. 正则表达式的处理
  5. 频繁地线程上下文切换

若是真的遇到了线上环境cpu偏高的问题, 不妨先从这几个角度进行分析.

最最最后, 给你们推荐一个工具, 能够线上分析jstack的一个网站, 很是的有用.

网站地址: fastthread.io/

相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程