[PG15 Only] UTILITY Statements can interfere hint in next preparedstatement after 5 executions in JDBC #237
Description
Repro
pg_conf
pg_hint_plan.debug_print = verbose
pg_hint_plan.message_level = warning
log_min_messages = warning
auto_explain.log_min_duration = 0
auto_explain.log_format = 'text'
auto_explain.log_buffers = 1
auto_explain.log_analyze = 1
JDBC is using default setting which
extended protocol
prepareThreshold=5
Table Setup. Without using pg_hint_plan the query would choose indexOnlyScan
create table test (id int primary key);
postgres=> explain select * from test where id = 0;
WARNING: hints in comment="(none)", query="explain select * from test where id = 0;", debug_query_string="explain select * from test where id = 0;"
WARNING: pg_hint_plan[qno=0x1]: planner: no valid hint
QUERY PLAN
---------------------------------------------------------------------------
Index Only Scan using test_pkey on test (cost=0.15..8.17 rows=1 width=4)
Index Cond: (id = 0)
(2 rows)
JDBC repro
Statement stmt = conn.createStatement();
PreparedStatement pstmt1 = conn.prepareStatement("/*+ BitmapScan(test) */ select * from test where id = ?");
for (int j = 0; j < 6; j++) {
stmt.executeUpdate("SET pg_hint_plan.enable_hint = on");
pstmt1.setInt(1,1);
rs = pstmt1.executeQuery();
}
log
2026-02-11 15:58:27 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="(none)", query="SET pg_hint_plan.enable_hint = on", debug_query_string="SET pg_hint_plan.enable_hint = on"
2026-02-11 15:58:27 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="BitmapScan(test) ", query="/*+ BitmapScan(test) */ select * from test where id = $1", debug_query_string="/*+ BitmapScan(test) */ select * from test where id = $1"
2026-02-11 15:58:27 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x5]: planner
2026-02-11 15:58:27 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x5]: setup_hint_enforcement index deletion: relation=17282(test), inhparent=0, current_hint_state=0xffffa35f8d40, hint_inhibit_level=0, scanmask=0x4
2026-02-11 15:58:27 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x5]: HintStateDump: {used hints:BitmapScan(test)}, {not used hints:(none)}, {duplicate hints:(none)}, {error hints:(none)}
2026-02-11 15:58:27 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:LOG: duration: 0.011 ms plan:
Query Text: /*+ BitmapScan(test) */ select * from test where id = $1
Bitmap Heap Scan on test (cost=4.16..8.18 rows=1 width=4) (actual time=0.008..0.009 rows=0 loops=1)
Recheck Cond: (id = 1)
Buffers: shared hit=2
-> Bitmap Index Scan on test_pkey (cost=0.00..4.16 rows=1 width=0) (actual time=0.005..0.005 rows=0 loops=1)
Index Cond: (id = 1)
Buffers: shared hit=2
2026-02-11 15:58:28 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="(none)", query="SET pg_hint_plan.enable_hint = on", debug_query_string="SET pg_hint_plan.enable_hint = on"
2026-02-11 15:58:28 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="BitmapScan(test) ", query="/*+ BitmapScan(test) */ select * from test where id = $1", debug_query_string="/*+ BitmapScan(test) */ select * from test where id = $1"
2026-02-11 15:58:28 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x7]: planner
2026-02-11 15:58:28 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x7]: setup_hint_enforcement index deletion: relation=17282(test), inhparent=0, current_hint_state=0xffffa35f8d40, hint_inhibit_level=0, scanmask=0x4
2026-02-11 15:58:28 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x7]: HintStateDump: {used hints:BitmapScan(test)}, {not used hints:(none)}, {duplicate hints:(none)}, {error hints:(none)}
2026-02-11 15:58:28 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:LOG: duration: 0.011 ms plan:
Query Text: /*+ BitmapScan(test) */ select * from test where id = $1
Bitmap Heap Scan on test (cost=4.16..8.18 rows=1 width=4) (actual time=0.008..0.009 rows=0 loops=1)
Recheck Cond: (id = 1)
Buffers: shared hit=2
-> Bitmap Index Scan on test_pkey (cost=0.00..4.16 rows=1 width=0) (actual time=0.006..0.006 rows=0 loops=1)
Index Cond: (id = 1)
Buffers: shared hit=2
2026-02-11 15:58:28 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="(none)", query="SET pg_hint_plan.enable_hint = on", debug_query_string="SET pg_hint_plan.enable_hint = on"
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="BitmapScan(test) ", query="/*+ BitmapScan(test) */ select * from test where id = $1", debug_query_string="/*+ BitmapScan(test) */ select * from test where id = $1"
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x9]: planner
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x9]: setup_hint_enforcement index deletion: relation=17282(test), inhparent=0, current_hint_state=0xffffa35f8d40, hint_inhibit_level=0, scanmask=0x4
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0x9]: HintStateDump: {used hints:BitmapScan(test)}, {not used hints:(none)}, {duplicate hints:(none)}, {error hints:(none)}
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:LOG: duration: 0.010 ms plan:
Query Text: /*+ BitmapScan(test) */ select * from test where id = $1
Bitmap Heap Scan on test (cost=4.16..8.18 rows=1 width=4) (actual time=0.008..0.009 rows=0 loops=1)
Recheck Cond: (id = 1)
Buffers: shared hit=2
-> Bitmap Index Scan on test_pkey (cost=0.00..4.16 rows=1 width=0) (actual time=0.005..0.006 rows=0 loops=1)
Index Cond: (id = 1)
Buffers: shared hit=2
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="(none)", query="SET pg_hint_plan.enable_hint = on", debug_query_string="SET pg_hint_plan.enable_hint = on"
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="BitmapScan(test) ", query="/*+ BitmapScan(test) */ select * from test where id = $1", debug_query_string="/*+ BitmapScan(test) */ select * from test where id = $1"
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0xb]: planner
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0xb]: setup_hint_enforcement index deletion: relation=17282(test), inhparent=0, current_hint_state=0xffffa35f8d40, hint_inhibit_level=0, scanmask=0x4
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0xb]: HintStateDump: {used hints:BitmapScan(test)}, {not used hints:(none)}, {duplicate hints:(none)}, {error hints:(none)}
2026-02-11 15:58:29 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:LOG: duration: 0.015 ms plan:
Query Text: /*+ BitmapScan(test) */ select * from test where id = $1
Bitmap Heap Scan on test (cost=4.16..8.18 rows=1 width=4) (actual time=0.013..0.013 rows=0 loops=1)
Recheck Cond: (id = 1)
Buffers: shared hit=2
-> Bitmap Index Scan on test_pkey (cost=0.00..4.16 rows=1 width=0) (actual time=0.009..0.009 rows=0 loops=1)
Index Cond: (id = 1)
Buffers: shared hit=2
2026-02-11 15:58:30 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="(none)", query="SET pg_hint_plan.enable_hint = on", debug_query_string="SET pg_hint_plan.enable_hint = on"
2026-02-11 15:58:30 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="BitmapScan(test) ", query="/*+ BitmapScan(test) */ select * from test where id = $1", debug_query_string="/*+ BitmapScan(test) */ select * from test where id = $1"
2026-02-11 15:58:30 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0xd]: planner
2026-02-11 15:58:30 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0xd]: setup_hint_enforcement index deletion: relation=17282(test), inhparent=0, current_hint_state=0xffffa35f8d40, hint_inhibit_level=0, scanmask=0x4
2026-02-11 15:58:30 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0xd]: HintStateDump: {used hints:BitmapScan(test)}, {not used hints:(none)}, {duplicate hints:(none)}, {error hints:(none)}
2026-02-11 15:58:30 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:LOG: duration: 0.012 ms plan:
Query Text: /*+ BitmapScan(test) */ select * from test where id = $1
Bitmap Heap Scan on test (cost=4.16..8.18 rows=1 width=4) (actual time=0.010..0.010 rows=0 loops=1)
Recheck Cond: (id = 1)
Buffers: shared hit=2
-> Bitmap Index Scan on test_pkey (cost=0.00..4.16 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=1)
Index Cond: (id = 1)
Buffers: shared hit=2
2026-02-11 15:58:31 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: hints in comment="(none)", query="SET pg_hint_plan.enable_hint = on", debug_query_string="SET pg_hint_plan.enable_hint = on"
2026-02-11 15:58:32 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:WARNING: pg_hint_plan[qno=0xe]: planner: no valid hint
2026-02-11 15:58:32 EST:freeip.amazon.com(64875):postgres@postgres:[38328]:LOG: duration: 0.023 ms plan:
Query Text: /*+ BitmapScan(test) */ select * from test where id = $1
Index Only Scan using test_pkey on test (cost=0.15..8.17 rows=1 width=4) (actual time=0.020..0.020 rows=0 loops=1)
Index Cond: (id = 1)
Heap Fetches: 0
Buffers: shared hit=2
At the 6th execution, pg_hint_plan stops working and falls back to the optimizer's default plan. The logs show: pg_hint_plan[qno=0xe]: planner: no valid hint
Root Cause Analysis
Executions 1-4: JDBC uses unnamed statements (since prepareThreshold = 5), sending the complete parse-bind-execute sequence for each execution.
Execution 5: JDBC switches to a named statement (S_1). Since this is the first time using this named statement, it still requires parsing, so the full parse-bind-execute sequence is sent.
Execution 6 (Problem): JDBC reuses the already-parsed statement S_1, sending only bind and execute commands—no parse command.
The Bug: The previous SET statement always triggers a parse operation, which sets the flags current_hint_retrieved = on and current_hint_str = NULL, but these flags are never reset. When S_1 reaches the planner phase without a parse command, pg_hint_plan sees that current_hint_retrieved is already set and skips the hint retrieval logic entirely. This causes the "no valid hint" error and the pg_hint_plan is completely skipped.
Solution
Upgrade to PG16, in 16 this commit skips the hint retrieval logic if it is a utility statement. a03bbdb