[
https://issues.apache.org/jira/browse/IMPALA-8295?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16802266#comment-16802266
]
Bikramjeet Vig commented on IMPALA-8295:
----------------------------------------
{noformat}
-- 2019-03-14 05:52:55,050 INFO MainThread: Main loop, will request 15
queries to end
-- 2019-03-14 05:52:55,050 INFO MainThread: Requesting 15 clients to end
queries
-- 2019-03-14 05:52:55,051 INFO MainThread: Cancelling query 18
-- 2019-03-14 05:52:55,051 INFO MainThread: Cancelling query 6
-- 2019-03-14 05:52:55,051 INFO MainThread: Cancelling query 21
-- 2019-03-14 05:52:55,051 INFO MainThread: Cancelling query 15
-- 2019-03-14 05:52:55,051 INFO MainThread: Cancelling query 27
-- 2019-03-14 05:52:55,051 INFO MainThread: Cancelling query 19
-- 2019-03-14 05:52:55,051 INFO MainThread: Cancelling query 13
-- 2019-03-14 05:52:55,052 INFO MainThread: Cancelling query 22
-- 2019-03-14 05:52:55,052 INFO MainThread: Cancelling query 28
-- 2019-03-14 05:52:55,052 INFO MainThread: Cancelling query 10
-- 2019-03-14 05:52:55,052 INFO MainThread: Cancelling query 17
-- 2019-03-14 05:52:55,052 INFO MainThread: Cancelling query 14
-- 2019-03-14 05:52:55,053 INFO MainThread: Cancelling query 23
-- 2019-03-14 05:52:55,053 INFO MainThread: Cancelling query 29
-- 2019-03-14 05:52:55,053 INFO MainThread: Cancelling query 26
-- 2019-03-14 05:52:55,070 INFO Thread-729: Ending query
QueryHandle(log_context='a546ed5fd7dcbc7d:d3696b7300000000',
id='a546ed5fd7dcbc7d:d3696b7300000000') by CLIENT_CANCEL
-- 2019-03-14 05:52:55,070 INFO Thread-735: Ending query
QueryHandle(log_context='46480b1651907fee:3eb3ad6200000000',
id='46480b1651907fee:3eb3ad6200000000') by CLIENT_CLOSE
-- canceling operation: <tests.common.impala_connection.OperationHandle object
at 0x7f654803c510>
-- 2019-03-14 05:52:55,070 INFO Thread-731: Ending query
QueryHandle(log_context='e44192d11104215c:885b565600000000',
id='e44192d11104215c:885b565600000000') by CLIENT_CLOSE
-- closing query for operation handle:
<tests.common.impala_connection.OperationHandle object at 0x7f654803a9d0>
-- 2019-03-14 05:52:55,070 INFO Thread-743: Ending query
QueryHandle(log_context='5440873eba9e51eb:9ebe11d900000000',
id='5440873eba9e51eb:9ebe11d900000000') by CLIENT_CLOSE
-- closing query for operation handle:
<tests.common.impala_connection.OperationHandle object at 0x7f65800c7710>
-- closing query for operation handle:
<tests.common.impala_connection.OperationHandle object at 0x7f654803a390>
-- 2019-03-14 05:52:55,127 INFO Thread-744: Ending query
QueryHandle(log_context='5648d83f6b6f196f:dd0bb7cd00000000',
id='5648d83f6b6f196f:dd0bb7cd00000000') by EOS
-- fetching results from: <tests.common.impala_connection.OperationHandle
object at 0x7f654803add0>
-- 2019-03-14 05:52:55,127 INFO Thread-733: Ending query
QueryHandle(log_context='b94d4d1e7c441288:93b9c4e600000000',
id='b94d4d1e7c441288:93b9c4e600000000') by CLIENT_CANCEL
-- canceling operation: <tests.common.impala_connection.OperationHandle object
at 0x7f654803aa10>
-- 2019-03-14 05:52:55,184 INFO Thread-739: Ending query
QueryHandle(log_context='bf4249eb076f2cd9:657a477f00000000',
id='bf4249eb076f2cd9:657a477f00000000') by CLIENT_CLOSE
-- closing query for operation handle:
<tests.common.impala_connection.OperationHandle object at 0x7f6548049410>
-- 2019-03-14 05:52:55,203 INFO Thread-737: Ending query
QueryHandle(log_context='c1433e2ac4b29f4f:45f5221000000000',
id='c1433e2ac4b29f4f:45f5221000000000') by CLIENT_CANCEL
-- canceling operation: <tests.common.impala_connection.OperationHandle object
at 0x7f654803a710>
-- 2019-03-14 05:52:55,240 INFO Thread-745: Ending query
QueryHandle(log_context='6548cf43e5befd8f:0afb7b1900000000',
id='6548cf43e5befd8f:0afb7b1900000000') by CLIENT_CANCEL
-- canceling operation: <tests.common.impala_connection.OperationHandle object
at 0x7f654803ca10>
-- 2019-03-14 05:53:27,192 INFO Thread-734: Ending query
QueryHandle(log_context='674c6b8df00d4b93:ac643dfc00000000',
id='674c6b8df00d4b93:ac643dfc00000000') by QUERY_TIMEOUT
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f6548049f10>
-- 2019-03-14 05:53:27,216 INFO Thread-738: Ending query
QueryHandle(log_context='fb420f4d683b56b4:8ea183af00000000',
id='fb420f4d683b56b4:8ea183af00000000') by QUERY_TIMEOUT
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f6548049d50>
-- 2019-03-14 05:53:27,236 INFO Thread-726: Ending query
QueryHandle(log_context='5946bde15cf09677:49f5c1bc00000000',
id='5946bde15cf09677:49f5c1bc00000000') by QUERY_TIMEOUT
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f6548034f90>
-- 2019-03-14 05:53:27,368 INFO Thread-730: Ending query
QueryHandle(log_context='cc4270a15075b7f0:8d5766f500000000',
id='cc4270a15075b7f0:8d5766f500000000') by QUERY_TIMEOUT
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f6548034350>
-- 2019-03-14 05:53:27,403 INFO Thread-742: Ending query
QueryHandle(log_context='0a45143d3c22020f:aac6357300000000',
id='0a45143d3c22020f:aac6357300000000') by QUERY_TIMEOUT
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f6548049ed0>
-- 2019-03-14 05:53:27,421 INFO Thread-722: Ending query
QueryHandle(log_context='29431f37930cd558:84052fa500000000',
id='29431f37930cd558:84052fa500000000') by QUERY_TIMEOUT
{noformat}
In *end_admitted_queries* it has a 60 sec timeout waiting for a set of running
queries as apparent form the log above. Digging further into all the queries
scheduled to be closed revealed that the following query is the one that kept
*end_admitted_queries* waiting for more than a minute:
{noformat}
I0314 05:53:57.121657 28710 coordinator.cc:863] Release admission control
resources for query_id=5648d83f6b6f196f:dd0bb7cd00000000
{noformat}
This query took about 61 seconds to finish from the moment the executing thread
realized that it had to end the query. It seems like the way to fix this is to
just increase the timeout since not only the query can take upto 60 secs to end
but also the executing thread can also take a while to wake up and realize that
it has to cancel the query (Thread-722 took about 30 secs to realize)
> test_mem_limit in test_admission_controller timed out waiting for query to end
> ------------------------------------------------------------------------------
>
> Key: IMPALA-8295
> URL: https://issues.apache.org/jira/browse/IMPALA-8295
> Project: IMPALA
> Issue Type: Bug
> Affects Versions: Impala 3.3.0
> Reporter: Bikramjeet Vig
> Assignee: Bikramjeet Vig
> Priority: Major
> Labels: broken-build, flaky-test
>
> {noformat}
> custom_cluster/test_admission_controller.py:1478: in test_mem_limit
> {'request_pool': self.pool_name, 'mem_limit': query_mem_limit})
> custom_cluster/test_admission_controller.py:1370: in run_admission_test
> self.end_admitted_queries(num_to_end)
> custom_cluster/test_admission_controller.py:1151: in end_admitted_queries
> assert (time() - start_time < STRESS_TIMEOUT),\
> E AssertionError: Timed out waiting 60 seconds for query end
> E assert (1551967400.261374 - 1551967340.1934941) < 60
> E + where 1551967400.261374 = time(){noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
