[Catalyst] [PATCH] Properly order the debug action list

[Andy Grundman]

The debug action list has so far been a simple array, and is populated in 
reverse order when dealing with forwards.  This patch turns the action list into 
a proper tree that is displayed in the proper execution order.  This comes with 
a slight hit in performance, but it's debug mode, so not a big deal. :)

Example:

sub default : Private {
     my ( $self, $c ) = @_;
     $c->forward('one');
     $c->forward('two');
     $c->forward('three');
}

sub one : Private {
     my ( $self, $c ) = @_;
     $c->forward('two');
}

sub two : Private {
     my ( $self, $c ) = @_;
     $c->forward('three');
}

sub three : Private {
     my ( $self, $c ) = @_;
     $c->forward('four');
}

sub four : Private { }

Old display:
.------------------------------------------------------------------+-----------.
| Action                                                           | Time      |
+------------------------------------------------------------------+-----------+
| -> /four                                                         | 0.000021s |
| -> /three                                                        | 0.000322s |
| -> /two                                                          | 0.000612s |
| -> /one                                                          | 0.000888s |
| -> /four                                                         | 0.000019s |
| -> /three                                                        | 0.000257s |
| -> /two                                                          | 0.000477s |
| -> /four                                                         | 0.000019s |
| -> /three                                                        | 0.000237s |
| /default                                                         | 0.003647s |
'------------------------------------------------------------------+-----------'

New display:
.------------------------------------------------------------------+-----------.
| Action                                                           | Time      |
+------------------------------------------------------------------+-----------+
| /default                                                         | 0.008394s |
|  -> /one                                                         | 0.002403s |
|   -> /two                                                        | 0.001647s |
|    -> /three                                                     | 0.000890s |
|     -> /four                                                     | 0.000030s |
|  -> /two                                                         | 0.001735s |
|   -> /three                                                      | 0.000909s |
|    -> /four                                                      | 0.000031s |
|  -> /three                                                       | 0.000946s |
|   -> /four                                                       | 0.000029s |
'------------------------------------------------------------------+-----------'

-Andy
-------------- next part --------------
Index: lib/Catalyst.pm
===================================================================
--- lib/Catalyst.pm	(revision 2828)
+++ lib/Catalyst.pm	(working copy)
@@ -17,6 +17,8 @@
 use Time::HiRes qw/gettimeofday tv_interval/;
 use URI;
 use Scalar::Util qw/weaken/;
+use Tree::Simple;
+use Tree::Simple::Visitor::FindByUID;
 use attributes;
 
 __PACKAGE__->mk_accessors(
@@ -896,6 +898,7 @@
       : ( caller(1) )[3];
 
     my $action = '';
+    
     if ( $c->debug ) {
         $action = "$code";
         $action = "/$action" unless $action =~ /\-\>/;
@@ -910,7 +913,41 @@
         }
 
         $action = "-> $action" if $callsub =~ /forward$/;
+
+        my $node = Tree::Simple->new( {
+            action  => $action,
+            elapsed => undef,       # to be filled in later
+        } );
+        $node->setUID( "$code" . $c->counter->{"$code"} );
+        
+        unless ( ( $code->name =~ /^_.*/ )
+            && ( !$c->config->{show_internal_actions} ) )
+        {         
+            # is this a root-level call or a forwarded call?
+            if ( $callsub =~ /forward$/ ) {
+           
+                # forward, locate the caller
+                if ( my $parent = $c->stack->[-1] ) {
+                    my $visitor = Tree::Simple::Visitor::FindByUID->new;
+                    $visitor->searchForUID( 
+                        "$parent" . $c->counter->{"$parent"} );
+                    $c->{stats}->accept( $visitor );
+                    if ( my $result = $visitor->getResult ) {
+                        $result->addChild( $node );
+                    }
+                }
+                else {
+                    # forward with no caller may come from a plugin
+                    $c->{stats}->addChild( $node );
+                }
+            }
+            else {
+                # root-level call
+                $c->{stats}->addChild( $node );
+            }
+        }
     }
+    
     push( @{ $c->stack }, $code );
     my $elapsed = 0;
     my $start   = 0;
@@ -922,14 +959,27 @@
         unless ( ( $code->name =~ /^_.*/ )
             && ( !$c->config->{show_internal_actions} ) )
         {
-            push @{ $c->{stats} }, [ $action, sprintf( '%fs', $elapsed ) ];
+            # FindByUID uses an internal die, so we save the existing error
+            my $error = $@;
+            
+            # locate the node in the tree and update the elapsed time
+            my $visitor = Tree::Simple::Visitor::FindByUID->new;
+            $visitor->searchForUID( "$code" . $c->counter->{"$code"} );
+            $c->{stats}->accept( $visitor );
+            if ( my $result = $visitor->getResult ) {
+                my $value = $result->getNodeValue;
+                $value->{elapsed} = sprintf( '%fs', $elapsed );
+                $result->setNodeValue( $value );
+            }
+            
+            # restore error
+            $@ = $error || undef;
         }
     }
     my $last = ${ $c->stack }[-1];
     pop( @{ $c->stack } );
 
     if ( my $error = $@ ) {
-
         if ( $error eq $DETACH ) { die $DETACH if $c->depth > 1 }
         else {
             unless ( ref $error ) {
@@ -1099,11 +1149,11 @@
     # Always expect worst case!
     my $status = -1;
     eval {
-        my @stats = ();
+        my $stats = ( $class->debug ) ? Tree::Simple->new : '';
 
         my $handler = sub {
             my $c = $class->prepare(@arguments);
-            $c->{stats} = \@stats;
+            $c->{stats} = $stats;
             $c->dispatch;
             return $c->finalize;
         };
@@ -1116,8 +1166,16 @@
             my $av = sprintf '%.3f',
               ( $elapsed == 0 ? '??' : ( 1 / $elapsed ) );
             my $t = Text::SimpleTable->new( [ 64, 'Action' ], [ 9, 'Time' ] );
-
-            for my $stat (@stats) { $t->row( $stat->[0], $stat->[1] ) }
+            
+            $stats->traverse( sub {
+                my $action = shift;
+                my $stat = $action->getNodeValue;
+                $t->row( 
+                    ( q{ } x $action->getDepth ) . $stat->{action},
+                    $stat->{elapsed} || '??'
+                );
+            } );
+            
             $class->log->info(
                 "Request took ${elapsed}s ($av/s)\n" . $t->draw );
         }