Oracle Blog

Sun, Systems and Solaris!

Friday Aug 27, 2010

Quite often, you may would have come across scenarios where you would want to prepare a trace of your own program and understand what is the execution flow of a particular function in your C program. In this example I will show you how exactly you can do that using DTrace.

Here is a simple C Program which implements two functions (add and sub).

Now I would like to trace the function add in this program and see what functions, in turn, are invoked when add is executed.

DTrace Code:

pid$1:test:$2:entry{ self->trace = 1;}

pid$1::$2:return/self->trace/{ self->trace = 0;}

pid$1:::entry,pid$1:::return/self->trace/{}

I will my binary test (using -o flag) and I will be exacuting this
binary by ./test. In another terminal, I will execute this DTrace
script, which uses the pid provider.
Notice the probe description, the module part of it carries the name of
my program binary (this way only those function calls made in the
context of my program will be traced. If you leave the module part
blank in the probe description, all function calls (including system
calls) will be included in the trace).

Let us compile this application (I am using Sun compiler, you can use gcc as well)

kumar@sunsolaris:~/Desktop$ cc -o test myc.c

Now let us run the DTrace script in another terminal window:

kumar@sunsolaris:~/Desktop$ dtrace -F -s myfunc.d `pgrep test` add

And here is the output:

As you can see, the script tells me that add function calls sub. Just imagine your C application having 1000 functions, and the simplicity that you can bring to the whole debugging process if you can understand the flow with this ease.

I have kept the sleep(30) in the beginning of the program so as to give me time to execute the DTrace script, about which I will be talking a little later.

Now i complied it with Sun Compiler and GCC

kumar@myosbox:~/Desktop/Demos$ suncc -o sunCCOutput simplec.c

kumar@myosbox:~/Desktop/Demos$ gcc -o gccOutput simplec.c

Now I wrote a simple DTrace script using the pid provider in order to figure out how printf is implemented (execution detail - functions which get invoked when printf function is called) in these compilers. The dtrace script is below:

pid$1::$2:entry{ self->trace = 1;}

pid$1::$2:return/self->trace/{ self->trace = 0;}

pid$1:::entry,pid$1:::return/self->trace/{}

Now it was the time to execute this script and compare the outputs. I am going to redirect the output of this script into two text files (sunCCOutput.txt and gccOutput.txt).

So you can see that there is no difference between gcc and suncc when if comes to implement the printf function. But its is so interesting to see that there are 19 function calls made everytime I use a printf in my c program! WOW! ;) I wonder if I could know it this easily if there was no Dtrace!