Skip to content

feat: profile and time deploy operations and facts#1723

Draft
wowi42 wants to merge 1 commit intopyinfra-dev:3.xfrom
KalvadTech:feat/timings-1717
Draft

feat: profile and time deploy operations and facts#1723
wowi42 wants to merge 1 commit intopyinfra-dev:3.xfrom
KalvadTech:feat/timings-1717

Conversation

@wowi42
Copy link
Copy Markdown
Collaborator

@wowi42 wowi42 commented May 5, 2026

Summary

Adds per-host timing for the prepare and execute phases of every operation, plus per-host per-fact timing. Surfaces the data via two new flags and always prints total elapsed wall time at the end of a run.

  • --timings: human-readable summary of the slowest operations and facts at the end of the run
  • --timings-json: structured timing data emitted to stdout for external tooling
  • --log-timestamps (also PYINFRA_LOG_TIMESTAMPS=1): wall-clock prefix on every log line

Closes #1717. Supersedes #469 and #640.

Implementation notes

  • New StateTimings dataclass on State.timings accumulates timings as the deploy progresses. Per-host data is stored under the concrete Host, with a small helper resolving gevent context proxies before storing them as dict keys.
  • Operations measure two phases: prepare time (the change-detection iteration of command_generator()) and execute time (the retry loop in _run_host_op).
  • Facts measure the entire _get_fact body so the network call and process() parsing are both included. Multiple samples per fact key are kept since facts can be re-fetched.
  • Default behaviour is unchanged unless a user passes one of the new flags. The total elapsed line is always printed (cheap, useful) but no slowest-ops table is shown without --timings.

Example

 pyinfra inventory.py test_unarchive.py --timings -y
--> Loading config...
--> Loading inventory...
--> Connecting to hosts...
    [10.0.10.23] Connected
    [10.0.10.21] Connected
    [10.0.10.22] Connected
    [10.0.10.20] Connected

--> Preparing operation files...
    Loading: test_unarchive.py
    [10.0.10.20] Ready: test_unarchive.py
    [10.0.10.22] Ready: test_unarchive.py
    [10.0.10.21] Ready: test_unarchive.py
    [10.0.10.23] Ready: test_unarchive.py

--> Skipping change detection
--> Beginning operation run...
--> Starting operation: Clean previous extraction roots
    [10.0.10.20] Success
    [10.0.10.21] Success
    [10.0.10.23] Success
    [10.0.10.22] Success

--> Starting operation: Upload and extract tar.gz
    [10.0.10.20] Success
    [10.0.10.21] Success
    [10.0.10.23] Success
    [10.0.10.22] Success

--> Starting operation: Extract with creates marker
    [10.0.10.20] Success
    [10.0.10.21] Success
    [10.0.10.23] Success
    [10.0.10.22] Success

--> Starting operation: Re-extract should skip (creates exists)
    [10.0.10.20] No changes
    [10.0.10.21] No changes
    [10.0.10.23] No changes
    [10.0.10.22] No changes

--> Starting operation: Extract with extra_opts (verbose)
    [10.0.10.20] Success
    [10.0.10.21] Success
    [10.0.10.23] Success
    [10.0.10.22] Success

--> Starting operation: Extract and chown tree
    [10.0.10.20] Success
    [10.0.10.21] Success
    [10.0.10.23] Success
    [10.0.10.22] Success

--> Starting operation: Verify extracted payloads
    [10.0.10.20] Success
    [10.0.10.21] Success
    [10.0.10.23] Success
    [10.0.10.22] Success

--> Starting operation: Verify chown applied
    [10.0.10.20] Success
    [10.0.10.23] Success
    [10.0.10.21] Success
    [10.0.10.22] Success

--> Starting operation: Tear down extraction roots
    [10.0.10.20] Success
    [10.0.10.21] Success
    [10.0.10.23] Success
    [10.0.10.22] Success

--> Results:
    Operation                                 Hosts   Success   Error   No Change
    Clean previous extraction roots           4       4         -       -
    Upload and extract tar.gz                 4       4         -       -
    Extract with creates marker               4       4         -       -
    Re-extract should skip (creates exists)   4       -         -       4
    Extract with extra_opts (verbose)         4       4         -       -
    Extract and chown tree                    4       4         -       -
    Verify extracted payloads                 4       4         -       -
    Verify chown applied                      4       4         -       -
    Tear down extraction roots                4       4         -       -
    Grand total                               36      32        -       4

--> Finished, took 2.49s

--> Timings:
    Operation                                 Hosts   Prepare (sum)   Execute (sum)   Slowest host
    Extract and chown tree                    4       0ms             1.07s           474ms
    Upload and extract tar.gz                 4       0ms             915ms           347ms
    Tear down extraction roots                4       0ms             852ms           361ms
    Verify extracted payloads                 4       0ms             839ms           358ms
    Extract with creates marker               4       0ms             760ms           251ms
    Clean previous extraction roots           4       0ms             754ms           223ms
    Extract with extra_opts (verbose)         4       0ms             617ms           262ms
    Verify chown applied                      4       0ms             138ms           103ms
    Re-extract should skip (creates exists)   4       0ms             137ms           100ms

    Fact                                                  Hosts   Calls   Total   Slowest
    files.Directory (path=/tmp)                           4       16      635ms   122ms
    server.Which (command=tar)                            4       4       481ms   239ms
    files.File (path=/etc/passwd)                         4       8       395ms   63ms
    server.TmpDir                                         4       4       246ms   96ms
    files.File (path=/tmp/unarchive-creates/marker.txt)   4       8       217ms   100ms

--> Disconnecting from hosts...

Test plan

  • scripts/dev-lint.sh (ruff, ruff format, mypy, arguments sync) passes
  • scripts/dev-test.sh passes (1675 tests)
  • New unit tests cover StateTimings accumulators, end-to-end op timing population, and JSON output shape
  • Manual smoke test against a real host (pyinfra @local exec -- echo hi --timings, --timings-json, --log-timestamps)

Add per-host timing for the prepare and execute phases of every
operation, plus per-host per-fact timing. Surface the data via
two new flags:

- --timings: print a human-readable summary of the slowest
  operations and facts at the end of the run
- --timings-json: emit structured timing data to stdout

The total elapsed wall time is always printed as
"Finished, took X" once a deploy has executed. Timestamps on log
lines can be opted in via --log-timestamps or
PYINFRA_LOG_TIMESTAMPS=1.

Closes pyinfra-dev#1717. Supersedes pyinfra-dev#469 and pyinfra-dev#640.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Profile and time deploy operations

1 participant