The linetimes.stp example to see which lines of code are expensive.

The linetimes.stp example to see which lines of code are expensive.

[William Cohen]

This Monday I wrote up a script that instruments a function on a per line basis and records the amount of time that each line takes. The script should make it easier to see what is going on with in a function. If you want to take a look at the script, it has been check in with the following commit:

http://sources.redhat.com/git/gitweb.cgi?p=systemtap.git;a=commit;h=e985df18d54c57bcd14bbed0ec420d353e767198

Below is an example run of the script for the do_unlinkat() function on a Fedora 12 machine. Is shows the avg and max time for each line of the function. The following table shows the number of times each line executes. Any suggestions for improvements to the script would be appreciated.

-Will

$ stap  linetimes.stp kernel do_unlinkat
^C
do_unlinkat called 11
region                                                        avg(us)    max(us)
kernel.statement("do_unlinkat@fs/namei.c:2315")                     5          8
kernel.statement("do_unlinkat@fs/namei.c:2322")                    13         16
kernel.statement("do_unlinkat@fs/namei.c:2323")                     9         11
kernel.statement("do_unlinkat@fs/namei.c:2324")                     9         11
kernel.statement("do_unlinkat@fs/namei.c:2327")                     8         10
kernel.statement("do_unlinkat@fs/namei.c:2330")                     8         10
kernel.statement("do_unlinkat@fs/namei.c:2332")                     8         10
kernel.statement("do_unlinkat@fs/namei.c:2333")                     8         10
kernel.statement("do_unlinkat@fs/namei.c:2335")                     8          9
kernel.statement("do_unlinkat@fs/namei.c:2337")                     7          8
kernel.statement("do_unlinkat@fs/namei.c:2339")                     7          8
kernel.statement("do_unlinkat@fs/namei.c:2340")                     7          8
kernel.statement("do_unlinkat@fs/namei.c:2342")                     7          8
kernel.statement("do_unlinkat@fs/namei.c:2343")                     6          8
kernel.statement("do_unlinkat@fs/namei.c:2348")                    35         60
kernel.statement("do_unlinkat@fs/namei.c:2350")                     6          9
kernel.statement("do_unlinkat@fs/namei.c:2352")                     6          9
kernel.statement("do_unlinkat@fs/namei.c:2354")                     6          9
kernel.statement("do_unlinkat@fs/namei.c:2355")                     5          9
kernel.statement("do_unlinkat@fs/namei.c:2356")                   828       6966
kernel.statement("do_unlinkat@fs/namei.c:2358")                     6         10
kernel.statement("do_unlinkat@fs/namei.c:2359")                     5         11
kernel.statement("do_unlinkat@fs/namei.c:2360")                     5         10
kernel.statement("do_unlinkat@fs/namei.c:2366")                     5         12

control flow graph information
=======================
kernel.statement("do_unlinkat@fs/namei.c:2315") 11
kernel.statement("do_unlinkat@fs/namei.c:2322") 11
kernel.statement("do_unlinkat@fs/namei.c:2323") 11
kernel.statement("do_unlinkat@fs/namei.c:2324") 11
kernel.statement("do_unlinkat@fs/namei.c:2327") 11
kernel.statement("do_unlinkat@fs/namei.c:2330") 11
kernel.statement("do_unlinkat@fs/namei.c:2332") 11
kernel.statement("do_unlinkat@fs/namei.c:2333") 11
kernel.statement("do_unlinkat@fs/namei.c:2335") 11
kernel.statement("do_unlinkat@fs/namei.c:2337") 11
kernel.statement("do_unlinkat@fs/namei.c:2339") 11
kernel.statement("do_unlinkat@fs/namei.c:2340") 11
kernel.statement("do_unlinkat@fs/namei.c:2342") 11
kernel.statement("do_unlinkat@fs/namei.c:2343") 11
kernel.statement("do_unlinkat@fs/namei.c:2348") 11
kernel.statement("do_unlinkat@fs/namei.c:2350") 11
kernel.statement("do_unlinkat@fs/namei.c:2352") 11
kernel.statement("do_unlinkat@fs/namei.c:2354") 11
kernel.statement("do_unlinkat@fs/namei.c:2355") 11
kernel.statement("do_unlinkat@fs/namei.c:2356") 11
kernel.statement("do_unlinkat@fs/namei.c:2358") 11
kernel.statement("do_unlinkat@fs/namei.c:2359") 11
kernel.statement("do_unlinkat@fs/namei.c:2360") 11
kernel.statement("do_unlinkat@fs/namei.c:2366") 11