Just adding some selected log entries for a slow metarecord search in hopes it may provide some clues.

Metarecord search for "apple juice" site:SAL

Search matched 8 metarecords with the following ids and associated sources, in the following order:

mmr.id    mmrsm.sources
2759947 - 2598144
2387987 - 3734245
2794176 - 2696417
2987877 - 2975240,3017142
3418043 - 2670717
2112438 - 3174791,3483376,3519535,3833608
2105728 - 2910493,3483453,3483581
2109922 - 3352056

The timelog showed the 70 second delay between Gathering meta_results/Returned from gathering meta_results for the second hit in the results (metarecord 2387987, source 3734245)

When the page loaded the second hit was missing format information. Looking at the threadtraces in the logs, the trace for the second hit shows several calls not present for the other hits, and is missing others that are present in the other hits. For hits 1 and 3-8, the threadtraces looked similar.

Here are threadtraces from the first three hits retrieved:

Hit 1

[2017-09-20 16:02:44] open-ils.search [INFO:30211:Application.pm:159:150564390479022184] CALL: open-ils.search open-ils.search.biblio.multiclass.query HASH(0x436e1c0), apple juice site(SAL) depth(2), 1
[2017-09-20 16:02:44] open-ils.storage [INFO:30241:Application.pm:159:150564390479022184] 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
open-ils.cstore 2017-09-20 16:02:44 [INFO:29957:osrf_application.c:1075:150564390479022184] CALL: open-ils.cstore open-ils.cstore.json_query.atomic {"from":["actor.org_unit_ancestors","63"]}
open-ils.cstore 2017-09-20 16:02:44 [INFO:29957:osrf_app_session.c:1177:150564390479022184] [open-ils.cstore] sent 1094 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30241
open-ils.cstore 2017-09-20 16:02:44 [INFO:29957:osrf_stack.c:163:150564390479022184] Message processing duration 0.002724
[2017-09-20 16:02:44] open-ils.storage [INFO:30241:metabib.pm:2984:150564390479022184] pref_ou =
[2017-09-20 16:02:44] open-ils.storage [WARN:30241:Application.pm:624:150564390479022184] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:44] open-ils.storage [WARN:30241:Application.pm:624:150564390479022184] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:44] open-ils.storage [WARN:30241:Application.pm:624:150564390479022184] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:44] open-ils.storage [WARN:30241:Application.pm:624:150564390479022184] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:44] open-ils.storage [INFO:30241:Transport.pm:163:150564390479022184] Message processing duration: 0.664
[2017-09-20 16:02:44] open-ils.search [INFO:30211:Biblio.pm:1243:150564390479022184] staged search: DB call took 0.673375129699707 seconds and returned 1 rows, including summary
[2017-09-20 16:02:44] open-ils.search [INFO:30211:Biblio.pm:1501:150564390479022184] staged search: cached with key=open-ils.search_0a9d9b599f04a914ad54db69bd940b7b, superpage=0, estimated=none, visible=1
[2017-09-20 16:02:44] open-ils.search [INFO:30211:Biblio.pm:1349:150564390479022184] 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)
[2017-09-20 16:02:44] open-ils.search [INFO:30211:CStoreEditor.pm:139:150564390479022184] editor[0|0] request en-US open-ils.cstore.json_query {"from":["search.facets_for_record_set","{}","{2598144}"]}
open-ils.cstore 2017-09-20 16:02:44 [INFO:30049:osrf_application.c:1075:150564390479022184] CALL: open-ils.cstore open-ils.cstore.json_query {"from":["search.facets_for_record_set","{}","{2598144}"]}
open-ils.cstore 2017-09-20 16:02:44 [INFO:30049:osrf_app_session.c:1177:150564390479022184] [open-ils.cstore] sent 849 bytes of data to <email address hidden>/open-ils.search_drone_at_localhost_30211
open-ils.cstore 2017-09-20 16:02:44 [INFO:30049:osrf_stack.c:163:150564390479022184] Message processing duration 0.004778
[2017-09-20 16:02:44] open-ils.search [INFO:30211:CStoreEditor.pm:139:150564390479022184] editor[0|0] json_query : returned 3 result(s)
[2017-09-20 16:02:44] open-ils.search [INFO:30211:Biblio.pm:1485:150564390479022184] facet compilation: cached with key=open-ils.search_0a9d9b599f04a914ad54db69bd940b7b_facets
[2017-09-20 16:02:44] open-ils.search [INFO:30211:Transport.pm:163:150564390479022184] Message processing duration: 0.701

Hit 2 (showing the delay)

[2017-09-20 16:02:44] open-ils.search [INFO:30223:Application.pm:159:150564390479022185] CALL: open-ils.search open-ils.search.biblio.multiclass.query HASH(0x43d5b90), apple juice site
(SAL) depth(2), 1
[2017-09-20 16:02:44] open-ils.storage [INFO:30220:Application.pm:159:150564390479022185] 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
open-ils.cstore 2017-09-20 16:02:44 [INFO:30048:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.record_attr_index_norm_map.search.atomic
 {"id":{"!=":null}},{"flesh_fields":{"crainm":["norm"]},"order_by":[{"class":"crainm","field":"pos"}],"flesh":1}
open-ils.cstore 2017-09-20 16:02:44 [INFO:30048:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 1086 bytes of data to <email address hidden>/open-ils.storage_dron
e_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:44 [INFO:30048:osrf_stack.c:163:150564390479022185] Message processing duration 0.011011
open-ils.cstore 2017-09-20 16:02:44 [INFO:30046:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.search.relevance_adjustment.search.atomic {"id"
:{"!=":null}}
open-ils.cstore 2017-09-20 16:02:44 [INFO:30046:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 1449 bytes of data to <email address hidden>/open-ils.storage_dron
e_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:44 [INFO:30046:osrf_stack.c:163:150564390479022185] Message processing duration 0.003818
open-ils.cstore 2017-09-20 16:02:44 [INFO:30036:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.metabib_field.search.atomic {"id":{"!=":
null}}
open-ils.cstore 2017-09-20 16:02:45 [INFO:30036:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 13445 bytes of data to <email address hidden>/open-ils.storage_dro
ne_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30036:osrf_stack.c:163:150564390479022185] Message processing duration 0.022764
open-ils.cstore 2017-09-20 16:02:45 [INFO:30038:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.metabib_search_alias.search.atomic {"ali
as":{"!=":null}}
open-ils.cstore 2017-09-20 16:02:45 [INFO:30038:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 2649 bytes of data to <email address hidden>/open-ils.storage_dron
e_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30038:osrf_stack.c:163:150564390479022185] Message processing duration 0.003299
open-ils.cstore 2017-09-20 16:02:45 [INFO:30035:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.metabib_field_index_norm_map.search.atom
ic {"id":{"!=":null}},{"flesh_fields":{"cmfinm":["norm"]},"order_by":[{"class":"cmfinm","field":"pos"}],"flesh":1}
open-ils.cstore 2017-09-20 16:02:45 [INFO:30035:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 27494 bytes of data to <email address hidden>/open-ils.storage_dro
ne_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30035:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 5928 bytes of data to <email address hidden>/open-ils.storage_dron
e_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30035:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 222 bytes of data to <email address hidden>/open-ils.storage_drone
_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30035:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 189 bytes of data to <email address hidden>/open-ils.storage_drone
_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30035:osrf_stack.c:163:150564390479022185] Message processing duration 0.237655
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.record_attr_definition.search.atomic {"n
ame":{"!=":null}}
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 26029 bytes of data to <email address hidden>/open-ils.storage_dro
ne_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 25801 bytes of data to <email address hidden>/open-ils.storage_dro
ne_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 25806 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 25739 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 25719 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 22383 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 222 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 189 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:45 [INFO:30034:osrf_stack.c:163:150564390479022185] Message processing duration 0.384085
open-ils.cstore 2017-09-20 16:02:46 [INFO:29957:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.metabib_class_ts_map.search.atomic {"active":"t"}
open-ils.cstore 2017-09-20 16:02:46 [INFO:29957:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 993 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:46 [INFO:29957:osrf_stack.c:163:150564390479022185] Message processing duration 0.002957
open-ils.cstore 2017-09-20 16:02:46 [INFO:30049:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.metabib_field_ts_map.search.atomic {"active":"t"}
open-ils.cstore 2017-09-20 16:02:46 [INFO:30049:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 369 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:46 [INFO:30049:osrf_stack.c:163:150564390479022185] Message processing duration 0.002020
open-ils.cstore 2017-09-20 16:02:46 [INFO:30048:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.metabib_class.search.atomic {"name":{"!=":null}}
open-ils.cstore 2017-09-20 16:02:46 [INFO:30048:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 834 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:46 [INFO:30048:osrf_stack.c:163:150564390479022185] Message processing duration 0.003665
open-ils.cstore 2017-09-20 16:02:46 [INFO:30046:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.direct.config.global_flag.retrieve "search.max_popularity_importance_multiplier"
open-ils.cstore 2017-09-20 16:02:46 [INFO:30046:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 568 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:46 [INFO:30046:osrf_stack.c:163:150564390479022185] Message processing duration 0.002270
open-ils.cstore 2017-09-20 16:02:46 [INFO:30036:osrf_application.c:1075:150564390479022185] CALL: open-ils.cstore open-ils.cstore.json_query.atomic {"from":["actor.org_unit_ancestors","63"]}
open-ils.cstore 2017-09-20 16:02:46 [INFO:30036:osrf_app_session.c:1177:150564390479022185] [open-ils.cstore] sent 1094 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:02:46 [INFO:30036:osrf_stack.c:163:150564390479022185] Message processing duration 0.002628
[2017-09-20 16:02:46] open-ils.storage [INFO:30220:metabib.pm:2984:150564390479022185] pref_ou =
[2017-09-20 16:02:46] open-ils.storage [WARN:30220:Application.pm:624:150564390479022185] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:46] open-ils.storage [WARN:30220:Application.pm:624:150564390479022185] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:46] open-ils.storage [WARN:30220:Application.pm:624:150564390479022185] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:46] open-ils.storage [WARN:30220:Application.pm:624:150564390479022185] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:02:46] open-ils.storage [INFO:30220:Transport.pm:163:150564390479022185] Message processing duration: 2.178
[2017-09-20 16:03:55] open-ils.storage [INFO:30220:XMPPReader.pm:379:150564390479022185] flushing data from socket...

Hit 3

opensrf@egtraining:/openils/var/log$ grep 2017-09-20 osrfsys.log | grep 150564390479022186 | less
[2017-09-20 16:03:55] open-ils.search [INFO:30211:Application.pm:159:150564390479022186] CALL: open-ils.search open-ils.search.biblio.multiclass.query HASH(0x424c220), apple juice site(SAL) depth(2), 1
[2017-09-20 16:03:55] open-ils.storage [INFO:30220:Application.pm:159:150564390479022186] 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, 2794176, core_limit, 10000, return_query, 1, limit, 1000, check_limit, 1000, offset, 0
open-ils.cstore 2017-09-20 16:03:55 [INFO:30038:osrf_application.c:1075:150564390479022186] CALL: open-ils.cstore open-ils.cstore.json_query.atomic {"from":["actor.org_unit_ancestors","63"]}
open-ils.cstore 2017-09-20 16:03:55 [INFO:30038:osrf_app_session.c:1177:150564390479022186] [open-ils.cstore] sent 1094 bytes of data to <email address hidden>/open-ils.storage_drone_at_localhost_30220
open-ils.cstore 2017-09-20 16:03:55 [INFO:30038:osrf_stack.c:163:150564390479022186] Message processing duration 0.002852
[2017-09-20 16:03:55] open-ils.storage [INFO:30220:metabib.pm:2984:150564390479022186] pref_ou =
[2017-09-20 16:03:56] open-ils.storage [WARN:30220:Application.pm:624:150564390479022186] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:03:56] open-ils.storage [WARN:30220:Application.pm:624:150564390479022186] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:03:56] open-ils.storage [WARN:30220:Application.pm:624:150564390479022186] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:03:56] open-ils.storage [WARN:30220:Application.pm:624:150564390479022186] open-ils.storage.biblio.multiclass.staged.search_fts: NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
[2017-09-20 16:03:56] open-ils.storage [INFO:30220:Transport.pm:163:150564390479022186] Message processing duration: 0.658
[2017-09-20 16:03:56] open-ils.search [INFO:30211:Biblio.pm:1243:150564390479022186] staged search: DB call took 0.66849422454834 seconds and returned 1 rows, including summary
[2017-09-20 16:03:56] open-ils.search [INFO:30211:Biblio.pm:1501:150564390479022186] staged search: cached with key=open-ils.search_f38c8fbe8b0954f49aa26049ba066ace, superpage=0, estimated=none, visible=1
[2017-09-20 16:03:56] open-ils.search [INFO:30211:Biblio.pm:1349:150564390479022186] Completed canonicalized search is: from_metarecord(2794176) 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)
[2017-09-20 16:03:56] open-ils.search [INFO:30211:CStoreEditor.pm:139:150564390479022186] editor[0|0] request en-US open-ils.cstore.json_query {"from":["search.facets_for_record_set","{}","{2696417}"]}
open-ils.cstore 2017-09-20 16:03:56 [INFO:30035:osrf_application.c:1075:150564390479022186] CALL: open-ils.cstore open-ils.cstore.json_query {"from":["search.facets_for_record_set","{}","{2696417}"]}
open-ils.cstore 2017-09-20 16:03:56 [INFO:30035:osrf_app_session.c:1177:150564390479022186] [open-ils.cstore] sent 1505 bytes of data to <email address hidden>/open-ils.search_drone_at_localhost_30211
open-ils.cstore 2017-09-20 16:03:56 [INFO:30035:osrf_stack.c:163:150564390479022186] Message processing duration 0.005023
[2017-09-20 16:03:56] open-ils.search [INFO:30211:CStoreEditor.pm:139:150564390479022186] editor[0|0] json_query : returned 6 result(s)
[2017-09-20 16:03:56] open-ils.search [INFO:30211:Biblio.pm:1485:150564390479022186] facet compilation: cached with key=open-ils.search_f38c8fbe8b0954f49aa26049ba066ace_facets
[2017-09-20 16:03:56] open-ils.search [INFO:30211:Transport.pm:163:150564390479022186] Message processing duration: 0.696