YATT Yet Another Truss Testimonial

Truss has got to be the single most useful system utility.

It’s too bad that the command line options are so hard to figure out. The options themselves aren’t that bad,(although there are a lot) it’s just that the man page needs to be rewritten from the top down to account for the newer functionality,and describe it in a comprehensive way. (ha ha,“comprehensive”and “man page”. A contradiction in terms)

The compiler is a terrible thing to debug. (Ours is anyway.) There is a driver front end that parses the command line options,and then runs a sequence of different compiler phases. I maintain a library that’s called in different ways from each of of these phases. So in order to understand how my library is being called “from the compiler”I have to inspect what’s happening in each different phase.

Like some other complicated systems,there is a logging system that can record almost all of my library’s API usage in an automatic way. Usually this suffices for figuring out what’s going on. But today it wasn’t quite enough. The trace log wasn’t telling me which phase was calling which routines. Usually you can guess,but I didn’t want to guess.

Since truss can trace user level calls in shared libraries,I figured I’d give it a whirl. My library is called “lib_I_dbg_gen.so.1″and the function I wanted to watch was called “dbg_set_state”.

I use the -f option to truss because I have to trace through all the children of the compiler driver. I trace the fork/exec system calls so I can see what the child process is. And I tell truus to watch for PLT calls look to the function of interest. (This only works with shared library interfaces,but these days that a very wide net)

% truss -f -texec,fork -ulib_I_dbg_gen:dbg_set_state  cc -xO2 -c t.c10429:execve("/set/mercury/dist/fcs.2/sparc-S2/opt/SUNWspro/.../cc",10429/1:fork1()= 1043010430/1:fork1()(returning as child ...)= 1042910430/1:execve("/set/mercury/dist/fcs.2/sparc-S2/opt/SUNWsp10429/1:fork1()= 1043210432/1:fork1()(returning as child ...)= 1042910432/1:execve("/set/mercury/dist/fcs.2/sparc-S2/opt/SUNWspro/10432/1@1:->lib_I_dbg_gen:dbg_set_state(0x0,0x0,0x0,0x0)10432/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0xff1eae9010432/1@1:->lib_I_dbg_gen:dbg_set_state(0x4ee000,0x0,0x0,0x4ee0a0)10432/1@1:<- lib_I_dbg_gen:dbg_set_state() = 010432/1@1:->lib_I_dbg_gen:dbg_set_state(0x0,0x15f,0x0,0xff1e93e8)10432/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0x4ee00010429/1:fork1()= 1043410434/1:fork1()(returning as child ...)= 1042910434/1:execve("/set/mercury/dist/fcs.2/sparc-S2/opt/.../cg10434/1@1:->lib_I_dbg_gen:dbg_set_state(0x0,0x0,0x0,0x872564)10434/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0xff1eae9010434/1@1:->lib_I_dbg_gen:dbg_set_state(0x872000,0xff1e93e8,10434/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0

Presto! I can see exactly who’s calling my function. (I truncated the long pathnames for this message)

Of course,it would be nice to see each line labelled with the name of the process that causes that trace line,along with its parents,so I have a script stashed away for that purpose:

% truss .... 2>&1 | truss_anno   cc,16432:execve("/set/vulcan/dist/build14.0/...cc",...   cc,16432/1:fork1()= 16433  cc/??,16433/1:fork1()(returning as child ...)= 16432  cc/acomp,16433/1:execve("/set/vulcan/dist/build14.0/...acomp",...   cc,16432/1:fork1()= 16435  cc/??,16435/1:fork1()(returning as child ...)= 16432  cc/iropt,16435/1:execve("/set/vulcan/dist/build14.0/...iropt",...  cc/iropt,16435/1@1:->lib_I_dbg_gen:dbg_set_state(0x0,0x0,0x0,0x0)  cc/iropt,16435/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0xff1eb5a0  cc/iropt,16435/1@1:->lib_I_dbg_gen:dbg_set_state(0x4e6000,0x0,0x0,0x4e60a0)  cc/iropt,16435/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0  cc/iropt,16435/1@1:->lib_I_dbg_gen:dbg_set_state(0x0,0x15f,0x0,0xff1e9b00)  cc/iropt,16435/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0x4e6000   cc,16432/1:fork1()= 16437  cc/??,16437/1:fork1()(returning as child ...)= 16432  cc/cg,16437/1:execve("/set/vulcan/dist/build14.0/...cg",...  cc/cg,16437/1@1:->lib_I_dbg_gen:dbg_set_state(0x0,0x0,0x0,0x8724b0)  cc/cg,16437/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0xff1eb5a0  cc/cg,16437/1@1:->lib_I_dbg_gen:dbg_set_state(0x872000,0xff1e9b00,0x0,0x1806bc)  cc/cg,16437/1@1:<- lib_I_dbg_gen:dbg_set_state() = 0

Now,the truss_anno script isn’t such a big deal for a small test case like this,but when you’re using truss to debug a Makefile it’s a life-saver. One nice thing is that it’s stream-based,so you can use it as a pipe filter. You don’t have to collect the output to a file and then process it in a seperate step.

Perl is the tool that showed my I could conjur up complicated data structures (like trees of records) in almost no time. I’m sure I’ll rant about how wonderful that is at some future point.