Adventures in writing a simple grammar profiler

Inspired by jnthn’s earlier post on Grammar::Debugger, I wondered how hard it would be to implement a simple Perl 6 grammar profiler.  Turns out it wasn’t that hard at all. As far as profiling goes, all I wanted was counts of how many times each rule was executed and the cumulative time each rule took to execute.    The interface I had in mind was something simple–a multi-level hash with names of grammars at the first level then, at the second level, names of the individual rules within the grammar, and finally the actual timing information.  The timing information would be accessed thusly:

say "MyGrammar::MyRule was called " ~ %timing<MyGrammar><MyRule><calls> ~ "times";
say "and took " ~ %timing<MyGrammar><MyRule><time> ~ " seconds to execute";

But first I had to figure out what jnthn’s code was doing. From the outside looking in, the basic technique is to replace the normal grammar meta-object with a custom meta-object that inherits most of the behavior of the normal grammar meta-object but replaces the normal method lookup with a custom one that returns a routine that collects the timing information while calling the original method. Looking at jnthn’s code, I see that if the method name starts with ! or is any one of “parse”, “CREATE”, “Bool”, “defined” or “MATCH”, we just return the original method without modification. This is so that we don’t trace private methods or accidentally trace methods that aren’t directly part of the grammar but are used by it. In my simple profiler, I need to get the name of the grammar, which I do by calling my $grammar = $obj.WHAT.perl. So it looks like I need to add “perl” to that list of methods to pass through unscathed. Otherwise, I get an infinite recursion. Anyway, for those method names that don’t match the aforementioned criteria, we return a custom built routine that accumulates the execution time and increments a counter for the number of calls. Seems straight-forward enough … below is the code (somewhat untested):

my %timing;

my class ProfiledGrammarHOW is Metamodel::GrammarHOW is Mu {

    method find_method($obj, $name) {
        my $meth := callsame;
        substr($name, 0, 1) eq '!' || $name eq any(<parse CREATE Bool defined MATCH perl BUILD DESTROY>) ??
            $meth !!
            -> $c, |args {
                my $grammar = $obj.WHAT.perl;
                %timing{$grammar} //= {};                   # Vivify grammar hash
                %timing{$grammar}{$meth.name} //= {};       # Vivify method hash
                my %t := %timing{$grammar}{$meth.name};
                my $start = now;                            # get start time
                my $result := $meth($obj, |args);           # Call original method
                %t<time> += now - $start;             # accumulate execution time
                %t<calls>++;
                $result
            }
    }

    method publish_method_cache($obj) {
        # no caching, so we always hit find_method
    }
}

sub get-timing is export { %timing }
sub reset-timing is export { %timing = {} }

my module EXPORTHOW { }
EXPORTHOW.WHO.<grammar> = ProfiledGrammarHOW;

Assuming the above code was saved in file called “GrammarProfiler.pm”, you’d use it by adding the line use GrammarProfiler; to the top of any program that makes grammar declarations. Then after you parse your grammar, you can call get-timing() to obtain the hash that has the timing information for the individual rules that were executed during the parse or reset-timing() to clear the timing information. Of course, a more full-fledged profiler would do much more work and provide many more profiling options, but this isn’t bad for a quick hack and it just might be useful too.