[06/11] impala git commit: IMPALA-6399: Fix timeout logic in test_query_profile_thrift_timestamps

[ta...@apache.org]

IMPALA-6399: Fix timeout logic in test_query_profile_thrift_timestamps

In the previous fix for IMPALA-6399 we increased the number of retries.
However, there was a bug in the retry logic: If the profile was missing,
we would call 'continue' without sleeping, thus eating through the
maximum number of retries in a short period of time.

This change now switches to a time-based wait-loop instead of a set
number of retries. It also moves the sleep() to the beginning of the
loop to make it less likely to forget  it when changing the code in the
future. Calling sleep() before trying to fetch the profile for the first
time also reduces the likelihood of hitting a warning when the profile
is not yet available.

This change also increases the timeout to 300 seconds and marks the test
for serial execution to decrease the likelihood of races.

Change-Id: I2f0f3db75c52b8b2081dd15ed7e7d2a1d6b22389
Reviewed-on: http://gerrit.cloudera.org:8080/9079
Reviewed-by: Lars Volker <lv...@cloudera.com>
Tested-by: Lars Volker <lv...@cloudera.com>


Project: http://git-wip-us.apache.org/repos/asf/impala/repo
Commit: http://git-wip-us.apache.org/repos/asf/impala/commit/07ab8772
Tree: http://git-wip-us.apache.org/repos/asf/impala/tree/07ab8772
Diff: http://git-wip-us.apache.org/repos/asf/impala/diff/07ab8772

Branch: refs/heads/2.x
Commit: 07ab8772e5f1be7232f0e94bc197009469195349
Parents: e32b230
Author: Lars Volker <lv...@cloudera.com>
Authored: Fri Jan 19 10:57:43 2018 -0800
Committer: Philip Zeyliger <ph...@cloudera.com>
Committed: Wed Jan 24 10:17:56 2018 -0800

----------------------------------------------------------------------
 tests/query_test/test_observability.py | 34 +++++++++++++++++------------
 1 file changed, 20 insertions(+), 14 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/impala/blob/07ab8772/tests/query_test/test_observability.py
----------------------------------------------------------------------
diff --git a/tests/query_test/test_observability.py b/tests/query_test/test_observability.py
index d0d4ecd..e8599b5 100644
--- a/tests/query_test/test_observability.py
+++ b/tests/query_test/test_observability.py
@@ -19,6 +19,7 @@ from tests.common.impala_test_suite import ImpalaTestSuite
 from tests.common.skip import SkipIfS3, SkipIfADLS, SkipIfIsilon, SkipIfLocal
 from tests.common.impala_cluster import ImpalaCluster
 import logging
+import pytest
 import time
 
 class TestObservability(ImpalaTestSuite):
@@ -132,6 +133,9 @@ class TestObservability(ImpalaTestSuite):
     assert results.runtime_profile.count("AGGREGATION_NODE") == 2
     assert results.runtime_profile.count("PLAN_ROOT_SINK") == 2
 
+  # IMPALA-6399: Run this test serially to avoid a delay over the wait time in fetching
+  # the profile.
+  @pytest.mark.execute_serially
   def test_query_profile_thrift_timestamps(self):
     """Test that the query profile start and end time date-time strings have
     nanosecond precision. Nanosecond precision is expected by management API clients
@@ -142,17 +146,18 @@ class TestObservability(ImpalaTestSuite):
     results = self.client.fetch(query, handle)
     self.client.close()
 
-    start_time_sub_sec_str = ""
-    end_time_sub_sec_str = ""
-    start_time = ""
-    end_time = ""
-
-    MAX_RETRIES = 300
-    for retries in xrange(MAX_RETRIES):
+    MAX_WAIT = 300
+    start = time.time()
+    end = start + MAX_WAIT
+    while time.time() <= end:
+      # Sleep before trying to fetch the profile. This helps to prevent a warning when the
+      # profile is not yet available immediately. It also makes it less likely to
+      # introduce an error below in future changes by forgetting to sleep.
+      time.sleep(1)
       tree = self.impalad_test_service.get_thrift_profile(query_id)
-
-      if tree is None:
+      if not tree:
         continue
+
       # tree.nodes[1] corresponds to ClientRequestState::summary_profile_
       # See be/src/service/client-request-state.[h|cc].
       start_time = tree.nodes[1].info_strings["Start Time"]
@@ -161,9 +166,10 @@ class TestObservability(ImpalaTestSuite):
       start_time_sub_sec_str = start_time.split('.')[-1]
       end_time_sub_sec_str = end_time.split('.')[-1]
       if len(end_time_sub_sec_str) == 0:
-        logging.info('end_time_sub_sec_str hasn\'t shown up yet, retries=%d', retries)
-        time.sleep(1)
+        elapsed = time.time() - start
+        logging.info("end_time_sub_sec_str hasn't shown up yet, elapsed=%d", elapsed)
         continue
+
       assert len(end_time_sub_sec_str) == 9, end_time
       assert len(start_time_sub_sec_str) == 9, start_time
       return True
@@ -171,7 +177,7 @@ class TestObservability(ImpalaTestSuite):
     # If we're here, we didn't get the final thrift profile from the debug web page.
     # This could happen due to heavy system load. The test is then inconclusive.
     # Log a message and fail this run.
-    dbg_str = 'Debug thrift profile for query ' + str(query_id) + ' not available in '
-    dbg_str += str(MAX_RETRIES) + ' seconds, '
-    dbg_str += '(' + start_time + ', ' + end_time + ').'
+
+    dbg_str = "Debug thrift profile for query {0} not available in {1} seconds".format(
+      query_id, MAX_WAIT)
     assert False, dbg_str