NYTProf v2 – A major advance in perl profilers

After much hacking, and just in time for OSCON, I’m delighted to announce the release of Devel::NYTProf version 2. A powerful, efficient, feature-rich perl source code profiler.

“If NYTProf 1 is a Toyota, then 2.0 is a Cadillac”
— Adam Kaplan, author of NYTProf 1.

The Short Story

(I’ve written up the long story, for the record, in another post.)

Adam forked Devel::FastProf (the best statement-level profiler at the time), added a test harness and tests, made some internal improvements, and grafted on an html report derived from Devel::Cover. The resulting Devel::NYTProf v1 was a big hit.

Meanwhile I’d been working on Devel::FastProf, contributing some interesting new profiling features, but it had no test harness and no html reports. When Adam released NYTProf I switched. Attracted not so much by the html report as by the test harness. (A lesson to anyone wanting to attract developers to an open source project.)

I started out by adding in the same new features I’d been adding to FastProf, albeit with more polish and tests. And then I got carried away…

“Holy shit! That is amazing.”
— Andy Lester, after using a recent development version.

Example Screen Shots

As an example I’ve used NYTProf to profile perlcritic 1.088 running on its own source code.

$ cd Perl-Critic-1.088
$ perl -d:NYTProf -S perlcritic .
$ nytprofhtml
$ open nytprof/index.html

The first image is the main index page, showing the top few subroutines and the start of the list of all source files.

NYTProf perlcritic index.png

Each source file has links to separate line-level, block-level, and sub-level reports (though I hope to merge them in future). Clicking on a subroutine name takes you to the line-level report for the file it’s defined in and positions you at the subroutine definition.

(The color coding is based on Median Absolute Deviation of all the values in the column, same as in NYProf v1.)

Here’s the all_perl_files() subroutine, for example:

NYTProf perlcritic all_perl_files.png

The colored numbers show the number of statements executed, the total time taken, and the average. The statement times are always exclusive times. Time actually spent on that statement, the expressions and any built-in functions it uses. It doesn’t include any time spent executing statements elsewhere in subroutines called by it. In NYTProf subroutine timings are inclusive and statement timings are exclusive.

Where did you come from and where are you going?

Notice the grey text.

On lines that define a subroutine NYTProf now adds ‘comments’ giving the total number of times the sub was called, the inclusive time spent in that sub, and the average. Then it adds a break-down of the same details for every location that called the subroutine. Here’s a better example of that:

NYTProf sub-callers.png

On lines that call subroutines NYTProf now adds ‘comments’ giving the name of the actual subroutines called (resolving code refs to subroutine names, including the class that handled a method call). It also tells you how many calls were made and how much time was spent in that subroutine for calls made from that line. Here’s an example:

NYTProf subs-called.png

When you mouse-over the grey text it turns black and you can click on embedded links to take you to the callers or callees. So with a few clicks you can run up and down the call stack exploring where the time is being spent and where the hot spots are being called from. The ability to explore the code so easily, guided by these performance signposts is incredibly useful.

Rolling up for a higher level view

Sometimes per-statement timing can overwhelming. In large subroutines it becomes “hard to see the wood for the trees”. So, for the first time in any Perl profiler, NYTProf now provides a block-level view of the timing data:

NYTProf perlcritic all_perl_files block level.png

What’s happening here is that NYTProf is taking the same time measurements per statement, but instead of accumulating the time against the line the statement is on, it accumulates it against the line of the first statement in the enclosing block. (The actual line it accumulates it against isn’t ideal in some cases. I’m hoping to improve that soon.)

This report is a little more tricky to read but can be very useful, especially in large subroutines. (I hope to improve the readability with some css :hover magic in future.)

The subroutine-level report is very similar except that all the timings are accumulated against line of the first statement in the subroutine.

Have a Look

Back in June I gave a talk at the Irish Open Source Technology conference where I showed the first version of the annotated html report (which I’d been hacking on till 3am the night before while struggling with a cold – presentations are great motivators). You can see the 15 minute video here or here).

Explore for yourself

I’ve uploaded the full set of reports for you to explore here. Take a look. Let me know what you think.

19 thoughts on “NYTProf v2 – A major advance in perl profilers

  1. Pingback: NYTProf v2 - the background story « Not this…

  2. Hi Stuart. Hopefully this’ll help:
    NYTProf is used during development/maintenance to profile all the source code without changing it.
    DashProfiler is for use in production by modifying specific parts of the source code to take measurements.

  3. i thought i saw in developer discussions that you were deep under the covers wrt mod_perl. Did mod_perl measurement code gel in this release?

    thanks! -g

  4. Wow. That looks very interesting, in fact extremely interesting! Read through the code and stumpled upon the “Currently there’s no support for Windows.”

    Being a Windows user, that’s a bit off-putting ;-) I could imagine that it could be a development decision to get the module done but I hope it is something that can be changed over time. Is the problem simply a different API or is it more fundamental?

  5. I don’t think there are any fundamental issues blocking windows support. It’s just a matter of someone doing it. I believe Steve Peters, one of the contributors, is already working on it. Perhaps you could help him.

  6. I’ll see what I can do but my knowledge of C or Windows internals will probably stop me from doing anything helpful :-/

  7. Pingback: OSCON 2008: Ultimate Perl Code Profiling, by Tim Bunce :: canspice.org

  8. Hi Tim,

    is there any way to tell NYTProf to just sample just specific functions? I have a Perl program with a 20-minute init time (loading >25 GB of dictionaries) and only then come the functions I want to profile. Of course profiling during the initialization takes longer and generates a huge profile file, which I want to skip.

    thanks, Michael

  9. Pingback: Devel::DProf - broken by the passage of time « Not this…

  10. Michael, you can call DB::disable_profile() early on, then call DB::enable_profile() just before the part you want to profile. In the next release you’ll be able to use the “start=no” option to avoid the need for the initial DB::disable_profile() call.

  11. Pingback: Ginnie’s Perl blog » Blog Archive » Профайлер для Perl - Devel::NYTProf

  12. Pingback: NYTProf, another perl profiler « Hao’s Blog

  13. Pingback: How can I track down CPU intensive requests in mod_perl? - Perl Solutions - Developers Q & A

Comments are closed.