Measure first, tune second

“Ansible is slow” is a complaint about wall-clock time, and it is almost always answered with the same guess: raise forks. Sometimes that helps. More often the run was spending eighty per cent of its time in one task that parallelism does nothing for, and the fork change makes the graph noisier without making the run shorter.

This part is about performance work, and it opens with measurement because every other lesson in it is a change you should not make without a baseline. The discipline is ordinary engineering practice and it is routinely skipped here, because Ansible’s settings are easy to change and its behaviour is hard to observe.

The timing callback is not in ansible-core

Start with the correction, because half the instructions on the internet predate it.

$ ansible-doc -t callback -l

ansible.builtin.default default Ansible screen output
ansible.builtin.junit   write playbook output to a JUnit file
ansible.builtin.minimal minimal Ansible screen output
ansible.builtin.oneline oneline Ansible screen output
ansible.builtin.tree    Save host events to files

Five callbacks, and no profile_tasks. It lives in the ansible.posix collection, along with profile_roles, timer and cgroup_perf_recap. If you installed the ansible community package you already have it; if you installed ansible-core and pinned your collections — which is what this course teaches — you have to ask for it.

# requirements.yml
collections:
- name: ansible.posix
  version: "2.1.0"

ansible-galaxy collection install -r requirements.yml

Then confirm — do not assume — that the name you are about to put in a config file resolves on your installation:

$ ansible-doc -t callback -l | grep -E 'profile|timer'

ansible.posix.cgroup_perf_recap        Profiles system activity of tasks an...
ansible.posix.profile_roles            adds timing information to roles
ansible.posix.profile_tasks            adds time information to tasks
ansible.posix.timer                    Adds time to play stats

A misspelled or unavailable callback name in callbacks_enabled produces a run with no timing output and no complaint, which is a slow way to discover you have not been measuring anything.

Enabling it

profile_tasks is an aggregate callback — it adds output alongside your normal stdout callback rather than replacing it, so enabling it does not change how the rest of the run is displayed.

Upstream gives the configuration form:

[defaults]
callbacks_enabled = ansible.posix.profile_tasks

For an investigation, the environment variable is better, because it applies to the one run you are measuring and leaves the repository untouched:

ANSIBLE_CALLBACKS_ENABLED=ansible.posix.profile_tasks \
ansible-playbook -i inventory/staging site.yml --check

The setting name changed in 2.11 — it was callback_whitelist before — and the environment variable is ANSIBLE_CALLBACKS_ENABLED, which ansible-config list confirms on your own controller if you are unsure.

What the output looks like

Two blocks are added. Each task banner gains a timestamp and two durations, and a TASKS RECAP at the end sorts tasks by wall-clock time.

$ ANSIBLE_CALLBACKS_ENABLED=ansible.posix.profile_tasks ansible-playbook -i slow.ini slow.yml -f 5

TASK [A second slow step] ******************************************************
Tuesday 11 August 2026  22:40:15 +0000 (0:00:00.016)       0:00:03.241 ********
ok: [web2]
ok: [web1]
ok: [web4]
ok: [web3]

TASKS RECAP ********************************************************************
Tuesday 11 August 2026  22:40:16 +0000 (0:00:01.149)       0:00:04.391 ********
===============================================================================
Wait for a slow dependency ---------------------------------------------- 3.20s
A second slow step ------------------------------------------------------ 1.15s
Another quick step ------------------------------------------------------ 0.02s
Quick check ------------------------------------------------------------- 0.02s

Three numbers, and they are easy to confuse:

• The timestamp is when the task started.
• The first duration in brackets is how long the previous task took.
• The second duration is elapsed time since the play began.

The TASKS RECAP is where the answer usually is. In that run, two tasks account for 4.35 of 4.39 seconds and the other two are rounding error. No amount of forks tuning moves the 3.20-second task, because it was not waiting on parallelism.

The finding you will usually get

Here is the same profiler on a play that does nothing but gather facts and print one value, across 24 hosts:

$ ANSIBLE_CALLBACKS_ENABLED=ansible.posix.profile_tasks ansible-playbook -i facts.ini facts.yml -f 12

TASKS RECAP ********************************************************************
Tuesday 11 August 2026  22:42:02 +0000 (0:00:00.121)       0:00:02.558 ********
===============================================================================
Gathering Facts --------------------------------------------------------- 2.43s
Nothing else ------------------------------------------------------------ 0.12s

Fact gathering was 95% of the run. That result is not a quirk of this example — it is the single most common finding when someone profiles a real playbook for the first time, and it is the reason two later lessons in this part are about facts rather than about concurrency.

The second most common finding is one task: a package manager refreshing metadata, a wait_for on something slow to start, a command invoking a script that sleeps, or a module that makes a network call per host.

Neither of those is fixed by forks. Both are obvious in a TASKS RECAP and invisible in a wall-clock number.

The investigation loop

1. BASELINE   Profile the run as it is. Three times. Record the TASKS RECAP.
2. IDENTIFY   Name the one task or phase that dominates. Write it down.
3. CHANGE     Change exactly one thing, aimed at that finding.
4. RE-MEASURE Profile again, three times, same inventory, same conditions.
5. DECIDE     Keep it if the improvement exceeds the run-to-run spread.
            Revert it otherwise. "No measurable difference" is a result.
6. REPEAT     From step 1, with the new baseline.

The rule that makes this work is step 3, and the specific prohibition worth writing into a team runbook is this: do not change forks and pipelining in the same commit.

They fail differently and they interact. Raising forks increases controller load; enabling pipelining changes what happens on each managed node and requires a sudoers property to be true. Change both, get a regression, and you cannot tell whether the controller is saturated or half your fleet is rejecting a non-TTY sudo — and the second one presents as intermittent task failures that look nothing like a performance setting.

Knowledge check