Regarding timeouts

[r0drigor]

1. What versions are you using?

• Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
• process.platform: win32
• process.version: v16.13.1
• process.arch: x64
• oracledb.version: 5.5.0
• oracledb.clientVersion: 21.7.0.0.0

2. Describe the problem.

Several questions here regarding timeouts. I'm running a query that has a certain execution time and I've tested with different callTimeout values.

testing timeout of 5 seconds and execution time of 12 error #0: Error: DPI-1080: connection was closed by ORA-3156

0: milliseconds elapsed = 10016

Always takes around double the time of the timeout to close the connection. Why does this happen?

testing timeout of 5 seconds and execution time of 8 error #0: Error: DPI-1067: call timeout of 5000 ms exceeded with ORA-3156

0: milliseconds elapsed = 8031

The same 5 second timeout now doesn't close the connection, but rather it calls the correct timeout at around the same time of the execution time. Why does this happen?

Error: DPI-1080: connection was closed by ORA-3156

I'm still getting the record inserted into the table when I get this error, and it seems like it shouldn't work this way (autoCommit = true).

3. Include a runnable Node.js script that shows the problem.

Node.js script:

const oracledb = require('oracledb');

async function run() {
  let pool;
  let start;
  let duration;
  let timeout = 5;
  let executionTime = 12;
  console.log(`testing timeout of ${timeout} seconds and execution time of ${executionTime}`);

  try {
    oracledb.autoCommit = true;
    pool = await oracledb.createPool({
      user: 'user',
      password: 'password',  // mypw contains the hr schema password
      connectString: '<connectionString>/TEST',
      poolMax: 1, // maximum size of the pool
      poolMin: 0, // let the pool shrink completely
      poolIncrement: 1, // only grow the pool by one connection at a time
      poolTimeout: 0  // never terminate idle connections
    });

    for (let i = 0; i < 5; i++) {
      let connection;
      try {
        connection = await pool.getConnection();
        connection.callTimeout = timeout * 1000;
        start = Date.now();
        result = await connection.execute("BEGIN DBMS_SESSION.SLEEP(${executionTime}); INSERT INTO TEST.STARWARS(MOVIE, YEAR) VALUES('Episode VI - The Return of the Jedi', '1983'); END;");
        // connection.commit();
        console.log("Result is:", result);
      } catch (err) {
        // connection.rollback();
        console.log(`error #${i}: ${err}`);
        // throw (err);
      } finally {
        duration = Date.now() - start;
        if (connection) {
          try {
            await connection.close(); // Put the connection back in the pool
          } catch (err) {
            // throw (err);
          }
        }
        console.log(`#${i}: milliseconds elapsed = ${Math.floor(duration)}`);
      }
    }

  } catch (err) {
    console.error(err.message);
  } finally {
    await pool.close();
  }
}

run();

SQL script:

CREATE SCHEMA TEST

CREATE TABLE TEST.STARWARS 
   (    "MOVIE" VARCHAR2(200 BYTE), 
    "YEAR" VARCHAR2(20 BYTE), 
    "INSERT_DATE" TIMESTAMP (6) DEFAULT SYSDATE
   ) SEGMENT CREATION IMMEDIATE 

[oliveirabc]

Hi,

I'm observing the same thing with:

Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
process.platform: linux
process.version: v18.12.1
process.arch: x64
oracledb.versionString: 5.5.0
oracledb.oracleClientVersionString: 21.8.0.0.0

Just a note that I'm not really sure about your test: Did you observe records being committed for all the errors or just some? On my tests, I did observe records committed for both DPI-1080 and DPI-1067.

Also, and for comparison, I've done some java testing with the JDBC driver ojdbc8.jar with the same database and statements and:

• did not observe records committed in case of timeout
• always returns the same timeout error:

  
  (72000/1013) ORA-01013: user requested cancel of current operation
  ORA-06512: at "SYS.DBMS_SESSION", line 435
  ORA-06512: at line 1

[oliveirabc]

Just noticed that there's a lot more log if DPI_DEBUG_LEVEL=100 Here's the log from r0drigor code when it returns:

error #0: Error: DPI-1067: call timeout of 5000 ms exceeded with ORA-3156
#0: milliseconds elapsed = 8031

while testing timeout of 5 seconds and execution time of 8

ODPI [00035] 2023-01-04 14:49:37.169: fn end dpiPool_acquireConnection(0x403400c980) -> 0
ODPI [00025] 2023-01-04 14:49:37.170: fn start dpiConn_setCallTimeout(0x403c00c980)
ODPI [00025] 2023-01-04 14:49:37.172: fn end dpiConn_setCallTimeout(0x403c00c980) -> 0
ODPI [00036] 2023-01-04 14:49:37.175: fn start dpiConn_prepareStmt(0x403c00c980)
ODPI [00036] 2023-01-04 14:49:37.176: allocated 3216 bytes at 0x4044000b60 (allocate error buffer)
ODPI [00036] 2023-01-04 14:49:37.176: allocated 176 bytes at 0x404400c980 (allocate handle)
ODPI [00036] 2023-01-04 14:49:37.181: fn end dpiConn_prepareStmt(0x403c00c980) -> 0
ODPI [00036] 2023-01-04 14:49:37.181: fn start dpiStmt_getInfo(0x404400c980)
ODPI [00036] 2023-01-04 14:49:37.181: fn end dpiStmt_getInfo(0x404400c980) -> 0
ODPI [00036] 2023-01-04 14:49:37.181: fn start dpiStmt_execute(0x404400c980) ###### Expected it to stop at 49:42 (5 seconds timeout) not 49:45
ODPI [00036] 2023-01-04 14:49:45.230: fn end dpiStmt_execute(0x404400c980) -> -1
ODPI [00025] 2023-01-04 14:49:45.237: fn start dpiStmt_release(0x404400c980)
ODPI [00025] 2023-01-04 14:49:45.241: freed ptr at 0x404400c980
ODPI [00025] 2023-01-04 14:49:45.241: fn end dpiStmt_release(0x404400c980) -> 0
error #0: Error: DPI-1067: call timeout of 5000 ms exceeded with ORA-3156
ODPI [00037] 2023-01-04 14:49:45.258: fn start dpiConn_close(0x403c00c980)

[cjbj]

Always takes around double the time of the timeout to close the connection. Why does this happen?

From the doc:

After a timeout occurs, node-oracledb attempts to clean up the internal connection state. The cleanup is allowed to take another callTimeout milliseconds.

[oliveirabc]

Hi,

I get it, it is allowed to take another timeout period to do the cleanup. But why does it take the whole timeout to complete the cleanup? And more, why does it take all timeout, even if I increase it?! That, I don't get it. Shouldn't it take the same time to cleanup every time, independently of the timeout?

[stale[bot]]

This issue has been automatically marked as inactive because it has not been updated recently. It will be closed if no further activity occurs. Thank you for your contributions.

[stale[bot]]

This issue has been automatically closed because it has not been updated for a month.