This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: Another Newbie question about measuring time in a sys call
- From: David A Sperry <David_A_Sperry at raytheon dot com>
- To: fche at redhat dot com (Frank Ch. Eigler)
- Cc: Li Guanglei <guanglei at cn dot ibm dot com>, systemtap at sources dot redhat dot com
- Date: Wed, 8 Feb 2006 10:54:00 -0500
- Subject: Re: Another Newbie question about measuring time in a sys call
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