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

[adrian at svn.slimdevices.com]

Author: adrian
Date: Sun Dec 10 07:12:07 2006
New Revision: 10931

URL: http://svn.slimdevices.com?rev=10931&view=rev
Log:
Bug: N/A
Description: perfmon - profile time spent processing each TT template
logged to when template warning threshold exceeded

To see all templates processed, start server with:
 --perfwarn template=0
(note overall time includes time in log4perl, this templ time does not)

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=10931&r1=10930&r2=10931&view=diff
==============================================================================
--- trunk/server/Slim/Web/Template/Context.pm (original)
+++ trunk/server/Slim/Web/Template/Context.pm Sun Dec 10 07:12:07 2006
@@ -15,21 +15,22 @@
 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 $indent = 0;
+my $depth = 0;
 
 my $last = 0;
 
+my (@start, @elapsed) = ([0], [0]);
 
 sub process {
 	my $self = shift;
 
-	my $now = Time::HiRes::time();
+	my $t1 = Time::HiRes::time();
 
-	if ($now - $last > 0.05) {
+	if ($t1 - $last > 0.05) {
 
 		main::idleStreams();
 
-		$last = $now = Time::HiRes::time();
+		$last = $t1;
 
 	}
 
@@ -41,13 +42,29 @@
 
 		my $temp = $_[0];
 
-		$indent++;
+		$elapsed[$depth] += $t1 - $start[$depth];
+
+		$depth++;
+
+		my $t2 = Time::HiRes::time();
+
+		$elapsed[$depth] = 0;
+		$start[$depth]   = $t2;
 
 		my $ret = \$self->SUPER::process(@_);
 
-		$indent--;
+		my $t3 = Time::HiRes::time();
 
-		$procTemplate->log(Time::HiRes::time() - $now, sub { "  " x $indent . (ref $temp ? $temp->{'name'} : $temp) } );
+		$procTemplate->log($t3 - $t2,
+			sub {
+				my $us = ($elapsed[$depth] + $t3 - $start[$depth]) * 1000000;
+				sprintf ("%-32s (this templ: %7d us)", "  " x $depth . (ref $temp ? $temp->{'name'} : $temp), $us);
+			}
+		);
+
+		$depth--;
+
+		$start[$depth] = Time::HiRes::time();
 
 		return $$ret;
 
@@ -55,4 +72,4 @@
 }
 
 1;
-	
+