基于 /proc 和 jstack 統(tǒng)計 jvm 線程池的上下文切換率

TL;DR

  • Linux 系統(tǒng)的 /proc/<pid>/status 文件中記錄了每個線程的上下文切換次數(shù)
  • 通過 jstack 命令能查看 jvm 應用中的線程 pid 及對應的線程池名字
  • 將這兩部分信息結合，可以實時統(tǒng)計每個線程池的每秒上下文切換次數(shù)，為定位程序的性能瓶頸提供依據(jù)
  • 這個方法中的 /proc 偽文件系統(tǒng)還能推廣到：/sys/fs/cgroup, ftrace, strace 等 Linux 提供的其他線程級 tracing 機制

背景

我司的監(jiān)控系統(tǒng)中有一項和上下文切換(context switch)相關，19年雙十一前壓測期間，就有若干臺服務器觸發(fā)了該警報，有些服務器的上下文切換率甚至高達 220K/S。過高的上下文切換頻率意味著有相當多 CPU 時間花在了內(nèi)核調度各線程，而不是應用程序處理業(yè)務邏輯上，所以找出導致高上下文切換率的 root cause，并給出對應的修復方案很有必要。

通過 pidstat 等命令雖然能很快定位到引起高上下文切換率的進程，但對于 java 應用而言，如果定位能具體到線程或線程池的話，將更有助于快速找到 java 代碼層面的 root cause。通過分析 pidstat 命令的運行原理發(fā)現(xiàn)，從 /proc/<pid>/status 中可以查看到每個線程的上下文切換次數(shù)，將這部分信息和 jstack 輸出的線程 pid 和線程池名字的映射關系進行結合，就能達到線程池級的上下文切換率統(tǒng)計和監(jiān)控了。

proc 偽文件系統(tǒng)

proc 是一個偽文件系統(tǒng)，一般被掛載到 /proc 目錄(當然你也可以通過 sudo mount -t proc proc ./myproc 將其掛載到任何你喜歡的目錄)。

proc 是一個文件系統(tǒng)，所以你能通過cat, less 等工具對 /proc 的文件進行讀寫（當然，大部分文件只能讀不能寫），例如：

~$ cat /proc/self/cmdline
cat/proc/self/cmdline

或者，你也可以在自己編寫的程序中，使用 open, read 等系統(tǒng)調用進行讀寫：

~$ python -c "print(open('/proc/self/cmdline').read())"
python-cprint(open('/proc/self/cmdline').read())

另一方面，proc是偽的文件系統(tǒng)。這就意味著，/proc/self/cmdline 不對標任何磁盤上的具體文件，其后面承載的并不是某塊盤片上一段靜靜躺著的 01 比特流，而是某個程序在收到 open, read 等系統(tǒng)調用請求后，即時計算出來的一段信息，這個程序就是 Linux 內(nèi)核，這段信息就是反應內(nèi)核及各個進程執(zhí)行狀態(tài)的各種數(shù)據(jù)結構。

以前面提到的 /proc/self/cmdline 為例，讀取這個文件，得到的是當前進程（也就是發(fā)起 open, read 系統(tǒng)調用的那個進程）的啟動命令行。它其實是 /proc/<pid>/cmdline 的特殊版，其中的 self 相當于指向當前進程 id 的軟鏈接。更普遍的，你還可以通過 cat /proc/1/cmdline 查看 init 進程的啟動命令：

~$ cat /proc/1/cmdline 
/usr/lib/systemd/systemd--switched-root--system--deserialize22

另一個例子，就是分析上下文切換率的數(shù)據(jù)源： /proc/<pid>/status，這個文件以人肉易讀的方式提供了進程的很多運行時信息，例如：

~$ cat /proc/1/status
Name:   systemd
State:  S (sleeping)
Tgid:   1
Ngid:   0
Pid:    1
PPid:   0
TracerPid:  0
Uid:    0   0   0   0
Gid:    0   0   0   0
FDSize: 64
Groups: 
VmPeak:   204388 kB
VmSize:   204240 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:    166676 kB
VmRSS:    166676 kB
VmData:   164124 kB
VmStk:       136 kB
VmExe:      1304 kB
VmLib:      3604 kB
VmPTE:       416 kB
VmSwap:        0 kB
Threads:    1
SigQ:   0/15093
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 7be3c0fe28014a03
SigIgn: 0000000000001000
SigCgt: 00000001800004ec
CapInh: 0000000000000000
CapPrm: 0000001fffffffff
CapEff: 0000001fffffffff
CapBnd: 0000001fffffffff
Seccomp:    0
Cpus_allowed:   3
Cpus_allowed_list:  0-1
Mems_allowed:   00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list:  0
voluntary_ctxt_switches:    7447210
nonvoluntary_ctxt_switches: 15686

這篇文章需要關注的主角，就是文件末尾兩行的 voluntary_ctxt_switches 和 nonvoluntary_ctxt_switches。他們分別表示：

  • voluntary_ctxt_switches: 進程自運行以來，自愿發(fā)起（通常由系統(tǒng)調用引起）的上下文切換次數(shù)。
  • nonvoluntary_ctxt_switches: 進程自運行以來，被迫發(fā)起（通常由CPU密集型運算觸發(fā)）的上下文切換次數(shù)。

從 /proc/<pid>/status 讀到的是進程的運行信息， 而要確定進程內(nèi)每個線程的運行狀態(tài)，則可以讀取 /proc/<pid>/task/<task_pid>/status 中的數(shù)據(jù)。

rate 估計算法

通過 /proc/<pid>/task/<task_pid>/status 讀取到的是每個線程的累計上下文切換次數(shù)，但我們更關心的，可能是上下文切換發(fā)生的速率，或者說每秒發(fā)生的次數(shù)。一個簡單的做法是間隔一秒，讀取兩次累計值，然后做diff，偽代碼是：

start = read_csw()
time.sleep(1)
end = read_csw()
rate = end - start

但這種做法受限比較多，例如：無法統(tǒng)計累計平均值、最近 1 分鐘、5 分鐘、15 分鐘的平均值等。實際上，此類統(tǒng)計需求，可以通過經(jīng)典的 exponentially weighted moving average (EWMA) 算法解決。該算法實現(xiàn)簡短，核心代碼不到百行 Python，應用廣泛-需要實時統(tǒng)計事件出現(xiàn)頻率的場合都能用上，例如：日志文件中某個關鍵字的出現(xiàn)頻率，通過 tcpdump 抓到的和外網(wǎng)的通信流量帶寬，甚至你打字的速度等。回到正文，我們可以使用該算法來統(tǒng)計線程的上下文切換頻率，偽代碼如下：

meter = ewma.Meter()
start_time = time.now()
last_csw = read_csw()

while time.now() - start_time < 60:
    cur_csw = read_csw()
    meter.mark(n=cur_csw - last_csw)
    last_csw = cur_csw
    print("mean csw_rate: %s" % meter.get_mean_rate())
    print("mean csw_rate in last 1 minute: %s" % meter.get_m1_rate())
    print("mean csw_rate in last 15 minutes: %s" % meter.get_m15_rate())

jstack

java 應用中，經(jīng)常使用 線程池 來隔離不同類型任務的并發(fā)處理，同一個線程池中的線程名通常具有統(tǒng)一的前綴，例如：線程池 kafka-consumer-xxx 用于消費 kafka 消息, grpc-worker-xxx 用于處理 gRPC 請求。
在java應用的故障排查中， 各線程的線程名、線程pid、調用棧等信息非常關鍵，使用 jdk 提供的 jstack 命令行工具能快速獲得這類信息，例如，以下 snippet 中顯示的便是一個hello world級java 應用的線程快照。以其中名為 "main" 的線程為例，它的 pid 是 0xe03（換算成十進制是3587），從其stack trace 可以看出當前正在執(zhí)行的java代碼是 Thread.sleep。

?  ~ jstack 22416
2020-05-25 19:14:57
Full thread dump OpenJDK 64-Bit Server VM (25.222-b10 mixed mode):

"Attach Listener" #9 daemon prio=9 os_prio=31 tid=0x00007ff61f829800 nid=0x4a07 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #8 daemon prio=9 os_prio=31 tid=0x00007ff62085a800 nid=0x4503 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007ff620837800 nid=0x4603 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007ff620835800 nid=0x4803 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007ff62001e000 nid=0x3603 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007ff62081d800 nid=0x3403 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007ff61f013000 nid=0x5203 in Object.wait() [0x000070000cef3000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000076ab08ed8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    - locked <0x000000076ab08ed8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007ff61f012800 nid=0x2d03 in Object.wait() [0x000070000cdf0000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000076ab06c00> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    - locked <0x000000076ab06c00> (a java.lang.ref.Reference$Lock)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=31 tid=0x00007ff620806000 nid=0xe03 waiting on condition [0x000070000c7de000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at Main.main(Main.java:3)

"VM Thread" os_prio=31 tid=0x00007ff620814000 nid=0x2b03 runnable 

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007ff620804000 nid=0x2007 runnable 

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007ff61f000800 nid=0x1b03 runnable 

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007ff61f004000 nid=0x1d03 runnable 

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007ff61f007000 nid=0x2a03 runnable 

"VM Periodic Task Thread" os_prio=31 tid=0x00007ff61f014800 nid=0x3803 waiting on condition 

JNI global references: 5

整合

使用 Python 腳本將 /proc/<pid>/task/<thread_pid>/status 中提供的線程級 context switch 計數(shù)，ewma rate 估計算法，jstack 命令提供的 java 線程(池)名與線程 pid 映射關系三者進行整合，我們便得到了一個可以實時查看任意 java 應用各線程池上下文切換頻次的工具。具體做法是：

  1. 間隔一定時間（例如500ms）掃描 /proc/<pid>/task 下各個線程的 status 文件，獲取每個線程的當前上下文切換計數(shù)，并減去上次掃描的計數(shù)得到掃描周期內(nèi)的增量。
  2. 調用 jstack <pid> 命令，獲取每個線程的線程名，截取這個名字前面的若干長度（如10）作為該線程的線程池名，并為每個線程池創(chuàng)建一個 ewma meter。
  3. 調用 meter.mark(n) 將步驟 1 中計算得到的增量更新到步驟 2 中創(chuàng)建的 ewma meter中。
  4. 調用 meter.get_mean_rate() 得到各線程池的平均上下文切換頻率，排序后，輸出排名靠前的十個線程池。

完整實現(xiàn)腳本見 gist

以下日志是一次線上測試的結果。從圖中可以看到，該應用平均每秒發(fā)生 914 次左右上下文切換，其中一半以上發(fā)生在以 gaia-servi 開頭的線程池內(nèi)。

~$ ./cswsnoop_jvm.py 1
###################################################################################################
total: 914.332857438
gaia-servi      461.870867106   461.870867106
grpc-defau      274.831239391   736.702106497
AsyncLogge      75.4100996903   812.112206188
grpc-timer      60.9907066689   873.102912857
VM Periodi      20.1876680486   893.290580905
StatsD-Dis      11.0018379794   904.292418885
jaeger.Rem      3.20440647419   907.496825359
C2 Compile      2.13625643762   909.633081796
VM Thread       1.28174892077   910.914830717
threadDeat      1.06814144974   911.982972167

拓展

這種 “收集tracing event” 然后 “按某個維度進行聚合、統(tǒng)計” 的實時監(jiān)控方案，還可以進行進一步拓展：

  • 從數(shù)據(jù)源方面考慮-還可以使用 Linux 內(nèi)核提供的其他 tracing event， 例如： 或者，根據(jù) /proc/<pid>/task/<thread_pid>/stat 中提供的 CPU 時間片計數(shù)，可以試試統(tǒng)計每個線程池花在用戶態(tài)和內(nèi)核態(tài)的 CPU 時間；根據(jù) ftrace 提供的 fork event，可以實時監(jiān)控每個線程池發(fā)起 fork 的頻次，以便快速定位產(chǎn)生大量臨時線程的病態(tài)代碼，類似于 brendangregg 的 execsnoop；或者以 strace 的輸出作為數(shù)據(jù)源，統(tǒng)計每個線程池發(fā)起某種系統(tǒng)調用的頻次。而用戶態(tài)代碼產(chǎn)生的一些事件，例如日志，也可以作為這種模式的監(jiān)控數(shù)據(jù)源，實現(xiàn)實時統(tǒng)計每個線程池的每秒日志量等目標（當然常規(guī)情況下，更傾向于使用ELK這種成熟的logging 解決方案）。
  • 從聚合維度考慮-除了在 java 線程池維度進行聚合外，我們還可以按照應用程序名，docker 容器 id 等維度進行聚合。達到“找出fork最頻繁的應用程序”， “列出最缺少CPU時間片的前十個容器”等任務
  • 兩相結合：例如把 tcpdump 的輸出作為數(shù)據(jù)源，以 packet 中的容器 ip 作為聚合維度，找出和外網(wǎng)通訊流量最大的容器。
?著作權歸作者所有,轉載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時請結合常識與多方信息審慎甄別。
平臺聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點，簡書系信息發(fā)布平臺，僅提供信息存儲服務。

友情鏈接更多精彩內(nèi)容