Measure Python Task Duration: Wall Time vs CPU Time with perf_counter and process_time

A script takes many seconds while CPU activity stays low. Is it calculating, or waiting for storage, the network, or another process? A single “runtime” number can make waiting look like a slow algorithm.

This beginner-to-intermediate tutorial adds elapsed time and current-process CPU time to a Python task. Validate the helper with controlled waiting and computing examples, then reuse it around actual processing stages. No third-party packages or Linux configuration changes are needed.

1. Method: record two clocks for the same stage

Python documents perf_counter and process_time:

• Subtract two perf_counter_ns() readings to measure elapsed time, including sleep.
• process_time_ns() counts user and system CPU time used by the current process, excluding sleep.
• _ns returns integer nanoseconds, not guaranteed nanosecond accuracy. Use date/time APIs for calendar timestamps; these readings are not Unix timestamps.

Our example emits each run’s result, both durations in seconds, and the medians of three runs as JSON. The measured scope is action() plus a little clock-reading overhead, not imports, argument parsing, or report printing.

For deciding when a periodic check starts next, use the monotonic fixed-interval scheduling method. This article diagnoses stage durations rather than scheduling tasks.

2. Setup: create a separate practice directory

Use an existing Python 3.10 or newer installation. These examples were tested on Linux with Python 3.11.4; the shell commands work in bash or zsh.

1. Create a new directory to avoid overwriting earlier reports. Choose another name when repeating the exercise:

python3 --version
mkdir timing-demo
cd timing-demo

2. Save the next section as stage_timing.py in that directory. Workloads are fixed: wait sleeps for 0.2 seconds; compute adds integers from 0 through 999999. --repeat accepts 1–10 and defaults to 3.

3. Implementation: timing helper and CLI

"""Measure elapsed and current-process CPU time. Python 3.10+."""
import argparse
import json
from statistics import median
import time


def measure(action):
    wall_start = time.perf_counter_ns()
    cpu_start = time.process_time_ns()
    result = action()
    cpu_ns = time.process_time_ns() - cpu_start
    wall_ns = time.perf_counter_ns() - wall_start
    return {
        "wall_seconds": wall_ns / 1_000_000_000,
        "cpu_seconds": cpu_ns / 1_000_000_000,
        "result": result,
    }


def compute():
    total = 0
    for number in range(1_000_000):
        total += number
    return total


def repeat_count(value):
    try:
        count = int(value)
    except ValueError as exc:
        raise argparse.ArgumentTypeError("repeat must be an integer") from exc
    if not 1 <= count <= 10:
        raise argparse.ArgumentTypeError("repeat must be between 1 and 10")
    return count


def main():
    parser = argparse.ArgumentParser(description=__doc__)
    parser.add_argument("mode", choices=("wait", "compute"))
    parser.add_argument("--repeat", type=repeat_count, default=3)
    args = parser.parse_args()
    action = (lambda: time.sleep(0.2)) if args.mode == "wait" else compute
    runs = [measure(action) for _ in range(args.repeat)]
    report = {
        "mode": args.mode,
        "runs": runs,
        "median_wall_seconds": median(row["wall_seconds"] for row in runs),
        "median_cpu_seconds": median(row["cpu_seconds"] for row in runs),
    }
    print(json.dumps(report, allow_nan=False, indent=2))


if __name__ == "__main__":
    main()

measure() returns the task’s original result so that speed changes cannot silently replace correctness checks. Task exceptions propagate instead of producing a success report. The helper does not retry, impose a timeout, or terminate work. For those controls around external commands, see subprocess timeouts and logs.

4. Usage: compare waiting with computing

1. Run these commands from the practice directory:

python3 stage_timing.py --help
python3 stage_timing.py wait --repeat 3 > wait.json
python3 stage_timing.py compute --repeat 3 > compute.json
python3 -m json.tool wait.json
python3 -m json.tool compute.json

2. Inspect median_wall_seconds and median_cpu_seconds. Waiting normally takes about 0.2 seconds of elapsed time with little CPU time; computing should return 499999500000 and consume measurable CPU time. Actual durations depend on machine load: another person’s numbers are not acceptance thresholds.

Low CPU time does not prove a network wait. Sleep, file I/O, locks, CPU scheduling, and child-process work can all produce a similar gap. process_time_ns() excludes child-process CPU and is not a single-thread measurement when the current process has multiple threads. Do not label wall - cpu as “exact I/O time” or treat their ratio as whole-machine CPU utilization.

For a real task, replace measure(compute) with measure(lambda: process_batch()), keeping the same input and result checks. If the computing stage warrants deeper analysis, use cProfile to locate function hotspots.

5. Validation: check results, units, and failures

1. Save this as check_timing.py. It checks actual reports and uses mocked clocks to verify unit conversion without brittle assertions such as “sleep must be slower than computation”:

import json
from pathlib import Path
from unittest.mock import patch
import stage_timing

wait = json.loads(Path("wait.json").read_text(encoding="utf-8"))
compute = json.loads(Path("compute.json").read_text(encoding="utf-8"))
assert wait["mode"] == "wait" and compute["mode"] == "compute"
for report in (wait, compute):
    assert len(report["runs"]) == 3
    assert all(row["wall_seconds"] >= 0 for row in report["runs"])
    assert all(row["cpu_seconds"] >= 0 for row in report["runs"])
assert all(row["result"] is None for row in wait["runs"])
assert all(row["result"] == 499999500000 for row in compute["runs"])
assert stage_timing.compute() == 499999500000

# Deterministic arithmetic test, independent of server load.
with patch.object(stage_timing.time, "perf_counter_ns", side_effect=[10, 210]), \
     patch.object(stage_timing.time, "process_time_ns", side_effect=[20, 70]):
    measured = stage_timing.measure(lambda: "done")
assert measured == {"wall_seconds": 200 / 1e9,
                    "cpu_seconds": 50 / 1e9, "result": "done"}

# Failed work must propagate its exception, not return a success measurement.
def fail():
    raise RuntimeError("demo failure")

try:
    stage_timing.measure(fail)
except RuntimeError as exc:
    assert str(exc) == "demo failure"
else:
    raise AssertionError("failure was swallowed")
print("PASS: results, clock arithmetic, and failure propagation")

2. Run the tests, then confirm that invalid arguments produce no success JSON:

python3 check_timing.py
if python3 stage_timing.py wait --repeat 0 > invalid.json 2> invalid.err; then
    echo "unexpected success" >&2
    exit 1
else
    code=$?
    test "$code" -eq 2 || exit 1
    test ! -s invalid.json || exit 1
    grep -F "repeat must be between 1 and 10" invalid.err
fi

The test should print PASS: results, clock arithmetic, and failure propagation. argparse returns exit code 2 for the invalid argument. Shell redirection creates or truncates the report first, so file existence does not establish success; gate downstream work on the exit status too.

6. Troubleshooting and measurement boundaries

This does not collect memory usage, system-wide CPU, or all child-process resources, and it is not an isolated benchmark. Use it to narrow an investigation before optimizing, not to advertise a fixed speedup.

Summary

Record elapsed time and current-process CPU time for the same stage to separate clues about calculation and waiting. Preserve original results, testing semantics with real input and units with mocked clocks. Once a stage is identified, choose a profiler or an I/O investigation rather than immediately adding threads.