SystemTap是一个深入检查Linux系统活动的工具，使用该工具编写一些简单的代码就可以轻松的提取应用或内核的运行数据，以诊断复杂的性能或者功能问题。有了它，开发者不再需要重编译、安装新内核、重启动等烦人的步骤，应用程序同理。
配合火焰图的可视化，对程序的性能分析极其有利。
SystemTap 基本思想是命名事件，并为它们提供处理程序。每当发生指定的事件时，内核都会将处理程序视为子例程运行，然后继续运行。有一系列的事件，例如进入或退出函数，计时器到期或整个SystemTap会话的开始和停止。处理程序是一系列脚本语言语句，用于指定事件发生时要完成的工作。这项工作通常包含从事件上下文中提取数据，将其存储到内部变量或打印结果。
SystemTap 的工作原理是将脚本翻译成C语言，执行C编译器创建一个内核模块。当模块被加载后，通过挂载到内核来激活所有的探测事件。然后，当事件发生再任何处理器上时，编译后的处理程序就运行，最终，SystemTap绘画停止，Hook取消，内核模块被移除，整个过程由命令行程序stap驱动。
原理图如下：
需要内核级别的支持，依赖了三个rpm下载链接，
这三个包的版本必须匹配当前内核的版本，比如我自己的内核版本是 3.10.0-327, 那么以上三个包版本都必须保持一致。
安装 SystemTap：
$ yum install systemtap
测试是否成功安装：
$ stap -ve ‘probe begin{printf("Hello, World\n"); exit();}‘
正常的话会输出 Hello, World，但是不出意外会出现版本不一致的情况：
ERROR: module version mismatch (#1 SMP Fri Nov 20 11:12:42 CST 2015 vs #1 SMP Thu Nov 19 22:10:57 UTC 2015), release 3.10.0-327.el7.x86_64
出现这个的情况是版本相同但是打包事件不相同的情况，修改这个时间和uname -a 中的时间保持一致。
$ rpm -ql kernel-devel | xargs grep UTS_VERSION 2>/dev/null
/usr/src/kernels/3.10.0-327.el7.x86_64/include/generated/compile.h:#define UTS_VERSION "#1 SMP Fri Nov 20 11:12:42 CST 2015"
再次运行那个hello测试，出现缓存的错误，删除缓存文件
最简单的探测类型就是跟踪事件。Systemtap支持许多内置事件，所有的事件家族见 tapset
可以探测的的常用事件：
常用的可打印值（具体见 tapset）：
$$var, 上下文中存在 $var，可以使用该变量stap 脚本简单，语法类似C；
# fuck
// fuck
/* fuck */
function foo() {
// exit(); // 退出 systemtap 会话
}
function if_expr() {
i = 0
if (i == 1)
printf("[if] i = %d\n", i);
else
printf("[else] i = %d\n", i);
}
function while_expr() {
i = 0;
while (i != 2)
printf("[while] i = %d\n", i++);
}
function for_expr() {
for (i = 0; i < 2; i++)
printf("[for] i = %d\n", i);
}
function str() {
uid = uid();
s_uid = sprint(uid);
f_uid = "fuck" . s_uid
printf("uid: %d-%s-%s\n", uid, s_uid); // uid: 0-0-fuck0
// exit();
}
global t; // 声明元组
global tpl[400]; // 声明一个400容量的元组
t["fuck"]++; // t["fuck"] 初始值默认为0, ++ 变成 1
t["fuck"] = 4396; // 赋值为4396
tpl["fuck", pid()]++; // 两个元素
tpl["shit", tid()]++;
// 包含4个维度 @count @avg @min @max
global t;
t["fuck", tid()] <<< 1
t["fuck", pid()] <<< 1
t[execname(), tid()] <<< 1
t["fuck", 5487] <<< 2
t["fuck", 5487] <<< 3
t["fuck", 5487] <<< 1
具体结构如下：
t["fuck",5487] @count=3 @min=1 @max=3 @sum=6 @avg=2
t["fuck",26060] @count=2 @min=1 @max=1 @sum=2 @avg=1
t["stapio",26060] @count=1 @min=1 @max=1 @sum=1 @avg=1
// 遍历（升序）, 限制5次循环
foreach([key, value] in t+ limit 5)
printf("%s: %d\n", key, value)
// 结果
stapio: 2571
fuck: 2571
fuck: 5487
Usage: stap [options] FILE Run script in file.
or: stap [options] -e SCRIPT Run given script.
or: stap [options] -l PROBE List matching probes.
or: stap [options] -L PROBE List matching probes and local variables.
[options]
-T TIME terminate the script after TIME seconds
除了直接执行脚本文件外，另外一个比较有用的功能 -L -l 现象，列出可探测点及局部变量
// 截取部分~
[root@localhost stp]# stap -l ‘process("/tmp/limlog/build/tests/LogTest").function("*")‘
process("/tmp/limlog/build/tests/LogTest").function("write@/tmp/limlog/limlog/Log.cpp:107")
process("/tmp/limlog/build/tests/LogTest").function("~LimLog@/tmp/limlog/limlog/Log.cpp:213")
process("/tmp/limlog/build/tests/LogTest").function("~LogLine@/tmp/limlog/limlog/Log.cpp:341")
process("/tmp/limlog/build/tests/LogTest").function("~LogSink@/tmp/limlog/limlog/Log.cpp:59")
process("/tmp/limlog/build/tests/LogTest").function("~_Impl@/usr/include/c++/4.8.2/thread:107")
process("/tmp/limlog/build/tests/LogTest").function("~_Impl_base@/usr/include/c++/4.8.2/thread:97")
$)[root@localhost stp]# stap -L ‘process("/tmp/limlog/build/tests/LogTest").function("*")‘
process("/tmp/limlog/build/tests/LogTest").function("id@/usr/include/c++/4.8.2/thread:73") $this:class id* const
process("/tmp/limlog/build/tests/LogTest").function("incConsumable@/tmp/limlog/limlog/Log.cpp:313") $this:class LimLog* const $n:uint32_t
process("/tmp/limlog/build/tests/LogTest").function("incConsumablePos@/tmp/limlog/limlog/Log.cpp:135") $this:class BlockingBuffer* const $n:uint32_t
process("/tmp/limlog/build/tests/LogTest").function("incConsumablePos@/tmp/limlog/limlog/Log.cpp:460") $n:uint32_t
process("/tmp/limlog/build/tests/LogTest").function("insert@/usr/include/c++/4.8.2/bits/basic_string.h:1319") $__c:char $__n:size_type $__pos:size_type $this:class basic_string<char, std::char_traits<char>, std::allocator<char> >* const
有这个功能，我们就可以看到函数所在源文件中的位置及可以根据的局部变量。
探针事件的关键字是 probe, 由 probe 引出需要跟踪的事件
// 脚本执行后显示 === begin ===
probe begin {
printf("=== begin ===\n");
}
根据上述的可跟踪的事件
[root@localhost stp]# cat foo.stp
#!/usr/bin/env stap
probe begin {
printf("=== begin ===\n");
}
probe end {
printf("=== end ===\n");
}
// 执行脚本
[root@localhost stp]# stap foo.stp -T 1
=== begin ===
=== end ===
// 调用open系统调用
[root@localhost stp]# cat foo.stp
#!/usr/bin/env stap
probe kernel.function("sys_open").call {
printf("%s call %s\n", execname(), ppfunc());
}
// open系统调用返回
probe kernel.function("sys_open").call {
printf("%s call %s over\n", execname(), ppfunc());
}
[root@localhost stp]# stap foo.stp -T 1
sh call SyS_open
sh call SyS_open over
sh call SyS_open
sh call SyS_open over
sh call SyS_open
sh call SyS_open over
[root@localhost stp]# cat foo.stp
#!/usr/bin/env stap
// 定时调用函数
probe timer.ms(500) {
printf("now: %d\n", gettimeofday_s());
}
[root@localhost stp]# stap foo.stp -T 3
now: 1593141081
now: 1593141081
now: 1593141082
now: 1593141082
now: 1593141083
// 取自春哥的sample-bt示例代码，定时调用栈取样
global bts;
probe timer.profile {
if (pid() == 5291)
bts[backtrace(), ubacktrace()] <<< 1
}
probe timer.s(10) {
foreach([k, u] in bts-) {
print_stack(k);
print_ustack(u);
printf("\\t%d\\n", @count(bts[k, u]));
}
exit();
}
// 结果为16进制地址，截取一部分数据，这部分数据需要进一步加工统计
[root@localhost stp]# stap foo.stp
0xffffffff810d6244 : 0xffffffff810d6244
0xffffffff810475fa : 0xffffffff810475fa
\t1\n 0xffffffffa0139f0d : 0xffffffffa0139f0d [xfs]
// 打印程序 LogTest 所有执行的函数
[root@localhost stp]# cat foo.stp
probe process("/tmp/limlog/build/tests/LogTest").function("*") {
printf("function: %s\n", ppfunc());
}
// 库函数也加载进来了
[root@localhost stp]# stap foo.stp
function: offsetOfPos
function: __distance<char*>
function: operator+<long int, std::ratio<1l, 1000000000l>, long int, std::ratio<1l, 1000000l> >
function: operator<<
//打印 LogTest 程序属于 Log.cpp 中的函数信息
[root@localhost stp]# cat foo.stp
probe process("/tmp/limlog/build/tests/LogTest").statement("*@Log.cpp") {
printf("function: %s\n", ppfunc());
}
// 过滤了库函数，只留下Log.cpp中的函数执行
[root@localhost stp]# stap foo.stp
function: singleton
function: produce
function: produce
function: produce
function: produce
function: used
function: used
function: consumable
function: operator<<
function: ~LogLine
// 获取上下文变量
[root@localhost stp]# stap -L ‘process("/tmp/limlog/build/tests/LogTest").statement("*@Log.cpp")‘
process("/tmp/limlog/build/tests/LogTest").statement("LimLog@/tmp/limlog/limlog/Log.cpp:185") $this:class LimLog* const
process("/tmp/limlog/build/tests/LogTest").statement("LogLine@/tmp/limlog/limlog/Log.cpp:336") $this:class LogLine* const $level:enum LogLevel $loc:struct LogLoc const&
process("/tmp/limlog/build/tests/LogTest").statement("append@/tmp/limlog/limlog/Log.cpp:346") $this:class LogLine* const $data:char const* $n:size_t
process("/tmp/limlog/build/tests/LogTest").statement("consumable@/tmp/limlog/limlog/Log.cpp:140") $this:class BlockingBuffer const* const
process("/tmp/limlog/build/tests/LogTest").statement("consume@/tmp/limlog/limlog/Log.cpp:146") $this:class BlockingBuffer* const $to:char* $n:uint32_t
// 这里我们追踪 consume 函数中的两个参数
[root@localhost stp]# cat foo.stp
probe process("/tmp/limlog/build/tests/LogTest").function("consume") {
printf("func = %s, $var(n) = %d, $var(to) = %p\n", ppfunc(), $n, $to);
}
[root@localhost stp]# stap foo.stp
func = consume, $var(n) = 406, $var(to) = 0x7f902a94d010
func = consume, $var(n) = 203, $var(to) = 0x7f902a94d1a6
func = consume, $var(n) = 790, $var(to) = 0x7f902a94d010
func = consume, $var(n) = 3319, $var(to) = 0x7f902a94d326
func = consume, $var(n) = 4235, $var(to) = 0x7f902a94d010
func = consume, $var(n) = 4235, $var(to) = 0x7f902a94d010
func = consume, $var(n) = 2326, $var(to) = 0x7f902a94d010
func = consume, $var(n) = 8470, $var(to) = 0x7f902a94d010
在探测点被执行时打印这种简单的用法外，还能进一步做一些其它的事情。
[root@localhost stp]# cat foo.stp
#!/usr/bin/env stap
global top_funcs;
probe begin {
printf("=== begin ===\n");
}
probe process("/tmp/limlog/build/tests/LogTest").statement("*@Log.cpp") {
top_funcs[ppfunc()]++;
}
probe end {
foreach(func in top_funcs- limit 10)
printf("%s: %d\n", func, top_funcs[func]);
printf("=== end ===\n");
}
// LogTest 在3秒内执行最多的10个函数及次数
[root@localhost stp]# stap foo.stp -T 3
=== begin ===
produce: 1152
append: 720
singleton: 646
operator<<: 608
produceLog: 576
used: 576
consumable: 359
incConsumablePos: 64
getLogLevel: 32
LogLine: 32
=== end ===
[root@localhost stp]# cat foo.stp
#!/usr/bin/env stap
global top_exec;
probe begin {
printf("=== begin ===\n");
}
probe kernel.function("sys_write") {
top_exec[execname()]++;
}
probe end {
foreach(exec in top_exec- limit 10)
printf("%s: %d\n", exec, top_exec[exec]);
printf("=== end ===\n");
}
[root@localhost stp]# stap foo.stp -T 3
=== begin ===
qemu-kvm: 2948
sync: 2174
virsh: 673
libvirtd: 305
route: 28
grep: 21
ps: 21
ssh: 16
python: 16
nginx: 16
=== end ===
调用层次需要借助 thread_indent 来打印合适的缩进，另外需要设置函数入口（call）和返回（return）的探测点。函数命名不足以使用function通配符来匹配，而 statement 虽然可以匹配我们想要的结果（过滤第三方函数），但是不支持 call 和return。虽然有一个比较傻但是的确可行的方式是，在脚本里面手动写入这些函数。
// 先取出需要关注的函数名称
stap -L ‘process("/tmp/limlog/build/tests/LogTest").statement("*@*.cpp")‘ | sed ‘s/.*statement(\"\(.*\)@.*\".*/\1/g‘ | sort -u
脚本如下：
#!/usr/bin/env stap
global f;
function init() {
f["append"] = 1;
f["benchmark"] = 1;
f["consumable"] = 1;
f["consume"] = 1;
f["date"] = 1;
f["datetime"] = 1;
f["formatTimestamp"] = 1;
f["getLogLevel"] = 1;
f["gettid"] = 1;
f["i16toa"] = 1;
f["i2a"] = 1;
f["i32toa"] = 1;
f["i64toa"] = 1;
f["incConsumable"] = 1;
f["incConsumablePos"] = 1;
f["LimLog"] = 1;
f["~LimLog"] = 1;
f["listStatistic"] = 1;
f["log_10_diff_element_len"] = 1;
f["log_10_diff_element_str"] = 1;
f["log_10_diff_element_x1"] = 1;
f["log_16_same_element_x6"] = 1;
f["log_1_same_element_x6"] = 1;
f["log_4_same_element_x6"] = 1;
f["LogLine"] = 1;
f["~LogLine"] = 1;
f["LogSink"] = 1;
f["~LogSink"] = 1;
f["main"] = 1;
f["now"] = 1;
f["operator<<"] = 1;
f["produce"] = 1;
f["produceLog"] = 1;
f["rollFile"] = 1;
f["setLogFile"] = 1;
f["setLogLevel"] = 1;
f["setRollSize"] = 1;
f["singleton"] = 1;
f["sink"] = 1;
f["sinkThreadFunc"] = 1;
f["stringifyLogLevel"] = 1;
f["test_blocking_buffer"] = 1;
f["test_itoa"] = 1;
f["test_timestamp"] = 1;
f["time"] = 1;
f["u16toa"] = 1;
f["u2a"] = 1;
f["u32toa"] = 1;
f["u64toa"] = 1;
f["used"] = 1;
f["write"] = 1;
}
probe begin {
printf("=== begin ===\n");
init();
}
probe process("/tmp/limlog/build/tests/LogTest").function("*").call {
fn = ppfunc()
if (f[fn] == 1)
printf("%s -> %s\n", thread_indent(4), ppfunc());
}
probe process("/tmp/limlog/build/tests/LogTest").function("*").return {
fn = ppfunc()
if (f[fn] == 1)
printf("%s <- %s\n", thread_indent(-4), ppfunc());
}
probe end {
printf("=== end ===\n");
}
函数的部分调用树如下所示：
=== begin ===
0 LogTest(25381): -> main
101 LogTest(25381): -> setLogFile
111 LogTest(25381): -> singleton
121 LogTest(25381): -> LimLog
129 LogTest(25381): -> LogSink
270 LogTest(25381): -> now
282 LogTest(25381): <- now
288 LogTest(25381): -> date
296 LogTest(25381): -> datetime
453 LogTest(25381): <- datetime
472 LogTest(25381): <- date
478 LogTest(25381): <- LogSink
576 LogTest(25381): <- LimLog
586 LogTest(25381): <- singleton
603 LogTest(25381): -> rollFile
0 LogTest(25382): -> sinkThreadFunc
650 LogTest(25381): <- rollFile
···
树状调用可以很清楚的展示出来程序的执行逻辑，甚至可以看到多线程的处理：sinkThreadFunc 和 rollFile 之间的跨度。
观察 libguestfs 的启动过程及耗时，libvirt 支持function 和mark（有5个，大致逻辑上的埋点）
#! /usr/bin/env stap
global start_time, prev;
function display_time () {
now = gettimeofday_us ()
delta = (prev > 0 ) ? now - prev : 0
printf ("%18d (+%10d): ", now - start_time, delta)
prev = now
}
probe begin {
start_time = gettimeofday_us ()
prev = 0
printf ("%-18s (+%10s): %s\n", "# time_usec",
"delta usec", "event")
}
probe process("/usr/lib*/libguestfs.so.0*").function("*")
{
display_time()
printf ("%s\n", ppfunc())
}
打印的结果，如果使用 libguestfs-test-tools 执行失败，可以根据产生的函数进入源代码中进行排查，缩小排查的范围
[root@localhost stp]# stap libguestfs.stp
# time_usec (+delta usec): event
1880754 (+ 0): _init
1880765 (+ 11): frame_dummy
1880768 (+ 3): register_tm_clones
1880772 (+ 4): compile_regexp_re_hostname_port
1880804 (+ 32): init_libguestfs
1881074 (+ 270): guestfs_int_init_direct_backend
1881079 (+ 5): guestfs_int_register_backend
1881083 (+ 4): guestfs_int_init_libvirt_backend
1881085 (+ 2): guestfs_int_register_backend
1881088 (+ 3): guestfs_int_init_uml_backend
···
而 libvirt 中 example/ 目录中就有包含一些关于 systemtap 的脚本文件。
在函数调用树之上更进一步，加入样本的频率得到svg格式的火焰图，用户可以点击不同的图层来查看更详细的信息。
火焰图工具为brendangregg开发的开源项目FlameGraph，配合春哥写的systemtap工具，用一段简单的shell脚本如下，可以得到一张svg的图片
#!/bin/bash
# 火焰图工具的路径
FlameGraph_PATH="/FlameGraph"
# 春哥的栈收集工具
OR_Stap_PATH="/home/zxh/dev/openresty-systemtap-toolkit"
if [ $# != 1 ] ; then
echo "Usage: sh $0 PID"
echo " e.g.: sh $0 4396"
exit 1;
fi
${OR_Stap_PATH}/sample-bt -p $1 -t 180 -u > /tmp/bt-sample
${FlameGraph_PATH}/stackcollapse-stap.pl /tmp/bt-sample > /tmp/bt_stap.out
${FlameGraph_PATH}/flamegraph.pl /tmp/bt_stap.out > backtrace.svg
rm -rf /tmp/bt-sample
rm -rf /tmp/bt_stap.out
CPU定时采样，根据采样生成的 backtrace.svg 如下，横轴为CPU占用的时间比例，纵轴为函数调用的深度：
这是一个日志库的benchmark，而主要耗时也在阻塞队列的消费上，符合预期。
原文：https://www.cnblogs.com/shuqin/p/13196585.html