openstack/tripleo-ansible
Code Issues Proposed changes

Make profile tasks host aware

Browse Source 
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
(cherry picked from commit c6308a1666)
This commit is contained in:
Alex Schultz 2020-09-15 14:47:33 -06:00
parent 29e0b91eef
commit a32091f5ff
1 changed files with 90 additions and 32 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

122
tripleo_ansible/ansible_plugins/callback/tripleo_profile_tasks.py
View File

@ -48,6 +48,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
@ -75,12 +76,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")
@ -90,43 +110,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]
@ -135,24 +182,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('~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~'
' End Summary Information '
'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~')