Bug #67858 for Capture-Tiny: poor performance under profiling

Sat Apr 30 03:29:03 2011 danboo [...] cpan.org - Ticket created

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

Sun May 01 03:50:18 2011 danboo [...] cpan.org - Subject changed from (no value) to 'poor performance under profiling'

Wed Nov 30 15:17:21 2011 dagolden [...] cpan.org - Correspondence added

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

Wed Nov 30 15:17:23 2011 The RT System itself - Status changed from 'new' to 'open'

Wed Nov 30 15:17:39 2011 dagolden [...] cpan.org - Severity Important changed to Normal

Wed Nov 30 15:41:20 2011 dagolden [...] cpan.org - Status changed from 'open' to 'patched'

Thu Dec 01 17:16:48 2011 dagolden [...] cpan.org - Correspondence added

Hopefully better in the recent release.

Thu Dec 01 17:16:49 2011 The RT System itself - Status changed from 'patched' to 'open'

Thu Dec 01 17:16:49 2011 dagolden [...] cpan.org - Status changed from 'open' to 'resolved'

Fri Dec 02 13:55:44 2011 danboo [...] cpan.org - Correspondence added

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!

Fri Dec 02 13:55:45 2011 The RT System itself - Status changed from 'resolved' to 'open'

Fri Dec 02 14:04:05 2011 dagolden [...] cpan.org - Correspondence added

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>

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

Bug #67858 for Capture-Tiny: poor performance under profiling

Preferred bug tracker