summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorByron Jones <bjones@mozilla.com>2013-06-19 10:05:52 +0200
committerByron Jones <bjones@mozilla.com>2013-06-19 10:05:52 +0200
commit8caf466c0cf82a06dc69a29a5e87900e86c2488a (patch)
tree3f1205c3ba63344268199f1678d8063fc8de1b47
parentc74993e8cb7d8f95f8942e5af57e1fb4b7e1e982 (diff)
downloadbugzilla-8caf466c0cf82a06dc69a29a5e87900e86c2488a.tar.gz
bugzilla-8caf466c0cf82a06dc69a29a5e87900e86c2488a.tar.xz
Bug 884177: updates to the timing collectors
-rwxr-xr-xprocess_bug.cgi28
-rwxr-xr-xshow_bug.cgi28
2 files changed, 44 insertions, 12 deletions
diff --git a/process_bug.cgi b/process_bug.cgi
index 635c788a4..cc6dda130 100755
--- a/process_bug.cgi
+++ b/process_bug.cgi
@@ -61,7 +61,7 @@ use Bugzilla::Token;
use List::MoreUtils qw(firstidx);
use Storable qw(dclone);
-use Time::HiRes qw(time);
+use Time::HiRes qw(clock_gettime CLOCK_MONOTONIC);
use Encode qw(encode_utf8);
use Sys::Syslog qw(:DEFAULT);
@@ -72,7 +72,7 @@ my $dbh = Bugzilla->dbh;
my $template = Bugzilla->template;
my $vars = {};
-my $timings = { start_time => time() };
+my $timings = { start_time => clock_gettime(CLOCK_MONOTONIC) };
######################################################################
# Subroutines
@@ -147,6 +147,8 @@ Bugzilla::User::match_field({
print $cgi->header() unless Bugzilla->usage_mode == USAGE_MODE_EMAIL;
+$timings->{load_bug} = clock_gettime(CLOCK_MONOTONIC);
+
# Check for a mid-air collision. Currently this only works when updating
# an individual bug.
if (defined $cgi->param('delta_ts'))
@@ -210,7 +212,7 @@ else {
check_token_data($token, 'buglist_mass_change', 'query.cgi');
}
-$timings->{validation_time} = time();
+$timings->{mid_air} = clock_gettime(CLOCK_MONOTONIC);
######################################################################
# End Data/Security Validation
@@ -399,14 +401,14 @@ if (defined $cgi->param('id')) {
$first_bug->set_flags($flags, $new_flags);
}
-$timings->{update_time} = time();
+$timings->{update_time} = clock_gettime(CLOCK_MONOTONIC);
##############################
# Do Actual Database Updates #
##############################
foreach my $bug (@bug_objects) {
my $changes = $bug->update();
- $timings->{db_time} = time();
+ $timings->{db_time} = clock_gettime(CLOCK_MONOTONIC);
if ($changes->{'bug_status'}) {
my $new_status = $changes->{'bug_status'}->[1];
@@ -419,7 +421,7 @@ foreach my $bug (@bug_objects) {
}
$timings->{recipients} = $bug->send_changes($changes, $vars);
- $timings->{bugmail_time} = time();
+ $timings->{bugmail_time} = clock_gettime(CLOCK_MONOTONIC);
}
# Delete the session token used for the mass-change.
@@ -445,7 +447,7 @@ elsif ($action eq 'next_bug' or $action eq 'same_bug') {
}
$template->process("bug/show.html.tmpl", $vars)
|| ThrowTemplateError($template->error());
- $timings->{template_time} = time();
+ $timings->{template_time} = clock_gettime(CLOCK_MONOTONIC);
_log_timings();
exit;
}
@@ -459,18 +461,20 @@ unless (Bugzilla->usage_mode == USAGE_MODE_EMAIL) {
|| ThrowTemplateError($template->error());
$template->process("global/footer.html.tmpl", $vars)
|| ThrowTemplateError($template->error());
- $timings->{template_time} = time();
+ $timings->{template_time} = clock_gettime(CLOCK_MONOTONIC);
_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",
+ $timings->{end_time} = clock_gettime(CLOCK_MONOTONIC);
+ my $entry = sprintf "process_bug bug-%s user-%s %.6f %.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->{end_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},
diff --git a/show_bug.cgi b/show_bug.cgi
index 332d5fcbd..66d8bdce7 100755
--- a/show_bug.cgi
+++ b/show_bug.cgi
@@ -31,11 +31,18 @@ use Bugzilla::User;
use Bugzilla::Keyword;
use Bugzilla::Bug;
+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 $cgi = Bugzilla->cgi;
my $template = Bugzilla->template;
my $vars = {};
my $user = Bugzilla->login();
+$timings->{login_time} = clock_gettime(CLOCK_MONOTONIC);
my $format = $template->get_format("bug/show", scalar $cgi->param('format'),
scalar $cgi->param('ctype'));
@@ -62,6 +69,7 @@ Bugzilla->switch_to_shadow_db unless $user->id;
if ($single) {
my $id = $cgi->param('id');
push @bugs, Bugzilla::Bug->check({ id => $id, cache => 1 });
+ $timings->{load_bug_time} = clock_gettime(CLOCK_MONOTONIC);
if (defined $cgi->param('mark')) {
foreach my $range (split ',', $cgi->param('mark')) {
if ($range =~ /^(\d+)-(\d+)$/) {
@@ -91,6 +99,7 @@ if ($single) {
}
Bugzilla::Bug->preload(\@bugs);
+$timings->{preload_time} = clock_gettime(CLOCK_MONOTONIC);
$vars->{'bugs'} = \@bugs;
$vars->{'marks'} = \%marks;
@@ -128,3 +137,22 @@ 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;
+ $timings->{end_time} = clock_gettime(CLOCK_MONOTONIC);
+ my $entry = sprintf "show_bug bug-%s user-%s %.6f %.6f %.6f %.6f %.6f",
+ $bugs[0]->id,
+ $user->id,
+ $timings->{end_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();
+}