Index: branches/release-30/lib/MT/Core.pm
===================================================================
--- branches/release-30/lib/MT/Core.pm (revision 1369)
+++ branches/release-30/lib/MT/Core.pm (revision 1372)
@@ -499,4 +499,7 @@
             # Basename settings
             'AuthorBansenameLimit' => { default => 30 },
+            'PerformanceLogging' => { default => 0 },
+            'PerformanceLoggingThreshold' => { default => 0.1 },
+            'ProcessMemoryCommand' => { handler => \&ProcessMemoryCommand },
         },
         upgrade_functions => \&load_upgrade_fns,
@@ -801,4 +804,24 @@
 }
 
+sub ProcessMemoryCommand {
+    my $cfg = shift;
+    $cfg->set_internal( 'ProcessMemoryCommand', @_ ) if @_;
+    my $cmd = $cfg->get_internal('ProcessMemoryCommand');
+    unless ($cmd) {
+        my $os = $^O;
+        if ($os eq 'darwin') {
+            $cmd = 'ps $$ -o rss=';
+        }
+        elsif ($os eq 'linux') {
+            $cmd = 'ps -p $$ -o rss=';
+        }
+        elsif ($os eq 'MSWin32') {
+            $cmd = { command => q{tasklist /FI "PID eq $$" /FO TABLE /NH},
+                regex => qr/([\d,]+) K/ };
+        }
+    }
+    return $cmd;
+}
+
 sub SecretToken {
     my $cfg = shift;
Index: branches/release-30/lib/MT/Util/ReqTimer.pm
===================================================================
--- branches/release-30/lib/MT/Util/ReqTimer.pm (revision 1372)
+++ branches/release-30/lib/MT/Util/ReqTimer.pm (revision 1372)
@@ -0,0 +1,160 @@
+=head1 NAME
+
+MT::Util::ReqTimer
+
+=head1 DESCRIPTION
+
+This is a simple class to let us get custom and granular
+and log parts of the request cycle.
+
+Note that the timerlogger has got some custom stuff in
+it to handle the data we're passing into it, so that
+it can log pretty in some placess and machine-readable
+in other places.
+
+Requires installation of Time::HiRes and List::Util
+(Time::HiRes is core to Perl 5.8.0 and later).
+
+=cut
+
+package MT::Util::ReqTimer;
+
+use strict;
+use List::Util qw( sum );
+use Time::HiRes;
+
+our $Timer;
+sub instance {
+    return $Timer ||= shift->new;
+}
+
+sub new {
+    my $class = shift;
+    $class = ref $class || $class;
+    my $self = bless {}, $class;
+    $self->start( @_ );
+    return $self;
+}
+
+sub start {
+    my $self = shift;
+    $self->{uri} = shift || '';
+    $self->{prev} = $self->{first} = Time::HiRes::time();
+    $self->{paused} = [];
+    $self->{elapsed} = 0;
+    $self->{dur} = [];
+}
+
+sub mark {
+    my ($self, $mark_str) = @_;
+    $mark_str = (caller(1))[3] unless $mark_str;
+    my $now = Time::HiRes::time();
+    my $dur = $now - $self->{prev};
+    $self->{elapsed} += $dur;
+    push @{$self->{dur}}, [ $dur, $mark_str, $self->{elapsed} ];
+    if (@{$self->{paused}}) {
+        my $paused = pop @{$self->{paused}};
+        if (ref $paused ne 'ARRAY') {
+            $paused = [];
+        }
+        my ($start, $end) = @$paused;
+
+        #back up enough to account for the time spent doing other things
+        $self->{prev} = $start - ($end - $now);
+    } else {
+        $self->{prev} = $now;
+    }
+}
+
+sub log {
+    my $self = shift;
+    #my $timerlogger = Log::Log4perl::get_logger('TypeCore::Util::ReqTimer');
+    #$timerlogger->info($self->{uri}, $self->{dur});
+}
+
+sub dump_line {
+    my $self = shift;
+    my (@more) = @_;
+    my @lines;
+    push @lines, "pid=$$";
+    push @lines, "uri=[" . $self->{uri} . ']' if $self->{uri};
+    push @lines, @more if @more;
+    my $total = 0;
+    my $threshold = MT->config->PerformanceLoggingThreshold;
+    foreach ( @{$self->{dur}} ) {
+        my $dur = $_->[0];
+        if ($_->[1] =~ m/^total\b/) {
+            $dur = $_->[2];
+        }
+        if ($dur >= $threshold) {
+            push @lines, sprintf("%s=%.5f", $_->[1], $dur);
+        }
+        $total += $_->[0];
+    }
+    push @lines, sprintf("Total=%.5f", $total);
+    my @times = localtime(time);
+    my $mon = ('Jan','Feb','Mar','Apr','May','Jun','Jul','Aug','Sep','Oct','Nov','Dec')[$times[4]];
+    my $day = ('Sun','Mon','Tue','Wed','Thu','Fri','Sat')[$times[6]];
+    my $mday = $times[3];
+    my $year = $times[5]+1900;
+    my ($hr, $mn, $sc) = ($times[2], $times[1], $times[0]);
+    my $ts = sprintf("%s %s %s %02d:%02d:%02d %04d", $day, $mon, $mday, $hr, $mn, $sc, $year);
+
+    require Sys::Hostname; # available in core as of Perl 5.6.0
+    my $hostname = Sys::Hostname::hostname();
+
+    return "[$ts] $hostname pt-times: " . join(", ", @lines) . "\n";
+}
+
+sub dump {
+    my $self = shift;
+    my $lines = '';
+    my $total = 0;
+    my $threshold = MT->config->PerformanceLoggingThreshold;
+    foreach ( @{$self->{dur}} ) {
+        my $dur = $_->[0];
+        if ($_->[1] =~ m/^total\b/) {
+            $dur = $_->[2];
+        }
+        if ($dur >= $threshold) {
+            $lines .= sprintf("%s - %.5f %s\n", $$, $dur, $_->[1]);
+        }
+        $total += $_->[0];
+    }
+    $lines .= sprintf("%s - %.5f --Total-- %s\n", $$, $total, $self->{uri});
+    return $lines;
+}
+
+sub pause_partial {
+    my $self = shift;
+    my $now = Time::HiRes::time();
+    push @{$self->{paused}}, [$self->{prev}, $now];
+
+    $self->{prev} = $now;
+}
+
+sub unpause {
+    my ($self) = @_;
+    my $now = Time::HiRes::time();
+    my $dur = $now - $self->{prev};
+    $self->{elapsed} += $dur;
+    if (@{$self->{paused}}) {
+        my $paused = pop @{$self->{paused}};
+        if (ref $paused ne 'ARRAY') {
+            $paused = [];
+        }
+        my ($start, $end) = @$paused;
+
+        #back up enough to account for the time spent doing other things
+        $self->{prev} = $start - ($end - $now);
+    } else {
+        $self->{prev} = $now;
+    }
+}
+
+sub total_elapsed {
+    my $timer = shift;
+    return Time::HiRes::time() - $timer->{first};
+}
+
+1;
Index: branches/release-30/lib/MT/Builder.pm
===================================================================
--- branches/release-30/lib/MT/Builder.pm (revision 1174)
+++ branches/release-30/lib/MT/Builder.pm (revision 1372)
@@ -283,4 +283,9 @@
     #print STDERR syntree2str($tokens,0) unless $count++ == 1;
 
+    my $timer;
+    if ($MT::DebugMode & 8) {
+        $timer = MT->get_timer();
+    }
+
     if ($cond) {
         my %lcond;
@@ -331,9 +336,5 @@
             my($h, $type) = $ctx->handler_for($t->[0]);
             if ($h) {
-                my $start;
-                if ($MT::DebugMode & 8) {
-                    require Time::HiRes;
-                    $start = [ Time::HiRes::gettimeofday() ];
-                }
+                $timer->pause_partial if $timer;
                 local($ctx->{__stash}{tag}) = $t->[0];
                 local($ctx->{__stash}{tokens}) = ref($tokens) ? bless $tokens, 'MT::Template::Tokens' : undef;
@@ -382,5 +383,5 @@
                     my $err = $ctx->errstr;
                     if (defined $err) {
-                        return $build->error(MT->translate("Error in <mt:[_1]> tag: [_2]", $t->[0], $ctx->errstr));
+                        return $build->error(MT->translate("Error in <mt[_1]> tag: [_2]", $t->[0], $ctx->errstr));
                     }
                     else {
@@ -402,7 +403,8 @@
                 $res .= $out
                     if defined $out;
-                if ($MT::DebugMode & 8) {
-                    my $elapsed = Time::HiRes::tv_interval($start);
-                    print STDERR "Builder: Tag [" . $t->[0] . "] - $elapsed seconds\n" if $elapsed > 0.25;
+
+                if ($timer) {
+                    $timer->mark("tag_"
+                        . lc($t->[0]) . args_to_string(\%args));
                 }
             } else {
@@ -417,4 +419,44 @@
 }
 
+sub args_to_string {
+    my ($args) = @_;
+    my $str = '';
+    foreach my $a (keys %$args) {
+        next if $a eq '@';
+        next unless defined $args->{$a};
+        next if $args->{$a} eq '';
+        $str .= ';' . $a . ':';
+        if (ref $args->{$a} eq 'ARRAY') {
+            foreach my $aa (@{ $args->{$a} }) {
+                $aa = '...' if $aa =~ m/ /;
+                $str .= $aa . ';';
+            }
+            chop($str);
+        } else {
+            $str .= $args->{$a} =~ m/ / ? '...' : $args->{$a};
+        }
+    }
+    my $more_args = $args->{'@'};
+    if ($more_args && @$more_args) {
+        foreach my $a (@$more_args) {
+            if (ref $a->[1] eq 'ARRAY') {
+                $str .= ' ' . $a->[0] . '=';
+                foreach my $aa (@{ $a->[1] }) {
+                    $aa = '...' if $aa =~ m/ /;
+                    $str .= $aa . ';';
+                }
+                chop($str);
+            } else {
+                next if exists $args->{$a->[0]}
+                    && ($args->{$a->[0]} eq $a->[1]);
+                next unless defined $args->[1];
+                next if $args->[1] eq '';
+                $str .= ';' . $a->[0] . ':';
+                $str .= $a->[1];
+            }
+        }
+    }
+    return $str ne '' ? '[' . substr($str,1) . ']' : '';
+}
 1;
 __END__
Index: branches/release-30/lib/MT/Tag.pm
===================================================================
--- branches/release-30/lib/MT/Tag.pm (revision 1208)
+++ branches/release-30/lib/MT/Tag.pm (revision 1372)
@@ -325,4 +325,7 @@
 sub __load_tags {
     my $obj = shift;
+    my $t = MT->get_timer;
+    $t->pause_partial if $t;
+
     if (!$obj->id) {
         $obj->{__tags} = [];
@@ -347,4 +350,5 @@
     }
     $obj->{__tags} = [ map { $_->name } @tags ];
+    $t->mark('MT::Tag::__load_tags') if $t;
     $obj->{__tag_objects} = \@tags;
 }
@@ -375,4 +379,8 @@
     my @tags = @{ $obj->{__tags} };
     return 1 unless @tags;
+
+    my $t = MT->get_timer;
+    $t->pause_partial if $t;
+
     $obj->{__tag_objects} = [];
     my $blog_id = $obj->has_column('blog_id') ? $obj->blog_id : 0;
@@ -427,4 +435,5 @@
         MT::Memcached->instance->delete( $obj->tag_cache_key );
     }
+    $t->mark('MT::Tag::save_tags') if $t;
     1;
 }
Index: branches/release-30/lib/MT/App.pm
===================================================================
--- branches/release-30/lib/MT/App.pm (revision 1371)
+++ branches/release-30/lib/MT/App.pm (revision 1372)
@@ -2049,4 +2049,10 @@
     my $q = $app->param;
 
+    my $timer;
+    if ($app->config->PerformanceLogging) {
+        $timer = $app->get_timer();
+        $timer->pause_partial();
+    }
+
     my($body);
     eval {
@@ -2252,4 +2258,9 @@
         }
     }
+
+    if ($timer) {
+        $timer->mark(ref($app) . '::run');
+    }
+
     $app->takedown();
 }
@@ -2314,4 +2325,8 @@
     require MT::Auth;
     MT::Auth->release;
+
+    if ($app->config->PerformanceLogging) {
+        $app->log_times();
+    }
 
     $app->request->finish;
Index: branches/release-30/lib/MT/Entry.pm
===================================================================
--- branches/release-30/lib/MT/Entry.pm (revision 1174)
+++ branches/release-30/lib/MT/Entry.pm (revision 1372)
@@ -222,4 +222,6 @@
 sub __load_category_data {
     my $entry = shift;
+    my $t = MT->get_timer;
+    $t->pause_partial if $t;
     my $cache = MT::Memcached->instance;
     my $memkey = $entry->cache_key('categories');
@@ -231,4 +233,5 @@
         $cache->set($memkey, $rows, CATEGORY_CACHE_TIME);
     }
+    $t->mark('MT::Entry::__load_category_data') if $t;
     return $rows;
 }
Index: branches/release-30/lib/MT/Template.pm
===================================================================
--- branches/release-30/lib/MT/Template.pm (revision 1369)
+++ branches/release-30/lib/MT/Template.pm (revision 1372)
@@ -91,4 +91,5 @@
     $tmpl->{include_path} = $param{path};
     $tmpl->{include_filter} = $param{filter};
+    $tmpl->{__file} = $file;
     my $contents = $tmpl->load_file($file);
     if (defined $contents) {
@@ -211,4 +212,10 @@
     $ctx ||= $tmpl->context;
 
+    my ($timer, $start);
+    if (MT->config->PerformanceLogging) {
+        $timer = MT->get_timer();
+    }
+    local $timer->{elapsed} = 0 if $timer;
+
     local $ctx->{__stash}{template} = $tmpl;
     my $tokens = $tmpl->tokens
@@ -243,8 +250,18 @@
         $ctx->var( 'page_columns', $columns ) if $columns;
     }
-    defined(my $res = $build->build($ctx, $tokens, $cond)) or
+
+    $timer->pause_partial if $timer;
+
+    my $res = $build->build($ctx, $tokens, $cond);
+
+    if ($timer) {
+        $timer->mark("MT::Template::build[" . ($tmpl->name || $tmpl->{__file}).']');
+    }
+
+    unless (defined($res)) {
         return $tmpl->error(MT->translate(
             "Publish error in template '[_1]': [_2]",
             $tmpl->name || $tmpl->{__file}, $build->errstr));
+    }
     $res =~ s/^\s*//;
     return $res;
Index: branches/release-30/lib/MT/WeblogPublisher.pm
===================================================================
--- branches/release-30/lib/MT/WeblogPublisher.pm (revision 1365)
+++ branches/release-30/lib/MT/WeblogPublisher.pm (revision 1372)
@@ -1210,4 +1210,5 @@
     my ( $blog, $root_path, $map, $at, $ctx, $cond, $build_static, %specifier )
       = @_;
+
     my $finfo;
     my $archiver = $mt->archiver($at);
@@ -1408,4 +1409,10 @@
     return 1 if ( $tmpl->build_dynamic );
     return 1 if ( $entry && $entry->status != MT::Entry::RELEASE() );
+
+    my $timer = MT->get_timer;
+    if ($timer) {
+        $timer->pause_partial;
+    }
+    local $timer->{elapsed} = 0 if $timer;
 
     if (
@@ -1451,6 +1458,7 @@
 
         $html = $tmpl->build( $ctx, $cond );
-        defined($html)
-          or return $mt->error(
+        unless (defined($html)) {
+            $timer->unpause if $timer;
+            return $mt->error(
             (
                 $category ? MT->translate(
@@ -1473,4 +1481,5 @@
             )
           );
+        }
         my $orig_html = $html;
         MT->run_callbacks(
@@ -1506,5 +1515,8 @@
         ## changed. If not, we won't update the published
         ## file, so as not to modify the mtime.
-        return 1 unless $fmgr->content_is_updated( $file, \$html );
+        unless ($fmgr->content_is_updated( $file, \$html )) {
+            $timer->unpause if $timer;
+            return 1;
+        }
 
         ## Determine if we need to build directory structure,
@@ -1516,7 +1528,9 @@
           unless $path eq '/'; ## OS X doesn't like / at the end in mkdir().
         unless ( $fmgr->exists($path) ) {
-            $fmgr->mkpath($path)
-              or return $mt->trans_error( "Error making path '[_1]': [_2]",
-                $path, $fmgr->errstr );
+            if (!$fmgr->mkpath($path)) {
+                $timer->unpause if $timer;
+                return $mt->trans_error( "Error making path '[_1]': [_2]",
+                    $path, $fmgr->errstr );
+            }
         }
 
@@ -1528,12 +1542,16 @@
         my $use_temp_files = !$mt->{NoTempFiles};
         my $temp_file = $use_temp_files ? "$file.new" : $file;
-        defined( $fmgr->put_data( $html, $temp_file ) )
-          or return $mt->trans_error( "Writing to '[_1]' failed: [_2]",
-            $temp_file, $fmgr->errstr );
+        unless ( defined $fmgr->put_data( $html, $temp_file ) ) {
+            $timer->unpause if $timer;
+            return $mt->trans_error( "Writing to '[_1]' failed: [_2]",
+                $temp_file, $fmgr->errstr );
+        }
         if ($use_temp_files) {
-            $fmgr->rename( $temp_file, $file )
-              or return $mt->trans_error(
-                "Renaming tempfile '[_1]' failed: [_2]",
-                $temp_file, $fmgr->errstr );
+            if (!$fmgr->rename( $temp_file, $file )) {
+                $timer->unpause if $timer;
+                return $mt->trans_error(
+                    "Renaming tempfile '[_1]' failed: [_2]",
+                    $temp_file, $fmgr->errstr );
+            }
         }
         MT->run_callbacks(
@@ -1568,4 +1586,6 @@
 
     }
+    $timer->mark("total:rebuild_file[template_id:" . $tmpl->id . "]")
+        if $timer;
     1;
 }
@@ -1689,4 +1709,10 @@
             $finfo->save();
         }
+
+        my $timer = MT->get_timer;
+        if ($timer) {
+            $timer->pause_partial;
+        }
+        local $timer->{elapsed} = 0 if $timer;
 
         my $ctx = MT::Template::Context->new;
@@ -1715,5 +1741,8 @@
 
         my $html = $tmpl->build($ctx);
-        return $mt->error( $tmpl->errstr ) unless defined $html;
+        unless (defined $html) {
+            $timer->unpause if $timer;
+            return $mt->error( $tmpl->errstr );
+        }
 
         my $orig_html = $html;
@@ -1752,7 +1781,9 @@
           unless $path eq '/';    ## OS X doesn't like / at the end in mkdir().
         unless ( $fmgr->exists($path) ) {
-            $fmgr->mkpath($path)
-              or return $mt->trans_error( "Error making path '[_1]': [_2]",
-                $path, $fmgr->errstr );
+            if (! $fmgr->mkpath($path) ) {
+                $timer->unpause if $timer;
+                return $mt->trans_error( "Error making path '[_1]': [_2]",
+                    $path, $fmgr->errstr );
+            }
         }
 
@@ -1760,12 +1791,15 @@
         my $use_temp_files = !$mt->{NoTempFiles};
         my $temp_file = $use_temp_files ? "$file.new" : $file;
-        defined( $fmgr->put_data( $html, $temp_file ) )
-          or return $mt->trans_error( "Writing to '[_1]' failed: [_2]",
-            $temp_file, $fmgr->errstr );
+        unless (defined( $fmgr->put_data( $html, $temp_file ) )) {
+            $timer->unpause if $timer;
+            return $mt->trans_error( "Writing to '[_1]' failed: [_2]",
+                $temp_file, $fmgr->errstr );
+        }
         if ($use_temp_files) {
-            $fmgr->rename( $temp_file, $file )
-              or
-              return $mt->trans_error( "Renaming tempfile '[_1]' failed: [_2]",
-                $temp_file, $fmgr->errstr );
+            if (!$fmgr->rename( $temp_file, $file )) {
+                $timer->unpause if $timer;
+                return $mt->trans_error( "Renaming tempfile '[_1]' failed: [_2]",
+                    $temp_file, $fmgr->errstr );
+            }
         }
         MT->run_callbacks(
@@ -1790,4 +1824,7 @@
             file         => $file
         );
+
+        $timer->mark("total:rebuild_indexes[template_id:" . $tmpl->id . ";file:$file]")
+            if $timer;
     }
     1;