Ansible is a wonderful automation tool that I have used for many years now. I have quite a library of playbooks and roles varying widely in complexity. One thing that got much easier in recent years is measuring and improving the performance of playbooks. Ansible 2.2 brought major performance improvements to the core execution engine. Now is a perfect time for comparing playbook execution time and optimizing tasks and templates.
In the early days, I would prefix
ansible-playbook with the
time command. This was a handy way to measure overall execution time but didn’t give any metrics on how long each task took to execute. This output doesn’t allow you to zero in on the long-running tasks.
Ansible is built around many types of plugins, one of which is callback plugins. Callback plugins allow you to add some very interesting capabilities to Ansible, such as making your computer read the playbook as it runs. Ansible ships with a number of callback plugins that are ready to use out of box — you simply have to enable them in your
ansible.cfg. Add a comma separated list of callback plugins to
callback_whitelist in your
callback_whitelist = osx_say, mail
The particular callback plugin that will help with performance tuning our playbooks is called
profile_tasks which prints out a detailed breakdown of task execution times sorted from longest to shortest as well as a running timer during play execution.
timer is another useful callback plugin that prints total execution time, similar to
time but with more friendly output.
callback_whitelist = profile_tasks, timer
With those callback plugins enabled, run your playbook the same and you’ll see more output.
1 2 3 4 5 6 7 8 9 10 11
At the end of the playbook run, you’ll see the following summary output:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21
Notice the tasks are sorted with the longest running tasks on top, making it easy to identify the best candidates for optimization. I find this technique particularly useful when working with complex templates that involved loops or nested loops. I have cut some of my playbook execution times down to one tenth the original simply by changing code inside a template.
One thing to note is that Ansible uses the system clock of the control machine when doing its time math. So if you run any tasks that modify the system clock during the play, the output will not be accurate.
I hope this helps you analyze your playbooks and begin to optimize your tasks for faster execution. Also take a look at the callback plugins that ship with Ansible. They unlock some very interesting capabilities when enabled.