gprof reporting zero times for one program

[David Mathog]

I'm having issues with gprof reporting empty times on the development
version of my network program nettee.  For a "normal" program (reads
and writes files, no network) the results show reasonable times.  In
fact, for the last release of nettee (0.1.8) gprof worked too.  However
for the version I'm working on now gprof only shows 0.0 in the time fields.

Software:
Mandriva 2007.1
Dual Opterons
binutils-2.17.50.0.9-1mdv2007.1
gcc-4.1.2-1mdv2007.1

This works as expected:

gcc -pg -O0 -g -lm -o fastaproperties fastaproperties.c
gunzip -c /usr/common/BLASTDB/dm_dna.nt.gz |./fastaproperties -
gprof -l fastaproperties > goo.txt

with output like (sorry about the wrap):

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
 56.73      0.60     0.60                             main
(fastaproperties.c:148 @ 8048ddb)
 23.84      0.85     0.25                             main
(fastaproperties.c:147 @ 8048e15)
  9.54      0.95     0.10                             main
(fastaproperties.c:144 @ 8048d8d)
  4.29      0.99     0.05                             main
(fastaproperties.c:147 @ 8048dd2)

Whereas for the development nettee:

gcc -Wall  -DNOUSLEEP -D_LARGEFILE64_SOURCE -D_POSIX_SOURCE  -pg -O0 -g
-o nettee nettee.c rb.c nio.c
./nettee  -v 255 -next monkey01 -in - </usr/common/BLASTDB/dm_dna.nt.gz
2>stderr.log
#this copies that largish file to node monkey01 in about 6 seconds
gprof -l nettee >foo.txt

produces (again, sorry about the wrap):

Flat profile:

Each sample counts as 0.01 seconds.
 no time accumulated

  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
  0.00      0.00     0.00      608     0.00     0.00 
rb_shadow_set_reconcile (rb.c:427 @ 8051b70)
  0.00      0.00     0.00      330     0.00     0.00 
writenbytes_noblock_n (nio.c:1267 @ 805579d)
  0.00      0.00     0.00      315     0.00     0.00 
readnbytes_noblock_n (nio.c:1323 @ 80558a0)
  0.00      0.00     0.00      311     0.00     0.00  write_rb_noblock_n
(nio.c:1155 @ 80554fc)
  0.00      0.00     0.00      297     0.00     0.00  read_rb_noblock_n
(nio.c:1105 @ 805537f)

This is not very helpful.  The program uses a standard sort
of network methodology, where it runs in a while loop using FD_SET,
runs select, and then reads/writes from/to those inputs/outputs which
select has marked as ready.  I know the program spends 99% of its time
in a routine called transmit(), where all of this work is performed,
but transmit is at the very end of the first list and looks like this:

  0.00      0.00     0.00        1     0.00     0.00  transmit
(nettee.c:1306 @ 804b7b1)

I tried transferring a larger file which took 20 seconds, but still all
the fields held 0.00 seconds.

Here's the older version:

gcc -Wall  -DNOUSLEEP -D_LARGEFILE64_SOURCE -D_POSIX_SOURCE  -pg -g -o
-O0 nettee ../nettee-0.1.8/nettee.c
./nettee  -v 255 -next monkey01 -in - </usr/common/BLASTDB/am_dna.nt.gz
2>stderr.log
gprof -l nettee >foo.txt

which looks fine:

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
 54.29      0.19     0.19                             writenbytes
(nettee.c:913 @ 804a30a)
 30.00      0.30     0.11                             writenbytes
(nettee.c:914 @ 804a326)
 12.86      0.34     0.05                             writenbytes
(nettee.c:916 @ 804a32c)
  2.86      0.35     0.01                             writenbytes
(nettee.c:912 @ 804a359)
  0.00      0.35     0.00    34071     0.00     0.00  readnbytes
(nettee.c:933 @ 804a36a)

What could be the problem in the new version of this program which is so
confusing gprof?  I've run nettee in valgrind and it was well behaved
running in there (albeit really slow).

Thanks,

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