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

10429:	execve("/set/mercury/dist/fcs.2/sparc-S2/opt/SUNWspro/.../cc",
10429/1:	fork1()						= 10430
10430/1:	fork1()		(returning as child ...)	= 10429
10430/1:	execve("/set/mercury/dist/fcs.2/sparc-S2/opt/SUNWsp
10429/1:	fork1()						= 10432
10432/1:	fork1()		(returning as child ...)	= 10429
10432/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() = 0xff1eae90
10432/1@1:	-> lib_I_dbg_gen:dbg_set_state(0x4ee000, 0x0, 0x0, 0x4ee0a0)
10432/1@1:	<- lib_I_dbg_gen:dbg_set_state() = 0
10432/1@1:	-> lib_I_dbg_gen:dbg_set_state(0x0, 0x15f, 0x0, 0xff1e93e8)
10432/1@1:	<- lib_I_dbg_gen:dbg_set_state() = 0x4ee000
10429/1:	fork1()						= 10434
10434/1:	fork1()		(returning as child ...)	= 10429
10434/1:	execve("/set/mercury/dist/fcs.2/sparc-S2/opt/.../cg
10434/1@1:	-> lib_I_dbg_gen:dbg_set_state(0x0, 0x0, 0x0, 0x872564)
10434/1@1:	<- lib_I_dbg_gen:dbg_set_state() = 0xff1eae90
10434/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. 😉