[teiid-issues] [JBoss JIRA] (TEIID-3904) TEIID31100 Parsing error: Encountered "[*]move[*] backward 5831" on openquery update command

Steve Tran (JIRA) issues at jboss.org
Mon Jan 18 15:51:00 EST 2016


    [ https://issues.jboss.org/browse/TEIID-3904?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13150228#comment-13150228 ] 

Steve Tran commented on TEIID-3904:
-----------------------------------

Just some more background just in case anybody is interested.  

The original root cause of this ticket was due to enable the "Use Declare/Fetch" setting on the ODBC driver.  I unchecked it and the query ran fine, albeit 3 minutes to update 4000 rows.  I was tailing the server.log and saw that it was doing work, so it wasn't like it was hanging.

{code}
15:02:41,541 DEBUG [org.teiid.TXN_LOG] (Worker784_QueryProcessorQueue7520537) after getOrCreateTransactionContext : E5auO50CNNZM LOCAL ID:TransactionImple < ac, BasicAction: 0:ffffa22c73d5:25363a56:5698eec3:5c07 status: ActionStatus.RUNNING >
15:02:41,541 DEBUG [org.teiid.BUFFER_MGR] (Worker784_QueryProcessorQueue7520537) Creating TupleBuffer: 246901 [Count] [class java.lang.Integer] batch size 2048 of type PROCESSOR
15:02:41,541 DEBUG [org.teiid.TXN_LOG] (Worker784_QueryProcessorQueue7520537) before resume:org.teiid.dqp.internal.process.TransactionServerImpl at 2cbb178f(E5auO50CNNZM LOCAL ID:TransactionImple < ac, BasicAction: 0:ffffa22c73d5:25363a56:5698eec3:5c07 status: ActionStatus.RUNNING >)
15:02:41,541 DEBUG [org.teiid.TXN_LOG] (Worker784_QueryProcessorQueue7520537) after resume : null
15:02:41,541 TRACE [org.teiid.BUFFER_MGR] (Worker784_QueryProcessorQueue7520537) Reserving buffer space 114688 FORCE
15:02:41,541 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Create State
15:02:41,541 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Processing NEW request: UPDATE Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST SET DO_NOT_USE = -1 WHERE (Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST.TM_PD_ID = 4491) AND (Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST.TM_PD_TYP_ID = 5) AND (Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST.DO_NOT_USE IS NULL)
15:02:41,541 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Obtained execution
15:02:41,541 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) Source-specific command: UPDATE "HSIDBA"."HSI_TM_PD_TEST" SET "DO_NOT_USE" = ? WHERE "HSIDBA"."HSI_TM_PD_TEST"."TM_PD_ID" = ? AND "HSIDBA"."HSI_TM_PD_TEST"."TM_PD_TYP_ID" = ? AND "HSIDBA"."HSI_TM_PD_TEST"."DO_NOT_USE" IS NULL
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Executed command
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Processing MORE request
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Getting results from connector
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Obtained last batch, total row count: 1
15:02:41,542 TRACE [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) closed atomic-request: E5auO50CNNZM.4596.0.171982
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Remove State
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Processing Close : UPDATE Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST SET DO_NOT_USE = -1 WHERE (Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST.TM_PD_ID = 4491) AND (Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST.TM_PD_TYP_ID = 5) AND (Oracle_cdtsorl232d_DEV.HSI_TM_PD_TEST.DO_NOT_USE IS NULL)
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Closed execution
15:02:41,542 DEBUG [org.teiid.CONNECTOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596.0.171982 Closed connection
15:02:41,542 DEBUG [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) QueryProcessor: closing processor
15:02:41,542 TRACE [org.teiid.BUFFER_MGR] (Worker784_QueryProcessorQueue7520537) Releasing buffer space 114688
15:02:41,542 DEBUG [org.teiid.TXN_LOG] (Worker784_QueryProcessorQueue7520537) before suspend:org.teiid.dqp.internal.process.TransactionServerImpl at 2cbb178f(E5auO50CNNZM LOCAL ID:TransactionImple < ac, BasicAction: 0:ffffa22c73d5:25363a56:5698eec3:5c07 status: ActionStatus.RUNNING >)
15:02:41,542 DEBUG [org.teiid.TXN_LOG] (Worker784_QueryProcessorQueue7520537) after suspend : null
15:02:41,542 DEBUG [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) [RequestWorkItem.sendResultsIfNeeded] requestID: E5auO50CNNZM.4596 resultsID: 246901 done: true
15:02:41,542 FINER [org.teiid.jdbc] (Worker784_QueryProcessorQueue7520537) Recieved update counts: [1]
15:02:41,542 TRACE [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) before closeRequest:org.teiid.dqp.internal.process.DQPCore at 1db340aa(4596)
15:02:41,542 DEBUG [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) closeQuery for requestID=E5auO50CNNZM.4596
15:02:41,542 TRACE [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596 more work WORKING
15:02:41,542 TRACE [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) after closeRequest : org.teiid.client.util.ResultsFuture at 3021d036
15:02:41,542 FINE  [org.teiid.jdbc] (Worker784_QueryProcessorQueue7520537) Successfully executed a query UPDATE TestVBL.HSI_TM_PD_TEST SET DO_NOT_USE=$1 WHERE (TM_PD_ID=$2 AND TM_PD_TYP_ID=$3 AND DO_NOT_USE IS NULL ) and obtained results
15:02:41,542 TRACE [org.teiid.ODBC] (Worker784_QueryProcessorQueue7520537) invoking client method: sendUpdateCount [UPDATE TestVBL.HSI_TM_PD_TEST SET DO_NOT_USE=$1 WHERE (TM_PD_ID=$2 AND TM_PD_TYP_ID=$3 AND DO_NOT_USE IS NULL ), 1]
15:02:41,543 TRACE [org.teiid.ODBC] (Worker784_QueryProcessorQueue7520537) invoking client method: setEncoding [UTF8, false]
15:02:41,543 FINE  [org.teiid.jdbc] (Worker784_QueryProcessorQueue7520537) Statement closed successfully.
15:02:41,543 TRACE [org.teiid.ODBC] (Worker784_QueryProcessorQueue7520537) invoking client method: statementClosed null
15:02:41,543 TRACE [org.teiid.ODBC] (Worker784_QueryProcessorQueue7520537) invoking client method: ready [true, false]
15:02:41,543 DEBUG [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) Removing tuplesource for the request E5auO50CNNZM.4596
15:02:41,543 DEBUG [org.teiid.BUFFER_MGR] (Worker784_QueryProcessorQueue7520537) Removing TupleBuffer: 246901
15:02:41,543 DEBUG [org.teiid.TXN_LOG] (Worker784_QueryProcessorQueue7520537) before suspend:org.teiid.dqp.internal.process.TransactionServerImpl at 2cbb178f(E5auO50CNNZM LOCAL ID:TransactionImple < ac, BasicAction: 0:ffffa22c73d5:25363a56:5698eec3:5c07 status: ActionStatus.RUNNING >)
15:02:41,543 DEBUG [org.teiid.TXN_LOG] (Worker784_QueryProcessorQueue7520537) after suspend : null
15:02:41,543 TRACE [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596 end processing MORE_WORK
15:02:41,543 TRACE [org.teiid.PROCESSOR] (Worker784_QueryProcessorQueue7520537) E5auO50CNNZM.4596 done processing - ignoring more MORE_WORK
{code}

According to https://docs.jboss.org/author/display/TEIID/Configuring+the+Data+Source+Name+%28DSN%29 
{quote}
# enable below when dealing large resultsets to enable cursoring(note prepared stmts will not work)
#UseDeclareFetch=1
{quote}
That's why we enabled declare/fetch in the first place.  I'll have to go back to the client and figure out what the original query was and why we needed to enable that in the first place.  But if the description about the handling large resultset is true, we're going to still need this backward move functionality in the future.

> TEIID31100 Parsing error: Encountered "[*]move[*] backward 5831" on openquery update command
> --------------------------------------------------------------------------------------------
>
>                 Key: TEIID-3904
>                 URL: https://issues.jboss.org/browse/TEIID-3904
>             Project: Teiid
>          Issue Type: Bug
>    Affects Versions: 8.7.1.6_2
>         Environment: Red Hat JBoss Data Virtualization 6.2 on EAP6.4.0 patched to version 6.4.3,
> JBoss Developer Studio 8.1.0GA with Teiid Designer plugin 9.0.3.Final.v20150810-1438-B1157
> 64-bit Windows 7 environment
>            Reporter: Steve Tran
>            Assignee: Steven Hawkins
>             Fix For: 8.13
>
>
> Getting an error when attempting to update an Oracle Table that was virtualized in JDV.  
> Here's the query
> update A
> set do_not_use = 1
>  FROM OPENQUERY(HSI, 'SELECT * FROM hsi_DW_ebl.hsi_tm_pd where do_not_use is null') A
> where do_not_use is null;
> {code}
> [Server:cdtssoa126d-jdv-one] 21:14:35,311 WARN  [org.teiid.ODBC] (Worker975_QueryProcessorQueue8734224) TEIID40020 Error occurred: org.teiid.jdbc.TeiidSQLException: TEIID31100 Parsing error: Encountered "[*]move[*] backward 5831" at line 1, column 1.
> [Server:cdtssoa126d-jdv-one] Was expecting: "alter" | "begin" | "call" | "create" | "delete" | "drop" | "exec" | "execute" | "insert" | "merge" ...
> [Server:cdtssoa126d-jdv-one]    at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.jdbc.StatementImpl.postReceiveResults(StatementImpl.java:667) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.jdbc.StatementImpl.access$100(StatementImpl.java:63) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.jdbc.StatementImpl$2.onCompletion(StatementImpl.java:515) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.client.util.ResultsFuture.done(ResultsFuture.java:135) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.client.util.ResultsFuture.access$200(ResultsFuture.java:40) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.client.util.ResultsFuture$1.receiveResults(ResultsFuture.java:79) [teiid-client-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.RequestWorkItem.sendError(RequestWorkItem.java:1001) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.RequestWorkItem.close(RequestWorkItem.java:556) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:352) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:51) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:254) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:274) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_75]
> [Server:cdtssoa126d-jdv-one]    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_75]
> [Server:cdtssoa126d-jdv-one]    at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_75]
> [Server:cdtssoa126d-jdv-one] Caused by: org.teiid.api.exception.query.QueryParserException: TEIID31100 Parsing error: Encountered "[*]move[*] backward 5831" at line 1, column 1.
> [Server:cdtssoa126d-jdv-one] Was expecting: "alter" | "begin" | "call" | "create" | "delete" | "drop" | "exec" | "execute" | "insert" | "merge" ...
> [Server:cdtssoa126d-jdv-one]    at org.teiid.query.parser.QueryParser.convertParserException(QueryParser.java:214) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.query.parser.QueryParser.parseCommand(QueryParser.java:164) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.query.parser.QueryParser.parseCommand(QueryParser.java:140) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.Request.parseCommand(Request.java:279) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.Request.generatePlan(Request.java:363) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.Request.processRequest(Request.java:435) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:613) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:315) [teiid-engine-8.7.1.6_2-redhat-6.jar:8.7.1.6_2-redhat-6]
> [Server:cdtssoa126d-jdv-one]    ... 8 more
> {code}



--
This message was sent by Atlassian JIRA
(v6.4.11#64026)


More information about the teiid-issues mailing list