Add a --profile option to spot which task takes more time

4 files changed, 109 insertions, 0 deletions

diff --git a/ansible-profile/LICENSE b/ansible-profile/LICENSE
new file mode 100644
index 000000000..1c0495384
--- /dev/null
+++ b/ansible-profile/LICENSE
@@ -0,0 +1,20 @@
+The MIT License (MIT)
+
+Copyright (c) 2014 Jharrod LaFon
+
+Permission is hereby granted, free of charge, to any person obtaining a copy of
+this software and associated documentation files (the "Software"), to deal in
+the Software without restriction, including without limitation the rights to
+use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of
+the Software, and to permit persons to whom the Software is furnished to do so,
+subject to the following conditions:
+
+The above copyright notice and this permission notice shall be included in all
+copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS
+FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
+COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER
+IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
+CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
diff --git a/ansible-profile/README.rst b/ansible-profile/README.rst
new file mode 100644
index 000000000..5c2e9069f
--- /dev/null
+++ b/ansible-profile/README.rst
@@ -0,0 +1,34 @@
+===============
+ansible-profile
+===============
+
+An Ansible plugin for timing tasks.
+
+
+Usage
+^^^^^
+
+Make a directory called `callback_plugins` next to your playbook and put `profile_tasks.py` inside of it.
+
+.. code-block:: bash
+
+    mkdir callback_plugins
+    cd callback_plugins
+    wget https://raw.githubusercontent.com/jlafon/ansible-profile/master/callback_plugins/profile_tasks.py
+
+Now, run your playbook just as you normally would!
+
+.. code-block:: bash
+
+   ansible <args here>
+   <normal output here>
+   PLAY RECAP ******************************************************************** 
+   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
diff --git a/ansible-profile/callback_plugins/profile_tasks.py b/ansible-profile/callback_plugins/profile_tasks.py
new file mode 100644
index 000000000..dc74ee291
--- /dev/null
+++ b/ansible-profile/callback_plugins/profile_tasks.py
@@ -0,0 +1,49 @@
+import time
+
+
+class CallbackModule(object):
+    """
+    A plugin for timing tasks
+    """
+    def __init__(self):
+        self.stats = {}
+        self.current = None
+
+    def playbook_on_task_start(self, name, is_conditional):
+        """
+        Logs the start of each task
+        """
+        if self.current is not None:
+            # Record the running time of the last executed task
+            self.stats[self.current] = time.time() - self.stats[self.current]
+
+        # Record the start time of the current task
+        self.current = name
+        self.stats[self.current] = time.time()
+
+    def playbook_on_stats(self, stats):
+        """
+        Prints the timings
+        """
+        # Record the timing of the very last task
+        if self.current is not None:
+            self.stats[self.current] = time.time() - self.stats[self.current]
+
+        # Sort the tasks by their running time
+        results = sorted(
+            self.stats.items(),
+            key=lambda value: value[1],
+            reverse=True,
+        )
+
+        # Just keep the top 10
+        results = results[:10]
+
+        # Print the timings
+        for name, elapsed in results:
+            print(
+                "{0:-<70}{1:->9}".format(
+                    '{0} '.format(name),
+                    ' {0:.02f}s'.format(elapsed),
+                )
+            )
diff --git a/bin/cluster b/bin/cluster
index 2ea389523..954322482 100755
--- a/bin/cluster
+++ b/bin/cluster
@@ -178,6 +178,9 @@ class Cluster(object):
             verbose, inventory, ansible_env, playbook
         )
 
+        if args.profile:
+            command = 'ANSIBLE_CALLBACK_PLUGINS=ansible-profile/callback_plugins ' + command
+
         if args.verbose > 1:
             command = 'time {}'.format(command)
 
@@ -234,6 +237,9 @@ if __name__ == '__main__':
     meta_parser.add_argument('-o', '--option', action='append',
                              help='options')
 
+    meta_parser.add_argument('-p', '--profile', action='store_true',
+                             help='Enable playbook profiling')
+
     action_parser = parser.add_subparsers(dest='action', title='actions',
                                           description='Choose from valid actions')