A first pass at DTrace

I've never really spent much time optimizing Puppet except in those areas that get particular complaints (and not always then), but now that I'm forced to run Leopard I figured I should see if I can put DTrace to use.

The first pass used the functime.d script, which tells me how long Puppet spends in each function. I couldn't get the file to execute directly, and I also couldn't get it to execute my script for me (which is a pretty good indication that I don't really know how to use DTrace), so I added the ability to pause my test script, giving me time to start dtrace. So, I run my test script, which I'm using to test parse time:

~/puppet/ext/puppet-test --modulepath /Users/luke/Desktop/puppet-stanford/modules/ -s parser -t parse --manifest ~/Desktop/puppet-stanford/master/manifests/site.pp -p

Then I run the dtrace script:

sudo dtrace -s ./functime.d -p 45847 2>&1 | tee functimes.log

This takes a heckuva long time to run (380 seconds or so, vs. about 6 normally), but in the end I get a big file that has histograms for all of the classes and methods, along with a sorted list of how long Puppet spends in each method. E.g., here's a histogram:

Puppet::Parser::Parser                              parse
         value  ------------- Distribution ------------- count
       8388608 |                                         0
      16777216 |                                         1
      33554432 |                                         0
      67108864 |                                         1
     134217728 |@@@@@@@                                  30
     268435456 |@@@@@@@@@                                39
     536870912 |@@@@@@@@@@@                              49
    1073741824 |@@@@@                                    21
    2147483648 |@@@                                      14
    4294967296 |@@                                       10
    8589934592 |@                                        6
   17179869184 |                                         2
   34359738368 |                                         0

And here's a few of the methods:

Puppet::Parser::Parser                   ast                      25881       1090     28219110
NilClass                                 nil?                    1982238         19     38713614
StringScanner                            check                   2044008         24     50380323
Hash                                     each                     84949       2789    236945697
Puppet::Parser::Parser                   import                       9   29288385    263595467
Puppet::Parser::Parser                   _reduce_132                  9   29289048    263601440
Object                                   catch                    56018       5403    302711262
Puppet::Parser::Lexer                    scan                       173    1752645    303207689
Racc::Parser                             _racc_yyparse_c            173    1752730    303222439
Object                                   __send__                   173    1752803    303234951
Racc::Parser                             yyparse                    173    1753138    303292971
Puppet::Parser::Parser                   parse                      173    1753536    303361785
Array                                    collect                    331     925551    306357434
Array                                    each                     26303      11912    313340970

The first annoying thing to notice about this is that this test is clearly collecting total time between method entry and exit, not the total time that we're in a method, which makes it a bit less useful for testing.

The next thing to notice is that we're calling nil? and check a ton of times, which adds up even though they're individually very cheap.

If we add up all of the calls to check and nil?, we get a bit less than half of the total run time of the parse method (which is the entry point to all of this code), which means they're having a big impact.

This really isn't anything I couldn't get from normal Ruby profiling, but based on my experience working with Brendan a bit at OSCON last year, I know there's much more available.

My next post on DTrace will hopefully include me covering how I used it to drill down a bit further.