Comment 3 for bug 1704396

Adding a timelog capture for an example of a search that exhibited the 70 second delay on our training server. Also attaching a capture of log entries for this search.

Note the 70 second jump in the timelog:

At 1.7283: past copy note retrieval call
At 71.8001: past peer bib id retrieval

Also note the 70 second gap in the attached log entries:

open-ils.cstore 2017-07-18 12:35:13 [INFO:21705:osrf_stack.c:163:150020070421828115] Message processing duration 0.005465
[2017-07-18 16:36:23] open-ils.circ [INFO:38459:Application.pm:159:150020070421828116] CALL: open-ils.circ open-ils.circ.copy_note.retrieve.all HASH(0x512e230)
open-ils.cstore 2017-07-18 12:36:23 [INFO:21142:osrf_application.c:1070:150020070421828116] CALL: open-ils.cstore open-ils.cstore.direct.asset.copy_note.search.atomic {"owning_copy":10622772,"pub":"t"}

Here's the query info:

Query: glamour
Qtype: title
Search_format: serial

https://egtraining.noblenet.org/eg/opac/record/1811637?query=glamour;qtype=title;fi%3Asearch_format=serial;locg=1;detail_record_view=0

Timelog

At 0.0000: New page
At 0.2291: Initial load
At 0.2969: load_record() began
At 0.3004: past added content stage 1
At 0.3013: past staff saved searches
At 0.3014: Loading results
At 0.3014: Getting search parameters
At 0.3022: Tag circed items?
At 0.3022: Got search parameters
At 0.3033: Firing off the multiclass query
At 0.3209: Returned from the multiclass query
At 0.3214: past related search info
At 0.3754: get_records_and_facets(): about to call multisession
At 0.3769: get_records_and_facets(): about to call unapi.bre via json_query (rec_ids has 1
At 1.3819: get_records_and_facets(): got response content
At 1.3828: get_records_and_facets(): parsed xml
At 1.3840: get_records_and_facets(): end of success handler
At 1.3841: get_records_and_facets():past session wait
At 1.3841: past get_records_and_facets()
At 1.3928: past copy note retrieval call
At 1.4310: past peer bib id retrieval
At 1.4446: past copy note retrieval call
At 1.4881: past peer bib id retrieval
At 1.5017: past copy note retrieval call
At 1.5448: past peer bib id retrieval
At 1.5581: past copy note retrieval call
At 1.6007: past peer bib id retrieval
At 1.6141: past copy note retrieval call
At 1.6572: past peer bib id retrieval
At 1.6704: past copy note retrieval call
At 1.7144: past peer bib id retrieval
At 1.7283: past copy note retrieval call
At 71.8001: past peer bib id retrieval
At 71.8181: past copy note retrieval call
At 71.8706: past peer bib id retrieval
At 71.8845: past copy note retrieval call
At 72.1416: past peer bib id retrieval
At 72.1566: past copy note retrieval call
At 72.2008: past peer bib id retrieval
At 72.2009: past store copy retrieval call
At 72.5801: past get_hold_copy_summary()
At 72.8488: past serials holding stuff
At 72.8489: past expandies
At 72.8509: past added content stage 2
At 72.8572: get_records_and_facets(): about to call multisession
At 72.8585: get_records_and_facets(): about to call unapi.mmr via json_query (rec_ids has 1
At 73.0858: get_records_and_facets(): got response content
At 73.0867: get_records_and_facets(): parsed xml
At 73.0885: get_records_and_facets(): end of success handler
At 73.0886: get_records_and_facets():past session wait