This is a continuation from the previous Trace user program with SystemTap Part 1.
Last time, the purpose was "Let's see the movement without changing the existing source", This time, I will describe how to use SystemTap for the purpose of "when developing your own program, let's trace while outputting the variable value of the attention point as a debugging jig".
The following features were realized in the previous trace script. -Indentation by function depth -List of function arguments and their values -Return value from the function ・ Detection of system calls (open / close, etc.)
In addition to the above, I wanted the following output to follow the behavior of my own program. ・ I want to know where I passed when there was a branch in the function. ・ I want to know the value of the variable of interest.
I was able to do it. There are places where it seems possible to make it a more sophisticated method, but I will publish it as a method at this point.
The implementation procedure is described. SystemTap scripts and their corresponding header files for C ++, Shows the execution method and execution result of C ++ source code, SystemTap.
Suppose you have three files under the / home / TestProgs / tr1 / directory: "tr2.cpp", "ttr3.stp" and "ttr3.h" shown below.
/home/TestProgs/tr2/ttr3.stp
#!/usr/bin/stap
probe $1.begin
{
printf("[proc begin] pid=%d,procname=%s\n",
pid(), //Process number
execname() //Execution file name
);
}
probe $1.end
{
printf("[proc end] pid=%d,procname=%s\n", pid(), execname());
}
//Probe on system call
probe $1.syscall
{
# open systemcall
if( $syscall == 2) {
printf("%s open(%s)\n",thread_indent(0),kernel_string($arg1))
}
# close systemcall
else if ( $syscall == 3) {
printf("%s close(%d)\n",thread_indent(0), $arg1)
}
//system call number is"ausyscall --dump"It can be obtained with the command of.
}
//Probe to the start of a function
probe $1.function("*").call
{
printf("%s-->%s(%s) @%s %s\n",
thread_indent(0),
ppfunc(), //Function name(Class name and namespace are not displayed)
$$parms, //Argument list
usymfileline(addr()), //File name and line number
probefunc() //Function name(Not demangled)
);
thread_indent(1); //
}
//Probe to the end of the function
probe $1.function("*").return
{
thread_indent(-1);
printf("%s<--%s,%s\n",
thread_indent(0),
ppfunc(),
$$return //Return value
);
}
//define TR_FUNC() STAP_PROBE2(myTrace,lineFunc,__LINE__,__PRETTY_FUNCTION__)
probe $1.provider("myTrace").mark("lineFunc")
{
printf("%s%s:%d:%s\n",
thread_indent(0),
usymfile(addr()), //Source code filename
$arg1, // __LINE__
user_string($arg2) //User space string__PRETTY_FUNCTION__
);
}
//define TR_LINE() STAP_PROBE1(myTrace,line,__LINE__)
probe $1.provider("myTrace").mark("line")
{
printf("%s L:%d\n",
thread_indent(0),
$arg1 // __LINE__
);
}
//define TR_LINE_MSG(a1) STAP_PROBE2(myTrace,lineMsg,__LINE__,a1)
probe $1.provider("myTrace").mark("lineMsg")
{
printf("%s L:%d, %s",
thread_indent(0),
$arg1, // __LINE__
user_string($arg2)
);
}
//define TR_MSG(a1) STAP_PROBE1(myTrace,msg,a1)
probe $1.provider("myTrace").mark("msg")
{
printf("%s",
user_string($arg1)
);
}
//define TR_d(a1) STAP_PROBE2(myTrace,p_d,#a1,a1)
probe $1.provider("myTrace").mark("p_d")
{
printf("%s=%d ",
user_string($arg1),
$arg2
);
}
//define TR_u(a1) STAP_PROBE2(myTrace,p_u,#a1,a1)
probe $1.provider("myTrace").mark("p_u")
{
printf("%s=%u ",
user_string($arg1),
$arg2
);
}
//define TR_x(a1) STAP_PROBE2(myTrace,p_x,#a1,a1)
probe $1.provider("myTrace").mark("p_x")
{
printf("%s=0x%x ",
user_string($arg1),
$arg2
);
}
//define TR_s(a1) STAP_PROBE2(myTrace,p_s,#a1,a1)
probe $1.provider("myTrace").mark("p_s")
{
printf("%s='%s' ",
user_string($arg1),
user_string($arg2)
);
}
//define TR_LOCAL() STAP_PROBE(myTrace,local);
probe $1.provider("myTrace").mark("local")
{
printf("[$$locals] %s\n",$$locals); //All local variables in scope
}
We used provider (). Mark () to probe the source code. -The character string specified by povider () is used as the namespace, and the character string specified by mark () is used as the identification name. -From the C ++ source code side, the variable name and variable value are displayed with a simple printf image.
/home/TestProgs/tr2/ttr3.h
#ifndef __TTR3_MYTRACE_H_
#define __TTR3_MYTRACE_H_ 1
#ifndef NO_MYTRACE
#include <stdio.h>
#include <sys/sdt.h>
//Indent+Source file name+line number+Demangled function name+new line
#define TR_FUNC() STAP_PROBE2(myTrace,lineFunc,__LINE__,__PRETTY_FUNCTION__)
//Indent+line number+new line
#define TR_LINE() STAP_PROBE1(myTrace,line,__LINE__)
//Indent+line number+Argument string
#define TR_LINE_MSG(a1) STAP_PROBE2(myTrace,lineMsg,__LINE__,a1)
//Argument string
#define TR_MSG(a1) STAP_PROBE1(myTrace,msg,a1)
//Variable name and its value(printf%d format)
#define TR_d(a1) STAP_PROBE2(myTrace,p_d,#a1,a1)
//Variable name and its value(printf%u format)
#define TR_u(a1) STAP_PROBE2(myTrace,p_u,#a1,a1)
//Variable name and its value(printf%x format)
#define TR_x(a1) STAP_PROBE2(myTrace,p_x,#a1,a1)
//Variable name and its value(printf%s format)
#define TR_s(a1) STAP_PROBE2(myTrace,p_s,#a1,a1)
//Variable names and their values for all local variables in scope+new line
#define TR_LOCAL() STAP_PROBE(myTrace,local);
//Dummy test function
// "> stap -v ttr3.stp "When, ttr3.mark defined by stp()However, if it does not appear even once in the CPP code, the stap execution will result in an error.
//Also serves as a test code ttr3.mark defined by stap()All of these are described in this function.
void STAP_TRACE_defines(){
int dmyI=0;
const char *dmyS="dummy";
TR_FUNC();
TR_LINE();
TR_LINE_MSG("test mesg\n");
TR_MSG("test mesg\n");
TR_d(dmyI);
TR_u(dmyI);
TR_x(dmyI);
TR_s(dmyS);
TR_LOCAL();
printf("%s %d\n",dmyS,dmyI);
}
#else
#define TR_FUNC() /**/
#define TR_LINE() /**/
#define TR_LINE_MSG(a1) /**/
#define TR_MSG(a1) /**/
#define TR_d(a1) /**/
#define TR_u(a1) /**/
#define TR_x(a1) /**/
#define TR_s(a1) /**/
#define TR_LOCAL() /**/
#endif // NO_MYTRACE
#endif // __TTR3_MYTRACE_H_
-Use the STAP_PROBE system functions defined in sys / sdt.h to mark the probe position of SystemTap. -TR_d, TR_u_TR_x, TR_s have one argument, but the variable name and variable value are obtained using the # operator of #define. -TR_d, TR_u_TR_x, TR_s are defined in the form corresponding to% d% u% x% s of printf. Floating point is not enough ... -I also want to combine TR_d, TR_u_TR_x, and TR_s into one using a template, etc ... (But% d and% x are difficult to distinguish automatically because they depend on the purpose ...).
/home/TestProgs/tr2/tr2.cpp
#include <stdio.h>
#include <stdint.h>
#include <unistd.h>
#include <assert.h>
#include "ttr3.h"
class classSample1{
public:
classSample1(){};
~classSample1(){};
int func_C1(){
printf("classSample1::func_C1()\n");
TR_LINE(); //Indent line number Newline
return 0;
}
int func_C2(int m);
int cnt_func_C2 = 0;
};
int classSample1::func_C2(int m){
printf("classSample2::func_C2()\n");
TR_FUNC(); //Indent file name line number demangled function name line break
cnt_func_C2++;
int l= cnt_func_C2 % 2;
uint32_t u32=0xfffffffd + cnt_func_C2;
uint64_t u64=0xfffffffffffffffd + cnt_func_C2;
int32_t i32=-3 + cnt_func_C2;
int64_t i64=-3 + cnt_func_C2;
printf("cnt_func_C2 %d , l:%d ,u32:%u, u64:%lu\n",cnt_func_C2,l,u32,u64);
TR_LINE_MSG("");TR_d(cnt_func_C2);TR_d(l);TR_MSG("\n"); //Indent line number cnt_func_C2 value l value line feed
TR_LINE_MSG("");TR_d(i32);TR_u(u32);TR_d(i64);TR_u(u64);TR_MSG("\n"); //Indent line number i32 value u32 value i64 value u64 value line feed
TR_LINE_MSG("");TR_LOCAL(); //Indent All local variables in this scope()
assert(cnt_func_C2<m); //Suspended as an example.
if (l == 0) {
TR_LINE_MSG("even.\n"); //Indent line number string
return 0;
}else{
TR_LINE_MSG("odd.\n"); //Indent line number string
return 1;
}
}
int main(int argc, char *argv[])
{
int ret=0;
classSample1 c1;
for(;;) {
ret = c1.func_C1();
sleep(2);
ret = c1.func_C2(5);
sleep(2);
}
return ret;
}
-TR _ *** is added like printf.
> cd /home/TestProgs/tr2/
> gcc -Wall -g -O0 -std=c++11 tr2.cpp -o tr2 -lstdc++
> stap -v ttr3.stp 'process("/home/TestProgs/tr2/tr2")'
Give the argument a string containing the full path to the executable. The parser result as shown below is output.
stdout
Pass 1: parsed user script and 491 library scripts using 243904virt/56396res/3316shr/53796data kb, in 790usr/40sys/837real ms.
WARNING: function _start return probe is blacklisted: keyword at ttr3.stp:45:1
source: probe $1.function("*").return
^
Pass 2: analyzed script: 57 probes, 41 functions, 6 embeds, 2 globals using 246812virt/60696res/4680shr/56704data kb, in 120usr/110sys/228real ms.
Pass 3: translated to C into "/tmp/stap4b9QpY/stap_8a82d56cba8247f5ae53b508cd7dbe33_50483_src.c" using 246956virt/61192res/5028shr/56848data kb, in 50usr/110sys/159real ms.
Pass 4: compiled C into "stap_8a82d56cba8247f5ae53b508cd7dbe33_50483.ko" in 4050usr/640sys/4517real ms.
Pass 5: starting run.
-Waiting for execution of the target program
> cd /home/TestProgs/tr2/
> ./tr2
stdout
[proc begin] pid=16890,procname=tr2
0 tr2(16890): open(/etc/ld.so.cache)
0 tr2(16890): close(3)
0 tr2(16890): open(/lib64/libstdc++.so.6)
0 tr2(16890): close(3)
0 tr2(16890): open(/lib64/libgcc_s.so.1)
0 tr2(16890): close(3)
0 tr2(16890): open(/lib64/libc.so.6)
0 tr2(16890): close(3)
0 tr2(16890): open(/lib64/libm.so.6)
0 tr2(16890): close(3)
0 tr2(16890):-->_start() @0x4006e0 _start
19 tr2(16890):-->__libc_csu_init() @0x400a10 __libc_csu_init
32 tr2(16890): -->_init() @0x400628 _init
43 tr2(16890): <--_init,
47 tr2(16890): -->frame_dummy() @0x4007a0 frame_dummy
57 tr2(16890): -->register_tm_clones() @0x400740 register_tm_clones
68 tr2(16890): <--register_tm_clones,
70 tr2(16890): <--frame_dummy,
73 tr2(16890):<--__libc_csu_init,
86 tr2(16890):-->main(argc=0x1 argv=0x7ffc0ea27058) @/home/TestProgs/tr2/tr2.cpp:53 main
100 tr2(16890): -->classSample1(this=0x0) @/home/TestProgs/tr2/tr2.cpp:11 _ZN12classSample1C2Ev
113 tr2(16890): <--classSample1,
116 tr2(16890): -->func_C1(this=0x7ffc0ea26f50) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
222 tr2(16890): L:15
227 tr2(16890): <--func_C1,return=0x0
2003172 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
2003220 tr2(16890): /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
2003281 tr2(16890): L:34, cnt_func_C2=1 l=1
2003299 tr2(16890): L:35, i32=-2 u32=4294967294 i64=-2 u64=18446744073709551614
2003324 tr2(16890): L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x1 u32=0xfffffffe u64=0xfffffffffffffffe i32=0xfffffffffffffffe i64=0xfffffffffffffffe
2003337 tr2(16890): L:44, odd.
2003345 tr2(16890): <--func_C2,return=0x1
4003668 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
4003729 tr2(16890): L:15
4003738 tr2(16890): <--func_C1,return=0x0
6006538 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
6006587 tr2(16890): /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
6006612 tr2(16890): L:34, cnt_func_C2=2 l=0
6006630 tr2(16890): L:35, i32=-1 u32=4294967295 i64=-1 u64=18446744073709551615
6006655 tr2(16890): L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x0 u32=0xffffffff u64=0xffffffffffffffff i32=0xffffffffffffffff i64=0xffffffffffffffff
6006668 tr2(16890): L:41, even.
6006676 tr2(16890): <--func_C2,return=0x0
8008347 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
8008409 tr2(16890): L:15
8008418 tr2(16890): <--func_C1,return=0x0
10009956 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
10010004 tr2(16890): /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
10010028 tr2(16890): L:34, cnt_func_C2=3 l=1
10010046 tr2(16890): L:35, i32=0 u32=0 i64=0 u64=0
10010070 tr2(16890): L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x1 u32=0x0 u64=0x0 i32=0x0 i64=0x0
10010081 tr2(16890): L:44, odd.
10010089 tr2(16890): <--func_C2,return=0x1
12014178 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
12014238 tr2(16890): L:15
12014246 tr2(16890): <--func_C1,return=0x0
14014842 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
14014888 tr2(16890): /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
14014912 tr2(16890): L:34, cnt_func_C2=4 l=0
14014930 tr2(16890): L:35, i32=1 u32=1 i64=1 u64=1
14014953 tr2(16890): L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x0 u32=0x1 u64=0x1 i32=0x1 i64=0x1
14014965 tr2(16890): L:41, even.
14014972 tr2(16890): <--func_C2,return=0x0
16015484 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
16015579 tr2(16890): L:15
16015588 tr2(16890): <--func_C1,return=0x0
18020986 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
18021033 tr2(16890): /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
18021057 tr2(16890): L:34, cnt_func_C2=5 l=1
18021074 tr2(16890): L:35, i32=2 u32=2 i64=2 u64=2
18021098 tr2(16890): L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x1 u32=0x2 u64=0x2 i32=0x2 i64=0x2
[proc end] pid=16890,procname=tr2
Of the previous feature, -Indentation by function depth -List of function arguments and their values -Return value from the function ・ System call detection In addition to, -Output the line number where the branch passed -Display the variable name and its value for the variable of interest With the addition of I feel that it can be conveniently used for tracing jigs of my own programs, incident generation during testing, etc.
Recommended Posts