Wednesday, November 28, 2012

Profiling with strace

Well trying to figure out what was the main culprit of slow CRAB execution as well as close to impossible execution times of scram (toolkit like make, but more flexible and specific to CMS software) I wanted to validate wether the time consumed by stat() calls on not existing files is significant enough or there are other reasons. As the simple crab -status command took a good 100-140 seconds there should be plenty to see.

So the first task was to find a simple profiling tool. Started with strace -c, but that only showed system time, which isn't too helpful as the total execution time was 1.6 seconds for the full 2 minute running of the code.

Next up I tried to just see the relative execution times of different syscalls with strace -r -t. The output has every line in strace prepended with amount of time it took to run it (in seconds). For example:


6378       0.000000 execve("/opt/software/CRAB2/python/crab", ["crab", "-status"], [/* 156 vars */]) = 0 <0.012506>
6378       0.013422 brk(0)              = 0xf79000 <0.000069>
6378       0.000518 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb904bfb000 <0.000143>

So looking through the whole execution with a simple addition seemed to double count the time, but at least gave a relative information capacity:


$ awk '{print $2}' crab.strace |sort -n|awk '{s+=$1} END { print s}'
208.992


To simplify counting I created an alias that summed together the time:

alias ctime="awk '{s+=\$2} END {print s}'"


So while the code probably run just 104 seconds we know we can add together this way. So now the check, did we lost most of the time in the failed openings and stats of files that do not exist:


$ grep ENOENT crab.strace |ctime
173.568

And the answer is a clear YES. So next up let's check the various system calls and their time:


$ for i in open stat access; do echo -n " $i -> "; grep " $i(" crab.strace |ctime; done
 open -> 139.159
 stat -> 39.4473
 access -> 0.331267

So now I just need to figure out how to dramatically reduce the list of paths that is accessed for libraries and I can reduce the execution time of the code.



No comments:

Post a Comment