Re: gprof reporting zero times for one program

[David Mathog]

Nick Clifton wrote:

> > Whereas for the development nettee:
> 
> > Each sample counts as 0.01 seconds.
> >  no time accumulated
> 
> Hmm, well it appears that there is no profiling information in the
gmon.out 
> file.  Have you checked that a gmon.out file is actually being
produced ?  And 
> that it is not empty ?

gmon.out is created and is not empty.  It contains some information as
the "called" columns have reasonable values, it is just times that are
all zero.

> 
> My first guess as to the cause would be that you are now linking with
startup 
> files which do not enable profiling.
I did that for an old version (which will profile) and the new one
(which will not) and could not see anything obviously different in the two.
  Try adding "-v" to the gcc command line 
> of the old and new nettee builds and see if different startup files
are being used.

The -v output looks the same, except for the lines in the new one which
result from the compile of the two new nio.c and rb.c files, that is,
the build for the previous one was:

gcc -Wall  -DNOUSLEEP -D_LARGEFILE64_SOURCE -D_POSIX_SOURCE -v -pg -g
-O0 -v -o nettee nettee.c>previous_v.txt 2>&1

and for the current one:

gcc -Wall  -DNOUSLEEP -D_LARGEFILE64_SOURCE -D_POSIX_SOURCE -v -pg -g
-O0 -o nettee nettee.c rb.c nio.c >current_v.txt 2>&1

ldd shows the same entries for both binaries.

I wonder if maybe this isn't some issue related to secondary files rb.c
and nio.c?  I tried 

export GPROF_PATH=/(the path)
gprof -l nettee

and while the times were all zero it did have line numbers in rb.c and 
nio.c.  So it found the source files and could read them ok.  Here are
the first two useful lines of gprof -l which show that it could resolve
line numbers in both nettee.c and rb.c, sorry about the wrap:

                0.00    0.00    7339/7339        transmit (nettee.c:1576
@ 804c5c8) [2241]
[2]      0.0    0.00    0.00    7339         rb_shadow_set_reconcile
(rb.c:427 @ 8052518) [2]

The time, self, and children fields are all zero, but the called graph
seems about right.

> 
> You might also try using the gcov program as an alternative to gprof (and 
> --coverage instead of -pg).

That ran and provided exactly the same coverage information which was
already in gprof, but no times.  Maybe I'm missing something but I do
not see how to induce gcov to emit execution times per line.

gcc -Wall  -DNOUSLEEP -D_LARGEFILE64_SOURCE -D_POSIX_SOURCE -coverage -g
-O0 -o nettee nettee.c rb.c nio.c
(run nettee on a transfer that took 38 seconds)
gcov nettee

The only change other than the use of multiple files, instead of
just one, that I can think of which might be causing this
is that the new version of nettee calls alarm(0) and alarm(time)
more frequently than did the previous version. If gprof embeds code
which uses the same mechanism it might never be seeing its timers going
off. Other than that, the rest of the code changes are just that - code
changes, there shouldn't be anything in normal logic to confuse gprof.
Valgrind runs cleanly so it isn't stomping on memory.

Thanks,

David Mathog
address@hidden
Manager, Sequence Analysis Facility, Biology Division, Caltech