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教程