Comment 33 for bug 1704396

Evergreen 2.12.4
opensrf 5.1

The search delay issue is still present. Metarecord searches that show the delay consistently show a lack of format icon and no record id in the title link for the first or second hit.

An example of a timelog for a metarecord search for "apple juice" is:

At 7.4020: Returned from get_records_and_facets()
At 7.8243: Firing off the second multiclass query
At 7.8249: Gathering meta_results
At 8.6264: Returned from gathering meta_results
At 8.6264: Returned from the second multiclass query
At 8.6268: Firing off the second multiclass query
At 8.6275: Gathering meta_results
At 79.6177: Returned from gathering meta_results
At 79.6178: Returned from the second multiclass query
At 79.6182: Firing off the second multiclass query
At 79.6191: Gathering meta_results
At 80.4367: Returned from gathering meta_results
At 80.4367: Returned from the second multiclass query

The timelog gap corresponds to these lines in OpenILS/WWW/EGCatloader/Search.pm

                $self->timelog("Gathering meta_results");
                $meta_results = $req->gather(1);
                $self->timelog("Returned from gathering meta_results");
                $self->timelog("Returned from the second multiclass query");

Also attaching a screenshot of the search results screen showing the missing info

For comparison, here are some grepped log entries from the first gather, which was successful (metarecord id 2759947, source id 2598144):

Here are all the log entries where metarecord id 2759947 appears:

[2017-09-12 12:53:44] open-ils.search [INFO:6649:CStoreEditor.pm:139:15052229973698331] editor[0|0] request en-US open-ils.cstore.json_query {"from":["search.facets_for_metarecord_set","{}","{2759947,2387987,2794176,2987877,3418043,2112438,2105728,2109922}"]}
open-ils.cstore 2017-09-12 12:53:44 [INFO:5427:osrf_application.c:1075:15052229973698331] CALL: open-ils.cstore open-ils.cstore.json_query {"from":["search.facets_for_metarecord_set","{}","{2759947,2387987,2794176,2987877,3418043,2112438,2105728,2109922}"]}
open-ils.cstore 2017-09-12 12:53:44 [INFO:5429:osrf_application.c:1075:15052229973698332] CALL: open-ils.cstore open-ils.cstore.json_query {"from":["unapi.mmr","2759947","marcxml","record","{holdings_xml,mra,acp,acnp,acns,bmp,cbs,mmr.unapi}","SAL","2","acn=>5,acp=>5,bre=>5",null,null,"63"]}
[2017-09-12 12:53:46] open-ils.storage [INFO:6490:Application.pm:159:15052229973698348] CALL: open-ils.storage open-ils.storage.biblio.multiclass.staged.search_fts.atomic estimation_strategy, inclusion, skip_check, 0, query, apple juice site(SAL) depth(2), from_metarecord, 2759947, core_limit, 10000, return_query, 1, limit, 1000, check_limit, 1000, offset, 0
[2017-09-12 12:53:47] open-ils.search [INFO:6649:Biblio.pm:1349:15052229973698348] Completed canonicalized search is: from_metarecord(2759947) core_limit(10000) limit(1000) badge_orgs(1,62,63) estimation_strategy(inclusion) site(SAL) depth(2) #CD_documentLength #CD_meanHarmonic #CD_uniqueWords (keyword: apple juice)

and all the entries where source id 2598144 appears:

[2017-09-12 12:53:47] open-ils.search [INFO:6649:CStoreEditor.pm:139:] editor[0|0] request en-US open-ils.cstore.json_query {"from":["search.facets_for_record_set","{}","{2598144}"]}
open-ils.cstore 2017-09-12 12:53:47 [INFO:6677:osrf_application.c:1075:15052229973698348] CALL: open-ils.cstore open-ils.cstore.json_query {"from":["search.facets_for_record_set","{}","{2598144}"]}
[2017-09-12 12:55:04] /usr/sbin/apache2 [INFO:3698:CStoreEditor.pm:139:15052229973698356] editor[0|0] request en-US open-ils.cstore.json_query.atomic {"from":"mfr","order_by":[{"class":"mfr","field":"id"}],"select":{"mfr":["tag","value"]},"where":{"-or":[{"-and":[{"tag":"020"},{"subfield":"a"}]},{"-and":[{"tag":"022"},{"subfield":"a"}]},{"-and":[{"tag":"024"},{"subfield":"a"},{"ind1":1}]}],"record":"2598144"}}
open-ils.cstore 2017-09-12 12:55:04 [INFO:6677:osrf_application.c:1075:15052229973698357] CALL: open-ils.cstore open-ils.cstore.json_query.atomic {"from":"mfr","order_by":[{"class":"mfr","field":"id"}],"select":{"mfr":["tag","value"]},"where":{"-or":[{"-and":[{"tag":"020"},{"subfield":"a"}]},{"-and":[{"tag":"022"},{"subfield":"a"}]},{"-and":[{"tag":"024"},{"subfield":"a"},{"ind1":1}]}],"record":"2598144"}}

Some grepped log entries for the failed gather (metarecord id 2387987, source id 3734245):

Here are all the log entries where metarecord id 2387987 appears:

[2017-09-12 12:53:44] open-ils.search [INFO:6649:CStoreEditor.pm:139:15052229973698331] editor[0|0] request en-US open-ils.cstore.json_query {"from":["search.facets_for_metarecord_set","{}","{2759947,2387987,2794176,2987877,3418043,2112438,2105728,2109922}"]}
open-ils.cstore 2017-09-12 12:53:44 [INFO:5427:osrf_application.c:1075:15052229973698331] CALL: open-ils.cstore open-ils.cstore.json_query {"from":["search.facets_for_metarecord_set","{}","{2759947,2387987,2794176,2987877,3418043,2112438,2105728,2109922}"]}
open-ils.cstore 2017-09-12 12:53:44 [INFO:5394:osrf_application.c:1075:15052229973698333] CALL: open-ils.cstore open-ils.cstore.json_query {"from":["unapi.mmr","2387987","marcxml","record","{holdings_xml,mra,acp,acnp,acns,bmp,cbs,mmr.unapi}","SAL","2","acn=>5,acp=>5,bre=>5",null,null,"63"]}
[2017-09-12 12:53:47] open-ils.storage [INFO:6460:Application.pm:159:15052229973698349] CALL: open-ils.storage open-ils.storage.biblio.multiclass.staged.search_fts.atomic estimation_strategy, inclusion, skip_check, 0, query, apple juice site(SAL) depth(2), from_metarecord, 2387987, core_limit, 10000, return_query, 1, limit, 1000, check_limit, 1000, offset, 0

and all the entries where source id 3734245appears:

[2017-09-12 12:55:04] /usr/sbin/apache2 [INFO:3697:CStoreEditor.pm:139:15052229973697172] editor[0|0] request en-US open-ils.cstore.json_query.atomic {"from":"mfr","order_by":[{"class":"mfr","field":"id"}],"select":{"mfr":["tag","value"]},"where":{"-or":[{"-and":[{"tag":"020"},{"subfield":"a"}]},{"-and":[{"tag":"022"},{"subfield":"a"}]},{"-and":[{"tag":"024"},{"subfield":"a"},{"ind1":1}]}],"record":"3734245"}}
open-ils.cstore 2017-09-12 12:55:04 [INFO:6678:osrf_application.c:1075:15052229973697173] CALL: open-ils.cstore open-ils.cstore.json_query.atomic {"from":"mfr","order_by":[{"class":"mfr","field":"id"}],"select":{"mfr":["tag","value"]},"where":{"-or":[{"-and":[{"tag":"020"},{"subfield":"a"}]},{"-and":[{"tag":"022"},{"subfield":"a"}]},{"-and":[{"tag":"024"},{"subfield":"a"},{"ind1":1}]}],"record":"3734245"}}