天天看點

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

作者 | 何波

【Arthas 官方社群正在舉行征文活動,參加即有獎品拿~

點選投稿

1.前言

背景

線上代碼經常會出現 CPU 占用過高的情況,按以往經驗我會使用 top 指令,進一步借助于 jstack 去檢視具體資訊進而進行問題排查,但基本上都逃不過需要重新發包的局面,及時是一個增量包,應用也需要短暫停啟。後來運維大兄弟讓我試一下 Arthas,說是可以進行代碼的熱更新操作,正好來試一下。

關于 Arthas 的安裝與基礎使用可以參考下面兩篇文章:

環境

JDK1.8

SPringBoot 2.2.2

Arthas

Linux

測試代碼:

@RequestMapping(value = "/bigThread")
@ResponseBody
public String bigThread(int id) {
    ArthasService.test();
    while (true) {
        Thread t2 = new Thread();
        t2.start();
        id ++;
        if(100000 == id) {
            return String.valueOf(id);
        }
    }
}           

思路

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

2.thread -b 檢視是否有阻塞線程

thread -b, 找出目前阻塞其他線程的線程,執行完之後并未發現,說明該線程并非一直阻塞、一直執行的。

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

3.thread 檢視占用最高的線程

當 thread 之後不跟參數時,顯示目前全部線程資訊,我覺得 thread -n 10,展示前 10 應該就夠用,可根據實際需要自己決定。

下圖可以很直覺的看出,我們的應用瞬間占用了 77% 的 CPU(這裡我是發起請求瞬間,通過 thread 檢視的,是以比較直覺,生産環境應該隻有阻塞,死鎖這種狀态才會比較直覺)。

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

4.thread id 檢視具體資訊

在上一步基礎上,我們進一步檢視,thread 15(因為上面的 ID=15)。

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

他的大緻意思就是:線程在等待一個條件進而繼續執行,可以看到方法是在執行 LinkedBlockingQueue.take 方法時候,檢視這個方法的 API 提示如下:

public E take() throws InterruptedException {
    E x;
    int c = -1;
    final AtomicInteger count = this.count;
    final ReentrantLock takeLock = this.takeLock;
    takeLock.lockInterruptibly();
    try {
        while (count.get() == 0) {
            notEmpty.await();
        }
        x = dequeue();
        c = count.getAndDecrement();
        if (c > 1)
            notEmpty.signal();
    } finally {
        takeLock.unlock();
    }
    if (c == capacity)
        signalNotFull();
    return x;
}           

其中:AtomicInteger 是保證高并發情況下的原子性,ReentrantLock 辨別可重入鎖,都是 JUC 包下需要了解的這裡不贅述,需要的百度了解下。

這段代碼關鍵點就在于:notEmpty.await(),從隊列中消費資料,當隊列為空是,線程阻塞,是以我們大緻知道現在出現的問題是線程阻塞,但是還是不知道具體哪行代碼的問題。

如果能夠明确知道這次更改了哪些代碼,可以直接執行步驟 6,不知道的話可以通過步驟 5 來定位問題。

5.watch 檢視哪個 Controller 執行了代碼

watch org.springframework.web.servlet.DispatcherServlet getHandler returnObj           

這個腳本可以檢測一切通過 DispatcherServlet 比對 Handler 的方法,也就是進入 Controller 的請求,如下:

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

找到了對應的代碼之後,我們來進一步觀察異常資訊,這裡可能會有一個問題:就是我明明能通過日志去檢視錯誤資訊,為什麼還需要這麼繁瑣的去操作。我的業務場景是:日志還是非常大的,剛撈到就被刷過去了,這時候定位日志不是很好操作,當然想撈下來日志肯定也是可以的,也很直覺,我一般也都是去檢視日志進行問題定位,這裡也是提供一個思路。

6.watch 該方法異常資訊

watch 類全路徑 方法名 "{params[0],throwExp}" -e -x 2           
記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

如上,錯誤很直覺的提示了出來,下面就可以修複解決了,這裡我們也可以通過 trace 指令,檢視執行時長:

trace 類全路徑 方法名 "{params[0],throwExp}" -e -x 2           

傳回資訊如下,也可以看到錯誤資訊,和每個方法執行的時長。

[arthas@10999]$ trace com.arthas.controller.OrderController bigThread
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 53 ms, listenerId: 10
`---ts=2020-08-19 14:45:57;thread_name=http-nio-0.0.0.0-8080-exec-10;id=16;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6
    `---[1452.684406ms] com.arthas.controller.OrderController:bigThread() [throws Exception]
        +---[0.168814ms] com.arthas.service.ArthasService:test() #20
        `---throw:java.lang.OutOfMemoryError #-2 [unable to create new native thread]           

7.jad 反編譯熱更新

在上面知道問題之後,我們就來定位問題就好了。

指令:jad 類全路徑 方法名

[arthas@13190]$ jad com.arthas.controller.OrderController

ClassLoader:                                                                                                                                                                                
+-org.springframework.boot.loader.LaunchedURLClassLoader@17f052a3                                                                                                                           
  +-sun.misc.Launcher$AppClassLoader@3d4eac69                                                                                                                                               
    +-sun.misc.Launcher$ExtClassLoader@45f45fa1                                                                                                                                             

Location:                                                                                                                                                                                   
file:/opt/software/arthas/Arthas.jar!/BOOT-INF/classes!/                                                                                                                                    

/*
 * Decompiled with CFR.
 * 
 * Could not load the following classes:
 *  com.arthas.service.ArthasService
 *  org.springframework.stereotype.Controller
 *  org.springframework.web.bind.annotation.RequestMapping
 *  org.springframework.web.bind.annotation.ResponseBody
 */
package com.arthas.controller;

import com.arthas.service.ArthasService;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.ResponseBody;

@Controller
public class OrderController {
    @RequestMapping(value={"/bigThread"})
    @ResponseBody
    public String bigThread(int id) {
        ArthasService.test();
        do {
            Thread t2 = new Thread();
            t2.start();
        } while (100000 != ++id);
        return String.valueOf(id);
    }
}

Affect(row-cnt:1) cost in 1513 ms.           

此時代碼就被反編譯了,為了能夠更改,是以我們需要輸出為 java 檔案。

指令:jad com.arthas.controller.OrderController > /tmp/OrderController.java

即:jad 類全路徑 方法名 > 存儲路徑/存儲名稱

然後到 tmp 路徑下 vi 修改 java 檔案即可,修改完成之後,檢視對應的 classloader 為編譯做準備。

sc -d *OrderController | grep classLoaderHash
mc -c 17f052a3 /tmp/OrderController.java -d /tmp           
記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

但是這裡編譯出錯了,官方提示:

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

是以我們本地編譯好 class 檔案,上傳上去是一樣的。

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

編譯前調用

[arthas@13190]$ trace com.arthas.controller.OrderController bigThread
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 77 ms, listenerId: 2
`---ts=2020-08-19 15:51:46;thread_name=http-nio-0.0.0.0-8080-exec-1;id=d;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6
    `---[6734.666529ms] com.arthas.controller.OrderController:bigThread() [throws Exception]
        +---[0.786517ms] com.arthas.service.ArthasService:test() #20
        `---throw:java.lang.OutOfMemoryError #-2 [unable to create new native thread]           

更新前代碼

@RequestMapping(value = "/bigThread")
@ResponseBody
public String bigThread(int id) {
    ArthasService.test();
    while (true) {
        Thread t2 = new Thread();
        t2.start();
        id ++;
        if(100000 == id) {
            return String.valueOf(id);
        }
    }
}           

更新後代碼

@RequestMapping(value = "/bigThread")
@ResponseBody
public String bigThread(int id) {
    ArthasService.test();
    Thread t2 = new Thread();
    t2.start();
    return "success";
}           

編譯指令

[arthas@13190]$ redefine /tmp/OrderController.class
redefine success, size: 1, classes:
com.arthas.controller.OrderController           

編譯後調用三次

`---ts=2020-08-19 15:52:02;thread_name=http-nio-0.0.0.0-8080-exec-3;id=f;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6
    `---[5.609405ms] com.arthas.controller.OrderController:bigThread()
        `---[0.204675ms] com.arthas.service.ArthasService:test() #20

`---ts=2020-08-19 15:52:04;thread_name=http-nio-0.0.0.0-8080-exec-4;id=10;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6
    `---[3.900149ms] com.arthas.controller.OrderController:bigThread()
        `---[0.14636ms] com.arthas.service.ArthasService:test() #20

`---ts=2020-08-19 15:52:04;thread_name=http-nio-0.0.0.0-8080-exec-5;id=11;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1f1c7bf6
    `---[1.90945ms] com.arthas.controller.OrderController:bigThread()
        `---[0.147353ms] com.arthas.service.ArthasService:test() #20           

可以發現時間從 6734.666529ms 變成 3ms 左右,說明熱更新的代碼生效了。

8.profile 繪制火焰圖做後續分析

如下圖所示:

記 Arthas 實作一次 CPU 排查與代碼熱更新1.前言2.thread -b 檢視是否有阻塞線程3.thread 檢視占用最高的線程4.thread id 檢視具體資訊5.watch 檢視哪個 Controller 執行了代碼6.watch 該方法異常資訊7.jad 反編譯熱更新8.profile 繪制火焰圖做後續分析Arthas 征文活動火熱進行中

Arthas 征文活動火熱進行中

Arthas 官方正在舉行征文活動,如果你有:

  • 使用 Arthas 排查過的問題
  • 對 Arthas 進行源碼解讀
  • 對 Arthas 提出建議
  • 不限,其它與 Arthas 有關的内容

歡迎參加征文活動,還有獎品拿哦~

阿裡巴巴雲原生 關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐,做最懂雲原生開發者的公衆号。”