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

Long running query fails on Teiid 8.1

shan_dind Feb 27, 2013 10:44 AM

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

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

1. Re: Long running query fails on Teiid 8.1

rareddy Feb 27, 2013 10:58 AM (in response to shan_dind)

How are you setting the "com.arjuna.ats.arjuna.recovery.periodicRecoveryPeriod" property?
Actions
2. Re: Long running query fails on Teiid 8.1

shan_dind Feb 27, 2013 11:15 AM (in response to rareddy)

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>
Actions
3. Re: Long running query fails on Teiid 8.1

rareddy Feb 27, 2013 11:18 AM (in response to rareddy)
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..
Actions
4. Re: Long running query fails on Teiid 8.1

rareddy Feb 27, 2013 11:26 AM (in response to rareddy)

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.
Actions
5. Re: Long running query fails on Teiid 8.1

shawkins Feb 27, 2013 11:46 AM (in response to rareddy)

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

Go to original post