NYTProf v5 trial uploaded

[Tim Bunce]

Hi.

I've uploaded Devel-NYTProf-4.90_90 to CPAN as a trial for cpantesters to chew on
before making a 5.00 release. Hopefully soon.

=head2 Changes in Devel::NYTProf 5.00

Added subroutine entry and return event stream,
controlled via the calls=N option. Default calls=1.

Added nytprofcalls command to process the call event stream to
generate a call tree (experimental).

Added Flame Graph visualization SVG using the generated call tree.

Changed blocks=N option to be 0 (disabled) by default.

Fixed test for perl 5.17+ hash randomization.
Fixed nytprofhtml for Windows thanks to Jan Dubois. PR#2
Fixed assorted nits thanks to Steve Peters. PR#1
Deprecated nytprofcsv - speak up if you use it!
No longer warn about $&, $` and $' being slow if $] >= 5.017008.

=cut

The Flame Graph visualization is a great way to 'see' where time is being spent.

This also includes an important change from Devel::NYTProf 4.23
that I released quietly a few months ago:

=head2 Changes in Devel::NYTProf 4.23 - 31st Dec 2012

Significant improvement in the accuracy of the subroutine profiler,
especially for frequent calls to very short duration subs/ops,
and more so for POSIX and OSX systems with sub-microsecond clocks.

=cut

I'd be grateful if you'd test it on some real-world applications ASAP.

Thanks!

Tim.

[Tim Bunce]

Anyone tried it out yet?

Tim.

> --
> --
> You've received this message because you are subscribed to
> the Devel::NYTProf Development User group.
>
> Group hosted at: http://groups.google.com/group/develnytprof-dev
> Project hosted at: http://perl-devel-nytprof.googlecode.com
> CPAN distribution: http://search.cpan.org/dist/Devel-NYTProf
>
> To post, email: develnyt...@googlegroups.com
> To unsubscribe, email: develnytprof-d...@googlegroups.com
> ---
> You received this message because you are subscribed to the Google Groups "Devel::NYTProf Dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to develnytprof-d...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>

[Vladimir Timofeev]

Hi

On Sat, Apr 6, 2013 at 6:21 PM, Tim Bunce <Tim....@pobox.com> wrote:
> Anyone tried it out yet?

Yes, just run test site from one of our big applications with it:
$ PERL5OPT=-d:NYTProf NYTPROF=addpid=1 prove
then merge these 134 reports:
$ nytprofmerge -o merged.out nytprof.out.*
and got:
Apr 06 22:30:53 vov.home kernel: Out of memory: Kill process 9028
(nytprofmerge) score 713 or sacrifice child
Apr 06 22:30:53 vov.home kernel: Killed process 9028 (nytprofmerge)
total-vm:23488952kB, anon-rss:23469036kB, file-rss:0kB

With current stable 4.25 all was okey.
nytprofmerge consume about 2.6Mb of RSS memory before its finish.

--
Vladimir Timofeev <vov...@gmail.com>

[Tim Bunce]

On Sat, Apr 06, 2013 at 11:13:12PM +0400, Vladimir Timofeev wrote:
> Hi

Hi Vladimir.

> On Sat, Apr 6, 2013 at 6:21 PM, Tim Bunce <Tim....@pobox.com> wrote:
> > Anyone tried it out yet?
>
> Yes, just run test site from one of our big applications with it:
> $ PERL5OPT=-d:NYTProf NYTPROF=addpid=1 prove
> then merge these 134 reports:
> $ nytprofmerge -o merged.out nytprof.out.*
> and got:
> Apr 06 22:30:53 vov.home kernel: Out of memory: Kill process 9028
> (nytprofmerge) score 713 or sacrifice child
> Apr 06 22:30:53 vov.home kernel: Killed process 9028 (nytprofmerge)
> total-vm:23488952kB, anon-rss:23469036kB, file-rss:0kB
>
> With current stable 4.25 all was okey.
> nytprofmerge consume about 2.6Mb of RSS memory before its finish.

2.6Mb of RSS memory doesn't seem like much. Did you mean GB?
The OOM log you quote shows about 23GB for total-vm.

I can't see how the changes in v5 would make nytprofmerge use more memory,
so I'm puzzled by your report.

How much memory does the v4.25 nytprofmerge use?

Tim.

[Vladimir Timofeev]

On Sun, Apr 7, 2013 at 1:24 AM, Tim Bunce <Tim....@pobox.com> wrote:
> On Sat, Apr 06, 2013 at 11:13:12PM +0400, Vladimir Timofeev wrote:
>> Hi
>
> Hi Vladimir.
>
>> On Sat, Apr 6, 2013 at 6:21 PM, Tim Bunce <Tim....@pobox.com> wrote:
>> > Anyone tried it out yet?
>>
>> Yes, just run test site from one of our big applications with it:
>> $ PERL5OPT=-d:NYTProf NYTPROF=addpid=1 prove
>> then merge these 134 reports:
>> $ nytprofmerge -o merged.out nytprof.out.*
>> and got:
>> Apr 06 22:30:53 vov.home kernel: Out of memory: Kill process 9028
>> (nytprofmerge) score 713 or sacrifice child
>> Apr 06 22:30:53 vov.home kernel: Killed process 9028 (nytprofmerge)
>> total-vm:23488952kB, anon-rss:23469036kB, file-rss:0kB
>>
>> With current stable 4.25 all was okey.
>> nytprofmerge consume about 2.6Mb of RSS memory before its finish.
>
> 2.6Mb of RSS memory doesn't seem like much. Did you mean GB?
> The OOM log you quote shows about 23GB for total-vm.

Sorry for my wording, I mean that
2.6Mb use nytprofmerge v4.25
OOM for nytprofmerge v5.0

>
> I can't see how the changes in v5 would make nytprofmerge use more memory,
> so I'm puzzled by your report.
>
> How much memory does the v4.25 nytprofmerge use?
>
> Tim.
>

[Vladimir Timofeev]

It can be reproduced on Catalyst test suite.
$ cpanm --look Catalyst
$ perl Makefile.PL && make
$ PERL5OPT=-d:NYTProf NYTPROF=addpid=1 prove -b

$ nytprofmerge -o merged.out nytprof.out.*

--
Vladimir Timofeev <vov...@gmail.com>

[Tim Bunce]

On Sun, Apr 07, 2013 at 02:13:01AM +0400, Vladimir Timofeev wrote:
> It can be reproduced on Catalyst test suite.
> $ cpanm --look Catalyst
> $ perl Makefile.PL && make
> $ PERL5OPT=-d:NYTProf NYTPROF=addpid=1 prove -b
> $ nytprofmerge -o merged.out nytprof.out.*

I've reproduced it and started investigating.

Thanks Vladimir.

Tim.

[Tim Bunce]

On Sat, Apr 06, 2013 at 11:13:12PM +0400, Vladimir Timofeev wrote:
>

> Apr 06 22:30:53 vov.home kernel: Out of memory: Kill process 9028
> (nytprofmerge) score 713 or sacrifice child
> Apr 06 22:30:53 vov.home kernel: Killed process 9028 (nytprofmerge)
> total-vm:23488952kB, anon-rss:23469036kB, file-rss:0kB

I've just uploaded Devel-NYTProf-4.90_91.tar.gz which fixes the leak.
Please retry with that and let me know how it goes.

Thanks!

Tim.

[Vladimir Timofeev]

Thanks!
Now merging process successfully finished with these memory consumption
$ nytprofmerge -o merged.out nytprof.out.* - about 4Gb
Then report generation was killed by OOM (about 26Gb) on line
"Extracting subroutine call data ..."
$ nytprofhtml -f merged.out
It can be okey probably, because merged.out has size 7.8Gb

I will try test with calls=0 tomorrow.

--
Vladimir Timofeev <vov...@gmail.com>

[Vladimir Timofeev]

Thanks! With 5.0 release we can profile our applications! Flame graphs
very pretty!

Sample memory usages that I collect for Catalyst test suite. Run as:
$ PERL5OPT=-d:NYTProf NYTPROF=addpid=1 prove -b

$ nytprofmerge -o merged.out nytprof.out.*

$ nytprofhtml -f merged.out

before https://github.com/timbunce/devel-nytprof/commit/ca91df417ad64cd0a4da70d81711ea4c27977dc3:
nytprofmerge - 230Mb
nytprofcalls - 5.5Gb
nytprofhtml - 147Mb (without nytprofcalls)
flamegraph.pl - 4Gb

after latest commits:
nytprofmerge - 230Mb
nytprofcalls - about 1Gb
nytprofhtml - 147Mb (without nytprofcalls)
flamegraph.pl - 4Gb

PS. if I set "calls=0" option, then nytprofhtml fail with error
"ERROR: No stack counts found "

--
Vladimir Timofeev <vov...@gmail.com>

[Tim Bunce]

On Tue, Apr 09, 2013 at 02:47:28AM +0400, Vladimir Timofeev wrote:
> Thanks! With 5.0 release we can profile our applications! Flame graphs
> very pretty!

I agree, they are very pretty :)

> Sample memory usages that I collect for Catalyst test suite. Run as:
> $ PERL5OPT=-d:NYTProf NYTPROF=addpid=1 prove -b
> $ nytprofmerge -o merged.out nytprof.out.*
> $ nytprofhtml -f merged.out
>
> before https://github.com/timbunce/devel-nytprof/commit/ca91df417ad64cd0a4da70d81711ea4c27977dc3:
> nytprofmerge - 230Mb
> nytprofcalls - 5.5Gb
> nytprofhtml - 147Mb (without nytprofcalls)
> flamegraph.pl - 4Gb
>
> after latest commits:
> nytprofmerge - 230Mb
> nytprofcalls - about 1Gb

Much better! :)

> nytprofhtml - 147Mb (without nytprofcalls)
> flamegraph.pl - 4Gb

That might be a problem for some people, but I can see ways to reduce
the memory usage if so.

> PS. if I set "calls=0" option, then nytprofhtml fail with error
> "ERROR: No stack counts found "

I can't reproduce that.

Tim.

> On Mon, Apr 8, 2013 at 3:56 AM, Vladimir Timofeev <vov...@gmail.com> wrote:
> > Thanks!
> > Now merging process successfully finished with these memory consumption
> > $ nytprofmerge -o merged.out nytprof.out.* - about 4Gb
> > Then report generation was killed by OOM (about 26Gb) on line
> > "Extracting subroutine call data ..."
> > $ nytprofhtml -f merged.out
> > It can be okey probably, because merged.out has size 7.8Gb
> >
> > I will try test with calls=0 tomorrow.
> >
> >
> > On Mon, Apr 8, 2013 at 2:40 AM, Tim Bunce <Tim....@pobox.com> wrote:
> >> On Sat, Apr 06, 2013 at 11:13:12PM +0400, Vladimir Timofeev wrote:
> >>>
> >>> Apr 06 22:30:53 vov.home kernel: Out of memory: Kill process 9028
> >>> (nytprofmerge) score 713 or sacrifice child
> >>> Apr 06 22:30:53 vov.home kernel: Killed process 9028 (nytprofmerge)
> >>> total-vm:23488952kB, anon-rss:23469036kB, file-rss:0kB
> >>
> >> I've just uploaded Devel-NYTProf-4.90_91.tar.gz which fixes the leak.
> >> Please retry with that and let me know how it goes.
> >>
> >> Thanks!
> >>
> >> Tim.
> >
> >
> >
> > --
> > Vladimir Timofeev <vov...@gmail.com>
>
>
>
> --
> Vladimir Timofeev <vov...@gmail.com>
>

[Vladimir Timofeev]

Hi

On Tue, Apr 9, 2013 at 12:35 PM, Tim Bunce <Tim....@pobox.com> wrote:
...

>> PS. if I set "calls=0" option, then nytprofhtml fail with error
>> "ERROR: No stack counts found "
>
> I can't reproduce that.

Agree.
Sorry, seems I was trying process old data files with new
Devel::NYTProf or so...