Menu ▾ ▴

#351 Query Time out not working as expected

JDBC
closed
John Eberhard
None
7
2021-09-23
2014-05-27
Anup
No

As per the JDBC Documentation Statement.setQueryTimeout(int) is supposed to timeout a running statement after a prescribed number of seconds as set using the setQueryTimeOut method.

However as per the IBM PTF (http://www-912.ibm.com/systems/electronic/support/a_dir/as4ptf.nsf/ALLPTFS/SI44506) this doesn't work for executeQuery and executeUpdate methods of the Statement class. For making it work for executeQuery and executeUpdate a separate property has to be set while creating the connection (query timeout mechanism= cancel) in addition to the setQueryTimeout(int) call.

We have a program where we are creating a CallableStatement for running a stored procedure on the AS400. Since we wanted to timeout the statement after a specified number of seconds , we followed what has been outlined in the PTF- Since our version is 7.8 the fix is already there. (We checked the source code of the jt400.jar to confirm)

This is the behavior we are seeing

  • AS400JDBCQueryCancelThread gets created. It cancels the statement after the time out expires.
    -However we see that the original statement call is blocked for a long time after the cancel and then throws an error saying the statement has been cancelled.

This doesn't really serve the purpose of time out as the call is still blocked for a considerable time after the timeout period has expired. How do we achieve that?

Version- 7.8, Java version- Java 7

Discussion

  • John Eberhard

    John Eberhard - 2014-05-27
    • status: open --> closed
    • assigned_to: John Eberhard
     

  • John Eberhard

    John Eberhard - 2014-05-27

    If you are seeing that the AS400JDBCQueryCancelThread is sending the request to cancel the job to the server, then the client is working as designed. You will need to work with IBM service to determine why the cancel is not taking effect.

    If the QZDASOINIT server job is doing processing below the TIMI, then the cancel will not be processed until the job returns to above the TIMI.

     

    • Anup

      Anup - 2014-05-28

      John. The job is cancelled as well. Only problem I see is that the original executeQuery call is not coming back immediately. It takes quite a while for it to come back and report that the query has been cancelled and throw an exception.

      What is TIMI? Can you elaborate on that?

       

  • John Eberhard

    John Eberhard - 2014-05-28

    To learn more about TIMI, just google IBM i TIMI. You will get lots of hits.

     

  • Nitin Viswanath

    Nitin Viswanath - 2021-09-22

    I'm facing the similar problem described here, When the Object is locked in IBM System and the cancel is tested, then we see the sql statement processing is ended immediately and appropriate error is thrown based on the set query timeout value.

    But while testing with any long running query (without locking object), we see cancel is being issued but it waits until the query completes execution and then throws Operation cancelled error.

    May I know what could be the issue here ? And why is the behaviour different with object locked versus long running query ?

    JT400 Version : 10.6, Java 8

     

    Last edit: Nitin Viswanath 2021-09-22

  • John Eberhard

    John Eberhard - 2021-09-22

    As I mentioned above, the issue is on the IBM i where the system is not processing the cancel quickly enough. I would suspect a lot of processing is occurring below the TIMI and the cancel is not handled until that processing is completed.

     

  • Nitin Viswanath

    Nitin Viswanath - 2021-09-22

    Okay, Thanks for replying John. I also observed cases where the QueryCancelThread is unable to issue cancel because of an exception highlighted below. Any comments on why it is unable to issue cancel in this case?

    Wed Sep 22 17:25:07:846 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : Preparing [select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP1 UNION ALL select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP2 UNION ALL select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP3].
    Wed Sep 22 17:25:08:033 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : Prepared STMT0005, SQL Statement -->[select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP1 UNION ALL select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP2 UNION ALL select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP3].
    Wed Sep 22 17:25:08:034 EDT 2021 as400@set..: PreparedStatementImpl STMT0005 (1238516971) :     Query timeout = "25".
    Wed Sep 22 17:25:08:035 EDT 2021 as400: QueryCancelThread Thread[Thread-292,5,Pooled Threads] (697562004) : run().
    Wed Sep 22 17:25:08:418 EDT 2021 as400: Cursor CRSR0005 (1671565857) open.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : getBlockingFactor(): Blocking -- blockCriteria_=2 and isForFetchOnly.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : getBlockingFactor: blockFactor is 2978.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: ResultSet CRSR0005 (2142796845) open. Parent: PreparedStatementImpl STMT0005 (1238516971) .
    Wed Sep 22 17:25:08:418 EDT 2021 as400@AS400JDBCResultSet: ResultSet CRSR0005 (2142796845) : Conncurrency = "1007".
    Wed Sep 22 17:25:08:418 EDT 2021 as400@AS400JDBCResultSet: ResultSet CRSR0005 (2142796845) : Fetch direction = "1000".
    Wed Sep 22 17:25:08:418 EDT 2021 as400@AS400JDBCResultSet: ResultSet CRSR0005 (2142796845) : Fetch size = "0".
    Wed Sep 22 17:25:08:418 EDT 2021 as400@AS400JDBCResultSet: ResultSet CRSR0005 (2142796845) : Max rows = "0".
    Wed Sep 22 17:25:08:418 EDT 2021 as400@AS400JDBCResultSet: ResultSet CRSR0005 (2142796845) : Type = "1003".
    Wed Sep 22 17:25:08:418 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : Executed STMT0005, SQL Statement --> [select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP1 UNION ALL select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP2 UNION ALL select SHPNUM, SHPTYP, LBLTYP, SVCCDE from PKGPFYYP3].
    Wed Sep 22 17:25:08:418 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : Update count = -1.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : Result set = true.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : Number of result sets = 0.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: PreparedStatementImpl STMT0005 (1238516971) : Row count estimate = 2978.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: QueryCancelThread Thread[Thread-292,5,Pooled Threads] (697562004) : Exception java.lang.InterruptedException: sleep interrupted caught.
    Wed Sep 22 17:25:08:418 EDT 2021 as400: QueryCancelThread Thread[Thread-292,5,Pooled Threads] (697562004) : Thread done.**
    Wed Sep 22 17:25:08:475 EDT 2021 as400: ConnectionImpl TST3 (392468936) : Fetching a block of data from the system 0,0.

     

    Last edit: Nitin Viswanath 2021-09-23

  • John Eberhard

    John Eberhard - 2021-09-23

    By definition

    void setQueryTimeout(int seconds)
    throws SQLException

    Sets the number of seconds the driver will wait for a Statement object to execute to the given number of seconds. By default there is no limit on the amount of time allowed for a running statement to complete. If the limit is exceeded, an SQLTimeoutException is thrown. A JDBC driver must apply this limit to the execute, executeQuery and executeUpdate methods.

    In your case, the execute portion has completed and data is now being fetched from the system.

     

Log in to post a comment.

MongoDB Logo MongoDB