From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 22875 invoked by alias); 8 Feb 2006 15:54:11 -0000 Received: (qmail 22866 invoked by uid 22791); 8 Feb 2006 15:54:10 -0000 X-Spam-Status: No, hits=-2.3 required=5.0 tests=AWL,BAYES_00,SPF_PASS X-Spam-Check-By: sourceware.org Received: from bos-gate3.raytheon.com (HELO bos-gate3.raytheon.com) (199.46.198.232) by sourceware.org (qpsmtpd/0.31) with ESMTP; Wed, 08 Feb 2006 15:54:08 +0000 Received: from dmoute00.directory.ray.com ([147.25.130.120]) by bos-gate3.raytheon.com (8.12.10/8.12.10) with ESMTP id k18Fs3YB017831 for ; Wed, 8 Feb 2006 10:54:05 -0500 (EST) Received: from dmsmtpe00.directory.ray.com (localhost [127.0.0.1]) by dmoute00.directory.ray.com (Switch-3.1.7/Switch-3.1.7) with ESMTP id k18Fs389024585 sender David_A_Sperry@raytheon.com for ; Wed, 8 Feb 2006 15:54:04 GMT Received: from ad2-msg02.and.us.ray.com (ad2-msg02.and.us.ray.com [138.127.58.142]) by dmsmtpe00.directory.ray.com (8.12.11/8.12.11) with ESMTP id k18Fs12R013672 sender David_A_Sperry@raytheon.com for ; Wed, 8 Feb 2006 15:54:01 GMT In-Reply-To: Subject: Re: Another Newbie question about measuring time in a sys call To: fche@redhat.com (Frank Ch. Eigler) Cc: Li Guanglei , systemtap@sources.redhat.com Message-ID: From: David A Sperry Date: Wed, 08 Feb 2006 15:54:00 -0000 MIME-Version: 1.0 Content-type: text/plain; charset=US-ASCII X-IsSubscribed: yes Mailing-List: contact systemtap-help@sourceware.org; run by ezmlm Precedence: bulk List-Subscribe: List-Post: List-Help: , Sender: systemtap-owner@sourceware.org X-SW-Source: 2006-q1/txt/msg00434.txt.bz2 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