Bug 884177: add simple instrumentation to process_bug.cgi

2 files changed, 47 insertions, 11 deletions

diff --git a/Bugzilla/Bug.pm b/Bugzilla/Bug.pm
index 75d388faa..bae5971ba 100644
--- a/Bugzilla/Bug.pm
+++ b/Bugzilla/Bug.pm
@@ -1223,15 +1223,15 @@ sub send_changes {
         changer   => $user,
     );
 
-    _send_bugmail({ id => $self->id, type => 'bug', forced => \%forced }, 
-                  $vars);
+    my $recipient_count = _send_bugmail(
+        { id => $self->id, type => 'bug', forced => \%forced }, $vars);
 
     # If the bug was marked as a duplicate, we need to notify users on the
     # other bug of any changes to that bug.
     my $new_dup_id = $changes->{'dup_id'} ? $changes->{'dup_id'}->[1] : undef;
     if ($new_dup_id) {
-        _send_bugmail({ forced => { changer => $user }, type => "dupe",
-                        id => $new_dup_id }, $vars);
+        $recipient_count += _send_bugmail(
+            { forced => { changer => $user }, type => "dupe", id => $new_dup_id }, $vars);
     }
 
     # If there were changes in dependencies, we need to notify those
@@ -1250,7 +1250,7 @@ sub send_changes {
 
             foreach my $id (@{ $self->blocked }) {
                 $params->{id} = $id;
-                _send_bugmail($params, $vars);
+                $recipient_count += _send_bugmail($params, $vars);
             }
         }
     }
@@ -1268,15 +1268,17 @@ sub send_changes {
     delete $changed_deps{''};
 
     foreach my $id (sort { $a <=> $b } (keys %changed_deps)) {
-        _send_bugmail({ forced => { changer => $user }, type => "dep",
-                         id => $id }, $vars);
+        $recipient_count += _send_bugmail(
+            { forced => { changer => $user }, type => "dep", id => $id }, $vars);
     }
 
     # Sending emails for the referenced bugs.
     foreach my $ref_bug_id (uniq @{ $self->{see_also_changes} || [] }) {
-        _send_bugmail({ forced => { changer => $user },
-                        id => $ref_bug_id }, $vars);
+        $recipient_count += _send_bugmail(
+            { forced => { changer => $user }, id => $ref_bug_id }, $vars);
     }
+
+    return $recipient_count;
 }
 
 sub _send_bugmail {
@@ -1284,7 +1286,7 @@ sub _send_bugmail {
 
     require Bugzilla::BugMail;
 
-    my $results = 
+    my $results =
         Bugzilla::BugMail::Send($params->{'id'}, $params->{'forced'}, $params);
 
     if (Bugzilla->usage_mode == USAGE_MODE_BROWSER) {
@@ -1295,6 +1297,8 @@ sub _send_bugmail {
             || ThrowTemplateError($template->error());
         $vars->{'header_done'} = 1;
     }
+
+    return scalar @{ $results->{sent} };
 }
 
 #####################################################################
diff --git a/process_bug.cgi b/process_bug.cgi
index 1f613982d..635c788a4 100755
--- a/process_bug.cgi
+++ b/process_bug.cgi
@@ -61,6 +61,9 @@ use Bugzilla::Token;
 
 use List::MoreUtils qw(firstidx);
 use Storable qw(dclone);
+use Time::HiRes qw(time);
+use Encode qw(encode_utf8);
+use Sys::Syslog qw(:DEFAULT);
 
 my $user = Bugzilla->login(LOGIN_REQUIRED);
 
@@ -69,6 +72,8 @@ my $dbh = Bugzilla->dbh;
 my $template = Bugzilla->template;
 my $vars = {};
 
+my $timings = { start_time => time() };
+
 ######################################################################
 # Subroutines
 ######################################################################
@@ -205,6 +210,8 @@ else {
     check_token_data($token, 'buglist_mass_change', 'query.cgi');
 }
 
+$timings->{validation_time} = time();
+
 ######################################################################
 # End Data/Security Validation
 ######################################################################
@@ -392,11 +399,14 @@ if (defined $cgi->param('id')) {
     $first_bug->set_flags($flags, $new_flags);
 }
 
+$timings->{update_time} = time();
+
 ##############################
 # Do Actual Database Updates #
 ##############################
 foreach my $bug (@bug_objects) {
     my $changes = $bug->update();
+    $timings->{db_time} = time();
 
     if ($changes->{'bug_status'}) {
         my $new_status = $changes->{'bug_status'}->[1];
@@ -408,7 +418,8 @@ foreach my $bug (@bug_objects) {
         }
     }
 
-    $bug->send_changes($changes, $vars);
+    $timings->{recipients} = $bug->send_changes($changes, $vars);
+    $timings->{bugmail_time} = time();
 }
 
 # Delete the session token used for the mass-change.
@@ -434,6 +445,8 @@ elsif ($action eq 'next_bug' or $action eq 'same_bug') {
         }
         $template->process("bug/show.html.tmpl", $vars)
           || ThrowTemplateError($template->error());
+        $timings->{template_time} = time();
+        _log_timings();
         exit;
     }
 } elsif ($action ne 'nothing') {
@@ -446,6 +459,25 @@ unless (Bugzilla->usage_mode == USAGE_MODE_EMAIL) {
         || ThrowTemplateError($template->error());
     $template->process("global/footer.html.tmpl", $vars)
         || ThrowTemplateError($template->error());
+    $timings->{template_time} = time();
+    _log_timings();
+}
+
+sub _log_timings {
+    return unless scalar(@bug_objects) == 1;
+    my $entry = sprintf "bug-%s user-%s %.6f %.6f %.6f %.6f %.6f %.6f %s\n",
+        $bug_objects[0]->id,
+        $user->id,
+        time() - $timings->{start_time},
+        $timings->{validation_time} - $timings->{start_time},
+        $timings->{update_time} - $timings->{validation_time},
+        $timings->{db_time} - $timings->{update_time},
+        $timings->{bugmail_time} - $timings->{db_time},
+        $timings->{template_time} - $timings->{bugmail_time},
+        $timings->{recipients};
+    openlog('apache', 'cons,pid', 'local4');
+    syslog('notice', encode_utf8("[timing] $entry"));
+    closelog();
 }
 
 1;