IMPALA-4987: Fix flaky test test_row_availability.py This patch keeps test_row_availbility from randomly failing. In this test the time interval between the 'Rows available' timeline event and the previous event in the runtime profile is measured in order to make sure that the rows become available after a specific amount of time. This measurement is not correct since the previous event is that the coordinator finished sending the query fragments to the backends, which means the execution on some backends might have already started. This patch tracks another event "Ready to start" as the beginning of the time interval instead. The coordinator begins to send the query fragments to the backends after this event so the time check should always pass.
Change-Id: I96142f1868a26426cbc34aa9a0e0a56979df66c3 Reviewed-on: http://gerrit.cloudera.org:8080/8036 Reviewed-by: Alex Behm <[email protected]> Tested-by: Impala Public Jenkins Project: http://git-wip-us.apache.org/repos/asf/incubator-impala/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-impala/commit/d7e41a37 Tree: http://git-wip-us.apache.org/repos/asf/incubator-impala/tree/d7e41a37 Diff: http://git-wip-us.apache.org/repos/asf/incubator-impala/diff/d7e41a37 Branch: refs/heads/master Commit: d7e41a3776991645577412583b2116fa0d3f192a Parents: 4a5757f Author: Tianyi Wang <[email protected]> Authored: Mon Sep 11 18:41:30 2017 -0700 Committer: Impala Public Jenkins <[email protected]> Committed: Wed Sep 13 00:55:05 2017 +0000 ---------------------------------------------------------------------- tests/query_test/test_rows_availability.py | 51 +++++++++++++++---------- 1 file changed, 30 insertions(+), 21 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/d7e41a37/tests/query_test/test_rows_availability.py ---------------------------------------------------------------------- diff --git a/tests/query_test/test_rows_availability.py b/tests/query_test/test_rows_availability.py index fa1ecb8..d8db865 100644 --- a/tests/query_test/test_rows_availability.py +++ b/tests/query_test/test_rows_availability.py @@ -71,31 +71,40 @@ class TestRowsAvailability(ImpalaTestSuite): self.impalad_test_service.wait_for_query_state(self.client, handle, self.client.QUERY_STATES['FINISHED'], timeout=20) - # Parse the query profile for the 'Rows available' timeline event. - rows_avail_line = self.__get_rows_available_event(handle) - # Match the parenthesized delta duration between the 'Rows available' event - # and the previous event. - matches = re.search(r'\(.*\)', rows_avail_line) - if matches is None: - assert False, "Failed to find parenthesized delta time in %s" % rows_avail_line - # Strip out parenthesis. - rows_avail_ms_str = matches.group(0)[1:-1] - rows_avail_ms = self.__parse_duration_ms(rows_avail_ms_str) - assert rows_avail_ms >= self.ROWS_AVAIL_LOWER_BOUND_MS,\ + profile = self.client.get_runtime_profile(handle) + start_time_ms = None + rows_avail_time_ms = None + for line in profile.split("\n"): + if "Ready to start on" in line: + start_time_ms = self.__parse_time_ms(self.__find_time(line)) + elif "Rows available:" in line: + rows_avail_time_ms = self.__parse_time_ms(self.__find_time(line)) + + if start_time_ms is None: + assert False, "Failed to find the 'Ready to start' timeline event in the " \ + "query profile:\n%s" % profile + if rows_avail_time_ms is None: + assert False, "Failed to find the 'Rows available' timeline event in the " \ + "query profile:\n%s" % profile + time_diff = rows_avail_time_ms - start_time_ms + assert time_diff >= self.ROWS_AVAIL_LOWER_BOUND_MS,\ "The 'Rows available' timeline event was marked prematurely %sms after the "\ - "previous timeline event.\nExpected the event to be marked no earlier than "\ - "%sms after the previous event.\nQuery: %s"\ - % (rows_avail_ms, self.ROWS_AVAIL_LOWER_BOUND_MS, query) + "'Ready to start' event.\nExpected the event to be marked no earlier than "\ + "%sms after the 'Ready to start' event.\nQuery: %s"\ + % (time_diff, self.ROWS_AVAIL_LOWER_BOUND_MS, query) self.close_query(handle) - def __get_rows_available_event(self, query_handle): - profile = self.client.get_runtime_profile(query_handle) - for line in profile.split("\n"): - if "Rows available:" in line: return line - assert False, "Failed to find the 'Rows available' timeline event in the "\ - "query profile:\n%s" % profile + @staticmethod + def __find_time(line): + """Find event time point in a line from the runtime profile timeline.""" + # Given line "- Rows available: 3s311ms (2s300ms)", this function returns "3s311ms" + match = re.search(r': (.*) \(', line) + if match is None: + assert False, "Failed to find time in runtime profile" + return match.group(1) - def __parse_duration_ms(self, duration): + @staticmethod + def __parse_time_ms(duration): """Parses a duration string of the form 1h2h3m4s5.6ms into milliseconds.""" matches = re.findall(r'([0-9]+h)?([0-9]+m)?([0-9]+s)?([0-9]+(\.[0-9]+)?ms)?', duration)
