Introduction
The source on GitHub.
After spending far too much time wondering which of the tasks in my long list of Ansible tasks were slow, I decided to do something about it. In the pursuit of automating everything, I've constructed a large collection of playbooks, complete with their own dependencies, to do just about anything that needs to be done for my web service stacks. Where I used to grow tired of waiting on compilers, I now find myself waiting on development stacks deploying to AWS - a large part of that time being the Ansible process. Rather than guess which tasks were slow, I set out to write a simple plugin that would print how long each task took to complete.
Ansible Plugins
I found out that writing an Ansible plugin is almost too easy (see the docs if you don't believe me). There are several plugin types, but the useful one for this exercise is the callback plugin type, which allows you to define functions to be called when certain events occur.
The core of the plugin is a class, called CallbackModule. After defining the class, you add a method to the class that is invoked at the start of each task.
# profile_tasks.py
class CallbackModule(object):
"""
A plugin for timing tasks
"""
def playbook_on_task_start(self, name, is_conditional):
"""
Logs the start of each task
"""
pass
This is just the stub of the implementation. Unfortunately, there is no corresponding on_task_stop callback - I checked, so I have to measure the task running time in an indirect way. But because the tasks run in order, note that when a task begins that the previous task has necessarily ended, so I can reset the clock when that happens. At the end of the playbook, Ansible prints the results, and also fires a playbook_on_stats event which makes a convenient place for the stats to print.
# profile_tasks.py
import time
class CallbackModule(object):
"""
A plugin for timing tasks
"""
def __init__(self):
# For storing timings
self.stats = {}
# For storing the name of the current task
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]
self.current = name
# Record the start time of the current task
self.stats[self.current] = time.time()
def playbook_on_stats(self, stats):
"""
Print the timings
"""
if self.current is not None:
# Record the timing of the very last task
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))
Now I know which tasks are slow, so I'm off to profile those in more detail.