[LINUX] User program tracing with SystemTap Part 2

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".

I want to use it as my own program development 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.

Example with sample code

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.

SystemTap script for tracing

/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
}

Supplement to ttr3.stp

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.

C ++ header file paired with ttr3.stp

/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_

Supplement to ttr3.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 ...).

Sample C ++ source code

/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;
}

Supplement

-TR _ *** is added like printf.

Compile C ++ source code

> cd /home/TestProgs/tr2/
> gcc -Wall -g -O0 -std=c++11 tr2.cpp -o tr2 -lstdc++

Run SystemTap script

> 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

Open another shell and execute the target program

> cd /home/TestProgs/tr2/
> ./tr2

Output of SystemTap script ttr3.stp

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.

Thank you for reading this far.

Recommended Posts

User program tracing with SystemTap Part 1
User program tracing with SystemTap Part 2
sandbox with neo4j part 10
Image processing with Python (Part 2)
Studying Python with freeCodeCamp part1
Bordering images with python Part 1
Scraping with Selenium + Python Part 1
Image processing with Python (Part 1)
Solving Sudoku with Python (Part 2)
Image processing with Python (Part 3)
Scraping with Selenium + Python Part 2