2

I do some i/o intensive programming in C on GNU/Linux and I would like to be able to trace all the i/o calls and to know the timings the application spends sleeping, waiting for IO for each call

Appart from the DIY method using gettimeoftheday everywhere, is there some tool to do that ? I want to be able to distinguish the calls from each other.

Ex of an output that would be usefull :

sendto at myprog.c:42    : 30µs
recvfrom at myprog.c:48  : 45µs
...

Note: what I want is real time, not cpu time like profilers generally give.

Thanks

Jocelyn delalande
  • 5,123
  • 3
  • 30
  • 34
  • What OS ? E.g. Mac OS X has "Instruments" which does this kind of thing. – Paul R Nov 22 '10 at 18:40
  • Somewhat off topic but just in case this becomes a high result in google. To do exactly this in `python`, you can check out this tool http://mg.pov.lt/blog/you-gotta-love-profiling.html – Falmarri Nov 22 '10 at 18:48

2 Answers2

3

The strace command has option -T which should do what you need. I checked the source code, it calls gettimeofday(2) to get the time, so it does report wall clock time, not CPU time.

Example output from strace -p 2956 -T on my computer:

stat("/proc/sys/fs/binfmt_misc", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0 <0.000028>
stat("/media/Klatch", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0 <0.000021>
stat("/media/Drum", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0 <0.000021>
close(18)                               = 0 <0.000019>
munmap(0x7fa088e60000, 4096)            = 0 <0.000022>
open("/etc/mtab", O_RDONLY)             = 18 <0.000024>
fstat(18, {st_mode=S_IFREG|0644, st_size=742, ...}) = 0 <0.000015>

The time is at the end of the line, in seconds. That's 15 to 28 microseconds for the system calls in the example above.

  • Take a deeper look at the timing options strace gives you. There are absolute, relative, and cumulative timer modes. They all have good uses. – Marcin Nov 22 '10 at 19:03
  • Ok, that's pretty good, too bad it can't use debugging symbols also to indicate from which line of the source code comes the call. – Jocelyn delalande Nov 22 '10 at 20:07
  • 1
    @Jocelyn: strace `-i` option combined with `addr2line -fe` should take care of that. – ninjalj Nov 22 '10 at 21:51
  • @ninja : exciting... but strace -i seems to give relocated runtime pointers which change on every run, can't help addr2line which works with relative pointers :-( – Jocelyn delalande Nov 23 '10 at 14:09
  • @Jocelyn: then, enabling the ADDR_NO_RANDOMIZE personality bit (for instance, via `setarch -R`) should help. – ninjalj Nov 23 '10 at 18:40
  • @ninja It does not, I'm trying to build my one-liner which would do the job but still the addresses, even with setarch -R seems not to work. I'm trying : _setarch i686 -R strace -T -e trace=network,file,desc -i ./mybin server 2>&1 | sed "s/\[\([[:xdigit:]]*\)\]/` addr2line -e mybin \\\1`/g"_ – Jocelyn delalande Nov 24 '10 at 11:11
0

There's a swiss-army knife that, for some strange reason, not everyone knows, maybe because it's too simple (and also ugly). Run it under GDB and just pause it a few times, like 10. Each time, study the call stack.

If 50% of the time is in I/O, 50% +/- of the samples will show it in the I/O, and each line of code on the call stack will show part of the chain of why it's doing the I/O. Same for sleep or any other blocking call. If the time isn't blocked, like you're bubble-sorting a huge array, it will show that too, and why. If it's spending time in some system library where you just don't know (or care) if it's blocked or not, same deal.

If it's taking longer because some other process is using some of the CPU time, that doesn't matter, because that doesn't change very much how your code spends its time on a percentage basis. You'll still find out how much IO or sleeping or crunching you're doing, percentage-wise, and exactly why.

If you want something prettier, though not really any more effective, give Zoom a try.

Community
  • 1
  • 1
Mike Dunlavey
  • 40,059
  • 14
  • 91
  • 135
  • @Jocelyn: Can you get a count N of calls to routine X? Total time multiplied by fraction of time X is active, divided by N, is average time per call, roughly. Clumsy, but there it is. – Mike Dunlavey Nov 23 '10 at 02:08