[Gllug] Profiling - where is all the time going?

[Rich Walker]

John Winters <john at sinodun.org.uk> writes:

> Hi all,
>
> I'm experimenting with profiling a compute intensive program.  It does
> practically no i/o and it isn't memory bound - it just thinks hard.
>
> I've compiled and linked with -pg and I seem to be getting a reasonably
> meaningful output except for one thing.  If I let the program run for 60
> seconds and then examine the profiling information I'm told that the
> cumulative time used by all the functions is 10.77 seconds.  Where could
> the other 49 seconds be going?

Use strace -c
ltrace -c, and look at the time spent in the library calls and
the system. 

 strace -c xeyes
execve("/usr/X11R6/bin/xeyes", ["xeyes"], [/* 33 vars */]) = 0
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.38    1.380009        2609       529           select
  0.83    0.011782          46       254           write
  0.79    0.011239          47       239       210 open
  0.77    0.010922          23       476       190 read
  0.07    0.000936           1       676           ioctl
  0.04    0.000630           1       877           gettimeofday
  0.03    0.000486         122         4           writev
  0.02    0.000265           6        48           old_mmap
  0.02    0.000238           9        27        25 access
  0.02    0.000219         110         2         1 connect
  0.01    0.000101           6        16           munmap
  0.01    0.000074           2        30           close
  0.00    0.000048           3        16        16 stat64
  0.00    0.000046           2        29           fstat64
  0.00    0.000031          16         2           socket
  0.00    0.000011           3         4           uname
  0.00    0.000009           5         2           setsockopt
  0.00    0.000007           1         5           brk
  0.00    0.000007           7         1           readv
  0.00    0.000005           1         5           fcntl64
  0.00    0.000002           2         1           getsockname
  0.00    0.000001           1         1           getpeername
  0.00    0.000000           0         1           getpid
------ ----------- ----------- --------- --------- ----------------
100.00    1.417068                  3245       442 total


time will also give you (some of) this information.
/usr/bin/time -v xeyes
Command terminated by signal 2
        Command being timed: "xeyes"
        User time (seconds): 0.01
        System time (seconds): 0.00
        Percent of CPU this job got: 0%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:05.46
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 0
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 397
        Minor (reclaiming a frame) page faults: 49
        Voluntary context switches: 0
        Involuntary context switches: 0
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0


Note that sometimes functions "disappear" off the radar of profiling -
static functions, things that are inlined and so forth.


cheers, Rich.


>
> TIA,
> John
>
> -- 
> Gllug mailing list  -  Gllug at gllug.org.uk
> http://lists.gllug.org.uk/mailman/listinfo/gllug

-- 
rich walker         |  Shadow Robot Company | rw at shadow.org.uk
technical director     251 Liverpool Road   |
need a Hand?           London  N1 1LX       | +UK 20 7700 2487
www.shadow.org.uk/products/newhand.shtml
-- 
Gllug mailing list  -  Gllug at gllug.org.uk
http://lists.gllug.org.uk/mailman/listinfo/gllug