Display the time it takes each vagrant ansible task to complete

Question

I'm converting a vagrant provisioner from shell to ansible and I was wondering if there's any option to show the actual time it takes to complete each task?

Ideally I want to benchmark the difference between installing multiple packages in yum using a shell: method and the in built yum: with_items method. ATM I'm sitting here with a stop watch but I need accurate times for this.

Answer 1

I've solved for timing Ansible task durations by adding a callback plugin. Callback plugins were designed to allow you to run your own arbitrary code based on events that happen in the context of an Ansible run.

The plugin I use is easily deployed by creating a callback_plugins directory and dropping a python script into it.

Here is an sample of the resulting output at the end of your playbook run:

PLAY RECAP ******************************************************************** 
npm_install_foo | Install node dependencies via npm ------------------- 194.92s
gulp_build | Run Gulp to build ----------------------------------------- 89.99s
nodejs | Update npm ---------------------------------------------------- 26.96s
common | Update apt cache and upgrade base os packages ----------------- 17.78s
forever | Install forever (restarts Node.js if it fails) --------------- 16.84s
nodejs | Node.js | Install Node.js and npm ----------------------------- 15.11s
bower | Install bower --------------------------------------------------- 9.37s
Copy locally fetched repo to each instance ------------------------------ 8.03s
express | Express | Install Express ------------------------------------- 8.00s

Additionally, I prepend the shell command time to the ansible-playbook run. This nicely aggregates all of the individual task durations.

EDIT #1:

As of Ansible v2.0.0 this particular plugin ships with Ansible itself! Just add callbacks_enabled = profile_tasks to your ~/.ansible.cfg file in the [defaults] section.

EDIT #2: Since Ansible v2.1.5 callback_whitelist has been deprecated in favor of callbacks_enabled.

[defaults]
callbacks_enabled = profile_tasks
...

Answer 2

Ansible puts timestamps into its logs, so you could use that. You can switch this on using your ansible.cfg file:

[defaults]
log_path = ./ansible.log

You could also do something crude like this - create a playbook that looks like this:

---
#
# Outputs a timestamp to the console
#
# Used for debugging/timing stuff.
#

- local_action: shell date +'%F %T'
  register: ts
  sudo: no

- name: Timestamp
  debug: msg="{{ ts.stdout }}"

Then include that wherever you want to output a timestamp.

Answer 3

Sadly, there is no performance logging by default.

But you can add your own callback listener to ansible. This call back will get notified on start and end of actions...

For complete example take a look at the datadog plugin

Answer 4

Simply prepend execution of the whole Ansible playbook with time. Make sure that your shell: script is doing the same thing as yum: module, such as update cache, download files vs using locally cached, etc etc.

Benefit of using yum: is, among other things, Ansible can better handle failed installs as opposed to just blindly running your shell: command as a monolithic thing.

I think the difference will be extremely small(fractions of a second to 2-3 seconds). I imagine you'd need to run your benchmark dozens of times to have statistically accurate results.