Combined profiling for a set of tests?

[Ryan Moore]

Is there any way to combine NYTProf output from multiple source files to give a useful / non-garbage output?

The docs indicate that you might be successful running nytprofmerge with two runs of the same source, but trying to combine multiple sources will probably not do what you expect. I'm trying to generate a combined profile for our tests running under prove (220 files in t/ and counting), but I'm coming across this limitation. Profiling the parent (perl -d:NYTProf prove) only gives timing for prove itself, and if I use "addpid=1" I can't combine the results to get anything sensible.

I even tried running with "compress=0" to see if the files were XML or CSV or some type of structured output that I could hack together, but they appear to be a proprietary binary format. Is there any hope for either running one NYTProf across a set of processes, or for combining separate runs into a usable nytprof-merged.out file?

 - Ryan

[Tim Bunce]

On Thu, Mar 21, 2013 at 03:58:13PM -0700, Ryan Moore wrote:
> Is there any way to combine NYTProf output from multiple source files to give a useful / non-garbage
> output?
> The docs indicate that you might be successful running nytprofmerge with two runs of the same source,
> but trying to combine multiple sources will probably not do what you expect. I'm trying to generate a
> combined profile for our tests running under prove (220 files in t/ and counting),

Why, specifically?

> but I'm coming across
> this limitation. Profiling the parent (perl -d:NYTProf prove) only gives timing for prove itself, and if
> I use "addpid=1" I can't combine the results to get anything sensible.
> I even tried running with "compress=0" to see if the files were XML or CSV or some type of structured
> output that I could hack together, but they appear to be a proprietary binary format. Is there any hope
> for either running one NYTProf across a set of processes, or for combining separate runs into a usable
> nytprof-merged.out file?

What's the problem with the current output from nytprofmerge?

In theory you might be able to hack on nytprofmerge to get something
more useful out.

Tim.

[Ryan Moore]

On Friday, March 22, 2013 9:34:37 AM UTC-7, Tim.Bunce wrote:

On Thu, Mar 21, 2013 at 03:58:13PM -0700, Ryan Moore wrote:
>    Is there any way to combine NYTProf output from multiple source files to give a useful / non-garbage
>    output?
>    The docs indicate that you might be successful running nytprofmerge with two runs of the same source,
>    but trying to combine multiple sources will probably not do what you expect. I'm trying to generate a
>    combined profile for our tests running under prove (220 files in t/ and counting),

Why, specifically?

Concentrating effort on improving the test setup itself. On any individual test a 1-second improvement might not be the best thing to focus on (or biggest timesink), but if that same one-second improvement is propagated to all 220 tests that's 3+ minutes of improvement for a full test run.

>    but I'm coming across
>    this limitation. Profiling the parent (perl -d:NYTProf prove) only gives timing for prove itself, and if
>    I use "addpid=1" I can't combine the results to get anything sensible.
>    I even tried running with "compress=0" to see if the files were XML or CSV or some type of structured
>    output that I could hack together, but they appear to be a proprietary binary format. Is there any hope
>    for either running one NYTProf across a set of processes, or for combining separate runs into a usable
>    nytprof-merged.out file?

What's the problem with the current output from nytprofmerge?

It seems to be only reporting a fraction of the time used overall, i.e. for a 30 minute test run it shows a function with 4 seconds of total usage as the top offender, and doesn't seem to include all of the t/* files in the output.

In theory you might be able to hack on nytprofmerge to get something
more useful out.

Tim.

I'm unfortunately a Perl n00b, but I'll take a look to see if there's anything obvious in nytprofmerge that applies to my use case. I'll also see if I can create a repro case with less than the several-hundred sources involved in my current failures. 

 - Ryan

[Tim Bunce]

On Fri, Mar 22, 2013 at 10:46:12AM -0700, Ryan Moore wrote:
> On Friday, March 22, 2013 9:34:37 AM UTC-7, Tim.Bunce wrote:
>
> On Thu, Mar 21, 2013 at 03:58:13PM -0700, Ryan Moore wrote:
> > Is there any way to combine NYTProf output from multiple source files to give a useful /
> non-garbage
> > output?
> > The docs indicate that you might be successful running nytprofmerge with two runs of the same
> source,
> > but trying to combine multiple sources will probably not do what you expect. I'm trying to
> generate a
> > combined profile for our tests running under prove (220 files in t/ and counting),
>
> Why, specifically?
>
> Concentrating effort on improving the test setup itself. On any individual test a 1-second improvement
> might not be the best thing to focus on (or biggest timesink), but if that same one-second improvement
> is propagated to all 220 tests that's 3+ minutes of improvement for a full test run.

I see your point. I'd guess that improving a random few, focusing on
common code paths, would have a similar effect.

I presume you're using a modern version of prove, which has many good
features for avoiding rerunning all tests.
See --state slow/fast etc in
https://metacpan.org/module/OVID/Test-Harness-3.26/bin/prove
Perhaps that would be of some help.

> What's the problem with the current output from nytprofmerge?
>
> It seems to be only reporting a fraction of the time used overall, i.e. for a 30 minute test run it
> shows a function with 4 seconds of total usage as the top offender, and doesn't seem to include all of
> the t/* files in the output.
>
> In theory you might be able to hack on nytprofmerge to get something
> more useful out.
>

> I'm unfortunately a Perl n00b, but I'll take a look to see if there's anything obvious in nytprofmerge
> that applies to my use case. I'll also see if I can create a repro case with less than the
> several-hundred sources involved in my current failures.

In my (very quick) testing it seems to work ok.

Small (ideally very small) test cases would be a big help.

Tim.

[Ryan Moore]

It turns out that one out of N files was aborting early and generating an empty/incomplete nytprof.out file, and merging that one with the other working files made everything unhappy. I have yet to track down which test is borking the rest, it might be something intermittent since testing [a-m]*.t and [n-z]*.t separately both show no failures.

Thanks for looking into a stupid-user-error, I'll send a repro case for the "bad nytprof.out merges badly" if I can isolate it.

 - Ryan

[Tim Bunce]

On Mon, Apr 08, 2013 at 01:59:44PM -0700, Ryan Moore wrote:
> It turns out that one out of N files was aborting early and generating an empty/incomplete nytprof.out
> file, and merging that one with the other working files made everything unhappy. I have yet to track
> down which test is borking the rest, it might be something intermittent since testing [a-m]*.t and
> [n-z]*.t separately both show no failures.
> Thanks for looking into a stupid-user-error, I'll send a repro case for the "bad nytprof.out merges
> badly" if I can isolate it.

Not a stupid-user-error, a stupid-software-error for not handling that case.

Did you see a 'Profile data incomplete ...' message? That's a warning
currently but probably ought to be an error in nytprofmerge.

Tim.