Instrument the TPAC: add timelog() method to EGCatLoader

Meant for timing how long events take to generate a single TPAC page,
the timelog() method will provide timing in microsecond granularity of
various events required to build the page.

To invoke: $self->timelog("Event description...");

Builds up a context variable named "timing" containing a list of
arrays; each array entry contains a time and the event description.

Signed-off-by: Dan Scott <dscott@laurentian.ca>

diff --git a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader.pm b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader.pm
index c333023..7b7f882 100644 (file)
--- a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader.pm
+++ b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader.pm
@@ -14,6 +14,7 @@ use OpenILS::Utils::CStoreEditor qw/:funcs/;
 use OpenILS::Utils::Fieldmapper;
 use DateTime::Format::ISO8601;
 use CGI qw(:all -utf8);
+use Time::HiRes;
 
 # EGCatLoader sub-modules 
 use OpenILS::WWW::EGCatLoader::Util;
@@ -33,6 +34,8 @@ use constant COOKIE_ANON_CACHE => 'anoncache';
 use constant ANON_CACHE_MYLIST => 'mylist';
 use constant ANON_CACHE_STAFF_SEARCH => 'staffsearch';
 
+use constant DEBUG_TIMING => 1;
+
 sub new {
     my($class, $apache, $ctx) = @_;
 
@@ -41,6 +44,7 @@ sub new {
     $self->apache($apache);
     $self->ctx($ctx);
     $self->cgi(new CGI);
+    $self->timelog("New page");
 
     OpenILS::Utils::CStoreEditor->init; # just in case
     $self->editor(new_editor());
@@ -77,6 +81,20 @@ sub cgi {
     return $self->{cgi};
 }
 
+sub timelog {
+    my($self, $description) = @_;
+
+    return unless DEBUG_TIMING;
+    return unless $description;
+    $self->ctx->{timing} ||= [];
+    
+    my $timer = [Time::HiRes::gettimeofday()];
+    $self->ctx->{time_begin} ||= $timer;
+
+    push @{$self->ctx->{timing}}, [
+        Time::HiRes::tv_interval($self->ctx->{time_begin}, $timer), $description
+    ];
+}
 
 # -----------------------------------------------------------------------------
 # Perform initial setup, load common data, then load page data
@@ -85,6 +103,7 @@ sub load {
     my $self = shift;
 
     $self->init_ro_object_cache;
+    $self->timelog("Initial load");
 
     my $stat = $self->load_common;
     return $stat unless $stat == Apache2::Const::OK;