You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues-all@impala.apache.org by "Bikramjeet Vig (JIRA)" <ji...@apache.org> on 2019/03/26 23:17:00 UTC
[jira] [Commented] (IMPALA-8295) test_mem_limit in
test_admission_controller timed out waiting for query to end
[ 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: issues-all-unsubscribe@impala.apache.org
For additional commands, e-mail: issues-all-help@impala.apache.org