Re: Can not cancel a call to a function that has opened a refcursor - Mailing list pgsql-bugs
From | Dave Cramer |
---|---|
Subject | Re: Can not cancel a call to a function that has opened a refcursor |
Date | |
Msg-id | CADK3HHLFge1agBkDZuWu4w2eaO4MmM6pCr9=UVNUrjfpm2rb4Q@mail.gmail.com Whole thread Raw |
In response to | Can not cancel a call to a function that has opened a refcursor (Mike Knowsley <mike.knowsley@bidorbuy.co.za>) |
List | pgsql-bugs |
On Thu, 5 Aug 2021 at 04:49, Mike Knowsley <mike.knowsley@bidorbuy.co.za> wrote:
SynopsisA request to cancel a call to a function does not cancel the function if the function has opened a refcursor which it is returning.The cancel request does not result in an error, but the function is not cancelled as expected, and continues until it returns normally.If the cancel is issued before the function opens the refcursor, the request does cancel the function as expected.I’m not sure if this is a bug or expected behaviour. Although I didn’t expect it. And it effectively means timeout and cancel can not be used to protect against long running queries using a refcursor.The essential issue is the same in these 3 test scenarios;1) Calling the function via JDBC CallableStatement.execute with a timeout set.The timeout does not cancel the function if it has opened a refcursor.It does cancel the function if the function has not yet opened a refcursor.2) Calling the function via JDBC CallableStatement.execute, with a separate java ’Timeout/TimeoutTask' thread issuing an explicit CallableStatement.cancel().The cancel request returns without error but does not cancel the function if it has opened a refcursor.It does cancel the function if the function has not yet opened a refcursor.3) calling select pg_cancel_backend(<pid>);From a separate psql clientpg_cancel_backend() returns without error but does not cancel the function if it has opened a refcursor.It does cancel the function if the function has not yet opened a refcursor.I initially thought this was Postgres JDBC client issue, but Dave Cramer said the JDBC client does send the cancel request to the Postgres server but it has no obvious effect.And testing using pg_cancel_backend with no JDBC involvement shows the same issue.Test environmentMac OSX developmentPostgres JDBC Driver Version: 43.3.8Oracle jdk 1.8.0_231Mac OSX Catalina 10.15.7Official Postgres Image from hub.docker.comPostgreSQL 12.3 (Debian 12.3-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bitAs an aside: Our production environment using AWS Aurora/Postgres seems to have the same issue.Test code
- psql function test_delay_in_refcursor
- psql function test_delay_before_refcursor
- java test class CallableStatementCancelTest
- CallableStatementCancelTest execution trace
-- delay of 10 seconds in the refcursor select create or replace function test_delay_in_refcursor() returns refcursor as $$ declare cursorReference refcursor; begin open cursorReference for select 'test', pg_sleep(5); return cursorReference; end; $$ language plpgsql; -- delay of 10 seconds in a select into (before opening the refcursor) create or replace function test_delay_before_refcursor() returns refcursor as $$ declare cursorReference refcursor; testResult varchar(100); begin select pg_sleep(5) into testResult; open cursorReference for select 'test'; return cursorReference; end; $$ language plpgsql;
import java.sql.CallableStatement; import java.sql.Connection; import java.sql.DriverManager; import java.sql.ResultSet; import java.sql.Types; import java.time.LocalDateTime; import java.util.Timer; import java.util.TimerTask; /** */ public class CallableStatementCancelTest { private static String CONNECTION_URL = "jdbc:postgresql://127.0.0.1:5432/xxx?user=xxx&password=xxx"; /** */ public static void main(String[] aArgs) { test1(); test2(); test3(); test4(); } /** */ private static void test1() { log("------ test1 --------"); Connection connection = null; CallableStatement callableStatement = null; ResultSet resultSet = null; try { connection = DriverManager.getConnection(CONNECTION_URL); connection.setAutoCommit(false); callableStatement = connection.prepareCall("{ ? = call test_delay_in_refcursor }"); callableStatement.setQueryTimeout(2); callableStatement.registerOutParameter(1, Types.REF_CURSOR); log("test1 callableStatement.execute() test_delay_in_refcursor with 2 second timeout"); callableStatement.execute(); log("test1 callableStatement.execute() returned - not cancelled"); resultSet = (ResultSet) callableStatement.getObject(1); } catch(Exception e) { if(e.getMessage().toLowerCase().contains("canceling statement")) { log("test1 callableStatement cancelled"); } else { log("test1 Exception : " + e.getMessage()); } } finally { try { if(resultSet != null) resultSet.close(); if(callableStatement != null) callableStatement.close(); if(connection != null) connection.close(); } catch(Exception e2) {} } } /** */ private static void test2() { log("------ test2 --------"); Connection connection = null; CallableStatement callableStatement = null; ResultSet resultSet = null; try { connection = DriverManager.getConnection(CONNECTION_URL); connection.setAutoCommit(false); callableStatement = connection.prepareCall("{ ? = call test_delay_before_refcursor }"); callableStatement.setQueryTimeout(2); callableStatement.registerOutParameter(1, Types.REF_CURSOR); log("test2 callableStatement.execute() test_delay_before_refcursor with 2 second timeout"); callableStatement.execute(); log("test2 callableStatement.execute() returned - not cancelled"); resultSet = (ResultSet) callableStatement.getObject(1); } catch(Exception e) { if(e.getMessage().toLowerCase().contains("canceling statement")) { log("test2 callableStatement cancelled"); } else { log("test2 Exception : " + e.getMessage()); } } finally { try { if(resultSet != null) resultSet.close(); if(callableStatement != null) callableStatement.close(); if(connection != null) connection.close(); } catch(Exception e2) {} } } /** */ private static void test3() { log("------ test3 --------"); Connection connection = null; CallableStatement callableStatement = null; ResultSet resultSet = null; Timer timer = null; try { connection = DriverManager.getConnection(CONNECTION_URL); connection.setAutoCommit(false); callableStatement = connection.prepareCall("{ ? = call test_delay_in_refcursor }"); callableStatement.registerOutParameter(1, Types.REF_CURSOR); log("test3 callableStatement.execute() test_delay_in_refcursor with Timer set to call CallableStatement.cancel() after 2 seconds"); final CallableStatement finalCallableStatement = callableStatement; timer = new Timer("TimerThread"); timer.schedule( new TimerTask() { public void run() { try { if(!finalCallableStatement.isClosed()) { log("test3 Timer calling finalCallableStatement.cancel()"); finalCallableStatement.cancel(); log("test3 Timer completed finalCallableStatement.cancel()"); } } catch(Exception e) { log("test3 TimerTask run exception " + e.getMessage()); } finally { cancel(); } } }, 2000 ); callableStatement.execute(); log("test3 callableStatement.execute() returned - not cancelled"); resultSet = (ResultSet) callableStatement.getObject(1); } catch(Exception e) { if(e.getMessage().toLowerCase().contains("canceling statement")) { log("test3 callableStatement cancelled"); } else { log("test3 Exception : " + e.getMessage()); } } finally { try { if(timer != null) { timer.cancel(); } if(resultSet != null) resultSet.close(); if(callableStatement != null) callableStatement.close(); if(connection != null) connection.close(); } catch(Exception e2) {} } } /** */ private static void test4() { log("------ test4 --------"); Connection connection = null; CallableStatement callableStatement = null; ResultSet resultSet = null; Timer timer = null; try { connection = DriverManager.getConnection(CONNECTION_URL); connection.setAutoCommit(false); callableStatement = connection.prepareCall("{ ? = call test_delay_before_refcursor }"); callableStatement.registerOutParameter(1, Types.REF_CURSOR); log("test4 callableStatement.execute() test_delay_before_refcursor with Timer set to call callableStatement.cancel() after 2 seconds"); final CallableStatement finalCallableStatement = callableStatement; timer = new Timer("TimerThread"); timer.schedule( new TimerTask() { public void run() { try { if(!finalCallableStatement.isClosed()) { log("test4 Timer calling finalCallableStatement.cancel()"); finalCallableStatement.cancel(); log("test4 Timer completed finalCallableStatement.cancel()"); } } catch(Exception e) { log("test4 TimerTask run exception " + e.getMessage()); } finally { cancel(); } } }, 2000 ); callableStatement.execute(); log("test4 callableStatement.execute() returned - not cancelled"); resultSet = (ResultSet) callableStatement.getObject(1); } catch(Exception e) { if(e.getMessage().toLowerCase().contains("canceling statement")) { log("test4 callableStatement cancelled"); } else { log("test4 Exception : " + e.getMessage()); } } finally { try { if(timer != null) { timer.cancel(); } if(resultSet != null) resultSet.close(); if(callableStatement != null) callableStatement.close(); if(connection != null) connection.close(); } catch(Exception e2) {} } } /** */ private static void log(String aMessage) { System.out.println(LocalDateTime.now() + " " + Thread.currentThread().getName() + " " + aMessage); } }
$ runide.sh com.xxx.CallableStatementCancelTest 2021-08-04T16:03:59.940 main ------ test1 -------- 2021-08-04T16:04:00.058 main test1 callableStatement.execute() test_delay_in_refcursor with 2 second timeout 2021-08-04T16:04:05.074 main test1 callableStatement.execute() returned - not cancelled 2021-08-04T16:04:05.075 main ------ test2 -------- 2021-08-04T16:04:05.089 main test2 callableStatement.execute() test_delay_before_refcursor with 2 second timeout 2021-08-04T16:04:07.101 main test2 callableStatement cancelled 2021-08-04T16:04:07.101 main ------ test3 -------- 2021-08-04T16:04:07.115 main test3 callableStatement.execute() test_delay_in_refcursor with Timer set to call CallableStatement.cancel() after 2 seconds 2021-08-04T16:04:09.119 TimerThread test3 Timer calling finalCallableStatement.cancel() 2021-08-04T16:04:09.119 TimerThread test3 Timer completed finalCallableStatement.cancel() 2021-08-04T16:04:12.124 main test3 callableStatement.execute() returned - not cancelled 2021-08-04T16:04:12.124 main ------ test4 -------- 2021-08-04T16:04:12.139 main test4 callableStatement.execute() test_delay_before_refcursor with Timer set to call callableStatement.cancel() after 2 seconds 2021-08-04T16:04:14.151 TimerThread test4 Timer calling finalCallableStatement.cancel() 2021-08-04T16:04:14.155 TimerThread test4 Timer completed finalCallableStatement.cancel() 2021-08-04T16:04:14.155 main test4 callableStatement cancelled
kind regardsMike Knowsleybidorbuy
I think this is just a protocol issue. The backend isn't looking for cancel requests at this point.
Dave
pgsql-bugs by date: