7 Replies Latest reply on Mar 24, 2015 3:45 PM by shawkins

    Subsequent query fails on cancellation of the first query execution for Oracle based VDB

    pranavk

      Hi,

       

      I am facing an issue related to [TEIID-3275] remaining work should always be canceled - JBoss Issue Tracker. I ran a select all query over an Oracle based Source model deployed inside a VDB which has 3mn records and the maxRows property is set on the prepared statement. With the fix in the above mentioned issue, the records are returned immediately as opposed to before. But when I run the same job a second time using the same connection I get an error as shown in the trace.

       

      When I looked into the issue further I saw that the fix led to a cancel call in JDBCBaseExecution. I created a sample program which executed the same query, and iterated over the resultset. When I issued a statement.cancell() in between this program execution I saw the same issue come up. Hence when I cancel the execution in this scenario, and execute the program on the same connection, this issue comes up.

       

      WARN  [CONNECTOR] Connector worker process failed for atomic-request=yZ/Wz9pIBjUS.18.0.266

      org.teiid.translator.jdbc.JDBCExecutionException: 1013 TEIID11008:TEIID11004 Error executing statement(s): [Prepared Values: [] SQL: SELECT

      g_0."Date", g_0."DayOfMonth", g_0."DayOfYear", g_0."IsLeapYear", g_0."IsWeekday", g_0."IsWeekend", g_0."JulianDay", g_0."JulianWeek", g_0."JulianYear

      ", g_0."MonthName", g_0."MonthNumber", g_0."Quarter", g_0."WeekOfYear", g_0."WeekdayName", g_0."WeekdayNumber", g_0."Year" FROM "TEST1"."1000rowsGtd"g_0]

      at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:131) ~[translator-jdbc-8.10.0.Final.jar:8.10.0.Final]

      at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.execute(ConnectorWorkItem.java:337) ~[teiid-engine-8.10.0.Final.jar:8.10.0.Final]

      at sun.reflect.GeneratedMethodAccessor254.invoke(Unknown Source) ~[na:na]

      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_55]

      at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_55]

      at org.teiid.dqp.internal.datamgr.ConnectorManager$1.invoke(ConnectorManager.java:209) [teiid-engine-8.10.0.Final.jar:8.10.0.Final]

      at com.sun.proxy.$Proxy232.execute(Unknown Source) [na:na]

      at org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:298) [teiid-engine-8.10.0.Final.jar:8.10.0.Final]

      at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:110) [teiid-engine-8.10.0.Final.jar:8.10.0.Final]

      at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:107) [teiid-engine-8.10.0.Final.jar:8.10.0.Final]

      at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_55]

      at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:58) [teiid-engine-8.10.0.Final.jar:8.10.0.Final]

      at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:276) [teiid-engine-8.10.0.Final.jar:8.10.0.Final]

      at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119) [teiid-engine-8.10.0.Final.jar

      :8.10.0.Final]

      at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210) [teiid-engine-8.10.0.Final.jar:8.10.0.Final]

       

      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]

      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]

      at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]

      Caused by: java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation

       

      at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:445) ~[na:na]

      at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:396) ~[na:na]

      at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:879) ~[na:na]

      at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:450) ~[na:na]

      at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) ~[na:na]

      at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531) ~[na:na]

      at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207) ~[na:na]

      at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:884) ~[na:na]

      at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1167) ~[na:na]

      at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1289) ~[na:na]

      at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3584) ~[na:na]

      at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3628) ~[na:na]

      at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1493) ~[na:na]

      at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) ~[commons-dbcp-1.4.jar:1.4]

      at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) ~[commons-dbcp-1.4.jar:1.4]

      at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:123) ~[translator-jdbc-8.10.0.Final.jar:8.10.0.Final]

      ... 17 common frames omitted

      WARN  [PROCESSOR] TEIID30020 Processing exception for request yZ/Wz9pIBjUS.18 'TEIID30504 vds_orc2-orcl-database: 1013 TEIID11008:TEIID1100

      4 Error executing statement(s): [Prepared Values: [] SQL: SELECT g_0."Date", g_0."DayOfMonth", g_0."DayOfYear", g_0."IsLeapYear", g_0."IsWeekday", g_0

      ."IsWeekend", g_0."JulianDay", g_0."JulianWeek", g_0."JulianYear", g_0."MonthName", g_0."MonthNumber", g_0."Quarter", g_0."WeekOfYear", g_0."WkdayNa

      me", g_0."WeekdayNumber", g_0."Year" FROM "TEST1"."1000rowsGtd" g_0]'. Originally TeiidProcessingException 'ORA-01013: user requested cancel of curren

      t operation

      Could you please point me to why this would be coming up?

       

      Thanks,

      Pranav

        • 1. Re: Subsequent query fails on cancellation of the first query execution for Oracle based VDB
          shawkins

          It sounds like you are saying that the connection after a cancel has been issued will throw an exception on a subsequent execution. 

           

          From the perspective of TEIID-3275 the flow is effectively:

           

          One thread executes a large query returning a portion of the results.

          Possibly the same thread (not concurrent to the execution) cancels the query and closes the result set, statement, etc. and returns the connection to the pool

           

          Our expectation would be that the connection should be ready for reuse at that point.  Can other statements be executed against the connection without exception for example?

          • 2. Re: Subsequent query fails on cancellation of the first query execution for Oracle based VDB
            pranavk

            Hi Steve,

             

            [It sounds like you are saying that the ...]

            Yes, that's right.

             

            I understand the flow that you mentioned with respect to TEIID-3275.

             

            [Our expectation would be that the connection should be ready for reuse at that point]

            Yes, that's exactly what should be taking place according to me. Even if the old statement objects made on the connection don't function, the expectation is that the new statement objects made using the pooled connection should work properly. But what's observed is the fact that:

            - execution fails on running the same query again after a cancelled execution.

            - execution fails intermittently when I make a different query on that connection.

            In both cases new Statement objects were being made.

            • 3. Re: Subsequent query fails on cancellation of the first query execution for Oracle based VDB
              shawkins

              I don't see anything for this issue other than recommendations to check any timeout values and to check on the oracle side with trace enabled to see what is happening.  If this is a general oracle issue we could look at disabling the cancel in this circumstance and just calling close.  But it seems like we'd still hit issues when there was a manual cancel.

              • 4. Re: Subsequent query fails on cancellation of the first query execution for Oracle based VDB
                capoorhimanshu

                Hi ,

                 

                I observed one thing when maxrows property is set and we create a Prepared Statement call goes to PreparedStatementRequest class . In generatePlan method at line number 115 base class generatePlan is called and addLimit flag is ignored and passed as false. This is causing complete query to get executed and that's the reason cancel call has to be called and causing this issue. If we do not ignore this parameter , query with limit key word will be generated and specific records will be fetched .In this we do not have to generate the cancel command and things should work fine when we set the max records property , however when user explicitly calls cancel on statement of VDB this issue will still be there.

                 

                Same thing happens when we create a Request type as normal statement i.e statement type is StatementType.STATEMENT not StatementType.PREPARED. In this case call goes to Request class and in this class addLimit property is not ignored hence sql query with limit keyword is generated and runs fine for maxrows property and above mentioned issue do not come even for Oracle.

                 

                 

                Thanks

                Himanshu Kapoor

                • 5. Re: Subsequent query fails on cancellation of the first query execution for Oracle based VDB
                  shawkins

                  > In generatePlan method at line number 115 base class generatePlan is called and addLimit flag is ignored and passed as false.

                   

                  This was effectively discussed on the previous thread.  It is better to use an explicit limit rather than max rows regardless of the statement type.  If a prepared statement is used, then at best we'd have to include a parameterized limit otherwise the plan would not be reusable.  That change has not been pursued (but can be logged as an enhancement), so just the base plan is reused for now.  Even if we make that change, this situation could still occur if the client does not completely read the result set, so we'll need to understand what is going on here as well. 

                  • 6. Re: Subsequent query fails on cancellation of the first query execution for Oracle based VDB
                    shawkins

                    I can get this behavior even outside Teiid, but I'm not sure yet what the most appropriate way to address this is.  Ultimately this is an oracle JDBC bug.  So an issue could be logger there, against IronJacamar possibly to improve the pooling logic in this regard, or we can also pursue adding a parameterized limit, and not using cancel aggressively against oracle.  I'm thinking the last of those is the easiest.