Bug 887180: show_bug and process_bug timings generating duplicates under mod_perl

3 files changed, 67 insertions, 107 deletions

diff --git a/Bugzilla/Instrument.pm b/Bugzilla/Instrument.pm
index 270a3d396..4ab74ff8e 100644
--- a/Bugzilla/Instrument.pm
+++ b/Bugzilla/Instrument.pm
@@ -10,66 +10,59 @@ package Bugzilla::Instrument;
 use strict;
 use warnings;
 
-use Bugzilla::Constants;
-use FileHandle;
-use Sys::Hostname;
-use Time::HiRes qw(time);
+use Time::HiRes qw(clock_gettime CLOCK_MONOTONIC);
+use Encode qw(encode_utf8);
+use Sys::Syslog qw(:DEFAULT);
 
 sub new {
-    my ($class, $name) = @_;
-    my $self = {
-        name    => $name,
-        times   => [],
-        fh      => FileHandle->new('>>' . _filename($name)),
-    };
-    return bless($self, $class);
+    my ($class, $label) = @_;
+    my $self = bless({ times => [], labels => [], values => [] }, $class);
+    $self->label($label);
+    $self->time('start_time');
+    return $self;
 }
 
-sub DESTROY {
-    my ($self) = @_;
-    $self->{fh}->print("\n");
-    $self->{fh}->close();
+sub time {
+    my ($self, $name) = @_;
+    # for now $name isn't used
+    push @{ $self->{times} }, clock_gettime(CLOCK_MONOTONIC);
 }
 
-sub begin {
-    my ($self, $label) = @_;
-    my $now = (time);
-    push @{ $self->{times} }, { time => $now, label => $label };
-    $self->_log($now, undef, $label);
+sub label {
+    my ($self, $value) = @_;
+    push @{ $self->{labels} }, $value;
 }
 
-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 value {
+    my ($self, $name, $value) = @_;
+    # for now $name isn't used
+    push @{ $self->{values} }, $value;
 }
 
-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);
-    }
-}
+sub log {
+    my $self = shift;
+
+    my @times = @{ $self->{times} };
+    return unless scalar(@times) >= 2;
+    my @labels = @{ $self->{labels} };
+    my @values = @{ $self->{values} };
 
-our ($_path, $_host);
-sub _filename {
-    my ($name) = @_;
-    if (!$_path) {
-        $_path = bz_locations()->{datadir} . "/timings";
-        mkdir($_path) unless -d $_path;
-        $_host = hostname();
-        $_host =~ s/^([^\.]+)\..+/$1/;
+    # calculate diffs
+    my @diffs = ($times[$#times] - $times[0]);
+    while (1) {
+        my $start = shift(@times);
+        last unless scalar(@times);
+        push @diffs, $times[0] - $start;
     }
-    return "$_path/$name-$_host-$$.log";
+
+    # build syslog string
+    my $format = '[timing]' . (' %s' x scalar(@labels)) . (' %.6f' x scalar(@diffs)) . (' %s' x scalar(@values));
+    my $entry = sprintf($format, @labels, @diffs, @values);
+
+    # and log
+    openlog('apache', 'cons,pid', 'local4');
+    syslog('notice', encode_utf8($entry));
+    closelog();
 }
 
 1;
diff --git a/process_bug.cgi b/process_bug.cgi
index 6731a8395..523523281 100755
--- a/process_bug.cgi
+++ b/process_bug.cgi
@@ -58,12 +58,10 @@ use Bugzilla::Keyword;
 use Bugzilla::Flag;
 use Bugzilla::Status;
 use Bugzilla::Token;
+use Bugzilla::Instrument;
 
 use List::MoreUtils qw(firstidx);
 use Storable qw(dclone);
-use Time::HiRes qw(clock_gettime CLOCK_MONOTONIC);
-use Encode qw(encode_utf8);
-use Sys::Syslog qw(:DEFAULT);
 
 my $user = Bugzilla->login(LOGIN_REQUIRED);
 
@@ -72,7 +70,7 @@ my $dbh = Bugzilla->dbh;
 my $template = Bugzilla->template;
 my $vars = {};
 
-my $timings = { start_time => clock_gettime(CLOCK_MONOTONIC) };
+my $timings = Bugzilla::Instrument->new('process_bug');
 
 ######################################################################
 # Subroutines
@@ -147,7 +145,7 @@ Bugzilla::User::match_field({
 
 print $cgi->header() unless Bugzilla->usage_mode == USAGE_MODE_EMAIL;
 
-$timings->{load_bug} = clock_gettime(CLOCK_MONOTONIC);
+$timings->time('load_bug');
 
 # Check for a mid-air collision. Currently this only works when updating
 # an individual bug.
@@ -212,7 +210,7 @@ else {
     check_token_data($token, 'buglist_mass_change', 'query.cgi');
 }
 
-$timings->{mid_air} = clock_gettime(CLOCK_MONOTONIC);
+$timings->time('mid_air');
 
 ######################################################################
 # End Data/Security Validation
@@ -401,14 +399,14 @@ if (defined $cgi->param('id')) {
     $first_bug->set_flags($flags, $new_flags);
 }
 
-$timings->{update_time} = clock_gettime(CLOCK_MONOTONIC);
+$timings->time('update_time');
 
 ##############################
 # Do Actual Database Updates #
 ##############################
 foreach my $bug (@bug_objects) {
     my $changes = $bug->update();
-    $timings->{db_time} = clock_gettime(CLOCK_MONOTONIC);
+    $timings->time('db_time');
 
     if ($changes->{'bug_status'}) {
         my $new_status = $changes->{'bug_status'}->[1];
@@ -420,8 +418,11 @@ foreach my $bug (@bug_objects) {
         }
     }
 
-    $timings->{recipients} = $bug->send_changes($changes, $vars);
-    $timings->{bugmail_time} = clock_gettime(CLOCK_MONOTONIC);
+    my $recipient_count = $bug->send_changes($changes, $vars);
+    $timings->time('bugmail_time');
+    $timings->label('bug-' . $bug->id);
+    $timings->label('user-' . $user->id);
+    $timings->value('recipient_count', $recipient_count);
 }
 
 # Delete the session token used for the mass-change.
@@ -447,8 +448,8 @@ elsif ($action eq 'next_bug' or $action eq 'same_bug') {
         }
         $template->process("bug/show.html.tmpl", $vars)
           || ThrowTemplateError($template->error());
-        $timings->{template_time} = clock_gettime(CLOCK_MONOTONIC);
-        _log_timings();
+        $timings->time('template_time');
+        $timings->log() if scalar(@bug_objects) == 1;
         exit;
     }
 } elsif ($action ne 'nothing') {
@@ -461,27 +462,8 @@ unless (Bugzilla->usage_mode == USAGE_MODE_EMAIL) {
         || ThrowTemplateError($template->error());
     $template->process("global/footer.html.tmpl", $vars)
         || ThrowTemplateError($template->error());
-    $timings->{template_time} = clock_gettime(CLOCK_MONOTONIC);
-    _log_timings();
-}
-
-sub _log_timings {
-    return unless scalar(@bug_objects) == 1;
-    return unless scalar(keys %$timings) == 8;
-    my $entry = sprintf "process_bug bug-%s user-%s %.6f %.6f %.6f %.6f %.6f %.6f %.6f %s\n",
-        $bug_objects[0]->id,
-        $user->id,
-        $timings->{template_time} - $timings->{start_time},
-        $timings->{load_bug} - $timings->{start_time},
-        $timings->{mid_air} - $timings->{load_bug},
-        $timings->{update_time} - $timings->{mid_air},
-        $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();
+    $timings->time('template_time');
+    $timings->log() if scalar(@bug_objects) == 1;
 }
 
 1;
diff --git a/show_bug.cgi b/show_bug.cgi
index bdd9dd5f0..f6c845ea9 100755
--- a/show_bug.cgi
+++ b/show_bug.cgi
@@ -30,19 +30,16 @@ use Bugzilla::Error;
 use Bugzilla::User;
 use Bugzilla::Keyword;
 use Bugzilla::Bug;
+use Bugzilla::Instrument;
 
-use Time::HiRes qw(clock_gettime CLOCK_MONOTONIC);
-use Encode qw(encode_utf8);
-use Sys::Syslog qw(:DEFAULT);
-
-my $timings = { start_time => clock_gettime(CLOCK_MONOTONIC) };
+my $timings = Bugzilla::Instrument->new('show_bug');
 
 my $cgi = Bugzilla->cgi;
 my $template = Bugzilla->template;
 my $vars = {};
 
 my $user = Bugzilla->login();
-$timings->{login_time} = clock_gettime(CLOCK_MONOTONIC);
+$timings->time('login_time');
 
 my $format = $template->get_format("bug/show", scalar $cgi->param('format'),
                                    scalar $cgi->param('ctype'));
@@ -96,10 +93,10 @@ if ($single) {
         }
     }
 }
-$timings->{load_bug_time} = clock_gettime(CLOCK_MONOTONIC);
+$timings->time('load_bug_time');
 
 Bugzilla::Bug->preload(\@bugs);
-$timings->{preload_time} = clock_gettime(CLOCK_MONOTONIC);
+$timings->time('preload_time');
 
 $vars->{'bugs'} = \@bugs;
 $vars->{'marks'} = \%marks;
@@ -137,22 +134,10 @@ print $cgi->header($format->{'ctype'});
 
 $template->process($format->{'template'}, $vars)
   || ThrowTemplateError($template->error());
-$timings->{template_time} = clock_gettime(CLOCK_MONOTONIC);
-
-_log_timings();
-
-sub _log_timings {
-    return unless scalar(@bugs) == 1;
-    return unless scalar(keys %$timings) == 5;
-    my $entry = sprintf "show_bug bug-%s user-%s %.6f %.6f %.6f %.6f %.6f",
-        $bugs[0]->id,
-        $user->id,
-        $timings->{template_time} - $timings->{start_time},
-        $timings->{login_time} - $timings->{start_time},
-        $timings->{load_bug_time} - $timings->{login_time},
-        $timings->{preload_time} - $timings->{load_bug_time},
-        $timings->{template_time} - $timings->{preload_time},
-    openlog('apache', 'cons,pid', 'local4');
-    syslog('notice', encode_utf8("[timing] $entry"));
-    closelog();
+$timings->time('template_time');
+
+if (scalar(@bugs) == 1) {
+    $timings->label('bug-' . $bugs[0]->id);
+    $timings->label('user-' . $user->id);
+    $timings->log();
 }