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:
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
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:150020070 421828115] Message processing duration 0.005465 Application. pm:159: 150020070421828 116] CALL: open-ils.circ open-ils. circ.copy_ note.retrieve. all HASH(0x512e230) osrf_applicatio n.c:1070: 150020070421828 116] CALL: open-ils.cstore open-ils. cstore. direct. asset.copy_ note.search. atomic {"owning_ copy":10622772, "pub":" t"}
[2017-07-18 16:36:23] open-ils.circ [INFO:38459:
open-ils.cstore 2017-07-18 12:36:23 [INFO:21142:
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 and_facets( ): about to call multisession and_facets( ): about to call unapi.bre via json_query (rec_ids has 1 and_facets( ): got response content and_facets( ): parsed xml and_facets( ): end of success handler and_facets( ):past session wait and_facets( ) copy_summary( ) and_facets( ): about to call multisession and_facets( ): about to call unapi.mmr via json_query (rec_ids has 1 and_facets( ): got response content and_facets( ): parsed xml and_facets( ): end of success handler and_facets( ):past session wait
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_
At 0.3769: get_records_
At 1.3819: get_records_
At 1.3828: get_records_
At 1.3840: get_records_
At 1.3841: get_records_
At 1.3841: past get_records_
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_
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_
At 72.8585: get_records_
At 73.0858: get_records_
At 73.0867: get_records_
At 73.0885: get_records_
At 73.0886: get_records_