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 ansible.cfg.

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

TASK [setup] *******************************************************************
Tuesday 06 December 2016  16:52:42 -0500 (0:00:00.037)       0:00:00.038 ******
ok: [el7]

TASK [gitlab : Include distribution specific variables] ************************
Tuesday 06 December 2016  16:52:42 -0500 (0:00:00.809)       0:00:00.847 ******
ok: [el7]

TASK [gitlab : Copy GitLab repo file] ******************************************
Tuesday 06 December 2016  16:52:43 -0500 (0:00:00.422)       0:00:01.311 ******
ok: [el7]

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

===============================================================================
gitlab : RHEL | Install GitLab CE -------------------------------------- 92.86s
gitlab : reconfigure gitlab -------------------------------------------- 79.59s
gitlab : RHEL | Install support packages ------------------------------- 23.69s
gitlab : upgrade gitlab ------------------------------------------------ 15.38s
gitlab : restart gitlab ------------------------------------------------- 6.29s
gitlab : RHEL | Install GitLab GPG key ---------------------------------- 1.99s
setup ------------------------------------------------------------------- 0.77s
gitlab : Copy gitlab.rb ------------------------------------------------- 0.73s
gitlab : Copy GitLab repo file ------------------------------------------ 0.72s
gitlab : Create gitlab-ci user ------------------------------------------ 0.59s
gitlab : Ensure GitLab accounts never expire ---------------------------- 0.54s
gitlab : Start and enable mail ------------------------------------------ 0.44s
gitlab : Create cron job to backup GitLab daily ------------------------- 0.39s
gitlab : Get current GitLab version ------------------------------------- 0.39s
gitlab : wait for unicorn ----------------------------------------------- 0.38s
gitlab : Create cron job to remove old GitLab backups ------------------- 0.27s
gitlab : include -------------------------------------------------------- 0.04s
gitlab : Include distribution specific variables ------------------------ 0.04s
gitlab : Copy GitLab CI SSL certificate ---------------------------------- 0.03s
gitlab : Copy GitLab CI SSL private key --------------------------------- 0.03s

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.