Friday Aug 27, 2010

Using DTrace to profile function flows in your C programs

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


#include <stdio.h>
int add(int a, int b);
int sub(int a, int b);
int main()
{
    int a;
    int b;
    int c;
    printf("\\nEnter A and B: ";);
    scanf("%d%d", &a, &b);
    c = add(a, b);
    printf ("\\n Val - %d", c);

}

int add(int a, int b)
{
    return (sub(a, b));

}

int sub(int a, int b)
{
    int c = a - b;
    return (c);
}


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.



Sunday Dec 20, 2009

What happens under the hood when you execute your C Programs?

I was a little curious to find out how my program gets executed. In order to find that out, I decided to write a simple c program which is here:



 #include <stdio.h>
int main()
{
    sleep(30);
    printf("Just testing an application!");
}



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



kumar@myosbox:~/Desktop/Demos$ ./sunCCOutput 
kumar@myosbox:~/Desktop/Demos$ pfexec dtrace -F -s pid.d `pgrep sunCCOutput` printf > SunCCOutput.txt
dtrace: script 'pid.d' matched 6712 probes
kumar@myosbox:~/Desktop/Demos$ ./gccOutput
kumar@myosbox:~/Desktop/Demos$ pfexec dtrace -F -s pid.d `pgrep gccOutput` printf > gccOutput.txt
dtrace: script 'pid.d' matched 6714 probes



Now, the content of the file SunCCOutput.txt is as follows:



CPU FUNCTION                                 
1 -> printf
1 -> _setorientation
1 <- _setorientation
1 -> _ndoprnt
1 -> _findbuf
1 -> isatty
1 -> ___errno
1 <- ___errno
1 -> ioctl
1 <- ioctl
1 <- isatty
1 -> _setbufend
1 -> getxfdat
1 <- getxfdat
1 -> isseekable
1 -> ___errno
1 <- ___errno
1 -> fstat64
1 <- fstat64
1 -> ___errno
1 <- ___errno
1 <- isseekable
1 <- _setbufend
1 <- _findbuf
1 -> _realbufend
1 -> getxfdat
1 <- getxfdat
1 <- _realbufend
1 -> memcpy
1 <- memmove
1 <- memcpy
1 -> memchr
1 <- memchr
1 -> ferror
1 <- ferror
1 <- _ndoprnt
1 -> ferror
1 <- ferror


Contents of the file gccOutput.txt is as follows:



CPU FUNCTION                                 
1 -> printf
1 -> _setorientation
1 <- _setorientation
1 -> _ndoprnt
1 -> _findbuf
1 -> isatty
1 -> ___errno
1 <- ___errno
1 -> ioctl
1 <- ioctl
1 <- isatty
1 -> _setbufend
1 -> getxfdat
1 <- getxfdat
1 -> isseekable
1 -> ___errno
1 <- ___errno
1 -> fstat64
1 <- fstat64
1 -> ___errno
1 <- ___errno
1 <- isseekable
1 <- _setbufend
1 <- _findbuf
1 -> _realbufend
1 -> getxfdat
1 <- getxfdat
1 <- _realbufend
1 -> memcpy
1 <- memmove
1 <- memcpy
1 -> memchr
1 <- memchr
1 -> ferror
1 <- ferror
1 <- _ndoprnt
1 -> ferror
1 <- ferror

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!

About

I am Abhishek and I work for Sun/Oracle! In this blog, I share my interest in systems, solaris, linux and other technologies :-)

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today