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

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):
+    def _get_uuid(self, item=None):
-        if self.current is None:
+        uuid = ''
-            return
+
-        self.stats[self.current]['time'] = (
+        if item and getattr(item, '_uuid', False):
-            time.time() - self.stats[self.current]['time']
+            # 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):
+    def _start_task(self, task, host=None):
-        # no previous timing because uuid was null
+        hostname = None
-        if not uuid:
+        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'),
+            self.tasks.get(uuid, ''),
-            str(timedelta(seconds=(time.time() - self.start_time))),
+            host,
-            u'{0:.02f}s'.format(self.stats[uuid].get('time', '-1'))
+            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):
+    def v2_runner_on_start(self, host, task):
-        self._timestamp()
+        self._start_task(task, host)
-        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_playbook_on_task_start(self, task, is_conditional):
+    # task ends
-        self._record_task(task)
+    def v2_playbook_on_failed(self, result, ignore_errors=False):
+        self._end_task(result)
 
-    def v2_playbook_on_handler_task_start(self, task):
+    def v2_runner_on_ok(self, result):
-        self._record_task(task)
+        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'{:>10}'.format(host),
-                u'{0:.02f}s'.format(result['time'])
+                self.tasks.get(uuid, ''),
+                u'{0:.02f}s'.format(result['total_time'])
             ]
             self._output(' | '.join(line))
 
-        self._output('~' * 89)
+        self._output('~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~'
+                     ' End Summary Information '
+                     '~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~')