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)

History Show all quoted text
  Thu Aug 13 07:55:46 2009 REHSACK [...] cpan.org - Ticket created
Subject: Subtract sys-times and make fork-follow can be turned off
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}'
  Thu Aug 13 12:12:14 2009 TIMB [...] cpan.org - Correspondence added
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?
  Thu Aug 13 12:12:14 2009 The RT System itself - Status changed from 'new' to 'open'
  Thu Aug 13 13:14:34 2009 REHSACK [...] cpan.org - Correspondence added
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.
  Thu Aug 13 15:46:00 2009 Tim.Bunce [...] pobox.com - Correspondence added
Subject: Re: [rt.cpan.org #48678] Subtract sys-times and make fork-follow can be turned off
Date: Thu, 13 Aug 2009 20:45:33 +0100
To: Jens Rehsack via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
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.
  Fri Aug 14 02:32:51 2009 REHSACK [...] cpan.org - Correspondence added
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
  Fri Aug 14 11:23:14 2009 Tim.Bunce [...] pobox.com - Correspondence added
Subject: Re: [rt.cpan.org #48678] Subtract sys-times and make fork-follow can be turned off
Date: Fri, 14 Aug 2009 16:22:45 +0100
To: Jens Rehsack via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
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.
  Sat Oct 24 11:56:14 2009 TIMB [...] cpan.org - Correspondence added
Resolved via new forkdepth=N option in next release.
  Sat Oct 24 11:56:15 2009 TIMB [...] cpan.org - Status changed from 'open' to 'resolved'