pg.ddx.io pgsql-bugs@postgresql.org mailing list archive
help / color / mirror / Atom feedCan not cancel a call to a function that has opened a refcursor
5+ messages / 3 participants
[nested] [flat]
* Can not cancel a call to a function that has opened a refcursor
@ 2021-08-05 02:45 Mike Knowsley <mike.knowsley@bidorbuy.co.za>
0 siblings, 2 replies; 5+ messages in thread
From: Mike Knowsley @ 2021-08-05 02:45 UTC (permalink / raw)
To: pgsql-bugs@lists.postgresql.org
Synopsis
A 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 client
pg_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.
https://github.com/pgjdbc/pgjdbc/issues/2222 <https://github.com/pgjdbc/pgjdbc/issues/2222;
And testing using pg_cancel_backend with no JDBC involvement shows the same issue.
Test environment
Mac OSX development
Postgres JDBC Driver Version: 43.3.8
Oracle jdk 1.8.0_231Mac OSX Catalina 10.15.7
Official Postgres Image from hub.docker.com
PostgreSQL 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-bit
As 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 regards
Mike Knowsley
bidorbuy
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Can not cancel a call to a function that has opened a refcursor
@ 2021-08-05 13:10 Dave Cramer <davecramer@postgres.rocks>
parent: Mike Knowsley <mike.knowsley@bidorbuy.co.za>
1 sibling, 0 replies; 5+ messages in thread
From: Dave Cramer @ 2021-08-05 13:10 UTC (permalink / raw)
To: Mike Knowsley <mike.knowsley@bidorbuy.co.za>; +Cc: pgsql-bugs@lists.postgresql.org
On Thu, 5 Aug 2021 at 04:49, Mike Knowsley <mike.knowsley@bidorbuy.co.za>
wrote:
> *Synopsis*
>
> A 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 client
> pg_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.
> https://github.com/pgjdbc/pgjdbc/issues/2222
> And testing using pg_cancel_backend with no JDBC involvement shows the
> same issue.
>
>
> *Test environment*
>
> Mac OSX development
> Postgres JDBC Driver Version: 43.3.8
> Oracle jdk 1.8.0_231Mac OSX Catalina 10.15.7
> Official Postgres Image from hub.docker.com
> PostgreSQL 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-bit
>
>
> As 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 regards
> Mike Knowsley
> bidorbuy
>
>
>
>
I think this is just a protocol issue. The backend isn't looking for cancel
requests at this point.
Dave
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Can not cancel a call to a function that has opened a refcursor
@ 2021-08-05 15:19 Tom Lane <tgl@sss.pgh.pa.us>
parent: Mike Knowsley <mike.knowsley@bidorbuy.co.za>
1 sibling, 2 replies; 5+ messages in thread
From: Tom Lane @ 2021-08-05 15:19 UTC (permalink / raw)
To: Mike Knowsley <mike.knowsley@bidorbuy.co.za>; +Cc: pgsql-bugs@lists.postgresql.org
Mike Knowsley <mike.knowsley@bidorbuy.co.za> writes:
> A request to cancel a call to a function does not cancel the function if the function has opened a refcursor which it is returning.
As far as I can see, there is no such bug; you're just misunderstanding
when the query referenced by the cursor will execute. The function
test_delay_in_refcursor() sets up the cursor and returns basically
immediately (certainly in much less than 2 seconds), so the timeout
you have in the JDBC code will never fire. The expected pg_sleep(5)
won't execute till you try to fetch something from the refcursor.
Trying this manually in psql, I get
...
CREATE FUNCTION
regression=# \timing
Timing is on.
regression=# begin;
BEGIN
Time: 0.306 ms
regression=*# select test_delay_in_refcursor();
test_delay_in_refcursor
-------------------------
<unnamed portal 1>
(1 row)
Time: 0.314 ms
regression=*# fetch from "<unnamed portal 1>";
?column? | pg_sleep
----------+----------
test |
(1 row)
Time: 5005.475 ms (00:05.005)
I could have canceled the FETCH (and doing so works);
but I'm way too old and slow to cancel the submillisecond
setup step.
regards, tom lane
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Can not cancel a call to a function that has opened a refcursor
@ 2021-08-05 15:42 Dave Cramer <davecramer@postgres.rocks>
parent: Tom Lane <tgl@sss.pgh.pa.us>
1 sibling, 0 replies; 5+ messages in thread
From: Dave Cramer @ 2021-08-05 15:42 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Mike Knowsley <mike.knowsley@bidorbuy.co.za>; pgsql-bugs@lists.postgresql.org
On Thu, 5 Aug 2021 at 11:19, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Mike Knowsley <mike.knowsley@bidorbuy.co.za> writes:
> > A request to cancel a call to a function does not cancel the function if
> the function has opened a refcursor which it is returning.
>
> As far as I can see, there is no such bug; you're just misunderstanding
> when the query referenced by the cursor will execute. The function
> test_delay_in_refcursor() sets up the cursor and returns basically
> immediately (certainly in much less than 2 seconds), so the timeout
> you have in the JDBC code will never fire. The expected pg_sleep(5)
> won't execute till you try to fetch something from the refcursor.
>
> Trying this manually in psql, I get
>
> ...
> CREATE FUNCTION
> regression=# \timing
> Timing is on.
> regression=# begin;
> BEGIN
> Time: 0.306 ms
> regression=*# select test_delay_in_refcursor();
> test_delay_in_refcursor
> -------------------------
> <unnamed portal 1>
> (1 row)
>
> Time: 0.314 ms
> regression=*# fetch from "<unnamed portal 1>";
> ?column? | pg_sleep
> ----------+----------
> test |
> (1 row)
>
> Time: 5005.475 ms (00:05.005)
>
> I could have canceled the FETCH (and doing so works);
> but I'm way too old and slow to cancel the submillisecond
> setup step.
>
>
Ya, that was the other idea I had.
Dave
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Can not cancel a call to a function that has opened a refcursor
@ 2021-08-05 22:52 Mike Knowsley <mike.knowsley@bidorbuy.co.za>
parent: Tom Lane <tgl@sss.pgh.pa.us>
1 sibling, 0 replies; 5+ messages in thread
From: Mike Knowsley @ 2021-08-05 22:52 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; davecramer@postgres.rocks; +Cc: pgsql-bugs@lists.postgresql.org
Thanks for the quick response Tom and Dave,
I did wonder if it was something like what you have described.
Although the JDBC lib appears to mask this from my test code.
In the first test case below (test1).
The plsql function has a 5 second pg_sleep delay on the select into the refcursor.
The Java logic traces before it calls callableStatement.execute() then immediately after the callableStatement.execute() returns but before the call to get the ResultSet.
The trace shows the JDBC callableStatement.execute() does not return for the functions full 5 second of the pg_sleep delay in the select into the refcursor. In that time the statements 2 second timeout does not interrupt this call.
So Postgres may return the refcursor almost immediately as you say, but the JDBC CallableStament.execute() doesn’t return immediately, it only returns when the query has found results.
Maybe not a bug but my essential problem remains. A function with a slow select into a refcursor can not be timed-out or cancelled.
BTW:
The second test case below (test7), shows a possible workaround for my use-case.
I alter the initial query to select into a temp table then select the temp table into the the open refcursor.
The timeout/cancel does work if it occurs during the (potentially slow) initial select into the temp table.
thanks again
Mike Knowsley
bidorbuy
---------
create or replace function test_delay_in_refcursor()
returns refcursor
as $$
declare
cursorReference refcursor;
begin
open cursorReference for
select 'test', pg_sleep(20);
return cursorReference;
end;
$$ language plpgsql;
/**
*/
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) {}
}
}
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
————
create or replace function test_delay_with_temp_table()
returns refcursor
as $$
declare
cursorReference refcursor;
begin
create temp table results as
select test from (
select 'test' as test, pg_sleep(5)
) x;
open cursorReference for
select * from results;
return cursorReference;
end;
$$ language plpgsql;
private static void test7() {
log("------ test7 --------");
Connection connection = null;
CallableStatement callableStatement = null;
ResultSet resultSet = null;
try {
connection = DriverManager.getConnection(CONNECTION_URL);
connection.setAutoCommit(false);
callableStatement = connection.prepareCall("{ ? = call test_delay_with_temp_table }");
callableStatement.setQueryTimeout(2);
callableStatement.registerOutParameter(1, Types.REF_CURSOR);
log("test7 callableStatement.execute() test_delay_with_temp_table with 2 second timeout");
callableStatement.execute();
log("test7 callableStatement.execute() returned - not cancelled");
resultSet = (ResultSet) callableStatement.getObject(1);
}
catch(Exception e) {
if(e.getMessage().toLowerCase().contains("canceling statement")) {
log("test7 callableStatement cancelled");
}
else {
log("test7 Exception : " + e.getMessage());
}
}
finally {
try {
if(resultSet != null) resultSet.close();
if(callableStatement != null) callableStatement.close();
if(connection != null) connection.close();
}
catch(Exception e2) {}
}
}
2021-08-06T10:22:48.076 main ------ test7 --------
2021-08-06T10:22:48.199 main test7 callableStatement.execute() test_delay_with_temp_table with 2 second timeout
2021-08-06T10:22:50.221 main test7 callableStatement cancelled
J/J 06/08/21 10:22:50 Completed job!
> On 6/08/2021, at 3:19 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Mike Knowsley <mike.knowsley@bidorbuy.co.za> writes:
>> A request to cancel a call to a function does not cancel the function if the function has opened a refcursor which it is returning.
>
> As far as I can see, there is no such bug; you're just misunderstanding
> when the query referenced by the cursor will execute. The function
> test_delay_in_refcursor() sets up the cursor and returns basically
> immediately (certainly in much less than 2 seconds), so the timeout
> you have in the JDBC code will never fire. The expected pg_sleep(5)
> won't execute till you try to fetch something from the refcursor.
>
> Trying this manually in psql, I get
>
> ...
> CREATE FUNCTION
> regression=# \timing
> Timing is on.
> regression=# begin;
> BEGIN
> Time: 0.306 ms
> regression=*# select test_delay_in_refcursor();
> test_delay_in_refcursor
> -------------------------
> <unnamed portal 1>
> (1 row)
>
> Time: 0.314 ms
> regression=*# fetch from "<unnamed portal 1>";
> ?column? | pg_sleep
> ----------+----------
> test |
> (1 row)
>
> Time: 5005.475 ms (00:05.005)
>
> I could have canceled the FETCH (and doing so works);
> but I'm way too old and slow to cancel the submillisecond
> setup step.
>
> regards, tom lane
^ permalink raw reply [nested|flat] 5+ messages in thread
end of thread, other threads:[~2021-08-05 22:52 UTC | newest]
Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-08-05 02:45 Can not cancel a call to a function that has opened a refcursor Mike Knowsley <mike.knowsley@bidorbuy.co.za>
2021-08-05 13:10 ` Dave Cramer <davecramer@postgres.rocks>
2021-08-05 15:19 ` Tom Lane <tgl@sss.pgh.pa.us>
2021-08-05 15:42 ` Dave Cramer <davecramer@postgres.rocks>
2021-08-05 22:52 ` Mike Knowsley <mike.knowsley@bidorbuy.co.za>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox