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.

Disabled by default; to enable, set DEBUG_TIMING = 1 in
OpenILS/WWW/EGCatLoader.pm

Signed-off-by: Dan Scott <dscott@laurentian.ca>
Signed-off-by: Lebbeous Fogle-Weekley <lebbeous@esilibrary.com>

diff --git a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader.pm b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader.pm
index c333023..2e83f0f 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 => 0;
+
 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;

diff --git a/Open-ILS/src/templates/opac/parts/footer.tt2 b/Open-ILS/src/templates/opac/parts/footer.tt2
index ce60628..76c6b7a 100644 (file)
--- a/Open-ILS/src/templates/opac/parts/footer.tt2
+++ b/Open-ILS/src/templates/opac/parts/footer.tt2
@@ -9,7 +9,14 @@
     <a href="http://example.com">[% l('Bottom Link 3') %]</a> &nbsp;|&nbsp;
     <a href="http://example.com">[% l('Bottom Link 4') %]</a> &nbsp;|&nbsp;
     <a href="http://example.com">[% l('Bottom Link 5') %]</a>
-
+    [% IF ctx.timing %]
+    <div id="timing">
+        [% FOR event IN ctx.timing %]
+        At <span class="timing-time">[% event.0 | format("%0.4f") %]</span>:
+        <span class="timing-event">[% event.1 %]</span><br />
+        [% END %]
+    </div>
+    [% END %]
     <div id="copyright_text" style="margin-top: 2em;">
         [% l('Copyright &copy; 2006-[_1] Georgia Public Library Service, and others', date.format(date.now, '%Y')) %]
     </div>