From c6308a1666bf871f1e51703c9040f14d87e6d708 Mon Sep 17 00:00:00 2001 From: Alex Schultz Date: Tue, 15 Sep 2020 14:47:33 -0600 Subject: [PATCH] Make profile tasks host aware When we switched to free, the task timing isn't accurate because it records time between two tasks. With free, the tasks may be on different hosts and not even the same task so the timing was the time between some tasks. This rewrite adjusts where we start and stop the task timing and includes a hostname in the calculation. The inclusion of the hostname allows us to pinpoint if tasks take longer on specific hosts as task ids are generally (but not always) the same between hosts. Change-Id: If0194091eb03186203e7724d506fdd36fd82baeb --- .../callback/tripleo_profile_tasks.py | 122 +++++++++++++----- 1 file changed, 89 insertions(+), 33 deletions(-) diff --git a/tripleo_ansible/ansible_plugins/callback/tripleo_profile_tasks.py b/tripleo_ansible/ansible_plugins/callback/tripleo_profile_tasks.py index 870dc5b67..6ecbaad4f 100644 --- a/tripleo_ansible/ansible_plugins/callback/tripleo_profile_tasks.py +++ b/tripleo_ansible/ansible_plugins/callback/tripleo_profile_tasks.py @@ -47,6 +47,7 @@ class CallbackModule(CallbackBase): def __init__(self): self.stats = collections.OrderedDict() + self.tasks = {} self.current = None self.sort_order = None self.task_output_limit = None @@ -74,12 +75,31 @@ class CallbackModule(CallbackBase): else: self.task_output_limit = int(self.task_output_limit) - def _timestamp(self): - if self.current is None: - return - self.stats[self.current]['time'] = ( - time.time() - self.stats[self.current]['time'] - ) + def _get_uuid(self, item=None): + uuid = '' + + if item and getattr(item, '_uuid', False): + # item is a task + uuid = item._uuid + elif item and getattr(item, '_task', False): + # item is a result (may not have a _task tho) + if getattr(item._task, '_uuid', False): + uuid = item._task._uuid + return '{:36}'.format(uuid) + + def _get_host(self, result): + delegated_vars = result._result.get('_ansible_delegated_vars', None) + if (getattr(result, '_host', False) + and getattr(result._host, 'get_name', False)): + msg = '%s' % result._host.get_name() + elif (getattr(result, '_host', False) + and getattr(result._host, 'name', False)): + msg = '%s' % result._host.name + else: + msg = 'UNKNOWN' + if delegated_vars: + msg += ' -> %s' % delegated_vars['ansible_host'] + return msg def _output(self, msg, color=None): timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f") @@ -89,43 +109,70 @@ class CallbackModule(CallbackBase): output = timestamp + ' | ' + msg self._display.display(output, color=color) - def _output_previous_timings(self, uuid): - # no previous timing because uuid was null - if not uuid: + def _start_task(self, task, host=None): + hostname = None + if host: + hostname = host.name + k = (hostname, task._uuid) + self.stats[k] = {'start': time.time(), + 'total_time': 0.0} + self.tasks[task._uuid] = task.get_name() + + def _end_task(self, result): + uuid = self._get_uuid(result) + host = self._get_host(result) + k = (host, uuid) + # the task never started, insert shrug emoji here. + if k not in self.stats: + self._display.warning('{} missing from stats'.format(k)) return + total_time = time.time() - self.stats[k]['start'] + self.stats[k]['total_time'] = total_time + line = [ uuid, u'{:>10}'.format('TIMING'), - self.stats[uuid].get('name', 'NONAME'), - str(timedelta(seconds=(time.time() - self.start_time))), - u'{0:.02f}s'.format(self.stats[uuid].get('time', '-1')) + self.tasks.get(uuid, ''), + host, + str(timedelta(seconds=time.time() - self.start_time)), + u'{0:.02f}s'.format(total_time) ] self._output(line, C.COLOR_DEBUG) - def _record_task(self, task): - self._timestamp() - self._output_previous_timings(self.current) - self.current = task._uuid - self.stats[self.current] = {'time': time.time(), - 'name': task.get_name()} - if self._display.verbosity >= 2: - self.stats[self.current]['path'] = task.get_path() + def v2_runner_on_start(self, host, task): + self._start_task(task, host) - def v2_playbook_on_task_start(self, task, is_conditional): - self._record_task(task) + # task ends + def v2_playbook_on_failed(self, result, ignore_errors=False): + self._end_task(result) - def v2_playbook_on_handler_task_start(self, task): - self._record_task(task) + def v2_runner_on_ok(self, result): + self._end_task(result) + def v2_runner_item_on_ok(self, result): + self._end_task(result) + + def v2_runner_on_failed(self, result, ignore_errors=False): + self._end_task(result) + + def v2_runner_item_on_failed(self, result): + self._end_task(result) + + def v2_runner_on_skipped(self, result): + self._end_task(result) + + def v2_runner_on_unreachable(self, result): + self._end_task(result) + + # playbook finished def playbook_on_stats(self, stats): - self._timestamp() self.current = None results = self.stats.items() # Sort the tasks by the specified sort if self.sort_order is not None: results = sorted( self.stats.items(), - key=lambda x: x[1]['time'], + key=lambda x: x[1]['total_time'], reverse=self.sort_order, ) results = results[:self.task_output_limit] @@ -134,26 +181,35 @@ class CallbackModule(CallbackBase): ' Summary Information ' '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~') self._output( - '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~' + '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~' + ' Total Tasks: {:<10} ' + '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~'.format(len(self.tasks))) + + self._output( + '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~' ' Elapsed Time: {} ' - '~~~~~~~~~~~~~~~~~~~~~~~~~~~~'.format( + '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~'.format( str(timedelta(seconds=(time.time() - self.start_time))))) header = [ '{:>36}'.format('UUID'), '{:>10}'.format('Info'), - '{}'.format('Task Name'), + '{:>10}'.format('Host'), + '{:>11}'.format('Task Name'), '{:>10}'.format('Run Time'), ] self._output(' | '.join(header)) - for uuid, result in results: + for (host, uuid), result in results: line = [ uuid, u'{:>10}'.format('SUMMARY'), - result['name'], - u'{0:.02f}s'.format(result['time']) + u'{:>10}'.format(host), + self.tasks.get(uuid, ''), + u'{0:.02f}s'.format(result['total_time']) ] self._output(' | '.join(line)) - self._output('~' * 89) + self._output('~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~' + ' End Summary Information ' + '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~')