Systemtap examples, Profiling - 2 Call Graph Tracing

背景

例子来自para-callgraph.stp 脚本, 该脚本用以输出指定函数的call,return之间发生的所有函数调用情况, 类似在PostgreSQL plpgsql中输出call stack.  
脚本内容以及注解 :   
[root@db-172-16-3-150 network]# cd /usr/share/systemtap/testsuite/systemtap.examples/profiling  
[root@db-172-16-3-150 profiling]# cat para-callgraph.stp  
#! /usr/bin/env stap  
  
function trace(entry_p, extra) {  
  %( $# > 1 %? if (tid() in trace) %)  // systemtap 预编译,  $#表示stap 传入的参数个数, 当参数个数大于1时, if (...)  
  // 参考  

http://blog.163.com/digoal@126/blog/static/16387704020139831157191/

  printf("%s%s%s %s\n",  
         thread_indent (entry_p),   // entry_p, 空格个数  
         (entry_p>0?"->":"<-"),  // entry_p>0时->, 否则<-  对应 $1.call和$1.return 的传入的1和-1 . 可以看清函数调用结构.  
         pp (),  
         extra)  
}  
  
%( $# > 1 %?   // systemtap 预编译,   
global trace  
probe $2.call {  
  trace[tid()] = 1  // 如果有2个stap参数, 第二个参数设置trace数组, 通过if (tid() in trace)判断函数trace是否需要输出printf....  
}  
probe $2.return {  
  delete trace[tid()]  // 函数返回后, 删除这个数组索引. 这样的话只有$2相关的函数事件才会输出printf(...)  
// 也就是说在$2.call触发后, $2.return触发前, 所有的$1的事件都会有printf输出.  
}  
%)  
  
probe $1.call   { trace(1, $$parms) }  // 输出函数的参数  
probe $1.return { trace(-1, $$return) }  // 输出函数返回值  
// 这个例子如果只有1个stap参数, 那么会输出所有与这个参数相关的调用情况和返回情况.  
// 如果有2个参数, 那么当第二个参数对应的事件被第一个参数包含时, 仅仅输出第二个参数事件的详细调用情况.  
// 如果传入参数为2, 那么去除预编译后的脚本如下 :   
#! /usr/bin/env stap  
  
function trace(entry_p, extra) {  
if (tid() in trace)  
  printf("%s%s%s %s\n",  
         thread_indent (entry_p),  
         (entry_p>0?"->":"<-"),  
         pp (),  
         extra)  
}  
  
global trace  
probe $2.call {  
  trace[tid()] = 1  
  trace(1, $$parms)  // 加这行, 方便观察$2.call触发开始.  
}  
probe $2.return {  
  trace(-1, $$return)  // 加这行, 方便观察  
  delete trace[tid()]  
  exit() // 加这行方便观察单次$2事件的中间调用, .$2.return触发后, stap立刻退出  
}  
  
probe $1.call   { trace(1, $$parms) }  
probe $1.return { trace(-1, $$return) }  
  
执行输出举例 :   
// 第一个参数 'kernel.function("*@fs/*.c")'  
// 第二个参数 'kernel.function("sys_read")'  
// 第一个参数通配符中已经包含了第二个参数的事件.  
[root@db-172-16-3-150 ~]# stap -L 'kernel.function("*@fs/*.c")'|grep sys_read  
...  
kernel.function("sys_read@fs/read_write.c:389") $fd:unsigned int $buf:char* $count:size_t $fput_needed:int  
...  
// 因此以下stap的执行结果应该是只包含'kernel.function("sys_read")'的调用和返回以及他们内部调用其他与'kernel.function("*@fs/*.c")'通配符匹配的函数事件. 不会出现其他函数的输出.  
// 以下结果我们看到sys_read这个函数中间还调用了其他什么函数(kernel.function("*@fs/*.c")通配符匹配的函数).  
[root@db-172-16-3-150 profiling]# stap para-callgraph.stp 'kernel.function("*@fs/*.c")' 'kernel.function("sys_read")'  
     0 stapio(6305):->kernel.function("sys_read@fs/read_write.c:389").call fd=0x4 buf=0x7fff7c222af0 count=0x2004  
    10 stapio(6305): ->kernel.function("fget_light@fs/file_table.c:298").call fd=0x4 fput_needed=0xffff8817e3005f54  
    15 stapio(6305): <-kernel.function("fget_light@fs/file_table.c:298").return return=0xffff88181950cc80  
    33 stapio(6305): ->kernel.function("vfs_read@fs/read_write.c:294").call file=0xffff88181950cc80 buf=0x7fff7c222af0 count=0x2004 pos=0xffff8817e3005f48  
    40 stapio(6305):  ->kernel.function("rw_verify_area@fs/read_write.c:232").call read_write=0x0 file=0xffff88181950cc80 ppos=0xffff8817e3005f48 count=0x2004  
    45 stapio(6305):  <-kernel.function("rw_verify_area@fs/read_write.c:232").return return=0x2004  
    51 stapio(6305):  ->kernel.function("inotify_inode_queue_event@fs/notify/inotify/inotify.c:297").call inode=0xffff881816fbd3d8 mask=0x1 cookie=0x0 name=0x0 n_inode=0x0  
    55 stapio(6305):  <-kernel.function("inotify_inode_queue_event@fs/notify/inotify/inotify.c:297").return   
    60 stapio(6305):  ->kernel.function("__fsnotify_parent@fs/notify/fsnotify.c:80").call dentry=0xffff88172e1c7680 mask=0x1  
    64 stapio(6305):  <-kernel.function("__fsnotify_parent@fs/notify/fsnotify.c:80").return   
    69 stapio(6305):  ->kernel.function("inotify_dentry_parent_queue_event@fs/notify/inotify/inotify.c:329").call dentry=0xffff88172e1c7680 mask=0x1 cookie=0x0 name=0xffff88172e1c7720  
    73 stapio(6305):  <-kernel.function("inotify_dentry_parent_queue_event@fs/notify/inotify/inotify.c:329").return   
    79 stapio(6305):  ->kernel.function("fsnotify@fs/notify/fsnotify.c:135").call to_tell=0xffff881816fbd3d8 mask=0x1 data=0xffff881816fbd3d8 data_is=0x2 file_name=0x0 cookie=0x0  
    83 stapio(6305):  <-kernel.function("fsnotify@fs/notify/fsnotify.c:135").return   
    86 stapio(6305): <-kernel.function("vfs_read@fs/read_write.c:294").return return=0xc  
    91 stapio(6305): ->kernel.function("fput@fs/file_table.c:196").call file=0xffff88181950cc80  
    94 stapio(6305): <-kernel.function("fput@fs/file_table.c:196").return   
   107 stapio(6305):<-kernel.function("sys_read@fs/read_write.c:389").return return=0xc  
// 如果把$1的范围放大到所有函数, 则可以跟踪到sys_read的所有函数调用. 但是这样会比较慢甚至把操作系统搞挂. 产生的ko也非常巨大.  
  
本文事件源代码 :   
SYSCALL_DEFINE3(read, unsigned int, fd, char __user *, buf, size_t, count)  
{  
        struct file *file;  
        ssize_t ret = -EBADF;  
        int fput_needed;  
  
        file = fget_light(fd, &fput_needed);  
        if (file) {  
                loff_t pos = file_pos_read(file);  
                ret = vfs_read(file, buf, count, &pos);  
                file_pos_write(file, pos);  
                fput_light(file, fput_needed);  
        }  
  
        return ret;  
}  

参考

1. https://sourceware.org/systemtap/SystemTap_Beginners_Guide/mainsect-profiling.html

2. https://sourceware.org/systemtap/examples/

3. /usr/share/systemtap/testsuite/systemtap.examples

4. systemtap-testsuite

5. /usr/share/systemtap/testsuite/systemtap.examples/index.txt

6. /usr/share/systemtap/testsuite/systemtap.examples/keyword-index.txt

7. /usr/share/systemtap/tapset

8. http://blog.163.com/digoal@126/blog/static/163877040201362691522349/

9. http://blog.163.com/digoal@126/blog/static/16387704020139831157191/

digoal’s 大量PostgreSQL文章入口