在做性能profile的时候,直观上感觉应该在profile的时候只记录基本数据,在最终记录完成后一次性进行符号解析,防止对系统性能造成影响。
所以写的probe脚本是这样的:
systemtap script:
global bts; // backtraces
probe timer.profile {
if (pid() == target()) {
bts[ubacktrace()] ++; // record every tick when in specific process
}
}
probe timer.s(5) {
exit(); // exit after 5 seconds
}
probe end {
foreach (count = bt in bts-) {
print_usyms(bt);
printf("\t%d\n", count);
}
}
但实际使用过程中,print_usyms()总是无法将符号解析出来。
怀疑stap命令行参数出错,将stap manual看了一遍又一遍,将-d/-ldd/--skip-badvars/--all-modules这些只要看着相关的参数一个个都加上了,还是不行。
怀疑stap版本太低,编译了最新版本也不行。
怀疑probe end时符号信息已经不存在了,在probe timer.profile中进行输出:
global bts;
global requestquit;
global quit;
probe begin {
requestquit = 0;
quit = 0;
}
probe timer.profile {
if (!requestquit) {
if (pid() == target()) {
bts[ubacktrace()] ++
}
} else {
if (!quit) {
quit = 1;
foreach (count = bt in bts-) {
print_usyms(bt);
printf("\t%d\n", count);
}
exit();
}
}
probe timer.s(5) {
requestquit = 1;
}
满怀信心去尝试,沮丧地发现还是不行。
最终忽然想到,timer类打点都是异步的,大部分timer.profile打点时(也就是每一个jiffy时钟中断发生时),当前cpu很可能没有执行到target()进程,这样print_usyms/print_ustack很可能拿不到当前进程的符号信息。print_usyms应该在pid()==target()时执行才能展示该进程的符号信息!再改:
global bts
global requestquit
global quit
probe begin {
requestquit = 0
quit = 0
}
probe timer.profile {
if (pid() == target()) {
if (!requestquit) {
bts[ubacktrace()] ++
} else {
if (!quit) {
quit = 1;
foreach (count = bt in bts-) {
print_syms(bt);
printf("\t%d\n", count);
}
exit();
}
}
}
}
probe timer.s(5) {
requestquit = 1
}
哈哈,搞定。
总结两点经验教训:
1. timer类异步事件发生时,cpu很可能没有在执行你希望观测的进程。实际上对于被监测的把单核占满的测试程序,在6核机器上,timer.profile只有1/4~1/3的打点是在target进程中的。
2. 当解析用户态符号时,如果当前上下文不是被观测的进程,则无法解析。