def test_rows_availability(self, vector):
# This test is run serially because it requires the query to come back within
# some amount of time. Running this with other tests makes it hard to bound
# that time.
query = vector.get_value('query')
# Execute async to get a handle. Wait until the query has completed.
handle = self.execute_query_async(query, vector.get_value('exec_option'))
self.impalad_test_service.wait_for_query_state(self.client, handle,
self.client.QUERY_STATES['FINISHED'], timeout=20)
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 = parse_duration_string_ms(self.__find_time(line))
elif "Rows available:" in line:
rows_avail_time_ms = parse_duration_string_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 "\
"'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 test_rows_sent_counters(self, vector):
"""Validate that ClientFetchWaitTimer, NumRowsFetched, RowMaterializationRate,
and RowMaterializationTimer are set to valid values in the ImpalaServer section
of the runtime profile."""
num_rows = 25
query = "select sleep(100) from functional.alltypes limit {0}".format(num_rows)
handle = self.execute_query_async(query, vector.get_value('exec_option'))
try:
# Wait until the query is 'FINISHED' and results are available for fetching.
self.wait_for_state(handle, self.client.QUERY_STATES['FINISHED'], 30)
# Sleep for 2.5 seconds so that the ClientFetchWaitTimer is >= 1s.
sleep(2.5)
# Fetch the results so that the fetch related counters are updated.
assert self.client.fetch(query, handle).success
runtime_profile = self.client.get_runtime_profile(handle)
fetch_timer = re.search("ClientFetchWaitTimer: (.*)", runtime_profile)
assert fetch_timer and len(fetch_timer.groups()) == 1 and \
parse_duration_string_ms(fetch_timer.group(1)) > 1000
assert "NumRowsFetched: {0} ({0})".format(num_rows) in runtime_profile
assert re.search("RowMaterializationRate: [1-9]", runtime_profile)
# The query should take at least 1s to materialize all rows since it should sleep
# for at least 1s during materialization.
materialization_timer = re.search("RowMaterializationTimer: (.*)", runtime_profile)
assert materialization_timer and len(materialization_timer.groups()) == 1 and \
parse_duration_string_ms(materialization_timer.group(1)) > 1000
finally:
self.client.close_query(handle)
def test_hash_join_timer(self, vector):
# This test runs serially because it requires the query to come back within
# some amount of time. Running this with other tests makes it hard to bound
# that time. It also assumes that it will be able to get a thread token to
# execute the join build in parallel.
test_case = vector.get_value('test cases')
query = test_case[0]
join_type = test_case[1]
# Ensure that the cluster is idle before starting the test query.
for impalad in ImpalaCluster.get_e2e_test_cluster().impalads:
verifier = MetricVerifier(impalad.service)
verifier.wait_for_metric("impala-server.num-fragments-in-flight",
0)
# Execute the query. The query summary and profile are stored in 'result'.
result = self.execute_query(query, vector.get_value('exec_option'))
# Parse the query summary; The join node is "id=3".
# In the ExecSummary, search for the join operator's summary and verify the
# avg and max times are within acceptable limits.
exec_summary = result.exec_summary
check_execsummary_count = 0
join_node_name = "03:%s" % (join_type)
for line in exec_summary:
if line['operator'] == join_node_name:
avg_time_ms = line['avg_time'] / self.NANOS_PER_MILLI
self.__verify_join_time(avg_time_ms, "ExecSummary Avg")
max_time_ms = line['max_time'] / self.NANOS_PER_MILLI
self.__verify_join_time(max_time_ms, "ExecSummary Max")
check_execsummary_count += 1
assert (check_execsummary_count == 1), \
"Unable to verify ExecSummary: {0}".format(exec_summary)
# Parse the query profile; The join node is "id=3".
# In the profiles, search for lines containing "(id=3)" and parse for the avg and
# non-child times to verify that they are within acceptable limits. Also verify
# that the build side is built in a different thread by searching for the string:
# "Join Build-Side Prepared Asynchronously"
profile = result.runtime_profile
check_fragment_count = 0
asyn_build = False
for line in profile.split("\n"):
if ("(id=3)" in line):
# Sample line:
# HASH_JOIN_NODE (id=3):(Total: 3s580ms, non-child: 11.89ms, % non-child: 0.31%)
strip1 = re.split("non-child: ", line)[1]
non_child_time = re.split(", ", strip1)[0]
non_child_time_ms = parse_duration_string_ms(non_child_time)
self.__verify_join_time(non_child_time_ms,
"Fragment non-child")
check_fragment_count += 1
# Search for "Join Build-Side Prepared Asynchronously"
if ("Join Build-Side Prepared Asynchronously" in line):
asyn_build = True
assert (asyn_build
), "Join is not prepared asynchronously: {0}".format(profile)
assert (check_fragment_count > 1), \
"Unable to verify Fragment or Average Fragment: {0}".format(profile)
def __verify_join_time(self, duration, comment):
duration_ms = parse_duration_string_ms(duration)
if (duration_ms > self.HASH_JOIN_UPPER_BOUND_MS):
assert False, "Hash join timing too high for %s: %s %s" % (
comment, duration, duration_ms)
if (duration_ms < self.HASH_JOIN_LOWER_BOUND_MS):
assert False, "Hash join timing too low for %s: %s %s" % (
comment, duration, duration_ms)
def test_hash_join_timer(self, vector):
# This test runs serially because it requires the query to come back within
# some amount of time. Running this with other tests makes it hard to bound
# that time. It also assumes that it will be able to get a thread token to
# execute the join build in parallel.
test_case = vector.get_value('test cases')
query = test_case[0]
join_type = test_case[1]
# Ensure that the cluster is idle before starting the test query.
for impalad in ImpalaCluster().impalads:
verifier = MetricVerifier(impalad.service)
verifier.wait_for_metric("impala-server.num-fragments-in-flight", 0)
# Execute the query. The query summary and profile are stored in 'result'.
result = self.execute_query(query, vector.get_value('exec_option'))
# Parse the query summary; The join node is "id=3".
# In the ExecSummary, search for the join operator's summary and verify the
# avg and max times are within acceptable limits.
exec_summary = result.exec_summary
check_execsummary_count = 0
join_node_name = "03:%s" % (join_type)
for line in exec_summary:
if line['operator'] == join_node_name:
avg_time_ms = line['avg_time'] / self.NANOS_PER_MILLI
self.__verify_join_time(avg_time_ms, "ExecSummary Avg")
max_time_ms = line['max_time'] / self.NANOS_PER_MILLI
self.__verify_join_time(max_time_ms, "ExecSummary Max")
check_execsummary_count += 1
assert (check_execsummary_count == 1), \
"Unable to verify ExecSummary: {0}".format(exec_summary)
# Parse the query profile; The join node is "id=3".
# In the profiles, search for lines containing "(id=3)" and parse for the avg and
# non-child times to verify that they are within acceptable limits. Also verify
# that the build side is built in a different thread by searching for the string:
# "Join Build-Side Prepared Asynchronously"
profile = result.runtime_profile
check_fragment_count = 0
asyn_build = False
for line in profile.split("\n"):
if ("(id=3)" in line):
# Sample line:
# HASH_JOIN_NODE (id=3):(Total: 3s580ms, non-child: 11.89ms, % non-child: 0.31%)
strip1 = re.split("non-child: ", line)[1]
non_child_time = re.split(", ", strip1)[0]
non_child_time_ms = parse_duration_string_ms(non_child_time)
self.__verify_join_time(non_child_time_ms, "Fragment non-child")
check_fragment_count += 1
# Search for "Join Build-Side Prepared Asynchronously"
if ("Join Build-Side Prepared Asynchronously" in line):
asyn_build = True
assert (asyn_build), "Join is not prepared asynchronously: {0}".format(profile)
assert (check_fragment_count > 1), \
"Unable to verify Fragment or Average Fragment: {0}".format(profile)
def test_rows_availability(self, vector):
# This test is run serially because it requires the query to come back within
# some amount of time. Running this with other tests makes it hard to bound
# that time.
query = vector.get_value('query')
# Execute async to get a handle. Wait until the query has completed.
handle = self.execute_query_async(query,
vector.get_value('exec_option'))
self.impalad_test_service.wait_for_query_state(
self.client,
handle,
self.client.QUERY_STATES['FINISHED'],
timeout=20)
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 = parse_duration_string_ms(
self.__find_time(line))
elif "Rows available:" in line:
rows_avail_time_ms = parse_duration_string_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 "\
"'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 test_host_profile_jvm_gc_metrics(self, unique_database):
self.execute_query_expect_success(
self.client,
"create function {0}.gc(int) returns int location '{1}' \
symbol='org.apache.impala.JavaGcUdfTest'".format(
unique_database,
get_fs_path('/test-warehouse/impala-hive-udfs.jar')))
profile = self.execute_query_expect_success(
self.client,
"select {0}.gc(int_col) from functional.alltypes limit 1000".
format(unique_database)).runtime_profile
gc_count_regex = "GcCount:.*\((.*)\)"
gc_count_match = re.search(gc_count_regex, profile)
assert gc_count_match, profile
assert int(gc_count_match.group(1)) > 0, profile
gc_time_millis_regex = "GcTimeMillis: (.*)"
gc_time_millis_match = re.search(gc_time_millis_regex, profile)
assert gc_time_millis_match, profile
assert parse_duration_string_ms(gc_time_millis_match.group(1)) > 0