SystemTap----thread_indent()函数分析 –使用thread_indent分析代码执行时间

 

http://blog.csdn.net/justlinux2010/article/details/10269033

SystemTap----thread_indent()函数分析 –使用thread_indent分析代码执行时间

分类： SystemTap 2013-08-24 15:15 335人阅读 评论(0) 举报

thread_indent是systemtap中一个非常有用的函数，声明如下：

thread_indent:string(delta:long)

它可以输出当前probe所处的可执行程序名称、线程id、函数执行的相对时间和执行的次数（通过空格的数量）信息，它的返回值就是一个字符串。参数delta是在每次调用时增加或移除的空白数量。

在没有看thread_indent函数的实现之前，对delta参数的作用非常疑惑，也很好奇它的格式是怎么输出的，所以决定看看这个函数是怎么实现的。

systemtap中使用的一些库函数在tapset目录下（我的是/usr/local/systemtap-2.3/share/systemtap/tapset），使用grep命令找到thread_indent()函数在indent.stp文件中定义，实现如下所示：

function thread_indent:string (delta:long)
{
return _generic_indent (tid(), sprintf("%s(%d)", execname(), tid()), delta)
}

我们看到thread_indent()是直接调用的_generic_indent()函数，第一个参数是当前的线程id（tid()函数的返回值），第二个参数是一个字符串，由可执行程序名称和线程id组成，格式为"EXECNAME(TID)"，第三个参数就是thread_indent()的delta参数。

接下来看_generic_indent()中是怎么处理的，其源码如下：

global _indent_counters, _indent_timestamps

function _generic_indent (idx, desc, delta)
{
ts = __indent_timestamp ()
if (! _indent_counters[idx]) _indent_timestamps[idx] = ts

# pre-increment for positive delta and post-decrement for negative delta
x = _indent_counters[idx] + (delta > 0 ? delta : 0)
_indent_counters[idx] += delta

return sprintf("%6d %s:%-*s", (ts - _indent_timestamps[idx]), desc, (x>0 ? x-1 : 0), "")
}

_generic_indent()中首先调用__indent_timestamp()获取当前的Unix时间，时间存储在局部变量ts中。__indent_timestamp()直接调用gettimeofday_us()来获取的时间，参见indent_default.stp文件。

如果_indent_counters[idx]为0，即线程id为idx中是第一次调用indent_timestamp()，则将当前的时间存储在数组_indent_timestamps中以线程idx为索引的位置上。

接下来就会用到thread_indent()中的参数delta。从后面的sprintf中可以看出x的值将决定在":"后面输出的空格的数量，如果x是正值的话，则x的值就是空格的数量；如果x是负数，则在":"后面不会输出空格。

每次thread_indent()调用时，对应_indent_counters数组中的项（以线程id为索引）都会加上delta。

如果delta的值是0，则_indent_counters数组中对应的项一直为0，则x的值也一直是0，_indent_timestamps数组中对应项存储的时间每次也会被更新，所以在输出时（ts - _indent_timestamps[idx])总是0，并且不会输出空格。

如果delta的值为负数，则_indent_counters数组中对应的项也一直是负数，则x的值也是负数，这样在sprintf中也不会输出空格，但是，_indent_timestamps数组中对应项的时间值不会每次都更新，所以在输出的时候还是可以看到相对运行时间。

如果delta的值为正值，则indent_counters数组中对应的项是正数，并且会一直增加，则x的值也会增加，这样在后面的打印中输出的空格数量会越来越多，也可以输出运行的相对时间。

至此可以看出thread_indent()中的delta参数可以控制输出的空白的数量，也即空格数数量，还可以控制是否输出相对时间。

通过这个函数的输出结果你可以知道某个函数的执行一次的时间，找到系统中可能会造成瓶颈的一些点，具体的例子参见indent.stp文件的末尾。

如果这个函数不满足你的需求的话，可以参照其思路构造自己的thread_indent()函数，非常地方便!

Stp脚本示例1：

probe kernel.function("ip_rcv")

{

printf ("%s -> %s\n", thread_indent(1), probefunc())

}

probe kernel.function("ip_rcv").return

{

printf ("%s <- %s\n", thread_indent(-1), probefunc())

}

//关键在于thread_indent(1)，和后面的thread_indent(-1)的配合，这样可以打印ip_rcv函数入口到出口之间，函数执行的时间(us)，如果要分析其它代码流程的执行时间，可以参考这样编写stp脚本，只需要更改探测点即可，结果示例如下：

     0 swapper(0): -> ip_rcv

    15 swapper(0): <- ip_rcv  //说明第一次执行花了15us

     0 swapper(0): -> ip_rcv

    16 swapper(0): <- ip_rcv  //说明第二次执行花了16us

     0 swapper(0): -> ip_rcv

     6 swapper(0): <- ip_rcv

     0 swapper(0): -> ip_rcv

     6 swapper(0): <- ip_rcv

     0 swapper(0): -> ip_rcv

     4 swapper(0): <- ip_rcv