From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <systemtap-return-2433-listarch-systemtap=sources.redhat.com@sourceware.org>
Received: (qmail 1241 invoked by alias); 8 Feb 2006 12:32:31 -0000
Received: (qmail 1234 invoked by uid 22791); 8 Feb 2006 12:32:30 -0000
X-Spam-Status: No, hits=-2.6 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 12:32:29 +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 k18CWOpi027034 	for <systemtap@sources.redhat.com>; Wed, 8 Feb 2006 07:32:24 -0500
Received: from pobox.toronto.redhat.com (pobox.toronto.redhat.com [172.16.14.4]) 	by int-mx1.corp.redhat.com (8.11.6/8.11.6) with ESMTP id k18CWJ129556; 	Wed, 8 Feb 2006 07:32:19 -0500
Received: from touchme.toronto.redhat.com (IDENT:postfix@touchme.toronto.redhat.com [172.16.14.9]) 	by pobox.toronto.redhat.com (8.12.8/8.12.8) with ESMTP id k18CWIje002284; 	Wed, 8 Feb 2006 07:32:18 -0500
Received: from ton.toronto.redhat.com (ton.toronto.redhat.com [172.16.14.15]) 	by touchme.toronto.redhat.com (Postfix) with ESMTP 	id AAD6B8000D8; Wed,  8 Feb 2006 07:32:18 -0500 (EST)
Received: from ton.toronto.redhat.com (localhost.localdomain [127.0.0.1]) 	by ton.toronto.redhat.com (8.13.1/8.13.1) with ESMTP id k18CWI5L007691; 	Wed, 8 Feb 2006 07:32:18 -0500
Received: (from fche@localhost) 	by ton.toronto.redhat.com (8.13.1/8.13.1/Submit) id k18CWH0h007688; 	Wed, 8 Feb 2006 07:32:17 -0500
X-Authentication-Warning: ton.toronto.redhat.com: fche set sender to fche@redhat.com using -f
To: David A Sperry <David_A_Sperry@raytheon.com>
Cc: <systemtap@sources.redhat.com>
Subject: Re: Another Newbie question about measuring time in a sys call
References: <OF9A980AD4.6A1AABB6-ON8525710F.0006CB90-8525710F.000827AB@mck.us.ray.com>
From: fche@redhat.com (Frank Ch. Eigler)
Date: Wed, 08 Feb 2006 12:32:00 -0000
In-Reply-To: <OF9A980AD4.6A1AABB6-ON8525710F.0006CB90-8525710F.000827AB@mck.us.ray.com>
Message-ID: <y0my80mni9a.fsf@ton.toronto.redhat.com>
User-Agent: Gnus/5.0808 (Gnus v5.8.8) Emacs/21.3
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Mailing-List: contact systemtap-help@sourceware.org; run by ezmlm
Precedence: bulk
List-Subscribe: <mailto:systemtap-subscribe@sourceware.org>
List-Post: <mailto:systemtap@sourceware.org>
List-Help: <mailto:systemtap-help@sourceware.org>, <http://sourceware.org/lists.html#faqs>
Sender: systemtap-owner@sourceware.org
X-SW-Source: 2006-q1/txt/msg00427.txt.bz2


David_A_Sperry wrote:

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

Indeed, the "name" value exported from the syscalls tapset has been
changed, for better or for worse.  Plus there are still some
"kernel.syscall.*" stragglers in the syscalls*stp files, so there is
plenty of reason for confusion.

Here's how the script might work today.


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\n", x,
       @count(ttime[x]), @avg(ttime[x]))
}

global callee, calltime, ttime


- FChE