When use JDBC's prepared Statement, HINT not work in the middle of the process.

[kfuru]

Hello, When use JDBC's prepared Statement, HINT not work in the middle of the process. This is presumably due to the effect of preparedStatement on the execution plan cache, but after a certain number of executions, the hint clause is ignored. In the following (Test3, Test4), the hint clause is ignored after the 6th execution, even though a hint clause is specified.

How to reproduce:

$ initdb --encoding=UTF8 --no-locale --data-checksums

$ cat <<@EOF >> $PGDATA/postgresql.conf
autovacuum=off
shared_preload_libraries = 'pg_hint_plan, auto_explain'
max_parallel_workers_per_gather = 0
auto_explain.log_min_duration = 0
pg_hint_plan.debug_print = on
@EOF
# NOTE: Set autovacuum=off to create a situation where the statistics diverge.

$ cat <<@EOF > sample.sql
drop table test;
create table test (id int, val int);
create index test_idx on test (id);
insert into test select n,n+100 from generate_series(1,100) n;

create or replace function my_func(int)
returns integer as \$\$
 select val from test where id=\$1;
\$\$ language sql;

drop table t1;
create table t1 (a int, b int);
create index t1_idx on t1 (a);
insert into t1 select 1,n from generate_series(1,5000000) n;
vacuum analyze t1;
update t1 set a = b;   -- NOTE: Do not ANALYZE after executing update to create a situation where statistical information diverges. (also autovacuum=off)
@EOF

$ pg_ctl -w start
$ createdb test
$ psql test -f sample.sql

# Since no AUTOANALYZE is performed, we can reproduce the situation where the SQL below will always be Seq Scan.
$ psql -d test -c "explain (analyze, buffers) select count(*) from t1 where a = 1;"
                                                   QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=194248.00..194248.01 rows=1 width=8) (actual time=387.431..387.433 rows=1 loops=1)
   Buffers: shared hit=225 read=44023
   ->  Seq Scan on t1  (cost=0.00..169248.00 rows=10000000 width=0) (actual time=69.471..387.425 rows=1 loops=1)  **SEQ SCAN**
         Filter: (a = 1)
         Rows Removed by Filter: 4999999
         Buffers: shared hit=225 read=44023
 Planning:
   Buffers: shared hit=67
 Planning Time: 0.371 ms
 Execution Time: 387.561 ms
(10 rows)

$ cat <<@EOF > Test.java
import java.sql.*;

class Test1 {
    public static void main (String args[]) throws SQLException, ClassNotFoundException {
        Connection conn = DriverManager.getConnection("jdbc:postgresql://localhost/test", "postgres", "");
        long start, end;
        String sql1 = "select count(*) from t1 where a = ?";

        System.out.println("SQL: " + sql1);
        PreparedStatement pstmt1 = conn.prepareStatement(sql1);
        for(int i=1; i<=12; i++) {
            try {
                pstmt1.setInt(1, 1);
                start = System.currentTimeMillis();
                ResultSet rset = pstmt1.executeQuery();
                rset.close();
                end = System.currentTimeMillis();

                System.out.println(i + ": " + (float)(end - start)+ " ms");
            }
            catch(SQLException e) {
                e.printStackTrace();
            }
        }
        pstmt1.close();
        conn.close();
    }
}

class Test2 {
    public static void main (String args[]) throws SQLException, ClassNotFoundException {
        Connection conn = DriverManager.getConnection("jdbc:postgresql://localhost/test", "postgres", "");
        long start, end;
        String sql1 = "/*+ IndexScan(t1 t1_idx) */ select count(*) from t1 where a = ?";

        System.out.println("SQL: " + sql1);
        PreparedStatement pstmt1 = conn.prepareStatement(sql1);
        for(int i=1; i<=12; i++) {
            try {
                pstmt1.setInt(1, 1);
                start = System.currentTimeMillis();
                ResultSet rset = pstmt1.executeQuery();
                rset.close();
                end = System.currentTimeMillis();

                System.out.println(i + ": " + (float)(end - start)+ " ms");
            }
            catch(SQLException e) {
                e.printStackTrace();
            }
        }
        pstmt1.close();
        conn.close();
    }
}

class Test3 {
    public static void main (String args[]) throws SQLException, ClassNotFoundException {
        Connection conn = DriverManager.getConnection("jdbc:postgresql://localhost/test", "postgres", "");
        long start, end;
        String sql1 = "/*+ IndexScan(t1 t1_idx) */ select count(*), my_func(1) from t1 where a = ?";

        System.out.println("SQL: " + sql1);
        PreparedStatement pstmt1 = conn.prepareStatement(sql1);
        for(int i=1; i<=12; i++) {
            try {
                pstmt1.setInt(1, 1);
                start = System.currentTimeMillis();
                ResultSet rset = pstmt1.executeQuery();
                rset.close();
                end = System.currentTimeMillis();

                System.out.println(i + ": " + (float)(end - start)+ " ms");
            }
            catch(SQLException e) {
                e.printStackTrace();
            }
        }
        pstmt1.close();
        conn.close();
    }
}

class Test4 {
    public static void main (String args[]) throws SQLException, ClassNotFoundException {
        Connection conn = DriverManager.getConnection("jdbc:postgresql://localhost/test", "postgres", "");
        long start, end;
        String sql1 = "/*+ IndexScan(t1 t1_idx) */ select count(*) from t1 where a = ?";
        String sql2 = "select 123";

        System.out.println("SQL1: " + sql1);
        System.out.println("SQL2: " + sql2);
        PreparedStatement pstmt1 = conn.prepareStatement(sql1);
        PreparedStatement pstmt2 = conn.prepareStatement(sql2);
        for(int i=1; i<=12; i++) {
            try {
                pstmt1.setInt(1, 1);
                start = System.currentTimeMillis();
                ResultSet rset = pstmt1.executeQuery();
                rset.close();
                end = System.currentTimeMillis();
                System.out.println("SQL1: " + i + ": " + (float)(end - start)+ " ms");

                start = System.currentTimeMillis();
                ResultSet rset2 = pstmt2.executeQuery();
                rset2.close();
                end = System.currentTimeMillis();
                System.out.println("SQL2: " + i + ": " + (float)(end - start)+ " ms");
            }
            catch(SQLException e) {
                e.printStackTrace();
            }
        }
        pstmt1.close();
        pstmt2.close();
        conn.close();
    }
}
@EOF

$ export CLASSPATH=./:./postgresql-42.6.0.jar
$ javac Test.java
$

Test1: Reproduce the situation in which the Index Scan is not performed due to deviation from the statistical information.

$ java Test1
SQL: select count(*) from t1 where a = ?
1: 372.0 ms
2: 357.0 ms
3: 356.0 ms
4: 353.0 ms
5: 351.0 ms
6: 350.0 ms
7: 350.0 ms
8: 351.0 ms
9: 351.0 ms
10: 377.0 ms
11: 379.0 ms
12: 383.0 ms
$

Test2: Add HINT clause to ensure that execution time is improved.

$ java Test2
SQL: /*+ IndexScan(t1 t1_idx) */ select count(*) from t1 where a = ?
1: 25.0 ms
2: 2.0 ms
3: 2.0 ms
4: 1.0 ms
5: 2.0 ms
6: 1.0 ms
7: 1.0 ms
8: 1.0 ms
9: 1.0 ms
10: 1.0 ms
11: 1.0 ms
12: 1.0 ms
$

Test3: If SQL contains a user function (SQL execution internally), the HINT clause will be ignored after several executions, even if the HINT clause is used.

$ java Test3
SQL: /*+ IndexScan(t1 t1_idx) */ select count(*), my_func(1) from t1 where a = ?
1: 14.0 ms
2: 2.0 ms
3: 2.0 ms
4: 1.0 ms
5: 2.0 ms
6: 366.0 ms  *HINT ignored*
7: 352.0 ms  *HINT ignored*
8: 352.0 ms  *HINT ignored*
9: 353.0 ms  *HINT ignored*
10: 379.0 ms   *HINT ignored*
11: 378.0 ms   *HINT ignored*
12: 378.0 ms   *HINT ignored*
$

Test4: Also even in situations where multiple SQLs are executed, the HINT clause is ignored after several executions, even if a HINT clause is used.

$ java Test4
SQL1: /*+ IndexScan(t1 t1_idx) */ select count(*) from t1 where a = ?
SQL2: select 123
SQL1: 1: 19.0 ms
SQL2: 1: 0.0 ms
SQL1: 2: 2.0 ms
SQL2: 2: 0.0 ms
SQL1: 3: 2.0 ms
SQL2: 3: 0.0 ms
SQL1: 4: 1.0 ms
SQL2: 4: 1.0 ms
SQL1: 5: 2.0 ms
SQL2: 5: 0.0 ms
SQL1: 6: 364.0 ms  *HINT ignored*
SQL2: 6: 1.0 ms
SQL1: 7: 350.0 ms  *HINT ignored*
SQL2: 7: 0.0 ms
SQL1: 8: 351.0 ms  *HINT ignored*
SQL2: 8: 1.0 ms
SQL1: 9: 352.0 ms  *HINT ignored*
SQL2: 9: 0.0 ms
SQL1: 10: 380.0 ms  *HINT ignored*
SQL2: 10: 0.0 ms
SQL1: 11: 379.0 ms  *HINT ignored*
SQL2: 11: 0.0 ms
SQL1: 12: 379.0 ms  *HINT ignored*
SQL2: 12: 0.0 ms
$

Probably, pg_hint_plan_post_parse_analyze() in pg_hint_plan.c is not called for the 6th time in the SQL using the HINT clause, so current_hint_retrieved=false is not executed. https://github.com/ossc-db/pg_hint_plan/blob/PG15/pg_hint_plan.c#L2986

pg_hint_plan.c:
2971    /*
2972     * Retrieve hint string from the current query.
2973     */
2974    static void
2975    pg_hint_plan_post_parse_analyze(ParseState *pstate, Query *query,
2976                                                                    JumbleState *jstate)
2977    {
2978            if (prev_post_parse_analyze_hook)
2979                    prev_post_parse_analyze_hook(pstate, query, jstate);
2980
2981            if (!pg_hint_plan_enable_hint || hint_inhibit_level > 0)
2982                    return;
2983
2984            /* always retrieve hint from the top-level query string */
2985            if (plpgsql_recurse_level == 0)
2986                    current_hint_retrieved = false;   ***6th time NOT CALLED***
2987
2988            /*
2989             * Jumble state is required when hint table is used.  This is the only
2990             * chance to have one already generated in-core.  If it's not the case, no
2991             * use to do the work now and pg_hint_plan_planner() will do the all work.
2992             */
2993            if (jstate)
2994                    get_current_hint_string(query, pstate->p_sourcetext, jstate);
2995    }

It seems that Yugabyte DB developers are also encountering the same problem. https://github.com/yugabyte/yugabyte-db/issues/12741

Since developer of yogabytedb seem to be resolved, is it possible to reflect this in the official's pg_hint_plan? https://github.com/yugabyte/yugabyte-db/commit/c303cebfaa0e73335ca54c173b352c235226e53e#diff-759bfed57e55331cff5c07c3de8b73268ec85205703e127f5ac2cf0974eb4e2d

In PostgreSQL15, I fixed as follows.

diff --git a/pg_hint_plan.c b/pg_hint_plan.c
index 9be70d0..795c6d1 100644
--- a/pg_hint_plan.c
+++ b/pg_hint_plan.c
@@ -528,6 +528,7 @@ static int set_config_int32_option(const char *name, int32 value,
                                                                        GucContext context);
 static int set_config_double_option(const char *name, double value,
                                                                        GucContext context);
+static void pg_hint_ExecutorEnd(QueryDesc *queryDesc);

 /* GUC variables */
 static bool    pg_hint_plan_enable_hint = true;
@@ -586,6 +587,7 @@ static post_parse_analyze_hook_type prev_post_parse_analyze_hook = NULL;
 static planner_hook_type prev_planner = NULL;
 static join_search_hook_type prev_join_search = NULL;
 static set_rel_pathlist_hook_type prev_set_rel_pathlist = NULL;
+static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;

 /* Hold reference to currently active hint */
 static HintState *current_hint_state = NULL;
@@ -730,6 +732,8 @@ _PG_init(void)
        join_search_hook = pg_hint_plan_join_search;
        prev_set_rel_pathlist = set_rel_pathlist_hook;
        set_rel_pathlist_hook = pg_hint_plan_set_rel_pathlist;
+       prev_ExecutorEnd = ExecutorEnd_hook;
+       ExecutorEnd_hook = pg_hint_ExecutorEnd;

        /* setup PL/pgSQL plugin hook */
        var_ptr = (PLpgSQL_plugin **) find_rendezvous_variable("PLpgSQL_plugin");
@@ -751,6 +755,7 @@ _PG_fini(void)
        planner_hook = prev_planner;
        join_search_hook = prev_join_search;
        set_rel_pathlist_hook = prev_set_rel_pathlist;
+       ExecutorEnd_hook = prev_ExecutorEnd;

        /* uninstall PL/pgSQL plugin hook */
        var_ptr = (PLpgSQL_plugin **) find_rendezvous_variable("PLpgSQL_plugin");
@@ -4923,6 +4928,16 @@ void plpgsql_query_erase_callback(ResourceReleasePhase phase,
        }
 }

+static void pg_hint_ExecutorEnd(QueryDesc *queryDesc) {
+
+       if (plpgsql_recurse_level <= 0) {
+               current_hint_retrieved = false;
+       }
+       if (prev_ExecutorEnd)
+               prev_ExecutorEnd(queryDesc);
+       else
+               standard_ExecutorEnd(queryDesc);
+}

 /* include core static functions */
 static void populate_joinrel_with_paths(PlannerInfo *root, RelOptInfo *rel1,

After fixed.

$ java Test3
SQL: /*+ IndexScan(t1 t1_idx) */ select count(*), my_func(1) from t1 where a = ?
1: 12.0 ms
2: 2.0 ms
3: 1.0 ms
4: 2.0 ms
5: 1.0 ms
6: 2.0 ms
7: 1.0 ms
8: 1.0 ms
9: 1.0 ms
10: 1.0 ms
11: 1.0 ms
12: 1.0 ms
$ java Test4
SQL1: /*+ IndexScan(t1 t1_idx) */ select count(*) from t1 where a = ?
SQL2: select 123
SQL1: 1: 14.0 ms
SQL2: 1: 1.0 ms
SQL1: 2: 1.0 ms
SQL2: 2: 0.0 ms
SQL1: 3: 2.0 ms
SQL2: 3: 0.0 ms
SQL1: 4: 1.0 ms
SQL2: 4: 1.0 ms
SQL1: 5: 1.0 ms
SQL2: 5: 0.0 ms
SQL1: 6: 1.0 ms
SQL2: 6: 0.0 ms
SQL1: 7: 1.0 ms
SQL2: 7: 0.0 ms
SQL1: 8: 1.0 ms
SQL2: 8: 0.0 ms
SQL1: 9: 1.0 ms
SQL2: 9: 0.0 ms
SQL1: 10: 1.0 ms
SQL2: 10: 0.0 ms
SQL1: 11: 1.0 ms
SQL2: 11: 0.0 ms
SQL1: 12: 1.0 ms
SQL2: 12: 0.0 ms
$

If there is no problem with this fix, I think you could reflect it. And it seems to be the same for pg_hint_plan14 and earlier versions.

Regards, kfuru

[yamatattsu]

Hi Furutani-san,

Thanks for the report. I'll fix the problem.

@michaelpq @horiguti Since there is the reproducer and the proposal to fix it, I think I can tackle it. I'm going to start to fix it in August. Is it okay?

[michaelpq]

I think I can tackle it. I'm going to start to fix it in August. Is it okay?

If you think you can handle it, that's OK by me!

[yamatattsu]

I think I can tackle it. I'm going to start to fix it in August. Is it okay?

If you think you can handle it, that's OK by me!

Yeah, right. Thanks!

Message ID: @.***>

[jjune235]

@kfuru Is there a workaround for this issue before the patched pg_hint_plan comes out? We are currently using the PG11 version in a Centos 7 environment.

[kfuru]

@jjune235

Is there a workaround for this issue before the patched pg_hint_plan comes out? We are currently using the PG11 version in a Centos 7 environment.

I haven't tried it with CentOS7 and PG11, disabling plan caching for PreparedStatements may help prevent fluctuations in execution plans.

But, these approach may not benefit from the PreparedStatement cache.

Add prepareThreshold=0 to JDBC connection parameters.

jdbc:postgresql://localhost/test?prepareThreshold=0

Or, disable preparedstatement cache for that statement only.

example:
    PreparedStatement pstmt1 = conn.prepareStatement(sql1);
    org.postgresql.PGStatement pgs1 = pstmt1.unwrap(org.postgresql.PGStatement.class);  //ADD
    pgs1.setPrepareThreshold(0);                                                        //ADD

[michaelpq]

@yamatattsu What's your status on this one? I'd like to do a new release by the next two weeks to catch up with PostgreSQL 16 itself, and addressing this issue would be nice.

[yamatattsu]

@michaelpq

What's your status on this one? I'd like to do a new release by the next two weeks to catch up with PostgreSQL 16 itself, and addressing this issue would be nice.

I started to fix that from last week. But I thought that I was going to fix this by mid-October as same as the Japanese document fix. If your deadline to fix the bug is by the end of this week or next week, I don't think I can handle that.

[michaelpq]

I started to fix that from last week. But I thought that I was going to fix this by mid-October as same as the Japanese document fix. If your deadline to fix the bug is by the end of this week or next week, I don't think I can handle that.

Okay, I'll take care of it myself, then.

[michaelpq]

Checked, re-checked and applied a fix to all the branches, taking into account that the compilation of plpgsql_recurse_level is much more precise in PG16 and master.