Skip Menu |
 

Preferred bug tracker

Please visit the preferred bug tracker to report your issue.

This queue is for tickets about the devel-nytprof CPAN distribution.

Report information
The Basics
Id: 48678
Status: resolved
Priority: 0/
Queue: devel-nytprof

People
Owner: Nobody in particular
Requestors: REHSACK [...] cpan.org
Cc:
AdminCc:

Bug Information
Severity: Wishlist
Broken in: 2.10
Fixed in: (no value)



Subject: Subtract sys-times and make fork-follow can be turned off
MIME-Version: 1.0
X-Mailer: MIME-tools 5.427 (Entity 5.427)
Content-Type: text/plain
Charset: utf8
Content-Disposition: inline
Content-Transfer-Encoding: binary
X-RT-Original-Encoding: utf-8
Content-Length: 4637
Download (untitled) / with headers
text/plain 4.5k
Alias made good PR for NYTProf, so I tried it out and he didn't exaggerate. But I miss 2 things: 1) Calls like fork(), select() etc. are fully counted - it should be possible to see the runtime costs of subroutines without 1a) syscalls, and maybe 1b) calls to other libraries We have some script which have an own implementation for a thing like IPC::Run - harmonized with some other features (own rpcd, scheduling it's requests harmonized with it's running other tasks - using based a select-based I/O multiplexer). This leads to my second wish: 2) Could the process follow via fork get a flag so that it could be turned off? When I profile a weekly run of our rpcd, I have more nytprof.out.${pid} files in the project directory that can be deleted with a single `rm -f nytprof.out.*` (find | xargs must be used). Further, that fork follow causes errors (25955 is the original daemon in debug mode, 25997 is the forked process to exec `/sapmnt/LN5/exe/cleanipc 11`: byjk02:ln5adm 13> env NYTPROF=addpid=1 /opt/pkgsrc/bin/perl -d:NYTProf ../bin/BDCappld.pl --applpart SAPSCS --applid LN5NEU --instance 11 -D ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCtimedTask {TID: 1, STATE: running, TIMEOUT=0.500000s since 'Wed 12 Aug 2009 06:12:07 PM CEST'}' ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Listening at '/tmp/BDC/BDCappld/=::SAPSCS::LN5NEU::11' with connection id nuGI8sOMDcqbJ ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCrpcd::KernTask {CID: nuGI8sOMDcqbJ, STATE: running}' ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCappld::Action {CID: 9uGBc72m5bRkH, STATE: running, ADDRESSEE => {DAEMON => appld, FUNCTION => status, MODULE => SAPSCS}, JID => 2, MESSAGE => {FORCE => 0, ONLY => 0, RUNLEVEL => 25}}' ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCrpc::Request {CID: nuGlT5deYuDer, STATE: running, ADDRESSEE => {DAEMON => rpcd, FUNCTION => status, MODULE => saposcol}, MESSAGE => <undef>}' ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCcommand::AsUser {PID: 25997, STATE: running, CMD => /sapmnt/LN5/exe/cleanipc 11}' ln5adm@byjk02 BDCappld.pl/25997 [#error(core)]: Exception caught executing 'BDCcommand::AsUser {PID: <n/a>, STATE: prepared, CMD => /sapmnt/LN5/exe/cleanipc 11}': ln5adm@byjk02 BDCappld.pl/25997 [#error(core)]: BDCmanager::start(): 0 previously waiting commands started - 0 waiting, 2 running, 442 file handles left ln5adm@byjk02 BDCappld.pl/25997 [#info(1)(core)]: Execute ok for 'BDCtimedTask {TID: 2, STATE: running, TIMEOUT=0.500000s since 'Wed 12 Aug 2009 06:12:30 PM CEST'}' ln5adm@byjk02 BDCappld.pl/25997 [#info(1)(core)]: Execute ok for 'BDCappld::Action {CID: 9uG1JMU5pHGA5, STATE: running, ADDRESSEE => {DAEMON => appld, FUNCTION => status, MODULE => SAPSCS}, JID => 4, MESSAGE => {FORCE => 0, ONLY => 0, RUNLEVEL => 25}}' ln5adm@byjk02 BDCappld.pl/25997 [#info(1)(core)]: Execute ok for 'BDCrpc::Request {CID: nuGzGW7GA8PHP, STATE: running, ADDRESSEE => {DAEMON => rpcd, FUNCTION => status, MODULE => saposcol}, MESSAGE => <undef>}' ln5adm@byjk02 BDCappld.pl/25997 [#info(1)(core)]: Execute ok for 'BDCcommand::AsUser {PID: 26856, STATE: running, CMD => /sapmnt/LN5/exe/cleanipc 11}' ln5adm@byjk02 BDCappld.pl/25997 [#info(1)(core)]: Execute ok for 'BDCcommand::AsUser {PID: 26862, STATE: running, CMD => /sapmnt/LN5/exe/startsap check SCS11 ln5}' ln5adm@byjk02 BDCappld.pl/25997 [#error(core)]: doing 'status' on child 'BDCappld::SapApplServ::sapstartsrv' returns -2 ln5adm@byjk02 BDCappld.pl/25997 [#info(1)(core)]: Execute ok for 'BDCtimedTask {TID: 3, STATE: running, TIMEOUT=0.500000s since 'Wed 12 Aug 2009 06:23:18 PM CEST'}' ln5adm@byjk02 BDCappld.pl/25997 [#info(1)(core)]: Execute ok for 'BDCcommand::AsUser {PID: 27141, STATE: running, CMD => /sapmnt/LN5/exe/startsap check SCS11 ln5}' ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCappld::Action {CID: 9uGkVkqhRMDfJ, STATE: running, ADDRESSEE => {DAEMON => appld, FUNCTION => status, MODULE => SAPSCS}, JID => 4, MESSAGE => {FORCE => 0, ONLY => 0, RUNLEVEL => 25}}' ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCrpc::Request {CID: nuGzGW7GA8PHP, STATE: running, ADDRESSEE => {DAEMON => rpcd, FUNCTION => status, MODULE => saposcol}, MESSAGE => <undef>}' ln5adm@byjk02 BDCappld.pl/25955 [#info(1)(core)]: Execute ok for 'BDCcommand::AsUser {PID: 27499, STATE: running, CMD => /sapmnt/LN5/exe/cleanipc 11}' ln5adm@byjk02 BDCappld.pl/27499 [#error(core)]: Exception caught executing 'BDCcommand::AsUser {PID: <n/a>, STATE: prepared, CMD => /sapmnt/LN5/exe/cleanipc 11}'
MIME-Version: 1.0
X-Mailer: MIME-tools 5.427 (Entity 5.427)
Content-Disposition: inline
Charset: utf8
Content-Type: text/plain
Message-ID: <rt-3.6.HEAD-26882-1250179934-969.48678-0-0 [...] rt.cpan.org>
Content-Transfer-Encoding: binary
X-RT-Original-Encoding: utf-8
Content-Length: 523
Download (untitled) / with headers
text/plain 523b
I don't feel I understand what you're asking for in relation to 1. You're aware of the slowops option I presume. I have a suggestion for 2 and you can tell me if it fits your needs: An fork=N option could be added. If N=0 then forks are not followed. If N>0 then a fork is followed **and the child process decrements N**. So N=1 would follow one level of fork but if the child forked a subchild then that one wouldn't be profiled. The default would be -1 which would profile all child process. Would that fit your needs?
MIME-Version: 1.0
In-Reply-To: <rt-3.6.HEAD-26882-1250179934-969.48678-0-0 [...] rt.cpan.org>
X-Mailer: MIME-tools 5.427 (Entity 5.427)
Content-Disposition: inline
Charset: utf8
References: <rt-3.6.HEAD-26882-1250179934-969.48678-0-0 [...] rt.cpan.org>
Content-Type: text/plain
Message-ID: <rt-3.6.HEAD-26882-1250183674-917.48678-0-0 [...] rt.cpan.org>
Content-Transfer-Encoding: binary
X-RT-Original-Encoding: utf-8
Content-Length: 1253
Download (untitled) / with headers
text/plain 1.2k
On Thu Aug 13 12:12:14 2009, TIMB wrote: Show quoted text
> I don't feel I understand what you're asking for in relation to 1. > You're aware of the slowops > option I presume.
slowops? [/usr/pkgsrc/devel/p5-Devel-NYTProf]# grep -R slowops work/Devel-NYTProf-2.10/ [/usr/pkgsrc/devel/p5-Devel-NYTProf]# I don't see any "slowops". I don't talk about the time such a function needs - it's more: when I call select (@read, @writ, @oob, 1) - select will wait up to 1s until it returns, and this time is added to the time the calling sub needs to run. This finally suggests a subroutine needs optimization, but it doesn't. So it would be good to see the times required without counting syscalls. Maybe it would be good to see, which sub's call most syscalls - but this is another thing. Show quoted text
> I have a suggestion for 2 and you can tell me if it fits your needs: > An fork=N option could be added. > If N=0 then forks are not followed. > If N>0 then a fork is followed **and the child process decrements N**. > So N=1 would follow one level of fork but if the child forked a > subchild then that one wouldn't > be profiled. > The default would be -1 which would profile all child process. > Would that fit your needs?
Yes, perfectly. N=1 is a special case of N>0, I assume.
MIME-Version: 1.0
X-Spam-Status: No, hits=0.0 required=8.0 tests=DK_SIGNED,SPF_PASS
In-Reply-To: <rt-3.6.HEAD-26882-1250183674-917.48678-5-0 [...] rt.cpan.org>
Content-Disposition: inline
References: <RT-Ticket-48678 [...] rt.cpan.org> <rt-3.6.HEAD-26882-1250179934-969.48678-5-0 [...] rt.cpan.org> <rt-3.6.HEAD-26882-1250183674-917.48678-5-0 [...] rt.cpan.org>
Message-ID: <20090813194437.GT86974 [...] timac.local>
Content-Type: text/plain; charset="utf-8"
X-RT-Original-Encoding: utf-8
Received: from la.mx.develooper.com (x1.develooper.com [207.171.7.70]) by diesel.bestpractical.com (Postfix) with SMTP id 6370C19B82C2 for <bug-devel-nytprof [...] rt.cpan.org>; Thu, 13 Aug 2009 15:45:50 -0400 (EDT)
Received: (qmail 1144 invoked by uid 103); 13 Aug 2009 19:45:49 -0000
Received: from x16.dev (10.0.100.26) by x1.dev with QMQP; 13 Aug 2009 19:45:49 -0000
Received: from mail-ew0-f221.google.com (HELO mail-ew0-f221.google.com) (209.85.219.221) by 16.mx.develooper.com (qpsmtpd/0.80) with ESMTP; Thu, 13 Aug 2009 12:45:43 -0700
Received: by ewy21 with SMTP id 21so999769ewy.45 for <bug-devel-nytprof [...] rt.cpan.org>; Thu, 13 Aug 2009 12:45:40 -0700 (PDT)
Received: by 10.216.90.212 with SMTP id e62mr239231wef.26.1250192738249; Thu, 13 Aug 2009 12:45:38 -0700 (PDT)
Received: from timac.local ([89.204.227.145]) by mx.google.com with ESMTPS id i34sm510355gve.28.2009.08.13.12.45.35 (version=SSLv3 cipher=RC4-MD5); Thu, 13 Aug 2009 12:45:37 -0700 (PDT)
Delivered-To: cpan-bug+devel-nytprof [...] diesel.bestpractical.com
Subject: Re: [rt.cpan.org #48678] Subtract sys-times and make fork-follow can be turned off
User-Agent: Mutt/1.5.17 (2007-11-01)
Domainkey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=sender:date:from:to:subject:message-id:references:mime-version :content-type:content-disposition:in-reply-to:user-agent; b=jWLjbDwDHZCToGB2Bxbs799yeWl2dQMOrK9Ir8YgrFbQRLctA94J4IElaEr4EooyA1 tjusfxQvhFXMsBLy4R7SaOblnU43SzNRxaqPx3OF0wq2MXo83jGkrUdJ4TDLghPEOPJR ZdK67mis3Ly3TAZMojIjk7UutHf0gR9Qpg1y8=
Return-Path: <tim.bunce [...] gmail.com>
Dkim-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:received:received:sender:date:from:to:subject :message-id:references:mime-version:content-type:content-disposition :in-reply-to:user-agent; bh=JylxGrZgZE+SpdIwa/VBJkArw/T3JYNDiyRE7+DYmUg=; b=ULygAZD/J86HoCFQnO1+MNviV2QPxCao1q2W5Vn1THpCvi9VuOFYmp81uwgUNSlZCW ar2Ps0we542zqyaLZ9BWLEjr/ryR0mWEhLEj+Ju6Y7BuraU1SasSUs/pHSJ7fDTSgW3A XAkfTd6PNcPXN4iWxFuM2esIOdHMnh+xoPePc=
X-Spam-Check-BY: 16.mx.develooper.com
X-Original-To: bug-devel-nytprof [...] rt.cpan.org
Date: Thu, 13 Aug 2009 20:45:33 +0100
Sender: Tim Bunce <tim.bunce [...] gmail.com>
X-Spam-Level: *
To: Jens Rehsack via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
RT-Message-ID: <rt-3.6.HEAD-26882-1250192760-690.48678-0-0 [...] rt.cpan.org>
Content-Length: 1989
Download (untitled) / with headers
text/plain 1.9k
On Thu, Aug 13, 2009 at 01:14:35PM -0400, Jens Rehsack via RT wrote: Show quoted text
> Queue: devel-nytprof > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=48678 > > > On Thu Aug 13 12:12:14 2009, TIMB wrote:
> > I don't feel I understand what you're asking for in relation to 1. > > You're aware of the slowops > > option I presume.
> > slowops? > [/usr/pkgsrc/devel/p5-Devel-NYTProf]# grep -R slowops > work/Devel-NYTProf-2.10/ > [/usr/pkgsrc/devel/p5-Devel-NYTProf]# > I don't see any "slowops".
I think Alias was using the v3 'sneak peak' http://blog.timbunce.org/2009/08/07/nytprof-v3-a-sneak-peak/ http://www.slideshare.net/Tim.Bunce/develnytprof-200907 which hasn't been release yet. Show quoted text
> I don't talk about the time such a function needs - it's more: when I > call select (@read, @writ, @oob, 1) - select will wait up to 1s until it > returns, and this time is added to the time the calling sub needs to > run. This finally suggests a subroutine needs optimization, but it doesn't. > So it would be good to see the times required without counting syscalls.
Well, guess what slowops does ;-) See the links above. Get it from http://code.google.com/p/perl-devel-nytprof/source/checkout Show quoted text
> Maybe it would be good to see, which sub's call most syscalls - but this > is another thing. >
> > I have a suggestion for 2 and you can tell me if it fits your needs: > > An fork=N option could be added. > > If N=0 then forks are not followed. > > If N>0 then a fork is followed **and the child process decrements N**. > > So N=1 would follow one level of fork but if the child forked a > > subchild then that one wouldn't > > be profiled. > > The default would be -1 which would profile all child process. > > Would that fit your needs?
> > Yes, perfectly.
Great. Show quoted text
> N=1 is a special case of N>0, I assume.
No, N=1 would profile any immediate children of the parent process. Inside those immediate children N would be 0 so any children they fork wouldn't be profiled. Tim.
MIME-Version: 1.0
In-Reply-To: <rt-3.6.HEAD-26882-1250192760-690.48678-0-0 [...] rt.cpan.org>
X-Mailer: MIME-tools 5.427 (Entity 5.427)
Content-Disposition: inline
Charset: utf8
References: <RT-Ticket-48678 [...] rt.cpan.org> <rt-3.6.HEAD-26882-1250179934-969.48678-5-0 [...] rt.cpan.org> <rt-3.6.HEAD-26882-1250183674-917.48678-5-0 [...] rt.cpan.org> <20090813194437.GT86974 [...] timac.local> <rt-3.6.HEAD-26882-1250192760-690.48678-0-0 [...] rt.cpan.org>
Content-Type: text/plain
Message-ID: <rt-3.6.HEAD-26882-1250231571-1894.48678-0-0 [...] rt.cpan.org>
Content-Transfer-Encoding: binary
X-RT-Original-Encoding: utf-8
Content-Length: 1428
Download (untitled) / with headers
text/plain 1.3k
On Thu Aug 13 15:46:00 2009, Tim.Bunce@pobox.com wrote: Show quoted text
> On Thu, Aug 13, 2009 at 01:14:35PM -0400, Jens Rehsack via RT wrote:
Show quoted text
> I think Alias was using the v3 'sneak peak' > http://blog.timbunce.org/2009/08/07/nytprof-v3-a-sneak-peak/ > http://www.slideshare.net/Tim.Bunce/develnytprof-200907 > which hasn't been release yet.
Yes, but I'm using the one from pkgsrc and I'm not allowed to use unpackaged 'sneak peak' (guidelines from customer ...) Show quoted text
> > I don't talk about the time such a function needs - it's more: when
> I
> > call select (@read, @writ, @oob, 1) - select will wait up to 1s
> until it
> > returns, and this time is added to the time the calling sub needs to > > run. This finally suggests a subroutine needs optimization, but it
> doesn't.
> > So it would be good to see the times required without counting
> syscalls. > > Well, guess what slowops does ;-) > > See the links above. > Get it from http://code.google.com/p/perl-devel- > nytprof/source/checkout
When it's reported fixed for 3.0, it's great enough. Thanks a lot. Show quoted text
> > N=1 is a special case of N>0, I assume.
> > No, N=1 would profile any immediate children of the parent process. > Inside those immediate children N would be 0 so any children they > fork wouldn't be profiled.
N=2 would profile all children of the process, inside them N=1, their children are profiled, too (with N=0) - and their children are left untouched. Jens
MIME-Version: 1.0
X-Spam-Status: No, hits=0.0 required=8.0 tests=DK_SIGNED,SPF_PASS
In-Reply-To: <rt-3.6.HEAD-26882-1250231571-1894.48678-5-0 [...] rt.cpan.org>
Content-Disposition: inline
References: <RT-Ticket-48678 [...] rt.cpan.org> <rt-3.6.HEAD-26882-1250179934-969.48678-5-0 [...] rt.cpan.org> <rt-3.6.HEAD-26882-1250183674-917.48678-5-0 [...] rt.cpan.org> <20090813194437.GT86974 [...] timac.local> <rt-3.6.HEAD-26882-1250192760-690.48678-5-0 [...] rt.cpan.org> <rt-3.6.HEAD-26882-1250231571-1894.48678-5-0 [...] rt.cpan.org>
Message-ID: <20090814152236.GA9874 [...] timac.local>
Content-Type: text/plain; charset="utf-8"
X-RT-Original-Encoding: utf-8
Received: from la.mx.develooper.com (x1.develooper.com [207.171.7.70]) by diesel.bestpractical.com (Postfix) with SMTP id 56D7519B82DD for <bug-devel-nytprof [...] rt.cpan.org>; Fri, 14 Aug 2009 11:23:03 -0400 (EDT)
Received: (qmail 12102 invoked by uid 103); 14 Aug 2009 15:23:02 -0000
Received: from x16.dev (10.0.100.26) by x1.dev with QMQP; 14 Aug 2009 15:23:02 -0000
Received: from mail-ew0-f221.google.com (HELO mail-ew0-f221.google.com) (209.85.219.221) by 16.mx.develooper.com (qpsmtpd/0.80) with ESMTP; Fri, 14 Aug 2009 08:22:56 -0700
Received: by ewy21 with SMTP id 21so1515310ewy.45 for <bug-devel-nytprof [...] rt.cpan.org>; Fri, 14 Aug 2009 08:22:52 -0700 (PDT)
Received: by 10.216.88.21 with SMTP id z21mr432472wee.60.1250263371454; Fri, 14 Aug 2009 08:22:51 -0700 (PDT)
Received: from timac.local ([89.204.235.54]) by mx.google.com with ESMTPS id g9sm4534308gvc.10.2009.08.14.08.22.49 (version=SSLv3 cipher=RC4-MD5); Fri, 14 Aug 2009 08:22:50 -0700 (PDT)
Delivered-To: cpan-bug+devel-nytprof [...] diesel.bestpractical.com
Subject: Re: [rt.cpan.org #48678] Subtract sys-times and make fork-follow can be turned off
User-Agent: Mutt/1.5.17 (2007-11-01)
Domainkey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=sender:date:from:to:subject:message-id:references:mime-version :content-type:content-disposition:in-reply-to:user-agent; b=E3PWAKBAJ6yFQxN+NppCUhvsDPMVJhhiU8JD65gT+IhNqhc/UCfVWZXvFjTzrFBYwI QGNHg1Th1E0T6po0LuU4gibVL9gNlMTCk0l0tg2JAe9FSgquZ06hQHhAylAie2p6GLNw INJjJrKvaMM0C7K90m2eHhbfenDoTjXlyJmsM=
Return-Path: <tim.bunce [...] gmail.com>
Dkim-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:received:received:sender:date:from:to:subject :message-id:references:mime-version:content-type:content-disposition :in-reply-to:user-agent; bh=FjJL91u/213F4qEou0SSeTG/gxfeqX8Z03kSWGeLtjQ=; b=lRyeg3XvTXwuKnUZ+cWSkNeYdgYZcB/aQRMpHSlqv+3xIUmuQ0zX/LZdh/RY2A6Zbs jpEBNy2NjlB7l4qFYLNrKhTaXiVFxRVk549k3xE95sGA94/2uo2NlMPal572V/FZx8qi jJujlADileGoW1ZP589I1FGUwylDW4i1OvTeI=
X-Spam-Check-BY: 16.mx.develooper.com
X-Original-To: bug-devel-nytprof [...] rt.cpan.org
Date: Fri, 14 Aug 2009 16:22:45 +0100
Sender: Tim Bunce <tim.bunce [...] gmail.com>
X-Spam-Level: *
To: Jens Rehsack via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
RT-Message-ID: <rt-3.6.HEAD-26882-1250263394-1403.48678-0-0 [...] rt.cpan.org>
Content-Length: 700
Download (untitled) / with headers
text/plain 700b
On Fri, Aug 14, 2009 at 02:32:55AM -0400, Jens Rehsack via RT wrote: Show quoted text
> > > So it would be good to see the times required without counting
> > syscalls. > > > > Well, guess what slowops does ;-)
> > When it's reported fixed for 3.0, it's great enough. > Thanks a lot.
I'm glad it (will be of) help. Show quoted text
> > > N=1 is a special case of N>0, I assume.
> > > > No, N=1 would profile any immediate children of the parent process. > > Inside those immediate children N would be 0 so any children they > > fork wouldn't be profiled.
> > N=2 would profile all children of the process, inside them N=1, their > children are profiled, too (with N=0) - and their children are left > untouched.
Exactly. Tim.
MIME-Version: 1.0
X-Mailer: MIME-tools 5.427 (Entity 5.427)
Content-Disposition: inline
Charset: utf8
Content-Type: text/plain
Message-ID: <rt-3.6.HEAD-3617-1256399774-1973.48678-0-0 [...] rt.cpan.org>
Content-Transfer-Encoding: binary
X-RT-Original-Encoding: utf-8
Content-Length: 52
Resolved via new forkdepth=N option in next release.


This service is sponsored and maintained by Best Practical Solutions and runs on Perl.org infrastructure.

Please report any issues with rt.cpan.org to rt-cpan-admin@bestpractical.com.