[JBoss JIRA] (TEIID-5643) When querying a larger dataset, teiid answers with 504 Gateway Time-out and throws exception
8:10 p.m.
[
https://issues.jboss.org/browse/TEIID-5643?page=com.atlassian.jira.plugin...
]
Christoph John edited comment on TEIID-5643 at 3/2/19 9:09 PM:
---------------------------------------------------------------
Hello Steven,
sorry for the late reply but I have not had a chance to look at the topic earlier. I have
put Xmx to 256m. This did not result in a HeapDump. I also tried to increase memory to
1024m this does not help to solve the topic either. What did you mean with
>Another thing to try is to take odata out of the picture - can you
run the representative query over jdbc without issue? And in general how long does it
take?
How can I run such a query? With what tool and how can I measure timing?
One further note, when setting log level to debug, I get the following output for a select
* on the table. When looking at the sql statement (I find no LIMIT in the select
statement) it looks to me like teiid does not set any limits on the query size like we
have discussed previously. Might this the bug I am running into? Not shure how I have to
interpret the output. It does not look like an error from the output. I mean the result
states the amount of records.
2019-03-03 02:00:23,028 DEBUG [org.teiid.COMMAND_LOG] (default task-4) ZmxEdrxorQPx START
USER COMMAND: startTime=2019-03-03
02:00:23.024 requestID=ZmxEdrxorQPx.0 txID=null sessionID=ZmxEdrxorQPx applicationName=JDBC principal=cef9d7d3-af13-4b13-9e93-ef3c5307f0e9 vdbName=svc vdbVersion=1 sql=/*+
cache(ttl:300000 scope:USER) */ SELECT g0.idCode, g0.lc, g0.product_name, g0.origins,
g0.brands, g0.quantity, g0.nova_group, g0.nutrition_grade_fr,
g0.ingredients_text_with_allergens, g0.energy_100g, g0.carbohydrates_100g, g0.sugars_100g,
g0.proteins_100g, g0.fat_100g, g0.saturated_fat_100g, g0.saturated_fat_modifier,
g0.salt_100g, g0.sodium_100g FROM my_nutri_diary.FDBProducts AS g0 ORDER BY g0.idCode /*
ZmxEdrxorQPx */
2019-03-03 02:00:23,035 DEBUG [org.teiid.COMMAND_LOG.SOURCE]
(Worker2_QueryProcessorQueue6) ZmxEdrxorQPx START DATA SRC COMMAND: startTime=2019-03-03
02:00:23.035 requestID=ZmxEdrxorQPx.0 sourceCommandID=0 executionID=1 txID=null modelName=my_nutri_diary translatorName=mysql sessionID=ZmxEdrxorQPx principal=cef9d7d3-af13-4b13-9e93-ef3c5307f0e9 sql=SELECT
g_0.idCode AS c_0, g_0.lc AS c_1, g_0.product_name AS c_2, g_0.origins AS c_3, g_0.brands
AS c_4, g_0.quantity AS c_5, g_0.nova_group AS c_6, g_0.nutrition_grade_fr AS c_7,
g_0.ingredients_text_with_allergens AS c_8, g_0.energy_100g AS c_9, g_0.carbohydrates_100g
AS c_10, g_0.sugars_100g AS c_11, g_0.proteins_100g AS c_12, g_0.fat_100g AS c_13,
g_0.saturated_fat_100g AS c_14, g_0.saturated_fat_modifier AS c_15, g_0.salt_100g AS c_16,
g_0.sodium_100g AS c_17 FROM my_nutri_diary.FDBProducts AS g_0 ORDER BY c_0
2019-03-03 02:00:23,036 DEBUG [org.teiid.COMMAND_LOG.SOURCE]
(Worker2_QueryProcessorQueue6) ZmxEdrxorQPx SOURCE SRC COMMAND: endTime=2019-03-03
02:00:23.036 requestID=ZmxEdrxorQPx.0 sourceCommandID=0 executionID=1 txID=null modelName=my_nutri_diary translatorName=mysql sessionID=ZmxEdrxorQPx principal=cef9d7d3-af13-4b13-9e93-ef3c5307f0e9 sourceCommand=[SELECT
g_0.`idCode` AS c_0, g_0.`lc` AS c_1, g_0.`product_name` AS c_2, g_0.`origins` AS c_3,
g_0.`brands` AS c_4, g_0.`quantity` AS c_5, g_0.`nova_group` AS c_6,
g_0.`nutrition_grade_fr` AS c_7, g_0.`ingredients_text_with_allergens` AS c_8,
g_0.`energy_100g` AS c_9, g_0.`carbohydrates_100g` AS c_10, g_0.`sugars_100g` AS c_11,
g_0.`proteins_100g` AS c_12, g_0.`fat_100g` AS c_13, g_0.`saturated_fat_100g` AS c_14,
g_0.`saturated_fat_modifier` AS c_15, g_0.`salt_100g` AS c_16, g_0.`sodium_100g` AS c_17
FROM `FDBProducts` AS g_0 ORDER BY c_0]
2019-03-03 02:00:34,342 DEBUG [org.teiid.COMMAND_LOG.SOURCE] (default task-4) ZmxEdrxorQPx
END SRC COMMAND: endTime=2019-03-03
02:00:34.342 requestID=ZmxEdrxorQPx.0 sourceCommandID=0 executionID=1 txID=null modelName=my_nutri_diary translatorName=mysql sessionID=ZmxEdrxorQPx principal=cef9d7d3-af13-4b13-9e93-ef3c5307f0e9 finalRowCount=657736 cpuTime(ns)=617122944
2019-03-03 02:00:34,437 DEBUG [org.teiid.COMMAND_LOG] (default task-4) ZmxEdrxorQPx END
USER COMMAND: endTime=2019-03-03
02:00:34.437 requestID=ZmxEdrxorQPx.0 txID=null sessionID=ZmxEdrxorQPx principal=cef9d7d3-af13-4b13-9e93-ef3c5307f0e9 vdbName=svc vdbVersion=1 finalRowCount=657736
was (Author: cjohn001):
Hello Steven,
sorry for the late reply but I have not had a chance to look at the topic earlier. I have
put Xmx to 256m. This did not result in a HeapDump. I also tried to increase memory to
1024m this does not help to solve the topic either. What did you mean with
>Another thing to try is to take odata out of the picture - can you
run the representative query over jdbc without issue? And in general how long does it
take?
How can I run such a query? With what tool and how can I measure timing?
When querying a larger dataset, teiid answers with 504 Gateway
Time-out and throws exception
--------------------------------------------------------------------------------------------
Key: TEIID-5643
URL: https://issues.jboss.org/browse/TEIID-5643
Project: Teiid
Issue Type: Bug
Affects Versions: 11.2.1
Reporter: Christoph John
Assignee: Steven Hawkins
Priority: Major
Attachments: Heap Dump analysis tool.pdf
Please note, I am using Teiid 11.2.0 and not 11.2.1 as specified above in this ticket. I
was not able to select a version 11.2.0.
The issue: I tried to query a table with a larger amount of records (about 600.000
records in the table). Teiid responds with
504 Gateway Time-out. The server didn't respond in time.
If Teiid tries to respond with 600.000 entries to such a request, it is reasonable that
it runs out of memory or other weird things happen. However, I would expect that in such a
case Teiid just answers with a fixed amount of records, say for example 1000, and provides
a kind of curser to enable subsequent requests to retrieve more data.
I am currently trying to find a workaround for the issue, as the issue blocks my work. Is
there maybe a kind of configuration option that I have to set explicitly for such a kind
of behavior I previously sketched?
Further note: When I send such a kind of select * request on the table to Teiid, I am
also not able for a certain time interval, about a minute, to get a responds to different
queries which select a single element on the mentioned table. Such a request then also
results in a 504 Gateway Time-out.
Attached error log:
2019-02-01 22:33:36,126 WARN
[org.jboss.jca.core.connectionmanager.pool.strategy.OnePool]
(Worker2_QueryProcessorQueue5) eayVFuq9y7OY IJ000407: No lazy enlistment available for
my_nutri_diary
2019-02-01 22:33:36,135 INFO [org.teiid.CONNECTOR] (Worker2_QueryProcessorQueue5)
eayVFuq9y7OY MySQLExecutionFactory
Commit=true;DatabaseProductName=MySQL;DatabaseProductVersion=8.0.13;DriverMajorVersion=8;DriverMajorVersion=0;DriverName=MySQL
Connector/J;DriverVersion=mysql-connector-java-8.0.13 (Revision:
66459e9d39c8fd09767992bc592acd2053279be6);IsolationLevel=2
2019-02-01 22:36:56,959 WARN [org.teiid.CONNECTOR] (Worker2_QueryProcessorQueue5)
eayVFuq9y7OY Connector worker process failed for atomic-request=eayVFuq9y7OY.0.0.0:
org.teiid.translator.jdbc.JDBCExecutionException: 0 TEIID11008:TEIID11004 Error executing
statement(s): [Prepared Values: [] SQL: SELECT g_0.`idCode` AS c_0, g_0.`lc` AS c_1,
g_0.`product_name` AS c_2, g_0.`origins` AS c_3, g_0.`brands` AS c_4, g_0.`quantity` AS
c_5, g_0.`nova_group` AS c_6, g_0.`nutrition_grade_fr` AS c_7,
g_0.`ingredients_text_with_allergens` AS c_8, g_0.`energy_100g` AS c_9,
g_0.`carbohydrates_100g` AS c_10, g_0.`sugars_100g` AS c_11, g_0.`proteins_100g` AS c_12,
g_0.`fat_100g` AS c_13, g_0.`saturated_fat_100g` AS c_14, g_0.`saturated_fat_modifier` AS
c_15, g_0.`salt_100g` AS c_16, g_0.`sodium_100g` AS c_17 FROM `FDBProducts` AS g_0 ORDER
BY c_0]
at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:127)
at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.execute(ConnectorWorkItem.java:393)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.teiid.dqp.internal.datamgr.ConnectorManager$1.invoke(ConnectorManager.java:229)
at com.sun.proxy.$Proxy51.execute(Unknown Source)
at
org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:302)
at
org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:108)
at
org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:104)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:61)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:278)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:115)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLException: Java heap space
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129)
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)
at
com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
at
com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:974)
at
com.mysql.cj.jdbc.ClientPreparedStatement.executeQuery(ClientPreparedStatement.java:1024)
at
org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:504)
at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:119)
... 18 more
2019-02-01 22:36:56,977 WARN [org.teiid.PROCESSOR] (default task-4) eayVFuq9y7OY
TEIID30020 Processing exception for request eayVFuq9y7OY.0 'TEIID30504 my_nutri_diary:
0 TEIID11008:TEIID11004 Error executing statement(s): [Prepared Values: [] SQL: SELECT
g_0.`idCode` AS c_0, g_0.`lc` AS c_1, g_0.`product_name` AS c_2, g_0.`origins` AS c_3,
g_0.`brands` AS c_4, g_0.`quantity` AS c_5, g_0.`nova_group` AS c_6,
g_0.`nutrition_grade_fr` AS c_7, g_0.`ingredients_text_with_allergens` AS c_8,
g_0.`energy_100g` AS c_9, g_0.`carbohydrates_100g` AS c_10, g_0.`sugars_100g` AS c_11,
g_0.`proteins_100g` AS c_12, g_0.`fat_100g` AS c_13, g_0.`saturated_fat_100g` AS c_14,
g_0.`saturated_fat_modifier` AS c_15, g_0.`salt_100g` AS c_16, g_0.`sodium_100g` AS c_17
FROM `FDBProducts` AS g_0 ORDER BY c_0]'. Originally TeiidProcessingException
'Java heap space' SQLError.java:129. Enable more detailed logging to see the
entire stacktrace.
2019-02-01 22:36:56,987 WARN [org.teiid.PROCESSOR] (default task-4) TEIID16053 Unable
to process odata request due to: TEIID30504 my_nutri_diary: 0 TEIID11008:TEIID11004 Error
executing statement(s): [Prepared Values: [] SQL: SELECT g_0.`idCode` AS c_0, g_0.`lc` AS
c_1, g_0.`product_name` AS c_2, g_0.`origins` AS c_3, g_0.`brands` AS c_4, g_0.`quantity`
AS c_5, g_0.`nova_group` AS c_6, g_0.`nutrition_grade_fr` AS c_7,
g_0.`ingredients_text_with_allergens` AS c_8, g_0.`energy_100g` AS c_9,
g_0.`carbohydrates_100g` AS c_10, g_0.`sugars_100g` AS c_11, g_0.`proteins_100g` AS c_12,
g_0.`fat_100g` AS c_13, g_0.`saturated_fat_100g` AS c_14, g_0.`saturated_fat_modifier` AS
c_15, g_0.`salt_100g` AS c_16, g_0.`sodium_100g` AS c_17 FROM `FDBProducts` AS g_0 ORDER
BY c_0] Increase the log level to see the entire stack trace.
2019-02-01 22:36:57,213 WARN [org.teiid.CONNECTOR] (Worker2_QueryProcessorQueue6)
NdaDihMR2Vlt Connector worker process failed for atomic-request=NdaDihMR2Vlt.0.0.1:
org.teiid.translator.jdbc.JDBCExecutionException: 0 TEIID11008:TEIID11004 Error executing
statement(s): [Prepared Values: [] SQL: SELECT g_0.`idCode` AS c_0, g_0.`lc` AS c_1,
g_0.`product_name` AS c_2, g_0.`origins` AS c_3, g_0.`brands` AS c_4, g_0.`quantity` AS
c_5, g_0.`nova_group` AS c_6, g_0.`nutrition_grade_fr` AS c_7,
g_0.`ingredients_text_with_allergens` AS c_8, g_0.`energy_100g` AS c_9,
g_0.`carbohydrates_100g` AS c_10, g_0.`sugars_100g` AS c_11, g_0.`proteins_100g` AS c_12,
g_0.`fat_100g` AS c_13, g_0.`saturated_fat_100g` AS c_14, g_0.`saturated_fat_modifier` AS
c_15, g_0.`salt_100g` AS c_16, g_0.`sodium_100g` AS c_17 FROM `FDBProducts` AS g_0 ORDER
BY c_0]
at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:127)
at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.execute(ConnectorWorkItem.java:393)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.teiid.dqp.internal.datamgr.ConnectorManager$1.invoke(ConnectorManager.java:229)
at com.sun.proxy.$Proxy51.execute(Unknown Source)
at
org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:302)
at
org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:108)
at
org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:104)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:61)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:278)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:115)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link
failure
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
1917
days inactive
1917
days old
0 comments
1 participants
participants (1)
-
Christoph John (Jira)