[open-ils-commits] [GIT] Evergreen ILS branch master updated. ee18ec89dda3c34c7570b4296cfa644e9abfbf93

Evergreen Git git at git.evergreen-ils.org
Wed Apr 25 16:43:13 EDT 2012


This is an automated email from the git hooks/post-receive script. It was
generated because a ref change was pushed to the repository containing
the project "Evergreen ILS".

The branch, master has been updated
       via  ee18ec89dda3c34c7570b4296cfa644e9abfbf93 (commit)
       via  18524ec34d43f4da378cea7b5eb9ea83ccd963c3 (commit)
      from  4d517fbbdf32fe205d47f7c7f9c0ff6954833773 (commit)

Those revisions listed above that are new to this repository have
not appeared on any other notification email; so we list those
revisions in full, below.

- Log -----------------------------------------------------------------
commit ee18ec89dda3c34c7570b4296cfa644e9abfbf93
Author: Lebbeous Fogle-Weekley <lebbeous at esilibrary.com>
Date:   Wed Apr 25 16:19:45 2012 -0400

    Apply timelog() to TPAC record detail page
    
    Early suggestion from results is that we either need to use unapi.bre more
    smartly, or optimize it further.
    
    Signed-off-by: Lebbeous Fogle-Weekley <lebbeous at esilibrary.com>
    Signed-off-by: Dan Scott <dscott at laurentian.ca>

diff --git a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Record.pm b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Record.pm
index 9150480..af1c3fc 100644
--- a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Record.pm
+++ b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Record.pm
@@ -14,6 +14,7 @@ sub load_record {
     my $ctx = $self->ctx;
     $ctx->{page} = 'record';  
 
+    $self->timelog("load_record() began");
     my $org = $self->_get_search_lib();
     my $org_name = $ctx->{get_aou}->($org)->shortname;
     my $pref_ou = $self->_get_pref_lib();
@@ -35,8 +36,10 @@ sub load_record {
     if ($ctx->{staff_saved_search_size}) {
         $ctx->{saved_searches} = ($self->staff_load_searches)[1];
     }
+    $self->timelog("past staff saved searches");
 
     $self->fetch_related_search_info($rec_id);
+    $self->timelog("past related search info");
 
     # run copy retrieval in parallel to bib retrieval
     # XXX unapi
@@ -52,10 +55,13 @@ sub load_record {
         depth => $depth,
         pref_lib => $pref_ou
     });
+
+    $self->timelog("past get_records_and_facets()");
     $ctx->{bre_id} = $rec_data[0]->{id};
     $ctx->{marc_xml} = $rec_data[0]->{marc_xml};
 
     $ctx->{copies} = $copy_rec->gather(1);
+    $self->timelog("past store copy retrieval call");
     $ctx->{copy_limit} = $copy_limit;
     $ctx->{copy_offset} = $copy_offset;
 
@@ -64,6 +70,7 @@ sub load_record {
 
     $self->get_hold_copy_summary($rec_id, $org);
 
+    $self->timelog("past get_hold_copy_summary()");
     $self->ctx->{bib_is_dead} = OpenILS::Application::AppUtils->is_true(
         OpenILS::Utils::CStoreEditor->new->json_query({
             select => { bre => [ 'deleted' ] },
@@ -91,6 +98,8 @@ sub load_record {
         };
     }
 
+    $self->timelog("past serials holding stuff");
+
     my %expandies = (
         marchtml => sub {
             $ctx->{marchtml} = $self->mk_marc_html($rec_id);
@@ -116,6 +125,7 @@ sub load_record {
         }
     }
 
+    $self->timelog("past expandies");
     return Apache2::Const::OK;
 }
 
diff --git a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm
index a283f41..57b8407 100644
--- a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm
+++ b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm
@@ -229,6 +229,8 @@ sub get_records_and_facets {
     $unapi_args->{flesh_depth} ||= 5;
 
     my @data;
+    my $outer_self = $self;
+    $self->timelog("get_records_and_facets(): about to call multisession");
     my $ses = OpenSRF::MultiSession->new(
         app => 'open-ils.cstore',
         cap => 10, # XXX config
@@ -236,11 +238,14 @@ sub get_records_and_facets {
             my($self, $req) = @_;
             my $data = $req->{response}->[0]->content;
 
+            $outer_self->timelog("get_records_and_facets(): got response content");
+
             # Protect against requests for non-existent records
             return unless $data->{'unapi.bre'};
 
             my $xml = XML::LibXML->new->parse_string($data->{'unapi.bre'})->documentElement;
 
+            $outer_self->timelog("get_records_and_facets(): parsed xml");
             # Protect against legacy invalid MARCXML that might not have a 901c
             my $bre_id;
             my $bre_id_nodes =  $xml->find('*[@tag="901"]/*[@code="c"]');
@@ -250,9 +255,12 @@ sub get_records_and_facets {
                 $logger->warn("Missing 901 subfield 'c' in " . $xml->toString());
             }
             push(@data, {id => $bre_id, marc_xml => $xml});
+            $outer_self->timelog("get_records_and_facets(): end of success handler");
         }
     );
 
+    $self->timelog("get_records_and_facets(): about to call unapi.bre via json_query (rec_ids has " . scalar(@$rec_ids));
+
     $ses->request(
         'open-ils.cstore.json_query',
          {from => [
@@ -265,6 +273,8 @@ sub get_records_and_facets {
         ]}
     ) for @$rec_ids;
 
+
+    $self->timelog("get_records_and_facets():almost ready to fetch facets");
     # collect the facet data
     my $search = OpenSRF::AppSession->create('open-ils.search');
     my $facet_req = $search->request(
@@ -273,10 +283,12 @@ sub get_records_and_facets {
 
     # gather up the unapi recs
     $ses->session_wait(1);
+    $self->timelog("get_records_and_facets():past session wait");
 
     my $facets = {};
     if ($facet_key) {
         my $tmp_facets = $facet_req->gather(1);
+        $self->timelog("get_records_and_facets(): gathered facet data");
         for my $cmf_id (keys %$tmp_facets) {
 
             # sort highest to lowest match count
@@ -291,6 +303,7 @@ sub get_records_and_facets {
                 data => \@entries
             }
         }
+        $self->timelog("get_records_and_facets(): gathered/sorted facet data");
     } else {
         $facets = undef;
     }

commit 18524ec34d43f4da378cea7b5eb9ea83ccd963c3
Author: Dan Scott <dscott at laurentian.ca>
Date:   Wed Apr 25 15:20:46 2012 -0400

    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 at laurentian.ca>
    Signed-off-by: Lebbeous Fogle-Weekley <lebbeous at 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
--- 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
--- 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>

-----------------------------------------------------------------------

Summary of changes:
 .../src/perlmods/lib/OpenILS/WWW/EGCatLoader.pm    |   19 +++++++++++++++++++
 .../perlmods/lib/OpenILS/WWW/EGCatLoader/Record.pm |   10 ++++++++++
 .../perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm   |   13 +++++++++++++
 Open-ILS/src/templates/opac/parts/footer.tt2       |    9 ++++++++-
 4 files changed, 50 insertions(+), 1 deletions(-)


hooks/post-receive
-- 
Evergreen ILS


More information about the open-ils-commits mailing list