[open-ils-commits] [GIT] Evergreen ILS branch rel_2_2 updated. 111b65b05119afff2bc286ee3ba9f1f2ffb9a8ea
Evergreen Git
git at git.evergreen-ils.org
Sat Apr 28 13:51:27 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, rel_2_2 has been updated
via 111b65b05119afff2bc286ee3ba9f1f2ffb9a8ea (commit)
via a34bd33836bacb8e7b16f4a4af95a436a1eb75ef (commit)
via a695983e105767743f1957f49a05f74afec3e514 (commit)
from 216096a1accf7d8f7946aecbb86a883d5db76415 (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 111b65b05119afff2bc286ee3ba9f1f2ffb9a8ea
Author: Dan Scott <dscott at laurentian.ca>
Date: Thu Apr 26 21:56:23 2012 -0400
TPAC: Instrument the search results page
Because we want to know why search results can be slowish, add timelog()
entries to pertinent locations in Search.pm.
Quick results on my laptop with the concerto set:
* 10 results = 1.1 seconds for get_records_and_facets()
* 50 results = 4.2 seconds for get_records_and_facets()
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/Search.pm b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Search.pm
index b4d77e2..48231d3 100644
--- a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Search.pm
+++ b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Search.pm
@@ -158,11 +158,13 @@ sub _get_search_limit {
return $limit if $limit;
if($self->editor->requestor) {
+ $self->timelog("Checking for opac.hits_per_page preference");
# See if the user has a hit count preference
my $lset = $self->editor->search_actor_user_setting({
usr => $self->editor->requestor->id,
name => 'opac.hits_per_page'
})->[0];
+ $self->timelog("Got opac.hits_per_page preference");
return OpenSRF::Utils::JSON->JSON2perl($lset->value) if $lset;
}
@@ -173,12 +175,15 @@ sub tag_circed_items {
my $self = shift;
my $e = $self->editor;
+ $self->timelog("Tag circed items?");
return 0 unless $e->requestor;
+ $self->timelog("Checking for opac.search.tag_circulated_items");
return 0 unless $self->ctx->{get_org_setting}->(
$e->requestor->home_ou,
'opac.search.tag_circulated_items');
# user has to be opted-in to circ history in some capacity
+ $self->timelog("Checking for history.circ.retention_*");
my $sets = $e->search_actor_user_setting({
usr => $e->requestor->id,
name => [
@@ -187,6 +192,8 @@ sub tag_circed_items {
]
});
+ $self->timelog("Return from checking for history.circ.retention_*");
+
return 0 unless @$sets;
return 1;
@@ -206,9 +213,11 @@ sub load_rresults_bookbag {
("-or" => {"pub" => "t", "owner" => $self->ctx->{"user"}->id}) :
("pub" => "t");
+ $self->timelog("Load results bookbag");
my $bbag = $self->editor->search_container_biblio_record_entry_bucket(
{"id" => $bookbag_id, "btype" => "bookbag", %authz}
);
+ $self->timelog("Got results bookbag");
if (!$bbag) {
$self->apache->log->warn(
@@ -227,6 +236,7 @@ sub load_rresults_bookbag {
sub load_rresults_bookbag_item_notes {
my ($self, $rec_ids) = @_;
+ $self->timelog("Load results bookbag item notes");
my $items_with_notes =
$self->editor->search_container_biblio_record_entry_bucket_item([
{"target_biblio_record_entry" => $rec_ids,
@@ -234,6 +244,7 @@ sub load_rresults_bookbag_item_notes {
{"flesh" => 1, "flesh_fields" => {"cbrebi" => ["notes"]},
"order_by" => {"cbrebi" => ["id"]}}
]);
+ $self->timelog("Got results bookbag item notes");
if (!$items_with_notes) {
$self->apache->log->warn("error from cstore retrieving cbrebi objects");
@@ -259,6 +270,7 @@ sub load_rresults {
my $ctx = $self->ctx;
my $e = $self->editor;
+ $self->timelog("Loading results");
# load bookbag metadata, if requested.
if (my $bbag_err = $self->load_rresults_bookbag) {
return $bbag_err;
@@ -272,15 +284,19 @@ sub load_rresults {
# Special alternative searches here. This could all stand to be cleaner.
if ($cgi->param("_special")) {
+ $self->timelog("Calling MARC expert search");
return $self->marc_expert_search(%args) if scalar($cgi->param("tag"));
+ $self->timelog("Calling item barcode search");
return $self->item_barcode_shortcut if (
$cgi->param("qtype") and ($cgi->param("qtype") eq "item_barcode")
);
+ $self->timelog("Calling call number browse");
return $self->call_number_browse_standalone if (
$cgi->param("qtype") and ($cgi->param("qtype") eq "cnbrowse")
);
}
+ $self->timelog("Getting search parameters");
my $page = $cgi->param('page') || 0;
my @facets = $cgi->param('facet');
my $limit = $self->_get_search_limit;
@@ -290,6 +306,7 @@ sub load_rresults {
my $metarecord = $cgi->param('metarecord');
my $results;
my $tag_circs = $self->tag_circed_items;
+ $self->timelog("Got search parameters");
$ctx->{page_size} = $limit;
$ctx->{search_page} = $page;
@@ -322,11 +339,13 @@ sub load_rresults {
if ($metarecord and !$internal) {
# TODO: other limits, like SVF/format, etc.
+ $self->timelog("Getting metarecords to records");
$results = $U->simplereq(
'open-ils.search',
'open-ils.search.biblio.metarecord_to_records',
$metarecord, {org => $ctx->{search_ou}, depth => $depth}
);
+ $self->timelog("Got metarecords to records");
# force the metarecord result blob to match the format of regular search results
$results->{ids} = [map { [$_] } @{$results->{ids}}];
@@ -358,7 +377,10 @@ sub load_rresults {
my $method = 'open-ils.search.biblio.multiclass.query';
$method .= '.staff' if $ctx->{is_staff};
+
+ $self->timelog("Firing off the multiclass query");
$results = $U->simplereq('open-ils.search', $method, $args, $query, 1);
+ $self->timelog("Returned from the multiclass query");
} catch Error with {
my $err = shift;
@@ -377,6 +399,7 @@ sub load_rresults {
$self->load_rresults_bookbag_item_notes($rec_ids) if $ctx->{bookbag};
+ $self->timelog("Calling get_records_and_facets()");
my ($facets, @data) = $self->get_records_and_facets(
$rec_ids, $results->{facet_key},
{
@@ -386,6 +409,7 @@ sub load_rresults {
pref_lib => $ctx->{pref_ou},
}
);
+ $self->timelog("Returned from get_records_and_facets()");
if ($page == 0) {
my $stat = $self->check_1hit_redirect($rec_ids);
@@ -426,6 +450,7 @@ sub check_1hit_redirect {
my ($sname, $org);
+ $self->timelog("Checking whether to jump to details on a single hit");
if ($ctx->{is_staff}) {
$sname = 'opac.staff.jump_to_details_on_single_hit';
$org = $ctx->{user}->ws_ou;
@@ -435,6 +460,8 @@ sub check_1hit_redirect {
$org = $self->_get_search_lib();
}
+ $self->timelog("Return from checking whether to jump to details on a single hit");
+
return undef unless
$self->ctx->{get_org_setting}->($org, $sname);
@@ -466,12 +493,14 @@ sub check_1hit_redirect {
sub item_barcode_shortcut {
my ($self) = @_;
+ $self->timelog("Searching for item_barcode");
my $method = "open-ils.search.multi_home.bib_ids.by_barcode";
if (my $search = create OpenSRF::AppSession("open-ils.search")) {
my $rec_ids = $search->request(
$method, $self->cgi->param("query")
)->gather(1);
$search->kill_me;
+ $self->timelog("Finished searching for item_barcode");
if (ref $rec_ids ne 'ARRAY') {
@@ -492,9 +521,11 @@ sub item_barcode_shortcut {
}
}
+ $self->timelog("Calling get_records_and_facets() for item_barcode");
my ($facets, @data) = $self->get_records_and_facets(
$rec_ids, undef, {flesh => "{holdings_xml,mra,acnp,acns,bmp}"}
);
+ $self->timelog("Returned from calling get_records_and_facets() for item_barcode");
$self->ctx->{records} = [@data];
$self->ctx->{search_facets} = {};
@@ -529,12 +560,14 @@ sub marc_expert_search {
$logger->info("query for expert search: " . Dumper($query));
+ $self->timelog("Getting search parameters");
# loc, limit and offset
my $page = $self->cgi->param("page") || 0;
my $limit = $self->_get_search_limit;
$self->ctx->{search_ou} = $self->_get_search_lib();
$self->ctx->{pref_ou} = $self->_get_pref_lib();
my $offset = $page * $limit;
+ $self->timelog("Got search parameters");
$self->ctx->{records} = [];
$self->ctx->{search_facets} = {};
@@ -551,6 +584,7 @@ sub marc_expert_search {
$offset = 0;
}
+ $self->timelog("Searching for MARC expert");
my $timeout = 120;
my $ses = OpenSRF::AppSession->create('open-ils.search');
my $req = $ses->request(
@@ -561,6 +595,7 @@ sub marc_expert_search {
my $resp = $req->recv($timeout);
my $results = $resp ? $resp->content : undef;
$ses->kill_me;
+ $self->timelog("Got our MARC expert results");
if (defined $U->event_code($results)) {
$self->apache->log->warn(
@@ -580,12 +615,14 @@ sub marc_expert_search {
return $stat if $stat;
}
+ $self->timelog("Calling get_records_and_facets() for MARC expert");
my ($facets, @data) = $self->get_records_and_facets(
$self->ctx->{ids}, undef, {
flesh => "{holdings_xml,mra,acnp,acns}",
pref_lib => $self->ctx->{pref_ou},
}
);
+ $self->timelog("Returned from calling get_records_and_facets() for MARC expert");
$self->ctx->{records} = [@data];
@@ -625,10 +662,12 @@ sub get_staff_search_settings {
return;
}
+ $self->timelog("Getting staff search size");
my $sss_size = $self->ctx->{get_org_setting}->(
$self->ctx->{physical_loc} || $self->ctx->{aou_tree}->()->id,
"opac.staff_saved_search.size",
);
+ $self->timelog("Got staff search size");
# Sic: 0 is 0 (off), but undefined is 10.
$sss_size = 10 unless defined $sss_size;
@@ -643,11 +682,13 @@ sub staff_load_searches {
my $list = [];
if ($cache_key) {
+ $self->timelog("Getting anon_cache value");
$list = $U->simplereq(
"open-ils.actor",
"open-ils.actor.anon_cache.get_value",
$cache_key, (ref $self)->ANON_CACHE_STAFF_SEARCH
);
+ $self->timelog("Got anon_cache value");
unless ($list) {
undef $cache_key;
@@ -671,11 +712,13 @@ sub staff_save_search {
splice @$list, $sss_size if scalar @$list > $sss_size;
+ $self->timelog("Setting anon_cache value");
$cache_key = $U->simplereq(
"open-ils.actor",
"open-ils.actor.anon_cache.set_value",
$cache_key, (ref $self)->ANON_CACHE_STAFF_SEARCH, $list
);
+ $self->timelog("Set anon_cache value");
return ($cache_key, $list);
}
commit a34bd33836bacb8e7b16f4a4af95a436a1eb75ef
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 b4fe528..498a04f 100644
--- a/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm
+++ b/Open-ILS/src/perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm
@@ -223,6 +223,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
@@ -230,11 +232,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"]');
@@ -244,9 +249,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 => [
@@ -259,6 +267,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(
@@ -267,10 +277,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
@@ -285,6 +297,7 @@ sub get_records_and_facets {
data => \@entries
}
}
+ $self->timelog("get_records_and_facets(): gathered/sorted facet data");
} else {
$facets = undef;
}
commit a695983e105767743f1957f49a05f74afec3e514
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> |
<a href="http://example.com">[% l('Bottom Link 4') %]</a> |
<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 © 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/Search.pm | 43 ++++++++++++++++++++
.../perlmods/lib/OpenILS/WWW/EGCatLoader/Util.pm | 13 ++++++
Open-ILS/src/templates/opac/parts/footer.tt2 | 9 ++++-
5 files changed, 93 insertions(+), 1 deletions(-)
hooks/post-receive
--
Evergreen ILS
More information about the open-ils-commits
mailing list