Missing query plan for auto_explain.

Our Postgres recently started reporting considerably different
execution times for the same query. When executed from our JDBC
application the Postgres logs report an average execution time of 1500
ms but when the query is manually executed through `psql` it doesn't
take longer than 50 ms.

With a view to investigate discrepancies in the plan we enabled
`auto_explain` in `session_preload_libraries` with
`auto_explain.log_min_duration = '1s'`. All application servers were
bounced to ensure new connections were created and picked up the
changes. However this trouble query does not have an explain plan
printed, even when its execution time exceeds the threshold (other
queries do though).

Does anyone have ideas of why the explain plan is not being printed?

Sample log entry for trouble query executed from application:
```
Aug 26 09:11:33 db-931 postgres[8106]: [66-1] 2022-08-26 09:11:33 GMT
[8106]: [5-1] db=betwave,user=betwave_app_readonly_user LOG:
duration: 1423.481 ms bind <unnamed>: /*@
org.sixty6.as66.QueryID:report.framework.userSearch */select
users.user_id, users.unique_identifier, user_profile.name,
user_profile.email, organisation.organisation_id,
organisation.description, user_realm.user_realm_id,
user_realm.description as col_8, user_realm.type,
user_realm_category.description as col_10, vip_schema.description as
col_11, vip_level.description as col_12, affiliate.description as
col_13, users.status, users.creation_date,
user_statistics.last_user_session_creation_date,
users.real_base_currency, users.fun_base_currency,
local_balance_account.balance
Aug 26 09:11:33 db-931 postgres[8106]: [66-2] #011from users users
Aug 26 09:11:33 db-931 postgres[8106]: [66-3] #011join user_profile user_profile
Aug 26 09:11:33 db-931 postgres[8106]: [66-4] #011on
user_profile.user_id = users.user_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-5] #011join user_realm user_realm
Aug 26 09:11:33 db-931 postgres[8106]: [66-6] #011on
user_realm.user_realm_id = users.user_realm_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-7] #011join organisation organisation
Aug 26 09:11:33 db-931 postgres[8106]: [66-8] #011on
organisation.organisation_id = user_realm.organisation_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-9] #011join
acl_allowed_organisation acl_allowed_organisation
Aug 26 09:11:33 db-931 postgres[8106]: [66-10] #011on
acl_allowed_organisation.organisation_id =
organisation.organisation_id and acl_allowed_organisation.permission =
$1 and acl_allowed_organisation.user_id = $2
Aug 26 09:11:33 db-931 postgres[8106]: [66-11] #011join affiliate affiliate
Aug 26 09:11:33 db-931 postgres[8106]: [66-12] #011on
affiliate.affiliate_id = users.affiliate_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-13] #011join
acl_allowed_affiliate acl_allowed_affiliate
Aug 26 09:11:33 db-931 postgres[8106]: [66-14] #011on
acl_allowed_affiliate.affiliate_id = affiliate.affiliate_id and
acl_allowed_affiliate.permission = $3 and
acl_allowed_affiliate.user_id = $4
Aug 26 09:11:33 db-931 postgres[8106]: [66-15] #011join
acl_allowed_user_realm_category acl_allowed_user_realm_category
Aug 26 09:11:33 db-931 postgres[8106]: [66-16] #011on
acl_allowed_user_realm_category.user_realm_category_id =
user_realm.user_realm_category_id and
acl_allowed_user_realm_category.permission = $5 and
acl_allowed_user_realm_category.user_id = $6
Aug 26 09:11:33 db-931 postgres[8106]: [66-17] #011join
user_statistics user_statistics
Aug 26 09:11:33 db-931 postgres[8106]: [66-18] #011on
user_statistics.user_id = users.user_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-19] #011join vip_level vip_level
Aug 26 09:11:33 db-931 postgres[8106]: [66-20] #011on
vip_level.vip_level_id = users.vip_level_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-21] #011join vip_schema vip_schema
Aug 26 09:11:33 db-931 postgres[8106]: [66-22] #011on
vip_schema.vip_schema_id = vip_level.vip_schema_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-23] #011join
user_realm_category user_realm_category
Aug 26 09:11:33 db-931 postgres[8106]: [66-24] #011on
user_realm_category.user_realm_category_id =
user_realm.user_realm_category_id
Aug 26 09:11:33 db-931 postgres[8106]: [66-25] #011left join
local_balance_account local_balance_account
Aug 26 09:11:33 db-931 postgres[8106]: [66-26] #011on
local_balance_account.user_id = users.user_id and
local_balance_account.currency = users.real_base_currency and
local_balance_account.balance_category = $7 and
local_balance_account.primary_balance = $8
Aug 26 09:11:33 db-931 postgres[8106]: [66-27] #011where users.type in
($9, $10) and user_realm.type in ($11, $12, $13) and
users.unique_identifier like $14 escape '\'
Aug 26 09:11:33 db-931 postgres[8106]: [66-28] #011order by
users.unique_identifier asc, user_realm.user_realm_id asc
Aug 26 09:11:33 db-931 postgres[8106]: [66-29] #011limit $15
Aug 26 09:11:33 db-931 postgres[8106]: [66-30] 2022-08-26 09:11:33 GMT
[8106]: [6-1] db=betwave,user=betwave_app_readonly_user DETAIL:
parameters: $1 = 'READ', $2 = '1468137', $3 = 'READ', $4 = '1468137',
$5 = 'READ', $6 = '1468137', $7 = 'CASH', $8 = 't', $9 = 'LOCAL', $10
= 'EXTERNAL', $11 = 'ADMIN', $12 = 'HUB', $13 = 'PLAYER', $14 =
'robinson06%', $15 = '200'
```

Sample log entry for another query executed from application:
```
Aug 26 15:10:58 db-931 postgres[40727]: [71-1] 2022-08-26 15:10:58 GMT
[40727]: [15-1] db=betwave,user=betwave_app_readonly_user LOG:
duration: 1069.964 ms plan:
Aug 26 15:10:58 db-931 postgres[40727]: [71-2] #011Query Text: /*@
org.sixty6.as66.QueryID:health.betwave.game.external.InProgressGamePlays:com.betconstruct
*/select x.hour, sum(x.in_progress_count) as col_2,
sum(x.closed_count) as col_3
Aug 26 15:10:58 db-931 postgres[40727]: [71-3] #011from ((select
date_trunc('hour',game_play.start_date AT TIME ZONE INTERVAL '0
seconds') AT TIME ZONE INTERVAL '0 seconds' as hour, count(*) as
in_progress_count, $1 as closed_count
Aug 26 15:10:58 db-931 postgres[40727]: [71-4] #011from game_play game_play
Aug 26 15:10:58 db-931 postgres[40727]: [71-5] #011join game_profile
game_profile
Aug 26 15:10:58 db-931 postgres[40727]: [71-6] #011on
game_profile.game_profile_id = game_play.game_profile_id
Aug 26 15:10:58 db-931 postgres[40727]: [71-7] #011join game game
Aug 26 15:10:58 db-931 postgres[40727]: [71-8] #011on game.game_id =
game_profile.game_id
Aug 26 15:10:58 db-931 postgres[40727]: [71-9] #011where
game.game_engine_id = $2 and game_play.status = $3 and
game_play.start_date >= $4 and game_play.start_date < $5
Aug 26 15:10:58 db-931 postgres[40727]: [71-10] #011group by
date_trunc('hour',game_play.start_date AT TIME ZONE INTERVAL '0
seconds') AT TIME ZONE INTERVAL '0 seconds')
Aug 26 15:10:58 db-931 postgres[40727]: [71-11] #011union all
Aug 26 15:10:58 db-931 postgres[40727]: [71-12] #011(select
date_trunc('hour',game_activity.interval_start_date AT TIME ZONE
INTERVAL '0 seconds') AT TIME ZONE INTERVAL '0 seconds' as hour, $6 as
in_progress_count, sum(game_activity.game_play_count) as closed_count
Aug 26 15:10:58 db-931 postgres[40727]: [71-13] #011from game_activity
game_activity
Aug 26 15:10:58 db-931 postgres[40727]: [71-14] #011join game game
Aug 26 15:10:58 db-931 postgres[40727]: [71-15] #011on game.game_id =
game_activity.game_id
Aug 26 15:10:58 db-931 postgres[40727]: [71-16] #011where
game.game_engine_id = $7 and tstzrange($8, $9, $10) @>
tstzrange(game_activity.interval_start_date,
game_activity.interval_end_date, $11)
Aug 26 15:10:58 db-931 postgres[40727]: [71-17] #011group by
date_trunc('hour',game_activity.interval_start_date AT TIME ZONE
INTERVAL '0 seconds') AT TIME ZONE INTERVAL '0 seconds')) as x
Aug 26 15:10:58 db-931 postgres[40727]: [71-18] #011group by x.hour
Aug 26 15:10:58 db-931 postgres[40727]: [71-19] #011having
sum(x.in_progress_count) > $12 and sum(x.in_progress_count) +
sum(x.closed_count) >= $13 and sum(x.in_progress_count) >=
(sum(x.in_progress_count) + sum(x.closed_count)) * $14
Aug 26 15:10:58 db-931 postgres[40727]: [71-20] #011GroupAggregate
(cost=10069.43..10072.16 rows=1 width=72)
Aug 26 15:10:58 db-931 postgres[40727]: [71-21] #011 Group Key:
"*SELECT* 1".hour
Aug 26 15:10:58 db-931 postgres[40727]: [71-22] #011 Filter:
((sum("*SELECT* 1".in_progress_count) > '0'::numeric) AND
((sum("*SELECT* 1".in_progress_count) + sum((('0'::bigint)::numeric)))
>= '0'::numeric) AND (sum("*SELECT* 1".in_progress_count) >=
((sum("*SELECT* 1".in_progress_count) + sum((('0'::bigint)::numeric)))
* '0'::numeric)))
Aug 26 15:10:58 db-931 postgres[40727]: [71-23] #011 -> Sort
(cost=10069.43..10069.53 rows=39 width=48)
Aug 26 15:10:58 db-931 postgres[40727]: [71-24] #011 Sort Key:
"*SELECT* 1".hour
Aug 26 15:10:58 db-931 postgres[40727]: [71-25] #011 -> Append
(cost=10048.65..10068.01 rows=39 width=48)
Aug 26 15:10:58 db-931 postgres[40727]: [71-26] #011 ->
Subquery Scan on "*SELECT* 1" (cost=10048.65..10050.08 rows=38
width=48)
Aug 26 15:10:58 db-931 postgres[40727]: [71-27] #011
-> GroupAggregate (cost=10048.65..10049.60 rows=38 width=24)
Aug 26 15:10:58 db-931 postgres[40727]: [71-28] #011
Group Key: (timezone('00:00:00'::interval,
date_trunc('hour'::text, timezone('00:00:00'::interval,
game_play.start_date))))
Aug 26 15:10:58 db-931 postgres[40727]: [71-29] #011
-> Sort (cost=10048.65..10048.75 rows=38 width=8)
Aug 26 15:10:58 db-931 postgres[40727]: [71-30] #011
Sort Key: (timezone('00:00:00'::interval,
date_trunc('hour'::text, timezone('00:00:00'::interval,
game_play.start_date))))
Aug 26 15:10:58 db-931 postgres[40727]: [71-31] #011
-> Nested Loop (cost=116.74..10047.66 rows=38 width=8)
Aug 26 15:10:58 db-931 postgres[40727]: [71-32] #011
-> Hash Join (cost=116.33..209.84 rows=18
width=8)
Aug 26 15:10:58 db-931 postgres[40727]: [71-33] #011
Hash Cond: (game_profile.game_id =
game.game_id)
Aug 26 15:10:58 db-931 postgres[40727]: [71-34] #011
-> Seq Scan on game_profile
(cost=0.00..86.54 rows=2654 width=16)
Aug 26 15:10:58 db-931 postgres[40727]: [71-35] #011
-> Hash (cost=116.12..116.12 rows=16
width=8)
Aug 26 15:10:58 db-931 postgres[40727]: [71-36] #011
-> Seq Scan on game
(cost=0.00..116.12 rows=16 width=8)
Aug 26 15:10:58 db-931 postgres[40727]: [71-37] #011
Filter: ((game_engine_id)::text =
'com.betconstruct'::text)
Aug 26 15:10:58 db-931 postgres[40727]: [71-38] #011
-> Index Scan using game_play_operable_unq01 on
game_play_operable game_play (cost=0.42..546.45 rows=8 width=16)
Aug 26 15:10:58 db-931 postgres[40727]: [71-39] #011
Index Cond: (game_profile_id =
game_profile.game_profile_id)
Aug 26 15:10:58 db-931 postgres[40727]: [71-40] #011
Filter: ((start_date >= '2022-08-25
16:00:00+00'::timestamp with time zone) AND (start_date < '2022-08-26
15:00:57.028601+00'::timestamp with time zone) AND ((status)::text =
'IN_PROGRESS'::text))
Aug 26 15:10:58 db-931 postgres[40727]: [71-41] #011 ->
GroupAggregate (cost=17.70..17.73 rows=1 width=48)
Aug 26 15:10:58 db-931 postgres[40727]: [71-42] #011
Group Key: (timezone('00:00:00'::interval, date_trunc('hour'::text,
timezone('00:00:00'::interval, game_activity.interval_start_date))))
Aug 26 15:10:58 db-931 postgres[40727]: [71-43] #011
-> Sort (cost=17.70..17.70 rows=1 width=16)
Aug 26 15:10:58 db-931 postgres[40727]: [71-44] #011
Sort Key: (timezone('00:00:00'::interval,
date_trunc('hour'::text, timezone('00:00:00'::interval,
game_activity.interval_start_date))))
Aug 26 15:10:58 db-931 postgres[40727]: [71-45] #011
-> Nested Loop (cost=0.70..17.69 rows=1 width=16)
Aug 26 15:10:58 db-931 postgres[40727]: [71-46] #011
-> Index Scan using game_activity_ix01 on game_activity
(cost=0.42..8.44 rows=1 width=24)
Aug 26 15:10:58 db-931 postgres[40727]: [71-47] #011
Index Cond: (tstzrange(interval_start_date,
interval_end_date, '[]'::text) <@ '["2022-08-25
16:00:00+00","2022-08-26 16:00:00+00"]'::tstzrange)
Aug 26 15:10:58 db-931 postgres[40727]: [71-48] #011
-> Index Scan using pk_game on game game_1
(cost=0.28..8.30 rows=1 width=8)
Aug 26 15:10:58 db-931 postgres[40727]: [71-49] #011
Index Cond: (game_id = game_activity.game_id)
Aug 26 15:10:58 db-931 postgres[40727]: [71-50] #011
Filter: ((game_engine_id)::text =
'com.betconstruct'::text)
```

Our environment consists of PostgreSQL 13.6 on Linux.