基于 /proc 和 jstack 统计 jvm 线程池的上下文

作者: 吉志龙 | 来源:发表于2020-05-25 20:56 被阅读0次

TL;DR

Linux 系统的 /proc/<pid>/status 文件中记录了每个线程的上下文切换次数

通过 jstack 命令能查看 jvm 应用中的线程 pid 及对应的线程池名字

将这两部分信息结合，可以实时统计每个线程池的每秒上下文切换次数，为定位程序的性能瓶颈提供依据

这个方法中的 /proc 伪文件系统还能推广到：/sys/fs/cgroup, ftrace, strace 等 Linux 提供的其他线程级 tracing 机制

背景

我司的监控系统中有一项和上下文切换(context switch)相关，19年双十一前压测期间，就有若干台服务器触发了该警报，有些服务器的上下文切换率甚至高达 220K/S。过高的上下文切换频率意味着有相当多 CPU 时间花在了内核调度各线程，而不是应用程序处理业务逻辑上，所以找出导致高上下文切换率的 root cause，并给出对应的修复方案很有必要。

通过 pidstat 等命令虽然能很快定位到引起高上下文切换率的进程，但对于 java 应用而言，如果定位能具体到线程或线程池的话，将更有助于快速找到 java 代码层面的 root cause。通过分析 pidstat 命令的运行原理发现，从 /proc/<pid>/status 中可以查看到每个线程的上下文切换次数，将这部分信息和 jstack 输出的线程 pid 和线程池名字的映射关系进行结合，就能达到线程池级的上下文切换率统计和监控了。

proc 伪文件系统

proc 是一个伪文件系统，一般被挂载到 /proc 目录(当然你也可以通过 sudo mount -t proc proc ./myproc 将其挂载到任何你喜欢的目录)。

proc 是一个文件系统，所以你能通过cat, less 等工具对 /proc 的文件进行读写（当然，大部分文件只能读不能写），例如：

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

或者，你也可以在自己编写的程序中，使用 open, read 等系统调用进行读写：

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

另一方面，proc是伪的文件系统。这就意味着，/proc/self/cmdline 不对标任何磁盘上的具体文件，其后面承载的并不是某块盘片上一段静静躺着的 01 比特流，而是某个程序在收到 open, read 等系统调用请求后，即时计算出来的一段信息，这个程序就是 Linux 内核，这段信息就是反应内核及各个进程执行状态的各种数据结构。

以前面提到的 /proc/self/cmdline 为例，读取这个文件，得到的是当前进程（也就是发起 open, read 系统调用的那个进程）的启动命令行。它其实是 /proc/<pid>/cmdline 的特殊版，其中的 self 相当于指向当前进程 id 的软链接。更普遍的，你还可以通过 cat /proc/1/cmdline 查看 init 进程的启动命令：

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

另一个例子，就是分析上下文切换率的数据源： /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: 进程自运行以来，自愿发起（通常由系统调用引起）的上下文切换次数。
nonvoluntary_ctxt_switches: 进程自运行以来，被迫发起（通常由CPU密集型运算触发）的上下文切换次数。

从 /proc/<pid>/status 读到的是进程的运行信息，而要确定进程内每个线程的运行状态，则可以读取 /proc/<pid>/task/<task_pid>/status 中的数据。

rate 估计算法

通过 /proc/<pid>/task/<task_pid>/status 读取到的是每个线程的累计上下文切换次数，但我们更关心的，可能是上下文切换发生的速率，或者说每秒发生的次数。一个简单的做法是间隔一秒，读取两次累计值，然后做diff，伪代码是：

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

但这种做法受限比较多，例如：无法统计累计平均值、最近 1 分钟、5 分钟、15 分钟的平均值等。实际上，此类统计需求，可以通过经典的 exponentially weighted moving average (EWMA) 算法解决。该算法实现简短，核心代码不到百行 Python，应用广泛-需要实时统计事件出现频率的场合都能用上，例如：日志文件中某个关键字的出现频率，通过 tcpdump 抓到的和外网的通信流量带宽，甚至你打字的速度等。回到正文，我们可以使用该算法来统计线程的上下文切换频率，伪代码如下：

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 应用中，经常使用线程池来隔离不同类型任务的并发处理，同一个线程池中的线程名通常具有统一的前缀，例如：线程池 kafka-consumer-xxx 用于消费 kafka 消息, grpc-worker-xxx 用于处理 gRPC 请求。
在java应用的故障排查中，各线程的线程名、线程pid、调用栈等信息非常关键，使用 jdk 提供的 jstack 命令行工具能快速获得这类信息，例如，以下 snippet 中显示的便是一个hello world级java 应用的线程快照。以其中名为 "main" 的线程为例，它的 pid 是 0xe03（换算成十进制是3587），从其stack trace 可以看出当前正在执行的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 计数，ewma rate 估计算法，jstack 命令提供的 java 线程(池)名与线程 pid 映射关系三者进行整合，我们便得到了一个可以实时查看任意 java 应用各线程池上下文切换频次的工具。具体做法是：

间隔一定时间（例如500ms）扫描 /proc/<pid>/task 下各个线程的 status 文件，获取每个线程的当前上下文切换计数，并减去上次扫描的计数得到扫描周期内的增量。
调用 jstack <pid> 命令，获取每个线程的线程名，截取这个名字前面的若干长度（如10）作为该线程的线程池名，并为每个线程池创建一个 ewma meter。
调用 meter.mark(n) 将步骤 1 中计算得到的增量更新到步骤 2 中创建的 ewma meter中。
调用 meter.get_mean_rate() 得到各线程池的平均上下文切换频率，排序后，输出排名靠前的十个线程池。

完整实现脚本见 gist

以下日志是一次线上测试的结果。从图中可以看到，该应用平均每秒发生 914 次左右上下文切换，其中一半以上发生在以 gaia-servi 开头的线程池内。

~$ ./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” 然后 “按某个维度进行聚合、统计” 的实时监控方案，还可以进行进一步拓展：

从数据源方面考虑-还可以使用 Linux 内核提供的其他 tracing event，例如：或者，根据 /proc/<pid>/task/<thread_pid>/stat 中提供的 CPU 时间片计数，可以试试统计每个线程池花在用户态和内核态的 CPU 时间；根据 ftrace 提供的 fork event，可以实时监控每个线程池发起 fork 的频次，以便快速定位产生大量临时线程的病态代码，类似于 brendangregg 的 execsnoop；或者以 strace 的输出作为数据源，统计每个线程池发起某种系统调用的频次。而用户态代码产生的一些事件，例如日志，也可以作为这种模式的监控数据源，实现实时统计每个线程池的每秒日志量等目标（当然常规情况下，更倾向于使用ELK这种成熟的logging 解决方案）。
从聚合维度考虑-除了在 java 线程池维度进行聚合外，我们还可以按照应用程序名，docker 容器 id 等维度进行聚合。达到“找出fork最频繁的应用程序”， “列出最缺少CPU时间片的前十个容器”等任务
两相结合：例如把 tcpdump 的输出作为数据源，以 packet 中的容器 ip 作为聚合维度，找出和外网通讯流量最大的容器。

基于 /proc 和 jstack 统计 jvm 线程池的上下文

TL;DR

背景

proc 伪文件系统

rate 估计算法

jstack

整合

拓展

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读