Another Newbie question about measuring time in a sys call

[David A Sperry <David_A_Sperry at raytheon dot com>]

Hi,
      I'm trying to run the top example from a few months ago to play with
measuring time. I run top in one window and stap in another. The problem is
I am getting some strange answers.

Here's the script I copied out of an old message:

[sperryd@ibm systap]$ cat top.stp
global called, ttime

probe kernel.syscall.* {
        if (execname() == "top")
                called[name] = gettimeofday_us()
}
probe kernel.syscall.*.return {
        if (execname() == "top")
                ttime[name] +=  gettimeofday_us() - called[name]
}

probe end {
        foreach ([n] in ttime-)
                printf("%s took %d usecs\n", n, ttime[n])
}


Here are the results I get:

[root@ibm systap]# stap top.stp -v
Pass 1: parsed user script and 11 library script(s) in 140usr/0sys/140real
ms.
Pass 2: analyzed script: 293 probe(s), 18 function(s), 2 global(s) in
1160usr/40sys/1210real ms.
Pass 3: translated to C into "/tmp/stapOj2TEx/stap_905.c" in
300usr/110sys/406real ms.
Pass 4: compiled C into "stap_905.ko" in 45460usr/1690sys/46011real ms.
stat64.return took 4918620585892709376 usecs
fcntl64.return took 1886781490013993830 usecs
lseek.return took 123050966740266106 usecs
llseek.return took 82033977826804214 usecs
ioctl.return took 82033977825997218 usecs
getdents.return took 82033977825866159 usecs
fstat64.return took 41016988912499374 usecs
gettimeofday.return took 41016988912493711 usecs
creat.return took -8486451935184063013 usecs
Pass 5: run completed in 10usr/100sys/117204real ms.
[root@ibm systap]#


I'm guessing the syscall tapsets may have changed and the associative array
may be getting confused between a call and it's return (lseek vs
lseek.return)

Any help would be appreciated

Thanks
Dave Sperry