Skip Menu |
 

Preferred bug tracker

Please visit the preferred bug tracker to report your issue.

This queue is for tickets about the Capture-Tiny CPAN distribution.

Report information
The Basics
Id: 67858
Status: open
Priority: 0/
Queue: Capture-Tiny

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

Bug Information
Severity: Normal
Broken in: 0.10
Fixed in: (no value)



Download (untitled) / with headers
text/plain 1.1k
I've been using Capture::Tiny lately to great effect, but recently came across a problem in conjunction with Devel::NYTProf. Perhaps you've already encountered this, but when run under profiling Capture::Tiny spends a great deal of time in C<_files_exist()>. A simple demonstration would be: Show quoted text
> perl -d:NYTProf -MCapture::Tiny=tee_merged -le 'tee_merged { print
"hi" } for 1 .. 100' > /dev/null Show quoted text
> nytprofcsv Generating CSV report...
Reading nytprof.out Processing nytprof.out data Writing sub reports to nytprof directory 100% ... Writing block reports to nytprof directory 100% ... Writing line reports to nytprof directory 100% ... Show quoted text
> grep 'sub _files_exist' nytprof/Capture-Tiny-pm-2-sub.csv
2.537151,196944,0.000013,sub _files_exist { -f $_ || return 0 for @_; return 1 } That grep result shows that C<_files_exist()> was called almost 200,000 times and took about 2.5 seconds. This adds noise to the profile output, and makes certain profiling tasks take an enormous amount of time. When run without NYTProf, performance is fine, so it seems to be based on interference. I'm not sure if you can alter this behavior, but wanted to bring it to your attention. Thanks for the module! - danboo
Download (untitled) / with headers
text/plain 700b
On Sat Apr 30 03:29:03 2011, DANBOO wrote: Show quoted text
> That grep result shows that C<_files_exist()> was called almost 200,000 > times and took about 2.5 seconds. This adds noise to the profile output, > and makes certain profiling tasks take an enormous amount of time. > > When run without NYTProf, performance is fine, so it seems to be based > on interference. I'm not sure if you can alter this behavior, but wanted > to bring it to your attention.
Thank you for taking the time to note the issue and I'm sorry I've been very tardy in replying. That's an intentional busy loop used to substitute for IPC in a more portable way. I might explore inserting Time::HiRes::usleep into the loop. David
Hopefully better in the recent release.
Download (untitled) / with headers
text/plain 1.2k
On Thu Dec 01 17:16:48 2011, DAGOLDEN wrote: Show quoted text
> Hopefully better in the recent release.
I appreciate you pursuing this. Unfortunately it may have made things worse. It looks like it spends even more time in usleep(). Using the same command in the profiling I now see: Show quoted text
> grep 'usleep(' nytprof/Capture-Tiny-pm-2-line.csv
6.862360,2129,0.003223,Time::HiRes::usleep(1000) if $have_usleep; Though perhaps my example is not representative of typical usage. It's a very tight loop with independent calls to tee_merged(), whereas a typical usage might be to have the loop within the tee_merged() CODE. It looks like the cost is associated with the call to tee_merged() and not the actual capture mechanism. I say that based on comparing these timings: Show quoted text
> time perl -le 'print "hi" for 1 .. 1000' | wc -l
1000 real 0m0.028s user 0m0.002s sys 0m0.028s Show quoted text
> time perl -MCapture::Tiny=tee_merged -le 'tee_merged { print "hi" }
for 1 .. 1000' | wc -l 1000 real 0m7.850s user 0m1.748s sys 0m3.925s Show quoted text
> time perl -MCapture::Tiny=tee_merged -le 'tee_merged { print "hi"
for 1 .. 1000 }' | wc -l 1000 real 0m0.074s user 0m0.041s sys 0m0.017s I'll have to be sure the captures in my application are at the outermost allowable scope. Thanks!
Subject: Re: [rt.cpan.org #67858] poor performance under profiling
Date: Fri, 2 Dec 2011 14:03:34 -0500
To: bug-Capture-Tiny [...] rt.cpan.org
From: David Golden <dagolden [...] cpan.org>
Download (untitled) / with headers
text/plain 1.2k
On Fri, Dec 2, 2011 at 1:55 PM, Daniel B. Boorstein via RT <bug-Capture-Tiny@rt.cpan.org> wrote: Show quoted text
> I appreciate you pursuing this. Unfortunately it may have made things > worse. It looks like it spends even more time in usleep(). Using the > same command in the profiling I now see:
The change is "fewer calls overall in exchange for a guaranteed short delay". (Which means it should yield the CPU in a slightly more friendly way, too.) Show quoted text
> Though perhaps my example is not representative of typical usage. It's a > very tight loop with independent calls to tee_merged(), whereas a > typical usage might be to have the loop within the tee_merged() CODE. > > It looks like the cost is associated with the call to tee_merged() and > not the actual capture mechanism.
Absolutely! For portability reasons, tee-ing is done by firing up an external process and piping output to it. That process does the actual tee-ing, sending output to the terminal on stdout and a copy to a file on stderr, which is what gets read back later for the capture. Plus, every subprocess has to open an arbitrary extra file as a (portable) way to signal readiness to the parent. So you definitely do *not* want a process fork and file creation, plus the busy loop to wait for file creation in a tight loop of your own. -- David


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.