Qprof profiler example

This is a short sample qprof session, using a Cshell environment. This was run inside the qprof build directory itself; that matters only in that the alias.csh file was available in the local directory. More commonly this file would be run as part of a .cshrc file.

We assume that qprof was previously built by typing "make install". We then perform the following operations:

1. Read alias.csh to establish some convient aliases.
2. Set QPROF_COLOR to indicate that we would like profiling output in a different color to distinguish it from program output. (Version 0.4 and later.)
3. Start profiling using one of the just introduced aliases.
4. Build a debuggable test application, generating profiling output for all subprocesses run in the process. This gives us some information where the time is spent during compilation and linking. Each line indicates a distinguishable program unit, and the number of times we sampled an associated program counter. It would be more informative if the executables were debuggable. It would be more detailed if we had set QPROF_GRANULARITY to "instruction". (Occasionally qprof generates messages about modifying the signal behavior of the application. Some of these actions could interfere with the application, but this is very rarely the case. Here the messages about SIGCHLD can be ignored.)
5. Run the debuggable test application, obtaining line-level (the default) profiling output.
6. Set the QPROF_STACK environment variable to allow called functions to be included in their callers, and rerun the test application. This time we discover that we are also in _start and __libc_start_main 100% of the time. (These are both part of the runtime startup code. _start calls __libc_start_main which calls main. Thus both are running as long as the main program is. Call stack profiling a requires a qprof build with libunwind.)
7. Use the qprof_stop alias to discontinue profiling.

$ source alias.csh 
$ setenv QPROF_COLOR green 
$ qprof_start 
$ cc -g dumb_test.c
qprof: /usr/lib/gcc-lib/i386-redhat-linux/3.2/cc1: 10 samples, 10 counts
cc1                                                              10     (100%)
qprof: /usr/bin/as: 2 samples, 2 counts
as                                                               1      ( 50%)
as(_IO_default_xsputn)                                           1      ( 50%)
qprof: /usr/bin/ld: 11 samples, 11 counts
libbfd-2.13.90.0.2.so(bfd_lookup_arch)                           5      ( 45%)
ld(_IO_flockfile)                                                3      ( 27%)
ld(memcpy)                                                       1      (  9%)
ld(__read)                                                       1      (  9%)
ld(__write)                                                      1      (  9%)
qprof: Forcing SIGCHLD to be ignored
qprof: /usr/lib/gcc-lib/i386-redhat-linux/3.2/collect2: 0 samples, 0 counts
qprof: Forcing SIGCHLD to be ignored
qprof: /usr/bin/gcc: 0 samples, 0 counts
$ ./a.out
qprof: /home/hboehm/qprof/a.out: 118 samples, 118 counts
main:dumb_test.c:34                                              47     ( 40%)
main:dumb_test.c:35                                              47     ( 40%)
main:dumb_test.c:36                                              24     ( 20%)
$ setenv QPROF_STACK
$ ./a.out
qprof: /home/hboehm/qprof/a.out: 118 samples, 354 counts
_start                                                           118    (100%)
main:dumb_test.c:34                                              47     ( 40%)
main:dumb_test.c:35                                              47     ( 40%)
main:dumb_test.c:36                                              24     ( 20%)
a.out(__libc_start_main)                                         118    (100%)
$ qprof_stop