From b3aa373932848930606d4cd2e34c4e325820bcca Mon Sep 17 00:00:00 2001 From: Joel Date: Thu, 25 Feb 2016 09:52:56 -0600 Subject: [PATCH] Update the profile task callback plugin to include a fix for duplicate named tasks. Added additional features to adjust the number of tasks output and the sort order. --- lib/ansible/plugins/callback/profile_tasks.py | 57 ++++++++++++------- .../plugins/callback/profile_tasks.rst | 19 ++++--- 2 files changed, 47 insertions(+), 29 deletions(-) diff --git a/lib/ansible/plugins/callback/profile_tasks.py b/lib/ansible/plugins/callback/profile_tasks.py index e4004c97d4..644c5653a5 100644 --- a/lib/ansible/plugins/callback/profile_tasks.py +++ b/lib/ansible/plugins/callback/profile_tasks.py @@ -1,3 +1,4 @@ +# (C) 2016, Joel, http://github.com/jjshoe # (C) 2015, Tom Paine, # (C) 2014, Jharrod LaFon, @JharrodLaFon # (C) 2012-2013, Michael DeHaan, @@ -22,6 +23,8 @@ from __future__ import (absolute_import, division, print_function) __metaclass__ = type +import collections +import os import time from ansible.plugins.callback import CallbackBase @@ -49,7 +52,7 @@ def filled(msg, fchar="*"): def timestamp(self): if self.current is not None: - self.stats[self.current] = time.time() - self.stats[self.current] + self.stats[self.current]['time'] = time.time() - self.stats[self.current]['time'] def tasktime(): @@ -72,12 +75,22 @@ class CallbackModule(CallbackBase): CALLBACK_NEEDS_WHITELIST = True def __init__(self): - self.stats = {} + self.stats = collections.OrderedDict() self.current = None + self.sort_order = os.getenv('PROFILE_TASKS_SORT_ORDER', True) + self.task_output_limit = os.getenv('PROFILE_TASKS_TASK_OUTPUT_LIMIT', 20) + + if self.sort_order == 'ascending': + self.sort_order = False; + + if self.task_output_limit == 'all': + self.task_output_limit = None + else: + self.task_output_limit = int(self.task_output_limit) super(CallbackModule, self).__init__() - def _record_task(self, name): + def _record_task(self, task): """ Logs the start of each task """ @@ -85,14 +98,14 @@ class CallbackModule(CallbackBase): timestamp(self) # Record the start time of the current task - self.current = name - self.stats[self.current] = time.time() + self.current = task._uuid + self.stats[self.current] = {'time': time.time(), 'name': task.get_name(), 'path': task.get_path()} - def playbook_on_task_start(self, name, is_conditional): - self._record_task(name) + def v2_playbook_on_task_start(self, task, is_conditional): + self._record_task(task) def v2_playbook_on_handler_task_start(self, task): - self._record_task('HANDLER: ' + task.name) + self._record_task(task) def playbook_on_setup(self): self._display.display(tasktime()) @@ -103,21 +116,25 @@ class CallbackModule(CallbackBase): timestamp(self) - # Sort the tasks by their running time - results = sorted( - self.stats.items(), - key=lambda value: value[1], - reverse=True, - ) + results = self.stats.items() - # Just keep the top 20 - results = results[:20] + # Sort the tasks by the specified sort + if self.sort_order != 'none': + results = sorted( + self.stats.iteritems(), + key=lambda x:x[1]['time'], + reverse=self.sort_order, + ) + + # Display the number of tasks specified or the default of 20 + results = results[:self.task_output_limit] # Print the timings - for name, elapsed in results: + for uuid, result in results: self._display.display( - "{0:-<70}{1:->9}".format( - '{0} '.format(name), - ' {0:.02f}s'.format(elapsed), + "{0:-<70}{1:-<70}{2:->9}".format( + '{0} '.format(result['path']), + '{0} '.format(result['name']), + ' {0:.02f}s'.format(result['time']), ) ) diff --git a/lib/ansible/plugins/callback/profile_tasks.rst b/lib/ansible/plugins/callback/profile_tasks.rst index a125d64260..97c0685d62 100644 --- a/lib/ansible/plugins/callback/profile_tasks.rst +++ b/lib/ansible/plugins/callback/profile_tasks.rst @@ -15,6 +15,11 @@ Add ``profile_tasks`` to the ``callback_whitelist`` in ``ansible.cfg``. Run playbooks as normal. +Certain options are configurable using environment variables. You can specify ``ascending`` or ``none`` for +the environment variable ``PROFILE_TASKS_SORT_ORDER`` to adjust sorting output. If you want to see more than +20 tasks in the output you can set ``PROFILE_TASKS_TASK_OUTPUT_LIMIT`` to any number, or the special value +``all`` to get a list of all tasks. + Features -------- @@ -53,15 +58,11 @@ No more wondering how old the results in a terminal window are. PLAY RECAP ******************************************************************** Thursday 11 June 2016 22:51:00 +0100 (0:00:01.011) 0:00:43.247 ********* =============================================================================== - really slow task | Download project packages----------------------------11.61s - security | Really slow security policies----------------------------------7.03s - common-base | Install core system dependencies----------------------------3.62s - common | Install pip------------------------------------------------------3.60s - common | Install boto-----------------------------------------------------3.57s - nginx | Install nginx-----------------------------------------------------3.41s - serf | Install system dependencies----------------------------------------3.38s - duo_security | Install Duo Unix SSH Integration---------------------------3.37s - loggly | Install TLS version----------------------------------------------3.36s + /home/bob/ansible/roles/old_and_slow/tasks/main.yml:4 ----------------old_and_slow : install tons of packages -------------------------------- 20.03s + /home/bob/ansible/roles/db/tasks/main.yml:4 --------------------------db : second task to run ------------------------------------------------- 2.03s + None -----------------------------------------------------------------setup ------------------------------------------------------------------- 0.42s + /home/bob/ansible/roles/www/tasks/main.yml:1 -------------------------www : first task to run ------------------------------------------------- 0.03s + /home/bob/ansible/roles/fast_task.yml:1 ------------------------------fast_task : first task to run ------------------------------------------- 0.01s Compatibility -------------