2

When profiling my code, gprof is outputting the following:

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 30.69     10.55    10.55                             _L_lock_154
 16.58     16.25     5.70 1126059616     0.00     0.00  double_cmp
 14.25     21.15     4.90    13737     0.36     0.36  bsdi
 10.01     24.59     3.44                             memcpy

(to take the 1st few lines only)

taking the top spot is a function i do not recognise, and neither does google unfortunately.

what could it be - does anyone know? as its taking up the lions share of my time i would be keen to find out.

using mikes suggestion for DIY profiling, I see this stack backtrace quite often:

Program received signal SIGINT, Interrupt.
0xb7fff424 in __kernel_vsyscall ()
(gdb) bt
#0  0xb7fff424 in __kernel_vsyscall ()
#1  0x080ada62 in __write_nocancel ()
#2  0x080859c1 in _IO_new_file_write ()
#3  0x08084b64 in new_do_write ()
#4  0x080861ed in _IO_new_do_write ()
#5  0x080869c5 in _IO_new_file_overflow ()
#6  0x08085f3e in _IO_new_file_xsputn ()
#7  0x080c4d54 in vfprintf ()
#8  0x080b071c in __fprintf_chk ()
#9  0x0805ec36 in fprint_track_hum ()
#10 0x0805efe1 in fprint_hash_tracks ()
#11 0x08049c33 in main (argc=22, argv=0xbfffeac4) at harness.c:537

although i don't see the call to _L_lock_154, I'm starting to think it might be something printing to file/stdio.h related - a lock on writing to a file pointer or some such. So I'll try and disable all printing and re-profile, see if the mystery function disappears..

UPDATE #1

no - its still a bit of a mystery, disabled all output to file/stdout but the sinistrous _L_lock_154 is still taking up 10% of my time. Could be something to do with reading from file but I can't run my harness without some input..

I'm really surprised google draws a blank on this - very rare..

UPDATE #2

just ran gprof in call graph rather than flat mode - it spits out this for _L_lock_154:

granularity: each sample hit covers 4 byte(s) for 0.03% of 36.86 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]     49.6   11.82    6.45                 _L_lock_154 [1]
                5.84    0.00 1198163721/1198163721     double_cmp [8]
                0.52    0.00 125628587/125628587     fptype_cmp [24]
                0.04    0.00 13096233/13096233     grp_cmp_by_density_descending [52]
                0.04    0.00 3464916/3464916     pdw_ptr_cmp_by_amp [53]
                0.01    0.00   73812/73812       pdw_ptr_cmp_by_idx [89]
                0.00    0.00   71682/9288620     int_cmp [44]
                0.00    0.00  636314/842100      pri_ptr_cmp_by_second_pdw_idx [123]
                0.00    0.00  277089/407783      pri_ptr_cmp_by_first_pdw_idx [124]
                0.00    0.00   76178/76178       window_cmp_by_emitter_id [128]
                0.00    0.00   10147/10147       pri_ptr_cmp_by_first_pdw_toa [137]
-----------------------------------------------

I'm sure this is trying to tell me something, but I'm not sure how to interpret it? All my cmp type functions are for use with qsort from stdlib - if _L_lock_154 is the parent to all these calls does it imply it is an alias for qsort?

bph
  • 10,728
  • 15
  • 60
  • 135
  • Symbols with a leading underscore and a capital leter are reserved for the compiler/C library for internal names. – Some programmer dude Feb 23 '15 at 11:59
  • If you haven't called that function, look who has, I'd say. – mafso Feb 23 '15 at 12:16
  • any ideas how i might do that, maybe an nm on the gcc runtime lib? – bph Feb 23 '15 at 12:25
  • If it is there, you would find it, and maybe _potential_ callers from within there. I would start with setting a breakpoint in the debugger and look who really calls it in your program (and who calls it that often). If this doesn't give you a hint after a few calls, that method is probably a little tedious, though. – mafso Feb 23 '15 at 12:39
  • i know it is not 'explicitly' (or directly) called from my program - how can i break on it when it is getting called implicitly/indirectly from some function that i don't know about? – bph Feb 23 '15 at 12:47
  • Can you run it under a debugger like GDB? Just hit Ctrl-C, switch to the thread of interest, and display the call stack. Do this 10 times. On about 3 of those times, you will see that function, and all the callers leading to it, along with the lines of code where the calls occur. That's [*this technique*](http://stackoverflow.com/a/378024/23771). – Mike Dunlavey Feb 23 '15 at 13:33
  • 1
    hi mike, i read about your profiling technique a couple of days ago - seems very sensible - will give it a try – bph Feb 23 '15 at 13:43

1 Answers1

3

OK, gprof samples on CPU time, while random pausing samples on wall-clock time. So when gprof says that routine takes 30% of time, it means CPU-time, which may well be less than 1% of wall-clock time. In other words, you are I/O-bound. So even if you could make it take 0 time, you would never see the difference. (That's why I disparage "CPU-profiling" - it leads less-experienced programmers to focus their attention on things that don't matter.)

In case this isn't clear, your program may do actual computing for 1 microsecond, of which a large part consists of going into and coming out the the I/O stack of routines. Once it reaches the bottom of the I/O stack, it may be waiting for 99 microseconds before coming out and using the CPU for another 1 microsecond. gprof is only telling you about how that 1% of time is used, as if that was all that mattered.

To get comparable results to gprof in random-pausing, you would have to discard any samples that contain __kernel_vsyscall. So you might have to take 100 samples before you found one that was actually using CPU time. That's a lot of work, but if you did it, I expect that you would see the Lock routine on about 30% of the non-I/O samples.

Remember, when gprof was written, it was by people working at UC Berkeley, an academic environment where a version of unix was being developed. It had a built-in assumption - that all I/O was necessary I/O. In real user-level software, that is very often not the case. Besides, I/O is not non-CPU time, it's just a different CPU. There's an I/O controller chip running that disk, port, or what-have-you.

Mike Dunlavey
  • 40,059
  • 14
  • 91
  • 135
  • Good, but the last paragraph is wrong. `gprof` was not written by people working on the kernel. – Basile Starynkevitch Feb 23 '15 at 20:05
  • @Basile: Thanks for pointing that out. I've edited it. The actual quote is "We developed this tool in response to our efforts to improve a code generator we were writing [Graham82]", which was: Graham, S. L., Henry, R. R., Schulman, R. A., ‘‘An Experiment in Table Driven Code Generation’’, SIGPLAN ’82 Symposium on Compiler Construction, June, 1982 – Mike Dunlavey Feb 23 '15 at 20:21
  • this is good stuff on the profiling - but i'd still like to know what that function is and what its doing/for – bph Feb 24 '15 at 10:04
  • 1
    @bph: To find that out, you need something that collects stack samples on CPU time. `oprofile` maybe? – Mike Dunlavey Feb 24 '15 at 13:21