[Slim-Checkins] r10960 - /trunk/server/Slim/Web/Template/Context.pm

[adrian at svn.slimdevices.com]

Author: adrian
Date: Thu Dec 14 11:52:41 2006
New Revision: 10960

URL: http://svn.slimdevices.com?rev=10960&view=rev
Log:
Bug: N/A
Description: improve accuracy of perfmon template timings

Modified:
    trunk/server/Slim/Web/Template/Context.pm

Modified: trunk/server/Slim/Web/Template/Context.pm
URL: http://svn.slimdevices.com/trunk/server/Slim/Web/Template/Context.pm?rev=10960&r1=10959&r2=10960&view=diff
==============================================================================
--- trunk/server/Slim/Web/Template/Context.pm (original)
+++ trunk/server/Slim/Web/Template/Context.pm Thu Dec 14 11:52:41 2006
@@ -15,11 +15,14 @@
 use base 'Template::Context';
 
 our $procTemplate = Slim::Utils::PerfMon->new('Process Template', [0.002, 0.005, 0.010, 0.015, 0.025, 0.050, 0.1, 0.5, 1, 5]);
-my $depth = 0;
+
+# Following allow timing of template processing excluding time in idleStreams and log4perl
+my $depth = 0;   # depth of template being processed
+my @start = [0]; # start time for latest execute of this template
+my @this  = [0]; # time spent in this template
+my @total = [0]; # total time spent in this template + deaper templates
 
 my $last = 0;
-
-my (@start, @elapsed) = ([0], [0]);
 
 sub process {
 	my $self = shift;
@@ -42,32 +45,35 @@
 
 		my $temp = $_[0];
 
-		$elapsed[$depth] += $t1 - $start[$depth];
+		$this[$depth] += $t1 - $start[$depth];
 
 		$depth++;
 
 		my $t2 = Time::HiRes::time();
 
-		$elapsed[$depth] = 0;
-		$start[$depth]   = $t2;
+		$this[$depth]  = 0;
+		$total[$depth] = 0;
+		$start[$depth] = $t2;
 
 		my $ret = \$self->SUPER::process(@_);
 
 		my $t3 = Time::HiRes::time();
 
-		$procTemplate->log($t3 - $t2,
+		my $this = $this[$depth] + $t3 - $start[$depth];
+		my $total= $total[$depth] += $this;
+
+		$procTemplate->log($total,
 			sub {
-				my $us = ($elapsed[$depth] + $t3 - $start[$depth]) * 1000000;
-				sprintf ("%-32s (this templ: %7d us)", "  " x $depth . (ref $temp ? $temp->{'name'} : $temp), $us);
+				sprintf ("%-32s (this templ: %7d us)", "  " x $depth . (ref $temp ? $temp->{'name'} : $temp), $this * 1000000);
 			}
 		);
 
 		$depth--;
 
 		$start[$depth] = Time::HiRes::time();
+		$total[$depth] += $total;
 
 		return $$ret;
-
 	}
 }