How to measure and display time taken for tasks when running ansible-playbook?

Question

I have one playbook and in this playbook, there are so many tasks. I need to know which task has taken how much time?

Is there any solution?

Answer 1

Add callbacks_enabled = profile_tasks in the [default] section in your ansible.cfg.

(Or callback_whitelist for Ansible < 2.11.)

Here is my ansible.cfg

[defaults]
inventory = hosts
callbacks_enabled = profile_tasks
deprecation_warnings = False

Here is my playbook

- hosts: localhost
  gather_facts: true
  tasks:
    - name: Sleep for 10 Sec
      command: sleep 10

    - name: Sleep for 5 Sec
      command: sleep 5

    - name: Sleep for 2 Sec
      command: sleep 2

Here is my play output.

PLAY [localhost] ***************************************

TASK [Gathering Facts] *********************************
Thursday 28 May 2020  09:36:04 +0000 (0:00:00.038)       0:00:00.038 **********
ok: [localhost]

TASK [Sleep for 10 Sec] ********************************
Thursday 28 May 2020  09:36:07 +0000 (0:00:03.695)       0:00:03.733 **********
changed: [localhost]

TASK [Sleep for 5 Sec] *********************************
Thursday 28 May 2020  09:36:18 +0000 (0:00:11.166)       0:00:14.899 **********
changed: [localhost]

TASK [Sleep for 2 Sec] *********************************
Thursday 28 May 2020  09:36:24 +0000 (0:00:05.965)       0:00:20.865 **********
changed: [localhost]

PLAY RECAP *********************************************
localhost                  : ok=4    changed=3    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

Thursday 28 May 2020  09:36:27 +0000 (0:00:02.878)       0:00:23.744 **********
===============================================================================
Sleep for 10 Sec------------------------------------------------ 11.17s
Sleep for 5 Sec------------------------------------------------- 5.97s
Gathering Facts------------------------------------------------- 3.70s
Sleep for 2 Sec ------------------------------------------------- 2.88s

Here at last it shows how much time each task took to complete the play.

The explanation about the parameter callbacks_enabled = profile_tasks is found in the official ansible doc...

https://docs.ansible.com/ansible/latest/plugins/callback.html#enabling-callback-plugins

https://docs.ansible.com/ansible/latest/plugins/callback.html#plugin-list

https://docs.ansible.com/ansible/latest/plugins/callback/profile_tasks.html

Answer 2

if you want to access that time within a playbook you can do something like this:

- name: Start
  set_fact:
    start_time: "{{ ansible_date_time.iso8601[:19] }}"

... do a bunch of stuff

- name: force update of current timestamp
  setup: filter='ansible_date_time'
- name: Get runtime
  set_fact:
    runtime: "{{ ((ansible_date_time.iso8601[:19] | to_datetime('%Y-%m-%dT%H:%M:%S')) - (start_time | to_datetime('%Y-%m-%dT%H:%M:%S'))).seconds }}"

That fact will then be accessible to you as "{{ runtime }}"

You have to force the update of ansible_date_time because it's gathered as a fact initially, and otherwise not refreshed.

Answer 3

callback_whitelist is deprecated and will be removed in Ansible 2.15), callbacks_enabled (introduced in 2.11) should be used instead in modern versions of Ansible

[defaults]
...
callbacks_enabled = ansible.posix.profile_tasks

Reference:

https://docs.ansible.com/ansible/latest/reference_appendices/config.html#callbacks-enabled