使用BPF监视JVM应用程序

Posted 2022-10-24 宣之于口

使用BPF监视JVM应用程序

参考文章: Fast and secure JVM application monitoring with BPF magic and JVM-BPF

一、Linux跟踪工具的概况

X轴为信息详细程度，Y轴为易于使用情况

• ftrace 是一种内置机制，其已包含在Linux中。它是一种跟踪性能问题等的工具。但是，它并非设计用于Java。它不能用于跟踪许多有趣的Java事件，例如垃圾回收，类加载等
• SystemTap 是一种非常底层的工具，可以跟踪用户空间中的内核事件和用户事件 (包括Java事件)。其主要问题是，要使用此工具，需要在其执行期间编译内核模块并将其加载到内核中
• SysDig 关注于跟踪容器中的性能，但是它只能与系统调用一起使用，提供的功能较少

二、JVM中的监视点

在运行的Java应用程序中，除了由操作系统执行的操作 (系统调用，网络事件) 之外，在大多数最新的Java版本中，OpenJDK还配备了许多USDT探针。它们中的大多数都是开箱即用的。

1. 探针

要探索其中的一些探针，请导航至$JAVA_HOME并查看tapset目录, 或者查看在线文件.

这些.stp文件包含一堆探针的描述和声明，包括其参数。例如，尝试查找gc_collect_tenured_begin和gc_collect_tenured_end探针描述

# 可选, 通过yum安装1.8.0版本openjdk
$ yum install java-1.8.0-openjdk* -y

# 路径
$ cd /etc/alternatives/java_sdk
$ ls tapset/
hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp     
hotspot_jni-1.8.0.242.b08-0.el7_7.x86_64.stp
hotspot_gc-1.8.0.242.b08-0.el7_7.x86_64.stp  
jstack-1.8.0.242.b08-0.el7_7.x86_64.stp

现在，让我们来看一个更实际的例子。现在，通过使用class_loaded探针来跟踪正在运行的Java应用程序，并查看正在加载哪些类。首先，通过运行以下命令: 看起来有四个参数，并且正在加载的类名作为第一个参数给出

$ grep -A 10 'probe.*class_loaded' tapset/*.stp
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp:probe hotspot.class_loaded =
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-  process("/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.242.b08-0.el7_7.x86_64/jre/lib/amd64/server/libjvm.so").mark("class__loaded")
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-  name = "class_loaded";
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-  class = user_string_n($arg1, $arg2);
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-  classloader_id = $arg3;
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-  is_shared = $arg4;
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-  probestr = sprintf("%s(class='%s',classloader_id=0x%x,is_shared=%d)",
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-                     name, class, classloader_id, is_shared);
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-
tapset/hotspot-1.8.0.242.b08-0.el7_7.x86_64.stp-

1. readelf

Linux有一个 readelf 工具，一般用于查看ELF格式的文件信息，常见的文件如在Linux上的可执行文件。

这是获取这些跟踪点列表的一种方法，其描述了那些嵌入在系统上任何Java应用程序中的跟踪点。我们看到Java事件: class_loaded，thread_start，object_alloc等

$ find /usr/lib/jvm -name libjvm.so -exec readelf -n  + | grep -A2 NT_STAPSDT
# output
 stapsdt              0x00000078       NT_STAPSDT (SystemTap probe descriptors)
    Provider: hotspot
    Name: mem__pool__gc__begin
--
  stapsdt              0x0000004d       NT_STAPSDT (SystemTap probe descriptors)
    Provider: hotspot
    Name: class__loaded
--
  stapsdt              0x0000004e       NT_STAPSDT (SystemTap probe descriptors)
    Provider: hotspot
    Name: object__alloc
--
  stapsdt              0x00000065       NT_STAPSDT (SystemTap probe descriptors)
    Provider: hotspot
    Name: thread__start
...

2. tplist

tplist 是BCC中的一个工具，可以显示来自二进制文件或正在运行的进程的probes列表

此时，我们可以运行一个Java应用程序

$ java slowy/App

现在，使用tplist以下命令发现可用的跟踪点：

$ ./tplist.py -p `pidof java` 
# ./tplist.py -p 19322 '*class*loaded'
/usr/lib/jvm/.../server/libjvm.so hotspot:object__alloc
/usr/lib/jvm/.../server/libjvm.so hotspot:method__entry
/usr/lib/jvm/.../server/libjvm.so hotspot:method__return
/usr/lib/jvm/.../server/libjvm.so hotspot:monitor__waited
/usr/lib/jvm/.../server/libjvm.so hotspot:monitor__wait
/usr/lib/jvm/.../server/libjvm.so hotspot:thread__stop
...

三、方法和堆栈跟踪

trace : 参与了系统级事件的跟踪，并同时从这些事件中接收了一系列Java调用。无需重新启动Java应用程序进行重新编译。

示例1: 每当Java应用程序加载类时，您都应该获得一条跟踪消息

$ sudo find / -name libjvm.so # 得到libjvm.so文件路径 path
$ ./trace.py 'u:/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.242.b08-0.el7_7.x86_64/jre/lib/amd64/server/libjvm.so:class__loaded "%s", arg1'

PID     TID     COMM            FUNC             -
...
11881   11882   java            class__loaded    java/security/UnresolvedPermission
11881   11882   java            class__loaded    java/security/BasicPermissionCollection
11881   11882   java            class__loaded    slowy/App
11881   11882   java            class__loaded    sun/launcher/LauncherHelper$FXHelper
11881   11882   java            class__loaded    java/lang/Class$MethodArray
11881   11882   java            class__loaded    java/io/IOException
11881   11882   java            class__loaded    java/lang/Void
11881   11882   java            class__loaded    java/util/Formatter
11881   11882   java            class__loaded    java/util/regex/Pattern
11881   11882   java            class__loaded    java/util/regex/Pattern$Node
...

示例2: Java应用程序将消息打印到控制台, 我们需要找出发送这些消息的代码

前提条件: -XX:+PreserveFramePointer , 可以获得更精确的堆栈跟踪，占用约3%的开销

当运行JAVA程序, 获取到一系列报错信息

$ java … myapp
Error fetching data, cleaning up.
Error fetching data, cleaning up.
Error fetching data, cleaning up.
Error fetching data, cleaning up.
[..]

下述示例获取了 SyS_write 的系统调用

# -U 指示用户空间中的调用堆栈; -p 仅保留Java进程的过滤器
$ ./trace.py 'SyS_write (arg1==1) "%s", arg2' -U -p `pidof java`

# 进程和线程标示
PID    TID    COMM         FUNC             -
27982  27983  java         SyS_write        Error fetching data, cleaning up.0
# 调用堆栈
write+0x2d [libpthread-2.24.so]
writeBytes+0x1f0 [libjava.so]
Java_java_io_FileOutputStream_writeBytes+0x1a [libjava.so]
[unknown] [perf-15527.map]
[unknown] [perf-15527.map]
[unknown] [perf-15527.map]
[unknown] [perf-15527.map]
...
JavaCalls::call_helper(JavaValue*, methodHandle*, …)+0xf53 [libjvm.so]
jni_invoke_static(JNIEnv_*, JavaValue*, _jobject*, …)+0x357 [libjvm.so]
jni_CallStaticVoidMethod+0x186 [libjvm.so]
JavaMain+0x6d1 [libjli.so]
start_thread+0xca [libpthread-2.24.

存在与 perf 一样的问题，需要一个代理来打印JIT编译代码的内存中的地址与实际方法名称之间的对应关系，可以使用perf-map-agent. (在perf那一节介绍过)

# create-java-perf-map.sh 在/root/perf-map-agent/bin/目录下
$ create-java-perf-map.sh `pidof java` "unfoldall,dottedclass"
$ tail /tmp/perf-`pidof java`.map
7f6ed52ea5c0 100 DataFetcher::processIt
7f6ed52eaa20 880 java.lang.ClassLoader::loadClass
7f6ed52ebf40 340 DataFetcher::fetchData
[...]

然后重新执行，使用代理的新结果，其解析了函数的名称，所有这些名称均从我们刚刚生成的.map文件中提取

$ trace 'SyS_write (arg1==1) "%s", arg2' -U -p `pidof java`
PID    TID    COMM         FUNC            -
25335  25336  java         SyS_write       Error fetching data, cleaning up.f8
write+0x24 [libpthread-2.24.so]
writeBytes+0x1f0 [libjava.so]
Java_java_io_FileOutputStream_writeBytes+0x1a [libjava.so]
java.io.FileOutputStream::writeBytes+0xc6 [perf-15527.map]
java.io.FileOutputStream::write+0x74 [perf-15527.map] 
java.io.BufferedOutputStream::flushBuffer+0xa5 [perf-15527.map]
java.io.BufferedOutputStream::flush+0x98 [perf-15527.map]
[...]
JavaCalls::call_helper(JavaValue*, methodHandle*, …)+0xf53 [libjvm.so]
...

示例3: Java应用程序通过直接调用 System.gc() 导致大量垃圾收集

前提条件:

• -XX:+PreserveFramePointer 3%左右的开销
• -XX:+ExtendedDTraceProbes 昂贵的开销，仅用于调试方法调用/对象分配

通过查看GC LOG可以看出存在多次 System.gc()

$ java … -XX:+PrintGC myapp
[Full GC (System.gc())  530K->255K(15872K), 0.0021490 secs]
[Full GC (System.gc())  255K->255K(15936K), 0.0020310 secs]
[Full GC (System.gc())  255K->255K(15936K), 0.0017840 secs]
[...]

使用trace 查看堆栈调用, 通过 method_entry 可以跟踪任何Java方法，为了表明我们对哪种特定方法感兴趣，我们替换一个条件，该条件要求arg4 (此方法名称) 等于 gc

$ trace 'u:.../libjvm.so:method__entry (STRCMP("gc", arg4)) "induced GC"' -U -p `pidof java`
PID    TID    COMM         FUNC             -
25413  25414  java         method__entry    induced GC
# 具有System.gc()此应用程序中每个调用的调用和堆栈跟踪的输出
    SharedRuntime::dtrace_method_entry(…)+0x7b [libjvm.so]
    java.lang.Runtime::gc+0x80 [perf-15605.map]
    java.lang.System::gc+0x40 [perf-15605.map]
    DataFetcher::fetchData+0xdc [perf-15605.map]
    RequestProcessor::processRequest+0xc0 [perf-15605.map]
    Collecty::main+0x14b [perf-15605.map]
    call_stub+0x88 [perf-15605.map]
    JavaCalls::call_helper(JavaValue*, methodHandle*, …)+0xf53 [libjvm.so]
	...

五、GC分析

示例: 了解Java应用程序生成的负载，确定它与GC有关，并弄清垃圾来自何处

# ustat
$ ustat -C
15:02:09 loadavg: 0.24 0.05 0.03 3/202 28698
PID    CMDLINE              METHOD/s   GC/s   OBJNEW/s   CLOAD/s  EXC/s  THR/s
28689  java -XX:+PreserveFr 0          888    0          0        0      0

# uobjnew: 使用昂贵的探针来跟踪对象分配，该探针需要-XX:+ExtendedDTraceProbes
TYPE                             ALLOCS        BYTES
java/lang/String                  12588            0
[C                                12588            0
[...]

# stackcount: 总结导致该探针的Java调用堆栈 (也可以生成火焰图)
$ stackcount -i 5 -p `pidof java` "u:.../libjvm.so:object__alloc"
SharedRuntime::dtrace_object_alloc(oopDesc*, int)
  TypeArrayKlass::allocate_common(int, bool, Thread*)
  OptoRuntime::new_array_C(Klass*, int, JavaThread*)
  _new_array_Java
  ResponseBuilder::addLine
  Allocy::main
  call_stub
…
  JavaMain
  start_thread
    870