背景
剛剛過去的雙十一, 公司訂單量又翻了一倍. 就在老闆坐在辦公室裡面偷偷笑的同時,坐在工位上的我們卻是一直瑟瑟發抖. 面對zabbix裡面時不時蹦出來的一條條CPU告警,默默地祈禱著不要出問題.
當然, 祈禱是解決不了問題的, 即使是開過光的伺服器也不行. CPU告警了, 還得老老實實地去看為啥CPU飈起來了.
接下來就是CPU排查三部曲
1. top -Hp $pid 找到最耗CPU的執行緒.
2. 將最耗CPU的執行緒ID轉成16進位制
3. 列印jstack, 到jstack裡面查這個執行緒在幹嘛
複製程式碼當然 如果你線上環境有裝arthas等工具的話, 直接thread -n就可以列印出最耗cpu的n個執行緒的堆疊,三個步驟一起幫你做了.
最後找到最耗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)
...
複製程式碼值得一提的是, 類似的執行緒還有800多個... 只是部分沒有消耗CPU而已
問題
很明顯, 這是因為logback列印日誌太多了造成的(此時應有一個尷尬而不失禮貌的假笑).
當大家都紛紛轉向討論接下來如何優化logback和打日誌的時候. 我卻眉頭一皺, 覺得事情並沒有那麼簡單:
這個執行緒不是被LockSupport.park掛起了, 處於WAITING狀態嗎? 被掛起即代表放棄佔用CPU了, 那為啥還會消耗CPU呢?
來看一下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. 處於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:
被park的執行緒
然後來看一下park的執行緒是否會消耗cpu
程式碼:
import java.util.concurrent.locks.LockSupport;
public class TestCpu {
public static void main(String[] args) {
while(true){
LockSupport.park();
}
}
}
複製程式碼visualvm顯示一切波瀾不驚,CPU毫無壓力 :
發生死鎖的執行緒
再來看看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() + " 執行結束!");
}
}
複製程式碼
也是可以看到雖然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情況:
每個執行緒的佔用cpu情況:
分析和總結
再回到我們文章開頭的執行緒堆疊(佔用了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偏高一般就是以下幾個原因:
- 程式碼中存在死迴圈
- JVM頻繁GC
- 加密和解密的邏輯
- 正規表示式的處理
- 頻繁地執行緒上下文切換
如果真的遇到了線上環境cpu偏高的問題, 不妨先從這幾個角度進行分析.
最最最後, 給大家推薦一個工具, 可以線上分析jstack的一個網站, 非常的有用.
網站地址: fastthread.io/