[
https://issues.apache.org/jira/browse/IMPALA-6227?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16464480#comment-16464480
]
Tim Armstrong edited comment on IMPALA-6227 at 5/4/18 11:04 PM:
----------------------------------------------------------------
Attached logs. I think this is the interesting part:
{noformat}
MainThread: Main loop, curr_metrics: admitted=26, queued=20, dequeued=14,
rejected=20, released=18, timed-out=0
MainThread: Main loop, will request 6 queries to end
MainThread: Requesting 6 clients to end queries
MainThread: Cancelling query 2
-- fetching results from: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
MainThread: Cancelling query 14
MainThread: Cancelling query 1
MainThread: Cancelling query 31
MainThread: Cancelling query 19
MainThread: Cancelling query 23
Thread-689: Ending query
QueryHandle(log_context='c04a7c92333c0646:63dfc09c00000000',
id='c04a7c92333c0646:63dfc09c00000000') by CLIENT_CLOSE
-- closing query for operation handle:
<tests.common.impala_connection.OperationHandle object at 0x7f090c016850>
Thread-697: Ending query
QueryHandle(log_context='4f4ce9ddfea34b66:4788b64100000000',
id='4f4ce9ddfea34b66:4788b64100000000') by CLIENT_CLOSE
-- closing query for operation handle:
<tests.common.impala_connection.OperationHandle object at 0x7f090c016e50>
Thread-667: Ending query
QueryHandle(log_context='7e474d8a33622077:2e7aacc800000000',
id='7e474d8a33622077:2e7aacc800000000') by CLIENT_CANCEL
-- canceling operation: <tests.common.impala_connection.OperationHandle object
at 0x44ccf90>
-- fetching results from: <tests.common.impala_connection.OperationHandle
object at 0x44ccc10>
Thread-680: Ending query
QueryHandle(log_context='364771ca11f54d6f:d826796e00000000',
id='364771ca11f54d6f:d826796e00000000') by QUERY_TIMEOUT
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x44ccc10>
Thread-685: Ending query
QueryHandle(log_context='b84cd4660695d218:b2b187d600000000',
id='b84cd4660695d218:b2b187d600000000') by CLIENT_CLOSE
-- closing query for operation handle:
<tests.common.impala_connection.OperationHandle object at 0x7f090c016690>
-- fetching results from: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
Thread-668: Ending query
QueryHandle(log_context='f04dcf86fc9b574c:86fcff5700000000',
id='f04dcf86fc9b574c:86fcff5700000000') by QUERY_TIMEOUT
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
Thread-677: Admitted query 11
Thread-700: Admitted query 34
-- fetching results from: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016e50>
Thread-695: Admitted query 29
Thread-679: Admitted query 13
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x44ccc10>
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x44ccc10>
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x44ccc10>
-- getting state for operation: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
Thread-671: Admitted query 5
Thread-676: Admitted query 10
-- fetching results from: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
MainThread: wait_for_metric_changes, initial=admitted=26, queued=20,
dequeued=14, rejected=20, released=18, timed-out=0
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=6 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=6 for
metrics=['released'])
MainThread: Found all 6 metrics after 0.5 seconds
MainThread: wait_for_metric_changes, initial=admitted=26, queued=20,
dequeued=14, rejected=20, released=18, timed-out=0
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
{noformat}
was (Author: tarmstrong):
Attached logs. I think this is the interesting part:
{noformat}
Thread-676: Admitted query 10
-- fetching results from: <tests.common.impala_connection.OperationHandle
object at 0x7f090c016250>
MainThread: wait_for_metric_changes, initial=admitted=26, queued=20,
dequeued=14, rejected=20, released=18, timed-out=0
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=6 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=6 for
metrics=['released'])
MainThread: Found all 6 metrics after 0.5 seconds
MainThread: wait_for_metric_changes, initial=admitted=26, queued=20,
dequeued=14, rejected=20, released=18, timed-out=0
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
MainThread: wait_for_metric_changes, current=admitted=30, queued=20,
dequeued=20, rejected=20, released=24, timed-out=0
MainThread: DeltaSum=4 Deltas={'dequeued': 6, 'admitted': 4, 'released': 6,
'rejected': 0, 'queued': 0, 'timed-out': 0} (Expected=5 for
metrics=['admitted', 'timed-out'])
{noformat}
> TestAdmissionControllerStress can be flaky
> ------------------------------------------
>
> Key: IMPALA-6227
> URL: https://issues.apache.org/jira/browse/IMPALA-6227
> Project: IMPALA
> Issue Type: Bug
> Components: Backend
> Affects Versions: Impala 2.11.0
> Reporter: Csaba Ringhofer
> Assignee: Tim Armstrong
> Priority: Critical
> Labels: flaky
> Attachments: TEST-impala-custom-cluster.xml
>
>
> jenkins build https://jenkins.impala.io/job/gerrit-verify-dryrun/1503/console
> failed at the following test:
> {noformat}
> 01:30:11 ] =================================== FAILURES
> ===================================
> 01:30:11 ] TestAdmissionControllerStress.test_mem_limit[num_queries: 30 |
> submission_delay_ms: 0 | exec_option: {'batch_size': 0, 'num_nodes': 0,
> 'disable_codegen_rows_threshold': 5000, 'disable_codegen': False,
> 'abort_on_error': 1, 'exec_single_node_rows_threshold': 0} | table_format:
> text/none | round_robin_submission: True]
> 01:30:11 ] custom_cluster/test_admission_controller.py:877: in test_mem_limit
> 01:30:11 ] {'request_pool': self.pool_name, 'mem_limit': query_mem_limit})
> 01:30:11 ] custom_cluster/test_admission_controller.py:760: in
> run_admission_test
> 01:30:11 ] assert metric_deltas['rejected'] ==\
> 01:30:11 ] E assert 5 == ((30 - 15) - 15)
> {noformat}
> This is probably related to the following recent commit:
> https://github.com/apache/incubator-impala/commit/7487c5de04c2c5d97b8a8d5c935d10568f1ed686
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-all-unsubscr...@impala.apache.org
For additional commands, e-mail: issues-all-h...@impala.apache.org
