CODEWITHSUNDEEP
timeansibleansible-role
Dharti Sutariya
Dharti Sutariya

Reputation: 489

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

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?

Upvotes: 27

Views: 35132

Answers (5)

dlouzan
dlouzan

Reputation: 1040

Apart from using profile_tasks in your playbook (which is awesome as a general tool and I use it myself), if you need to calculate the specific time taken between two tasks and use the timestamps at your leisure in code, you can use a template with now():

  block:
    - name: Some long operation (e.g. database migrations) - register start
      set_fact:
        long_op_start: "{{ now() }}"
    - name: Some long operation
      command: run-something
    - name: Some long operation - register end
        long_op_end: "{{ now() }}"
    # Print debug info, or use the timestamps to calculate whatever you need
    - name: Print execution time
      debug:
        msg: "Long operation start: {{ long_op_start }}, end: {{ long_op_end }}"

Do not use ansible_date_time as that is cached at the beginning of the run as discussed above in another answer, and is currently discouraged, see upstream docs: https://docs.ansible.com/ansible/latest/playbook_guide/playbooks_vars_facts.html.

Upvotes: 1

Pradeep Kumar H C
Pradeep Kumar H C

Reputation: 686

Add callbacks_enabled = profile_tasks in the [defaults] 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

Upvotes: 50

amaterasu48
amaterasu48

Reputation: 29

Thanks to @James_SO, I was able to have Ansible calculate the seconds for the target tasks I wanted to measure the duration. That said, I had multiple of them, so gotcha for me was executing the following for every task I wanted to measure the duration.

- name: force update of current timestamp
  setup: filter='ansible_date_time'

Upvotes: -1

Konstantin Volenbovskyi
Konstantin Volenbovskyi

Reputation: 192

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

Upvotes: 12

James_SO
James_SO

Reputation: 1387

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.

Upvotes: 5

Related Questions