Re: Another Newbie question about measuring time in a sys call

[David A Sperry <David_A_Sperry@raytheon.com>]

Thanks Frank and Li,

Both of your examples work and are a big help!

Frank, I like your example using tid() instead of pid() and the @ave()
function. I modified your script to add @min() and @max() just to see what
would happen and it worked! I got
syscall ioctl count 38 avg 19 min 16 max 23
syscall gettimeofday count 19 avg 11 min 11 max 12
syscall llseek count 38 avg 10 min 9 max 13
syscall fstat64 count 19 avg 11 min 11 max 13
syscall fcntl64 count 722 avg 11 min 7 max 26
syscall creat count 3211 avg 38 min 33 max 1760
syscall stat64 count 1577 avg 32 min 29 max 80
syscall lseek count 57 avg 9 min 8 max 12
syscall getdents count 38 avg 56 min 29 max 80

From this quick test I can see that syscall creat  has at least one call
that took a long time. Really cool!

Dave


systemtap-owner@sourceware.org wrote on 02/08/2006 07:32:17 AM:

>
> David_A_Sperry wrote:
>
> > probe kernel.syscall.* {
> >         if (execname() == "top")
> >                 called[name] = gettimeofday_us()
> > }
> > probe kernel.syscall.*.return {
> >         if (execname() == "top")
> >                 ttime[name] +=  gettimeofday_us() - called[name]
> > }
>
> Indeed, the "name" value exported from the syscalls tapset has been
> changed, for better or for worse.  Plus there are still some
> "kernel.syscall.*" stragglers in the syscalls*stp files, so there is
> plenty of reason for confusion.
>
> Here's how the script might work today.
>
>
> probe kernel.syscall.* {
>    if (execname() != "top") next
>    callee[tid()] = name # saved because .return probe changes name
>    calltime[tid()] = gettimeofday_us()
> }
>
> probe kernel.syscall.*.return {
>    if (execname() != "top") next
>    c=calltime[tid()]
>    if (!c) next
>    delete calltime[tid()]
>    ttime[callee[tid()]] <<< gettimeofday_us() - c
> }
>
> # Note: code like the above probe pair could go into a higher layer
> # standard tapset.
>
> probe end {
>    foreach (x in ttime)
>      printf("syscall %s count %d avg %d\n", x,
>        @count(ttime[x]), @avg(ttime[x]))
> }
>
> global callee, calltime, ttime
>
>
> - FChE