From dfb9acfb6b76c7db463454df452c1941bf728766 Mon Sep 17 00:00:00 2001 From: Byron Jones Date: Thu, 27 Jun 2013 12:27:42 +0800 Subject: Bug 887180: show_bug and process_bug timings generating duplicates under mod_perl --- Bugzilla/Instrument.pm | 89 +++++++++++++++++++++++--------------------------- process_bug.cgi | 48 +++++++++------------------ show_bug.cgi | 37 +++++++-------------- 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(); } -- cgit v1.2.3-24-g4f1b