# timing tasks and plays.

**URL:** <https://forum.ansible.com/t/timing-tasks-and-plays/17761>\
**Category:** Ansible Developer\
**Created:** [March 17, 2015, 1:29am UTC](https://forum.ansible.com/t/timing-tasks-and-plays/17761 "2015-03-17T01:29:14Z")\
**Posts on this page:** 4\
**Page:** 1

<div class="post-metadata">

**Author:** ![Timothy\_Appnel](https://avatars.discourse-cdn.com/v4/letter/t/e5b9ba/32.png) [@Timothy\_Appnel](https://forum.ansible.com/u/Timothy_Appnel)\
**Post date:** [March 17, 2015, 1:29am UTC](https://forum.ansible.com/t/timing-tasks-and-plays/17761/1 "2015-03-17T01:29:14Z")

</div>

There’s been a bit of a metrics jihad going on at the day job that got me thinking about how I’d implement something in Ansible to time a playbook or each task. In fact we just had an incident where recording some playbook metrics would have been pretty helpful in spotting we had a problem. (It was what Ansible was running, not Ansible BTW.)

So my first thought to achieve that was to use callbacks. Thing is there is only start hooks (i.e. playbook\_on\_task\_start, playbook\_on\_play\_start), but not an end. Is that correct or is there some Ansible magic I’m missing? Admittedly I’ve not been able to keep up with the code base especially the v2 changes so I could be asking a question that’s already been answered.

Thoughts?

---

<div class="post-metadata">

**Author:** ![Brian\_Coca](https://avatars.discourse-cdn.com/v4/letter/b/6de8d8/32.png) [@Brian\_Coca](https://forum.ansible.com/u/Brian_Coca)\
**Post date:** [March 17, 2015, 1:35am UTC](https://forum.ansible.com/t/timing-tasks-and-plays/17761/2 "2015-03-17T01:35:18Z")

</div>

there already are a few useful callbacks to do what you want, for  
general profiling i use  
profile\_tasks.py, there are others that log to syslog, it should be  
pretty easy to compose exactly what you need.

As for the methods available to callbacks, check in  
lib/ansible/callbacks.py for the base class.

---

<div class="post-metadata">

**Author:** ![Timothy\_Appnel](https://avatars.discourse-cdn.com/v4/letter/t/e5b9ba/32.png) [@Timothy\_Appnel](https://forum.ansible.com/u/Timothy_Appnel)\
**Post date:** [March 17, 2015, 2:05am UTC](https://forum.ansible.com/t/timing-tasks-and-plays/17761/3 "2015-03-17T02:05:07Z")

</div>

Thanks Brian. I’m assuming you mean this plugin: [https://github.com/jlafon/ansible-profile/blob/master/callback\_plugins/profile\_tasks.py](https://github.com/jlafon/ansible-profile/blob/master/callback_plugins/profile_tasks.py).

That little bit of code is a clever way of dealing the lack of an explicit “end” callback point. So I can safely assume that between the end of one task and the start of another virtually nothing will run that may skew those timings? Perhaps this is an edge case, but couldn’t notification handler skew the last task? Something like a graceful restart of a server?

For the record I wasn’t being entirely clear to what meant. I wasn’t thinking about profiling but more about feeding a time series database like Graphite or InfluxDB where we could compare historical trends and monitor what’s been happening with Grafana et al. For instance, in the case I eluded to the playbook was being run via autosys and had been completing successful. What got missed was the steep climb in runtime some tasks were taking on a certain hosts over the course of multiple runs and days. Having metrics on the brain, it occurred to me that we would have caught that before it broke down if we had been collecting those sorts of numbers.

---

<div class="post-metadata">

**Author:** ![Brian\_Coca](https://avatars.discourse-cdn.com/v4/letter/b/6de8d8/32.png) [@Brian\_Coca](https://forum.ansible.com/u/Brian_Coca)\
**Post date:** [March 17, 2015, 12:47pm UTC](https://forum.ansible.com/t/timing-tasks-and-plays/17761/4 "2015-03-17T12:47:00Z")

</div>

Currently only one task executes at a time, handlers are a task and  
won't execute until the previous task is done. This is why starting a  
new task indicates the end of the previous one.
