Hello everyone :wave: !

This is the first step for #10

This proposition allow creating tests using pytest framework where we can chose strategy, inventory for the same playbook file (see tests/integration/tests/basic.py) I have also made some utilities functions that parse trace to ensure its integrity. This include also related github action CI.yml (here a sample)

Waiting for your feedback, Thanks!

Actual Behavior

Chrome:

Cannot open file. Error Message:

Firefox Profiler

Cannot open file. Error Message:

Perfetto UI

Trace is shown correctly:

Expected Behavior

trace files can be open opened by all viewers that are mentioned in the readme, not just perfetto UI.

Versions

• ansible: ansible 4.6.0 ansible-core 2.11.6
• ansible-trace: main commit 8f9270205172554f760fe8bc61089f6b855fdbef
• python: Python 3.9.2

simple playbook used for testing

---
- hosts: localhost
  gather_facts: true
  tasks:
    - name: "output if not debian 11"
      debug:
        msg: "test"
      when: 'not (ansible_distribution == "Debian" and ansible_distribution_major_version == "11")'

    - name: "output if debian 11"
      debug:
        msg: "test"
      when: (ansible_distribution == "Debian" and ansible_distribution_major_version == "11")

output of trace callback for test playbook

trace.json

[
{
  "args": {
    "name": "localhost"
  },
  "cat": "process",
  "name": "process_name",
  "ph": "M",
  "pid": 1
}[
{
  "args": {
    "args": null,
    "host": "localhost",
    "path": "/home/user/repos/ansible-test/testenv-test.yml:2",
    "task": "Gathering Facts"
  },
  "cat": "runner",
  "id": 6508616308570991776,
  "name": "Gathering Facts",
  "ph": "B",
  "pid": 1,
  "ts": 1634299695390039.8
}[
{
  "args": {
    "status": "ok"
  },
  "cat": "runner",
  "id": 6508616308570991776,
  "name": "Gathering Facts",
  "ph": "E",
  "pid": 1,
  "ts": 1634299696186142.0
}[
{
  "args": {
    "args": null,
    "host": "localhost",
    "path": "/home/user/repos/ansible-test/testenv-test.yml:5",
    "task": "output if not debian 11"
  },
  "cat": "runner",
  "id": 746051916975514963,
  "name": "output if not debian 11",
  "ph": "B",
  "pid": 1,
  "ts": 1634299696197881.8
}[
{
  "args": {
    "status": "skipped"
  },
  "cat": "runner",
  "id": 746051916975514963,
  "name": "output if not debian 11",
  "ph": "E",
  "pid": 1,
  "ts": 1634299696210522.0
}[
{
  "args": {
    "args": null,
    "host": "localhost",
    "path": "/home/user/repos/ansible-test/testenv-test.yml:10",
    "task": "output if debian 11"
  },
  "cat": "runner",
  "id": 1296121251497600435,
  "name": "output if debian 11",
  "ph": "B",
  "pid": 1,
  "ts": 1634299696215914.5
}[
{
  "args": {
    "status": "ok"
  },
  "cat": "runner",
  "id": 1296121251497600435,
  "name": "output if debian 11",
  "ph": "E",
  "pid": 1,
  "ts": 1634299696230237.2
}
]

modified trace file that i could open with perfettoUI, chrome and firefox profiler

[
{
  "args": {
    "name": "localhost"
  },
  "cat": "process",
  "name": "process_name",
  "ph": "M",
  "pid": 1
},
{
  "args": {
    "args": null,
    "host": "localhost",
    "path": "/home/user/repos/ansible-test/testenv-test.yml:2",
    "task": "Gathering Facts"
  },
  "cat": "runner",
  "id": 6508616308570991776,
  "name": "Gathering Facts",
  "ph": "B",
  "pid": 1,
  "ts": 1634299695390039.8
},
{
  "args": {
    "status": "ok"
  },
  "cat": "runner",
  "id": 6508616308570991776,
  "name": "Gathering Facts",
  "ph": "E",
  "pid": 1,
  "ts": 1634299696186142.0
},
{
  "args": {
    "args": null,
    "host": "localhost",
    "path": "/home/user/repos/ansible-test/testenv-test.yml:5",
    "task": "output if not debian 11"
  },
  "cat": "runner",
  "id": 746051916975514963,
  "name": "output if not debian 11",
  "ph": "B",
  "pid": 1,
  "ts": 1634299696197881.8
},
{
  "args": {
    "status": "skipped"
  },
  "cat": "runner",
  "id": 746051916975514963,
  "name": "output if not debian 11",
  "ph": "E",
  "pid": 1,
  "ts": 1634299696210522.0
},
{
  "args": {
    "args": null,
    "host": "localhost",
    "path": "/home/user/repos/ansible-test/testenv-test.yml:10",
    "task": "output if debian 11"
  },
  "cat": "runner",
  "id": 1296121251497600435,
  "name": "output if debian 11",
  "ph": "B",
  "pid": 1,
  "ts": 1634299696215914.5
},
{
  "args": {
    "status": "ok"
  },
  "cat": "runner",
  "id": 1296121251497600435,
  "name": "output if debian 11",
  "ph": "E",
  "pid": 1,
  "ts": 1634299696230237.2
}
]

Hey :wave: ,

This PR close #3 ! Here how it does looks like with all playbooks with strategy free:

It is not accurate as we lack of callback to achieve this, but here how it is done: The play duration event will only be created right before when a task for a given host will start. At the start of a new play, we add an E event for all the plays we created before.

We do one as well at the very end to handle the last play condition.

Even if it is not accurate, it gives a better pictures of what is going on.

Let me know if it is ok for you!

Hi everyone :wave: ,

With Ansible you are able to interpolate task name in certain circumstances. One is when you use include_tasks, you are able to interpolate your tasks name in the included file like the following:

---

- name: "Echo {{ include_message }}"
  shell: "echo {{ include_message }}"

Unfortunately the task name is not yet interpolated in hook v2_runner_on_start for linear strategy, which cause B event to have a different name than the E event. As the E & B events name differs, the end is not catch, here is an example:

Fortunately v2_playbook_on_task_start hook (which is triggered before v2_runner_on_start) returns the interpolated name. We could use that.

I have been experiencing the following warning with ansible-trace using python3.6:

[WARNING]: Failure using method (v2_runner_on_failed) in callback plugin (<ansible_collections.mhansen.ansible_trace.plugins.callback.trace.CallbackModule object at 0x7fcddc736358>):
module 'time' has no attribute 'time_ns'

It causes not having trace at all, such as:

[
{
  "args": {
    "name": "localhost"
  },
  "cat": "process",
  "name": "process_name",
  "ph": "M",
  "pid": 1
}
]

This issue is caused by the fact that python have implemented time.time_ns() since 3.7 only.

For python 3.6 we could be using time.time() * 1000000 instead of time.time_ns() / 1000 when time_ns is not present in time package, such as:

"ts": time.time_ns() / 1000 if "time_ns" in time.__dict__ else time.time() * 100000,

for the follwing lines:

• https://github.com/mhansen/ansible-trace/blob/main/plugins/callback/trace.py#L120
• https://github.com/mhansen/ansible-trace/blob/main/plugins/callback/trace.py#L142

The precision level seems to be good enough to don't impact the behavior of ansible-trace:

Currently this plugin keep only one trace.json, thus not allowing to run multiple plays and have the trace for each of them.

I suggest to :

• change the default output directory to ./trace (or something else) to avoid cluttering the current dir with too many files
• change the output file to something like play-<timestamp>-<playbook_name>.json
• add an option to set a rotation for these trace files (ie. keep only 30 of them)

I already have proof of concept locally, if you are OK with i can submit a pull request that we can discuss further.

:wave: , To compute the timestamp (in microseconds) we use:

time.time_ns() / 1000  if "time_ns" in time.__dict__ else time.time() * 100000

While the first one does the right conversion, the other one does not as time.time() gives time as second. So we need 10^6 and not 10^5

:wave: !

Close #18 Close #1 Close #23

Rework tests to take in account there can be multiple duration events with the same uuid As we are lacking of callback this is mostly hack atm

Here some examples:

And here an use case:

Sorry for the noise, with all tests will fix it asap, Waiting for your review !

:wave: everyone !

I'd like to do like #3 but for roles. I cannot see hooks that would allow us to do that easily, however I think we could manage it with some hacks.

Judging by how many blog posts there are about pipelining, this is an important aspect of overall latency.

This definitely needs more callbacks though, we just don't have the hooks to achieve this yet.