From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 2727 invoked by alias); 8 Feb 2006 21:14:36 -0000 Received: (qmail 2716 invoked by uid 22791); 8 Feb 2006 21:14:35 -0000 X-Spam-Status: No, hits=-2.5 required=5.0 tests=AWL,BAYES_00,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: sourceware.org Received: from mx1.redhat.com (HELO mx1.redhat.com) (66.187.233.31) by sourceware.org (qpsmtpd/0.31) with ESMTP; Wed, 08 Feb 2006 21:14:34 +0000 Received: from int-mx1.corp.redhat.com (int-mx1.corp.redhat.com [172.16.52.254]) by mx1.redhat.com (8.12.11/8.12.11) with ESMTP id k18LEWvK018331 for ; Wed, 8 Feb 2006 16:14:32 -0500 Received: from pobox.corp.redhat.com (pobox.corp.redhat.com [172.16.52.156]) by int-mx1.corp.redhat.com (8.11.6/8.11.6) with ESMTP id k18LEW100684; Wed, 8 Feb 2006 16:14:32 -0500 Received: from vpn83-150.boston.redhat.com (vpn83-150.boston.redhat.com [172.16.83.150]) by pobox.corp.redhat.com (8.12.8/8.12.8) with ESMTP id k18LEUeA031486; Wed, 8 Feb 2006 16:14:31 -0500 Subject: Re: Another Newbie question about measuring time in a sys call From: Martin Hunt To: "Frank Ch. Eigler" Cc: David A Sperry , "systemtap@sources.redhat.com" In-Reply-To: References: Content-Type: text/plain Organization: Red Hat Inc Date: Wed, 08 Feb 2006 21:14:00 -0000 Message-Id: <1139433329.3948.31.camel@monkey2> Mime-Version: 1.0 X-Mailer: Evolution 2.0.2 (2.0.2-25) Content-Transfer-Encoding: 7bit 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/msg00445.txt.bz2 Another way that works now is to not use the syscall tapset. probe kernel.function("sys_*") { if (target() != tid()) next calltime[tid()] = gettimeofday_us() } probe kernel.function("sys_*").return { if (target() != tid()) next c=calltime[tid()] if (!c) next delete calltime[tid()] ttime[probefunc()] <<< gettimeofday_us() - c } probe end { printf("\n") foreach (x in ttime) printf("%s count %d avg %d\n", x, @count(ttime[x]), @avg(ttime[x])) } global calltime, ttime ---------- Note I change the filter to compare target() to tid(). This allows you to profile any command with the above code just by using the "-c" option to stap. > stap -c ps system_calls.stp PID TTY TIME CMD 19129 pts/6 00:00:00 stpd 19135 pts/6 00:00:00 ps sys_munmap count 7 avg 14 sys_mprotect count 6 avg 9 sys_mmap2 count 25 avg 8 sys_readlink count 2 avg 20 sys_rt_sigaction count 34 avg 5 sys_read count 231 avg 20 sys_rt_sigprocmask count 7 avg 6 sys_write count 3 avg 17 sys_brk count 6 avg 5 sys_open count 234 avg 12 sys_getdents64 count 2 avg 37 sys_geteuid count 2 avg 5 sys_time count 2 avg 7 sys_lseek count 2 avg 5 sys_ioctl count 2 avg 7 sys_access count 6 avg 8 sys_newuname count 2 avg 8 sys_fcntl64 count 1 avg 5 sys_fstat64 count 13 avg 5 sys_stat64 count 123 avg 9 sys_set_thread_area count 2 avg 6 sys_sigreturn count 1 avg 9 sys_close count 234 avg 6 sys_getpgrp count 1 avg 6 sys_getppid count 1 avg 5 sys_getpid count 1 avg 6 sys_getegid count 1 avg 5 sys_getgid count 1 avg 5 sys_getuid count 1 avg 5 Unfortunately we don't have a way to tell the translator which field to use to sort the output. Of course you could just pipe the output through sort. Martin