5 Replies Latest reply on Feb 27, 2013 11:46 AM by Steven Hawkins

    Long running query fails on Teiid 8.1

    Shantanu D Newbie

      Hi,

       

      In our project enviorment we are using Teiid 8.1 and trying to fetch around 1,00,000 records from the table.

      We are using XA transaction for the data source and as per my understanding XA transaction recovery runs every 2 mins.

       

      There are two scenarios where I am facing issues -

       

      1) When we try to run a get query to fetch 100000 records but in the batches of 1000 then teiid issues the CANCEL command after roughly 2 mins . This I am able to fix by increasing the PeriodicRcovery timing using 'com.arjuna.ats.arjuna.recovery.periodicRecoveryPeriod' property.

       

      2) When we try to run multiple concurrent requests to get the same results as above, Teiid issues the CANCEL command on the statement and we are not able to solve this issue by increasing the Periodic Recovery timings.

       

      I am not really sure if this has something to do with the XA transanction recovery or why Teiid is trying to cancel the statement. Can you please provide me with any pointers?

       

      Thanks,

      Shantanu

       

      Please see the logs below where we are trying to -

       

      ---------------------------------

       

      09:13:25,741 FINE  [org.teiid.client.sockets] (http--0.0.0.0-8080-2) read asynch message:3757

      09:13:25,741 FINE  [org.teiid.client.sockets] (http--0.0.0.0-8080-2) read asynch message:3757

      09:13:33,163 FINE  [org.teiid.jdbc] (Thread-91) Statement closed successfully.

      09:13:33,163 FINE  [org.teiid.jdbc] (Thread-91) Statement closed successfully.

      09:13:33,163 FINEST [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://localhost:31000;ApplicationName=openworks_user=user.connection] (Thread-91) release_connection           __EclipseLinkSessionId__: 236231130

      09:13:33,163 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://localhost:31000;ApplicationName=openworks_user=user.transaction] (Thread-91) release_unit_of_work           __EclipseLinkSessionId__: 532442311

      09:13:33,163 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://localhost:31000;ApplicationName=openworks_user=user.connection] (Thread-91) client_released           __EclipseLinkSessionId__: 382584547

      09:13:33,163 DEBUG [org.teiid.TRANSPORT] (New I/O server worker #1-1) processing message:MessageHolder: key=3758 contents=Invoke interface org.teiid.client.DQP.closeRequest

      09:13:33,163 DEBUG [org.teiid.TRANSPORT] (New I/O server worker #1-1) processing message:MessageHolder: key=3758 contents=Invoke interface org.teiid.client.DQP.closeRequest

      09:13:33,163 DEBUG [org.teiid.PROCESSOR] (New I/O server worker #1-1) closeQuery for requestID=sJH1fXmsdX0J.4

      09:13:33,163 DEBUG [org.teiid.PROCESSOR] (New I/O server worker #1-1) closeQuery for requestID=sJH1fXmsdX0J.4

      09:13:33,163 DEBUG [org.teiid.CONNECTOR] (New I/O server worker #1-1) sJH1fXmsdX0J.4.4.5 Processing CANCEL request

      09:13:33,163 DEBUG [org.teiid.CONNECTOR] (New I/O server worker #1-1) sJH1fXmsdX0J.4.4.5 Processing CANCEL request

      09:13:33,163 DEBUG [org.teiid.COMMAND_LOG] (New I/O server worker #1-1)           CANCEL SRC COMMAND:          endTime=2013-02-27 09:13:33.163          requestID=sJH1fXmsdX0J.4          sourceCommandID=4          txID=null          modelName=5000_10          translatorName=delegate          sessionID=sJH1fXmsdX0J          principal=user@dsds-security-domain          finalRowCount=-1

      09:13:33,163 DEBUG [org.teiid.COMMAND_LOG] (New I/O server worker #1-1)           CANCEL SRC COMMAND:          endTime=2013-02-27 09:13:33.163          requestID=sJH1fXmsdX0J.4          sourceCommandID=4          txID=null          modelName=5000_10          translatorName=delegate          sessionID=sJH1fXmsdX0J          principal=user@dsds-security-domain          finalRowCount=-1

      09:13:33,163 INFO  [com.lgc.ow.teiid.translator.OWTBaseExecution] (New I/O server worker #1-1) Canceling execution. Rollback

      09:13:33,256 DEBUG [org.teiid.CONNECTOR] (New I/O server worker #1-1) The atomic request sJH1fXmsdX0J.4.4.5 has been canceled.

      09:13:33,256 DEBUG [org.teiid.CONNECTOR] (New I/O server worker #1-1) The atomic request sJH1fXmsdX0J.4.4.5 has been canceled.

       

      ----------------------------------------

        • 1. Re: Long running query fails on Teiid 8.1
          Ramesh Reddy Master

          How are you setting the "com.arjuna.ats.arjuna.recovery.periodicRecoveryPeriod" property?

          • 2. Re: Long running query fails on Teiid 8.1
            Shantanu D Newbie

            We are setting the property using a properties file that is passed to JBoss standalone.bat file using a -P parameter.

             

            For one of my colleagues, the query fails after 2 minutes even after setting the recovery scan to happen every 15 minutes. Please see the logs below.

             

            09:29:06,036 DEBUG [org.teiid.COMMAND_LOG] (Worker2_QueryProcessorQueue1895)     START DATA SRC COMMAND:    startTime=2013-02-27 09:29:06.036    requestID=kLNCOWeV9nmr.0    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    sql=*******

            09:29:06,036 DEBUG [org.teiid.COMMAND_LOG] (Worker2_QueryProcessorQueue1895)     START DATA SRC COMMAND:    startTime=2013-02-27 09:29:06.036    requestID=kLNCOWeV9nmr.0    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    sql=*******

            09:29:06,083 INFO  [com.lgc.ow.teiid.translator.OWTBaseExecution] (Worker2_QueryProcessorQueue1895) Executing Openworks Query:*******

            09:29:11,911 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-2) closeSession hwEnXA1Q5rZk

            09:29:11,911 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-2) closeSession hwEnXA1Q5rZk

            09:30:32,680 FINEST [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.connection] (Thread-81) release_connection     __EclipseLinkSessionId__: 44808654

            09:30:32,680 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.transaction] (Thread-81) release_unit_of_work     __EclipseLinkSessionId__: 1492411530

            09:30:32,680 DEBUG [org.teiid.COMMAND_LOG] (New I/O server worker #2-1)     CANCEL SRC COMMAND:    endTime=2013-02-27 09:30:32.68    requestID=kLNCOWeV9nmr.0    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=-1

            09:30:32,680 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.connection] (Thread-81) client_released     __EclipseLinkSessionId__: 460637763

            09:30:32,680 DEBUG [org.teiid.COMMAND_LOG] (New I/O server worker #2-1)     CANCEL SRC COMMAND:    endTime=2013-02-27 09:30:32.68    requestID=kLNCOWeV9nmr.0    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=-1

            09:30:32,695 INFO  [com.lgc.ow.teiid.translator.OWTBaseExecution] (New I/O server worker #2-1) Canceling execution. Rollback

            09:30:32,695 DEBUG [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1922)     END SRC COMMAND:    endTime=2013-02-27 09:30:32.695    requestID=kLNCOWeV9nmr.0    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=4608

            09:30:32,695 DEBUG [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1922)     END SRC COMMAND:    endTime=2013-02-27 09:30:32.695    requestID=kLNCOWeV9nmr.0    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=4608

            09:30:32,695 INFO  [com.lgc.ow.teiid.translator.OWTBaseExecution] (Worker1_QueryProcessorQueue1922) Closing Execution

            09:30:53,071 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            09:30:53,071 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            09:32:53,669 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            09:32:53,669 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            09:34:31,639 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.connection] (http--0.0.0.0-8080-1) client_acquired     __EclipseLinkSessionId__: 44808654

            09:34:31,639 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.transaction] (http--0.0.0.0-8080-1) acquire_unit_of_work_with_argument     __EclipseLinkSessionId__: 346687050

            09:34:31,639 FINEST [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.query] (http--0.0.0.0-8080-1) execute_query     __EclipseLinkSessionId__: 646115039

            09:34:31,655 FINEST [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.connection] (http--0.0.0.0-8080-1) acquire_connection     __EclipseLinkSessionId__: 44808654

            09:34:31,655 FINE  [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.sql] (http--0.0.0.0-8080-1) ******* WHERE (SOURCE_NAME = ?)

                bind => [WELLS_100K_NAD27]     __EclipseLinkSessionId__: 44808654

            09:34:31,686 DEBUG [org.teiid.COMMAND_LOG] (Worker5_QueryProcessorQueue1924)     START DATA SRC COMMAND:    startTime=2013-02-27 09:34:31.686    requestID=kLNCOWeV9nmr.1    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    sql=******

            09:34:31,686 DEBUG [org.teiid.COMMAND_LOG] (Worker5_QueryProcessorQueue1924)     START DATA SRC COMMAND:    startTime=2013-02-27 09:34:31.686    requestID=kLNCOWeV9nmr.1    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    sql=**********

            09:34:31,717 INFO  [com.lgc.ow.teiid.translator.OWTBaseExecution] (Worker5_QueryProcessorQueue1924) Executing Openworks Query:**************

            09:34:53,671 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            09:34:53,671 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            09:36:32,706 FINEST [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.connection] (Thread-81) release_connection     __EclipseLinkSessionId__: 44808654

            09:36:32,706 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.transaction] (Thread-81) release_unit_of_work     __EclipseLinkSessionId__: 646115039

            09:36:32,706 FINER [org.eclipse.persistence.session.vfs:/C:/landmark/jboss-as-7.1.1.Final/bin/content/dsdataserver.war/WEB-INF/classes/_teiidDynamicUnit_url=jdbc:teiid:OW_TEIID@mm://134.132.115.7:31000;ApplicationName=openworks_user=user.connection] (Thread-81) client_released     __EclipseLinkSessionId__: 346687050

            09:36:32,706 DEBUG [org.teiid.COMMAND_LOG] (New I/O server worker #2-1)     CANCEL SRC COMMAND:    endTime=2013-02-27 09:36:32.706    requestID=kLNCOWeV9nmr.1    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=-1

            09:36:32,706 DEBUG [org.teiid.COMMAND_LOG] (New I/O server worker #2-1)     CANCEL SRC COMMAND:    endTime=2013-02-27 09:36:32.706    requestID=kLNCOWeV9nmr.1    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=-1

            09:36:32,706 INFO  [com.lgc.ow.teiid.translator.OWTBaseExecution] (New I/O server worker #2-1) Canceling execution. Rollback

            09:36:32,706 DEBUG [org.teiid.COMMAND_LOG] (Worker4_QueryProcessorQueue1948)     END SRC COMMAND:    endTime=2013-02-27 09:36:32.706    requestID=kLNCOWeV9nmr.1    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=4608

            09:36:32,706 DEBUG [org.teiid.COMMAND_LOG] (Worker4_QueryProcessorQueue1948)     END SRC COMMAND:    endTime=2013-02-27 09:36:32.706    requestID=kLNCOWeV9nmr.1    sourceCommandID=3    txID=null    modelName=5000_10    translatorName=delegate    sessionID=kLNCOWeV9nmr    principal=user@dsds-security-domain    finalRowCount=4608

            09:36:32,706 INFO  [com.lgc.ow.teiid.translator.OWTBaseExecution] (Worker4_QueryProcessorQueue1948) Closing Execution

            09:36:53,675 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            09:36:53,675 DEBUG [org.teiid.SECURITY] (New I/O server worker #2-1) Keep-alive ping received for session: kLNCOWeV9nmr

            </p>

            • 3. Re: Long running query fails on Teiid 8.1
              Ramesh Reddy Master

              To increase the transactions timeout in AS7, you need to add following in the "transactions" subsystem configuration in the standalone-teiid.xml file

               

              <coordinator-environment default-timeout="600"/>
              

               

              The above is set to 10 mins, the default is 5 mins. So, I am still not sure how you are seeing a timeout at 2 min.

               

              Ramesh..

              • 4. Re: Long running query fails on Teiid 8.1
                Ramesh Reddy Master

                Also in your log I did not see any transaction-reaper timeouts. This could be due to the logging level you are using. See if you can turn it on at DEBUG or TRACE level and find why the CANCEL is being issued.

                • 5. Re: Long running query fails on Teiid 8.1
                  Steven Hawkins Master

                  > I am not really sure if this has something to do with the XA transanction recovery or why Teiid is trying to cancel the statement. Can you please provide me with any pointers?

                   

                  It should not be related.  It's probably best to start with the close and work backwards.

                   

                  > 09:13:33,163 DEBUG [org.teiid.TRANSPORT] (New I/O server worker #1-1) processing message:MessageHolder: key=3758 contents=Invoke interface org.teiid.client.DQP.closeRequest

                   

                  This is from the perspective of our JDBC client via a socket connection.  If you do not see a preceeding message about DQP.cancelRequest or "Cancelling query ...", then there is no relevant timeout (client side nor server side) specific to Teiid that is causing an issue.  If that's the case and assuming that the default timeout for is truly 5 minutes, then you need to see if EclipseLink is setting a transaction timeout property and/or debug when/why EclipseLink is closing the connection.

                   

                  Steve