一个非常实用的 Systemtap 例子 linetimes.stp

SystemTap是一种系统级活动跟踪器，可以在Linux内核中监视和分析系统软件和硬件的行为。它允许开发人员和系统管理员使用高级脚本语言来创建和执行诊断和故障排除任务，以便更深入地了解系统性能问题。SystemTap提供了一个框架，以便用户编写自定义的脚本，这些脚本会在系统运行时插入到内核中, 经典SystemTap组成就是 probe (探测点) 与 handler(处理程序)。SystemTap脚本可以捕获和记录有关系统请求、I/O操作、进程行为等方面的信息，并可以根据需要对这些信息进行过滤、聚合和分析。 与其他性能分析工具相比，SystemTap的优点在于其高度可定制性和灵活性,调试点多,功能强大。除了监测,调试,分析 Linux 系统的利器. SystemTap 还可以用与监测调试库,已经用户的应用程序.

通过Systemtap, 我们可以清楚地了解内核,库,以及应用的详细运作流程, 就像其他的编程语言一样, Systemtap 也有自己一套语言(语法类似与 C, awk 和 shell, 上手非常简单,学习曲线平缓). 在Linux 系统中, 已有很多现成并且非常好用的例子 collection of examples .比如, 其中有一些Systemtap 的例子可以用来分析系统的问题, 有一些例子可以用于系统优化, 有一些例子可以用做内核 bug /CVE 漏洞实时修复等等.

Linux 系统带有的例子大概有 200 余个, 按照不同的功能和使用方式进行分类, 按照类似 “NETWORK”, “DISK”, “NFS”, “PROCESS” 等等进行划分. 通过这些功能的划分, 就可以很方便找到想要用的 Systemtap 的例子.

而在这些实用,功能强大的例子当中, 有个非常好用而且强大的例子, 叫做 linetimes.stp, 它在 “PROFILING” 这个分类下面. 通过使用这个 linetimes.stp , 我们可以清楚地监测,分析函数执行的时候, 它所调用的每一个函数的执行时间, 甚至是每一条语句的执行的时间. 这就大大方便了我们在对应用,内核,标准库/非标准库 做性能分析, 调试,优化的动作. 简直就像是茫茫大海的中一盏明灯.

如何来使用这个 linetime.stp 脚本呢?

这个脚本是 systemtap-client RPM 的一部分, 在 Red Hat Enterprise Linux (RHEL) , Fedor, CentOS, CentOS Stream 的系统上, 只要安装了 systemtap-client 这个 RPM 的话, 就可以在 /usr/share/systemtap/examples/profiling/ 路径下面找到它. 要执行它也非常简单, 只要我们执行下面的命令就可以了.

具体的命令解释, 在这条命令中, sudo 表示获取到相应权限, “stap” 为 SystemTap 执行的一个命令行前端, --example 参数表示不需要指定脚本绝对路径, 由 stap 来自动完成, 它会在所在路径中找到相应的脚本. linetimes.stp 为要执行的脚本, module("nfsd") 为 linetimes.stp 脚本的第一个参数, 表示想要分析 “nfsd” 这个内核模块. nfsd4_open 为linetimes.stp 脚本的第二个参数, 表示想要分析的模块中的 nfsd4_open 这个函数. -c sleep 10 作为”stap” 的参数, 表示希望 linetimes.stp 在执行 10 秒中后自动退出.

$ sudo stap --example linetimes.stp 'module("nfsd")' nfsd4_open -c "sleep 10"

执行完毕后, 可以看到类似下面的输出. 首先 module("nfsd") nfsd4_open call count: 12 这行表示在脚本对内核模块 nfsd 的函数 nfsd4_open 监控的 10 秒钟内, nfsd4_open 函数总共执行了 12 次. 而在接着下面的输出中region 列中 , 可以清晰地看到 nfsd4_open 这个函数的每一行执行的位置, 在 avg(us) 和 max(us) 列中, 可以看到对应的函数的每一行的执行的平均时间和最大执行时间 (单位是 us) .

可以特别关注这一行 module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:418") 3937 8962, 表示在模块源代码的 nfs4proc.c 的第 418 行中, 它的执行时间是最长的. 平均执行时间到了 3937 us. 进而可以去查看对应的内核源代码 (当前的环境是linux-4.18.0-375.el8.x86_64 ), 在路径/usr/src/debug/kernel-4.18.0-375.el8/linux-4.18.0-375.el8.x86_64/fs/nfsd/nfs4proc.c 下, 找到第 418 行, 那就可以清楚地知道,是因为 do_open_lookup 函数这个占用了最多的时间. 而这个函数是用于打开和查找文件时被调用的, 所以耗时也是一个正常行为了. 可以看到, 通过这个 linetimes.stp 很好的展示了一个模块执行分析情况, 给后续分析,优化提供了一个非常的好基础.

module("nfsd") nfsd4_open call count: 12
region                                           avg(us)	max(us)
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:352")      2      4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:353")      2      4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:354")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:357")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:358")      6      8
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:365")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:368")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:373")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:374")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:378")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:382")      5     18
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:383")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:395")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:397")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:402")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:403")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:408")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:411")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:415")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:418")   3937   	8962
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:419")      8      16
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:431")      5      5
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:432")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:453")      5      7
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:454")      2      3
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:457")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:460")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:461")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:462")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:463")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:465")      1      3
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:466")      1      2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:467")      1      2

这个 linetimes.stp 除了上面提供的输出信息之外, 还提供了一个代码的详细调用过程. 在输出中, from 和 to 表示从那一行开始, 执行到那一行, 也就是下面一行的输出是紧接着上面的一行的, 而在行数后面的数字则表示执行了的次数. 例如, 请看 from 的 module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:352")
到 to 的 module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:353") 12 的输出. 它们表示这行代码 nfsd4_open@fs/nfsd/nfs4proc.c:352 执行完后, 调用 nfsd4_open@fs/nfsd/nfs4proc.c:353 这行代码, 并且 nfsd4_open@fs/nfsd/nfs4proc.c:353 执行了 12 次.

另外一个有趣的例子是 from 的 module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:415"). 它后面有两个 to , 第一个是 module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:418") 执行了8次 , 而另外一个 to 是 module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:431"), 执行了4 次. 为什么同一行的代码后面后会调用两个不同行数的代码呢? 这是因为 nfsd4_open@fs/nfsd/nfs4proc.c:415 这行代码是一个 switch 语句(C 语言常见的 switch-case 语句 ), 所以从 from to 的调用关系还可以看得出来函数执行的一个逻辑. 而这样调用关系, 可以很好地给我们展示一个代码的逻辑结构.

control flow graph information
from
    to
=======================
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:352")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:353") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:353")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:354") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:354")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:357") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:357")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:358") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:358")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:365") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:365")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:368") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:368")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:373") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:373")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:374") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:374")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:378") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:378")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:382") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:382")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:383") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:383")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:395") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:395")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:397") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:397")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:402") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:402")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:403") 6
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:408") 6
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:403")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:408") 6
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:408")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:411") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:411")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:415") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:415")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:418") 8
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:431") 4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:418")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:419") 6
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:461") 2
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:419")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:461") 6
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:431")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:432") 4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:432")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:453") 4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:453")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:454") 4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:454")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:457") 4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:457")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:460") 4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:460")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:465") 4
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:461")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:462") 8
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:462")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:463") 8
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:463")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:465") 8
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:465")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:466") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:466")
    module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:467") 12
module("nfsd").statement("nfsd4_open@fs/nfsd/nfs4proc.c:467")
    module("nfsd").function("nfsd4_open@fs/nfsd/nfs4proc.c:350").return 12

那这个这么强大而且实用的Systemtap 脚本, 它又是怎么实现的呢?

小背景知识, 在程序的编译过程中, 编译器会生成的调试信息, 而这些信息会包含不同的有用信息，包括函数分布的区间, 机器指令与源文件的映射和与源代码行映射关系等。编译器会把这些信息做一个关联,并做相应的标记. 有了这些信息, 就为分析调试提供了前置条件. 接下来详细分析这个 linetimes.stp 脚本是怎么实现的.

// 定义了一个 probe 点(探测点), “$1” 为脚本输入的第一个参数 (可以是kernel, module 或者是application) @2 为脚本输入的第二个参数, 是代表函数的名字. "@*:*" 表示希望探测所有的文件以及所有的代码行. probe $1.statement(@2 "@*:*")

目前, 已经有了探测点了, 下一步则是在handler 中,如何计算探测点执行的时间和如何记录函数的调用关系了. 所以脚本里面需要来做一个记录. 而“times” 和 last_pp 是用来记录这些数据的全局关联数组. 在probe 对应的handler上, 使用 tid() (获取到线程的 ID) 这个tapset (可以理解为 systemtap 的库函数) 来关联起这些关联数组. 之所以使用 tid() 是因为这样可以在多线程的情况下也能很好的作为区隔.

默认情况下, 在没有监测到函数入口的时候, 关联数组的返回是 0 , 需要避免出现计算不准确(比如负数)的情况. 所以需要先判断这个 time[pid()] 关联数组是否为 0 数值. 假设是非 0 的话, 则表明已经有 probe 被触发了,其时间和probe 点信息已经被记录到了 times 和 last_pp 关联数组里面了.

接下来的 if 判断中, 是用于计算两个 probe 点间的时间差, 然后通过 <<< 运算符注入到”region” 关联数组中. 而 probe 点信息则通过”tid()” 存储到 last_pp 关联数组中. 最后则是将”from”和 to 调用路径存储到 cfg 关联数组中.

再接下来则更新关联数组 times 和 last_pp ,来看具体的解释.

// 定义 global 的关联数组, times, last_pp, region 和 cfg
global times, last_pp, region, cfg

// 定义了一个 “probe” 点, “$1” 脚本输入的第一个参数 (kernel, module 或者是application) “@2” 为脚本输入第二个参数, 就是函数的名字.  "@*:*" 表示希望探测所有的文件以及所有的代码行
probe $1.statement(@2 "@*:*") {

//  在 “probe” 点被触发时, 通过 “gettimeofday_us()”  获取从 epoch 的 “us” 时间, 存入临时变量 “t” 中
  t = gettimeofday_us()

// 线程上的上一次 “probe” 触发的时候存入到关联数组中. (通过”tid()”感知)
  s = times[tid()]

// 判断之前有没有 “probe” 点触发过. 有则进入 “if” 计算时间差
  if (s) {
	// 计算 “probe” 触发的时间差, 并且存入临时变量 “e” 中.
e = t - s

// 将时间差 “e” 存入到关联数组 ”region” 中, 并且通过 “last_pp[tid()]” 记录 “probe” 点.
	region[last_pp[tid()]] <<< e

	// 将 “probe” 点信息存储  “last_pp” 和 “pp()” 调用函数的信息存入到关联数组 “cfg” 中, 并且增加计数 
	cfg[last_pp[tid()], pp()] <<< 1
  }

// 更新 “times” 关联数组的时间信息, 为下一次计算做准备
  times[tid()] = t

// 更新 “last_pp” 为下一次记录函数做准备
  last_pp[tid()] = pp()
}

处理对函数调用的返回监测.

脚本对函数的监测可以参考上面针对代码行的方式, 但是需要特别监测函数的 return. 与上面主要区别是 在 return probe 中. 从关联数组中删除了 times 和 last_pp 旧的条目信息. 之所以是要删除是因为线程可能在执行过程中通过 return 离开函数后，然后又再次调用该函数, 如果不清除 times 和 last_pp 条目信息，可能记录就是两次 return 调用的时间了, 而不是所期望的真正的调用时间了. 下面则来看具体的分析.

//定义了一个 “probe” 点, “$1” 脚本输入的第一个参数 (kernel, module 或者是application) “@2” 为脚本输入第二个参数, 就是函数的名字.   “return” 表示为在函数 “return” 时触发.
probe $1.function(@2).return {

//   在 “probe” 点被触发时, 通过 “gettimeofday_us()”  获取从 epoch 的 “us” 时间, 存入临时变量 “t” 中
  t = gettimeofday_us()

//  线程上的上一次 “probe” 触发的时候存入到关联数组中. (通过”tid()”感知)
  s = times[tid()]
  
// 判断之前有没有 “probe” 点触发过. 有则进入 “if” 计算时间差
  if (s) {
	// 计算 “probe” 触发的时间差, 并且存入临时变量 “e” 中.
e = t - s

// 将时间差 “e” 存入到关联数组 ”region” 中, 并且通过 “last_pp[tid()]” 记录 “probe” 点.
	region[last_pp[tid()]] <<< e

	// 将 “probe” 点信息存储  “last_pp” 和 “pp()” 调用函数的信息存入到关联数组 “cfg” 中, 并且增加计数  
	cfg[last_pp[tid()], pp()] <<< 1
  }

// 清除关联数组” times” 的内容
  delete times[tid()]

// 清除关联数组” last_pp” 的内容
  delete last_pp[tid()]
}

处理对函数调用的入口的监测.

为了统计出代码的执行频率,以及函数调用的次数, 需要使用定义全局关联数组, 并对数组进行相应的操作来完成. 另外在 probe 里面, 可能会出现同时运行多个 probe 的情况, 所以使用统计运算符 <<< 来提高效率. 下面我们来看具体的实现.

// 定义了一个全局关联数组变量, "calls”
global calls

监测结果的输出

`// “probe” 的名字 “end”; “end” 是一个特殊的 “probe” 点, 用以表示结束
probe end {

// 使用printf 格式化输出. 它输出了监测的名字, 接着是监测的函数, 再来就是执行的次数.
  printf("\n%s %s call count: %d\n", @1, @2, @count(calls));
// 使用printf 格式化输出. 它输出了提示信息, 比如  region, avg(us) 和 max(us). 
  printf("\n%-58s %10s %10s\n", "region", "avg(us)", "max(us)");

// 使用 foreach 遍历 region, p+ 表示将输出的代码行进行排序.
  foreach (p+ in region) {

	// 使用 printf 输出代码行, 平均执行时间和最大执行时间
	printf("%-58s %10d %10d\n", p, @avg(region[p]), @max(region[p]));
  }

// 使用 printf 输出提示信息, 这个部分为输出调用关系
  printf("\n\ncontrol flow graph information\n")
  printf("from\n\tto\n=======================\n")

// 使用 foreach 再次遍历 region  
  foreach ([src+] in region) {

	// 第一层 foreach 通过printf 以降序的方式输出执行的代码行
 	printf("%-s\n", src)

	// 嵌套使用 foreach 遍历 “cfg”
 	foreach ([s,dest+] in cfg[src,*]) { # slice for all dest's
	
	// 第二层foreach 通过 “printf” 紧接着输出在外层 foreach 执行的代码行, 通过两层 foreach 就完成了调用的关系的输出.
    	printf("\t%-s %d\n", dest, @count(cfg[src,dest]));
 	}
  }
}

把以上过程分析综合起来就是 “linetimes.stp” 这个脚本了.

/usr/share/systemtap/examples/process/linetimes.stp

#!/usr/bin/stap
#
# Copyright (C) 2010-2015 Red Hat, Inc.
# Written by William Cohen 
#
# The linetimes.stp script takes two arguments: where to find the function
# and the function name. linetimes.stp will instrument each line in the
# function. It will print out the number of times that the function is
# called, a table with the average and maximum time each line takes,
# and control flow information when the script exits.
#
# For example all the lines of the do_unlinkat function:
#
# stap linetimes.stp kernel do_unlinkat

global calls, times, last_pp, region, cfg

probe $1.function(@2).call { calls <<< 1 }
probe $1.function(@2).return {
  t = gettimeofday_us()
  s = times[tid()]
  if (s) {
	e = t - s
	region[last_pp[tid()]] <<< e
	cfg[last_pp[tid()], pp()] <<< 1
  }
  delete times[tid()]
  delete last_pp[tid()]
}

probe $1.statement(@2 "@*:*") {
  t = gettimeofday_us()
  s = times[tid()]
  if (s) {
	e = t - s
	region[last_pp[tid()]] <<< e
	cfg[last_pp[tid()], pp()] <<< 1
  }
  times[tid()] = t
  last_pp[tid()] = pp()
}

probe end {
  printf("\n%s %s call count: %d\n", @1, @2, @count(calls));
  printf("\n%-58s %10s %10s\n", "region", "avg(us)", "max(us)");
  foreach (p+ in region) {
	printf("%-58s %10d %10d\n", p, @avg(region[p]), @max(region[p]));
  }

  printf("\n\ncontrol flow graph information\n")
  printf("from\n\tto\n=======================\n")
  foreach ([src+] in region) {
 	printf("%-s\n", src)
 	foreach ([s,dest+] in cfg[src,*]) { # slice for all dest's
    	printf("\t%-s %d\n", dest, @count(cfg[src,dest]));
 	}
  }
}
`

一些使用上的限制.

虽然 linetimes.stp 非常强大, 但是依然还是有它无法触及的地方

• 使用这个 SystemTap 脚本的时候, 因为涉及到函数的跳转, 可能会带来稍许的性能损耗, 但通常来说, 这个损耗会很小, 基本不会对被监测的代码造成太大的干扰. 这个 SystemTap 脚本特别适合监测分析一些函数调用较多的程序.
• 对于使用到 inline 的函数, 因为这些 inline 函数是没有 entry 和 return 的, 所以 linetimes.stp 是无法监测 inline 函数的. 而在有些特别的被编译器优化过的函数, linetimes.stp 也是无法精确的监测的.
• 有些编译器对编译出来的代码可能会重新调整顺序, 这样的情况下 linetimes.stp 脚本在调用的输出上,可能会有些偏差.
• 如果应用里面使用的递归函数调用, linetimes.stp 脚本的调用关系输出可能会出现 from 和 to 指向同一个的情况.

总结

如果在平时工作,测试,开发中配碰到一些棘手的系统问题, 那可以在考虑使用这些实用且强大 systemtap examples , 看看这些 SystemTap 例子中看看有没一些能满足问题场景的脚本. 如果有就可以拿来即用. 或者也可以通过相应的修改后, 作为一个针对特定场景脚本来使用. 同样, 通过 SystemTap 上游社区, 还可以发现更多关于SystemTap 宝藏.