Обсуждение: Can not cancel a call to a function that has opened a refcursor

Поиск
Список
Период
Сортировка

Can not cancel a call to a function that has opened a refcursor

От
Mike Knowsley
Дата:
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.
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



Re: Can not cancel a call to a function that has opened a refcursor

От
Dave Cramer
Дата:


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.
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 

Re: Can not cancel a call to a function that has opened a refcursor

От
Tom Lane
Дата:
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
isreturning. 

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

Re: Can not cancel a call to a function that has opened a refcursor

От
Dave Cramer
Дата:


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

Re: Can not cancel a call to a function that has opened a refcursor

От
Mike Knowsley
Дата:
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