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

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

fche@redhat.com wrote on 02/08/2006 10:18:06 AM:

>
> David_A_Sperry wrote:
>
> > [...]
> > syscall creat count 3211 avg 38 min 33 max 1760
> > [...]
> > From this quick test I can see that syscall creat  has at least one
call
> > that took a long time. Really cool!
>
> AFAIK, top does not perform any file creation.  Did you change the
> script to monitor other processes too?  (You can store execname() etc.
> in auxiliary arrays.)
>

I was lazy and just modified the prinf line.  I re-ran the script without
top running and got no results as expected. I started top, then ran the
script and got the results below:

*** without top running ***
[root@ibm systap]# stap top2.stp -v
Pass 1: parsed user script and 11 library script(s) in 130usr/10sys/140real
ms.
Pass 2: analyzed script: 293 probe(s), 19 function(s), 3 global(s) in
1160usr/6
sys/1221real ms.
Pass 3: translated to C into "/tmp/stapQealzt/stap_5083.c" in
380usr/90sys/488r
al ms.
Pass 4: compiled C into "stap_5083.ko" in 59980usr/1480sys/60048real ms.
Pass 5: run completed in 10usr/350sys/72255real ms.
[root@ibm systap]#

*** with top running before script invocation ***
[root@ibm systap]# stap top2.stp -v
Pass 1: parsed user script and 11 library script(s) in 140usr/0sys/139real
ms.
Pass 2: analyzed script: 293 probe(s), 19 function(s), 3 global(s) in
1190usr/3
sys/1233real ms.
Pass 3: translated to C into "/tmp/stapMP4oDM/stap_5220.c" in
390usr/90sys/484r
al ms.
Pass 4: compiled C into "stap_5220.ko" in 59920usr/1660sys/60245real ms.
syscall ioctl count 80 avg 18 min 14 max 24
syscall gettimeofday count 40 avg 11 min 11 max 13
syscall llseek count 80 avg 10 min 8 max 12
syscall fstat64 count 40 avg 11 min 10 max 12
syscall fcntl64 count 1920 avg 11 min 6 max 150
syscall creat count 6772 avg 37 min 32 max 103
syscall stat64 count 3326 avg 31 min 29 max 98
syscall lseek count 120 avg 8 min 7 max 11
syscall getdents count 80 avg 55 min 31 max 80
Pass 5: run completed in 20usr/340sys/127410real ms.
[root@ibm systap]#

*** The contents of the script: ***

[sperryd@ibm systap]$ cat top2.stp
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 min %d max %d\n", x,
       @count(ttime[x]), @avg(ttime[x]), @min(ttime[x]), @max(ttime[x]))
}

global callee, calltime, ttime

[sperryd@ibm systap]$


*** here's a list of open files: ***

[sperryd@ibm systap]$ lsof |grep top
top       5218 sperryd  cwd       DIR      22,66     4096   21731427
/home/sperryd/systap
top       5218 sperryd  rtd       DIR      22,65     4096          2 /
top       5218 sperryd  txt       REG      22,65    58260    1270863
/usr/bin/top
top       5218 sperryd  mem       REG      22,65    46660     981161
/lib/libnss_files-2.3.90.so
top       5218 sperryd  mem       REG        0,0                   0 [vdso]
(stat: No such file or directory)
top       5218 sperryd  mem       REG      22,65   121480     982781
/lib/ld-2.3.90.so
top       5218 sperryd  mem       REG      22,65  1487244     982782
/lib/libc-2.3.90.so
top       5218 sperryd  mem       REG      22,65    54500     982805
/lib/libproc-3.2.6.so
top       5218 sperryd  mem       REG      22,65    16304     982784
/lib/libdl-2.3.90.so
top       5218 sperryd  mem       REG      22,65   291960    1266716
/usr/lib/libncurses.so.5.5
top       5218 sperryd    0u      CHR      136,3                   5
/dev/pts/3
top       5218 sperryd    1u      CHR      136,3                   5
/dev/pts/3
top       5218 sperryd    2u      CHR      136,3                   5
/dev/pts/3
top       5218 sperryd    3r      REG        0,3        0 4026531841
/proc/uptime
top       5218 sperryd    4r      REG        0,3        0 4026531840
/proc/loadavg
top       5218 sperryd    5r      REG        0,3        0 4026531853
/proc/stat
top       5218 sperryd    6r      REG        0,3        0 4026531842
/proc/meminfo
[sperryd@ibm systap]$


-Dave