Bug 870202: investigate ways of improving the performance of bugmail composition

2 files changed, 111 insertions, 1 deletions

diff --git a/Bugzilla/BugMail.pm b/Bugzilla/BugMail.pm
index 37421ce3e..55a37c230 100644
--- a/Bugzilla/BugMail.pm
+++ b/Bugzilla/BugMail.pm
@@ -43,6 +43,7 @@ use Bugzilla::Bug;
 use Bugzilla::Comment;
 use Bugzilla::Mailer;
 use Bugzilla::Hook;
+use Bugzilla::Instrument;
 
 use Date::Parse;
 use Date::Format;
@@ -75,6 +76,16 @@ sub Send {
     my ($id, $forced, $params) = @_;
     $params ||= {};
 
+    my $instrument;
+    my $current_login = Bugzilla->user->login;
+    if ($current_login eq 'ehsan@mozilla.com'
+        || $current_login eq 'glob@mozilla.com'
+        || $current_login eq 'dkl@mozilla.com')
+    {
+        $instrument = Bugzilla::Instrument->new('bugmail');
+        $instrument->begin("bug $id user $current_login");
+    }
+
     my $dbh = Bugzilla->dbh;
     my $bug = new Bugzilla::Bug($id);
 
@@ -155,6 +166,7 @@ sub Send {
     ###########################################################################
     # Start of email filtering code
     ###########################################################################
+    $instrument && $instrument->begin('email filtering');
     
     # A user_id => roles hash to keep track of people.
     my %recipients;
@@ -213,7 +225,9 @@ sub Send {
     Bugzilla::Hook::process('bugmail_recipients',
                             { bug => $bug, recipients => \%recipients,
                               users => \%user_cache, diffs => \@diffs });
+    $instrument && $instrument->end();
 
+    $instrument && $instrument->begin('watchers');
     if (scalar keys %recipients) {
         # Find all those user-watching anyone on the current list, who is not
         # on it already themselves.
@@ -240,6 +254,7 @@ sub Send {
         next unless $watcher_id;
         $recipients{$watcher_id}->{+REL_GLOBAL_WATCHER} = BIT_DIRECT;
     }
+    $instrument && $instrument->end();
 
     # We now have a complete set of all the users, and their relationships to
     # the bug in question. However, we are not necessarily going to mail them
@@ -327,6 +342,7 @@ sub Send {
                                         { updated_bug     => $bug,
                                           referenced_bugs => $referenced_bugs });
 
+                $instrument && $instrument->begin("sending to " . $user->login);
                 $sent_mail = sendMail(
                     { to       => $user, 
                       bug      => $bug,
@@ -338,7 +354,9 @@ sub Send {
                       diffs    => \@diffs,
                       rels_which_want => \%rels_which_want,
                       referenced_bugs => $referenced_bugs,
+                      instrument      => $instrument,
                     });
+                $instrument && $instrument->end();
             }
         }
 
@@ -359,6 +377,7 @@ sub Send {
         $bug->{lastdiffed} = $end;
     }
 
+    $instrument && $instrument->end();
     return {'sent' => \@sent, 'excluded' => \@excluded};
 }
 
@@ -374,6 +393,7 @@ sub sendMail {
     my @diffs = @{ $params->{diffs} };
     my $relRef      = $params->{rels_which_want};
     my $referenced_bugs = $params->{referenced_bugs};
+    my $instrument = $params->{instrument};
 
     # Only display changes the user is allowed see.
     my @display_diffs;
@@ -438,9 +458,14 @@ sub sendMail {
         new_comments => \@send_comments,
         threadingmarker => build_thread_marker($bug->id, $user->id, !$bug->lastdiffed),
         referenced_bugs => $referenced_bugs,
+        instrument => $instrument,
     };
+    $instrument && $instrument->begin('generating bugmail');
     my $msg =  _generate_bugmail($user, $vars);
+    $instrument && $instrument->end();
+    $instrument && $instrument->begin('sending to mta');
     MessageToMTA($msg);
+    $instrument && $instrument->end();
 
     return 1;
 }
@@ -449,11 +474,17 @@ sub _generate_bugmail {
     my ($user, $vars) = @_;
     my $template = Bugzilla->template_inner($user->setting('lang'));
     my ($msg_text, $msg_html, $msg_header);
-  
+    my $instrument = $vars->{instrument};
+
+    $instrument && $instrument->begin('header');
     $template->process("email/bugmail-header.txt.tmpl", $vars, \$msg_header)
         || ThrowTemplateError($template->error());
+    $instrument && $instrument->end();
+
+    $instrument && $instrument->begin('text body');
     $template->process("email/bugmail.txt.tmpl", $vars, \$msg_text)
         || ThrowTemplateError($template->error());
+    $instrument && $instrument->end();
 
     my @parts = (
         Email::MIME->create(
@@ -464,6 +495,7 @@ sub _generate_bugmail {
         )
     );
     if ($user->setting('email_format') eq 'html') {
+        $instrument && $instrument->begin('html body');
         $template->process("email/bugmail.html.tmpl", $vars, \$msg_html)
             || ThrowTemplateError($template->error());
         push @parts, Email::MIME->create(
@@ -472,8 +504,10 @@ sub _generate_bugmail {
             },
             body => $msg_html,
         );
+        $instrument && $instrument->end();
     }
 
+    $instrument && $instrument->begin('email object');
     # TT trims the trailing newline, and threadingmarker may be ignored.
     my $email = new Email::MIME("$msg_header\n");
 
@@ -486,6 +520,7 @@ sub _generate_bugmail {
         $email->content_type_set('multipart/alternative');
     }
     $email->parts_set(\@parts);
+    $instrument && $instrument->end();
     return $email;
 }
 
diff --git a/Bugzilla/Instrument.pm b/Bugzilla/Instrument.pm
new file mode 100644
index 000000000..270a3d396
--- /dev/null
+++ b/Bugzilla/Instrument.pm
@@ -0,0 +1,75 @@
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+#
+# This Source Code Form is "Incompatible With Secondary Licenses", as
+# defined by the Mozilla Public License, v. 2.0.
+
+package Bugzilla::Instrument;
+
+use strict;
+use warnings;
+
+use Bugzilla::Constants;
+use FileHandle;
+use Sys::Hostname;
+use Time::HiRes qw(time);
+
+sub new {
+    my ($class, $name) = @_;
+    my $self = {
+        name    => $name,
+        times   => [],
+        fh      => FileHandle->new('>>' . _filename($name)),
+    };
+    return bless($self, $class);
+}
+
+sub DESTROY {
+    my ($self) = @_;
+    $self->{fh}->print("\n");
+    $self->{fh}->close();
+}
+
+sub begin {
+    my ($self, $label) = @_;
+    my $now = (time);
+    push @{ $self->{times} }, { time => $now, label => $label };
+    $self->_log($now, undef, $label);
+}
+
+sub end {
+    my ($self, $label) = @_;
+    my $now = (time);
+    my $timer = pop @{ $self->{times} };
+    my $start = $timer ? $timer->{time} : undef;
+    $label ||= $timer->{label} if $timer;
+    $self->_log($now, $start, $label);
+}
+
+sub _log {
+    my ($self, $now, $then, $label) = @_;
+    $label ||= '';
+    my $level = scalar(@{ $self->{times} });
+    if ($then) {
+        $label = ('<' x ($level + 1)) . ' ' . $label;
+        $self->{fh}->printf("[%.5f] %-60s (+%.4f)\n", $now, $label, $now - $then);
+    } else {
+        $label = ('>' x $level) . ' ' . $label;
+        $self->{fh}->printf("[%.5f] %s\n", $now, $label);
+    }
+}
+
+our ($_path, $_host);
+sub _filename {
+    my ($name) = @_;
+    if (!$_path) {
+        $_path = bz_locations()->{datadir} . "/timings";
+        mkdir($_path) unless -d $_path;
+        $_host = hostname();
+        $_host =~ s/^([^\.]+)\..+/$1/;
+    }
+    return "$_path/$name-$_host-$$.log";
+}
+
+1;