[Performance] Rare 30 ms host-side runner_run tails in sustained four-chip depth-two runs

[high-cloud]

Platform

a2a3 (Ascend 910B/C hardware)

Runtime Variant

tensormap_and_ringbuffer

Summary

A Simpler-only four-chip workload with sustained depth-two asynchronous submission has rare, multi-step host-side latency tails. The device execution time stays stable while one chip process occasionally spends an additional 20--33 ms inside the host chip.run.runner_run envelope. Independent tails also occur between runner_run and validate, and inside validate itself.

This reproducer imports only simpler, simpler_setup, and normal runtime dependencies. It does not use PyPTO, pypto-lib, or a serving stack.

Git Commit ID

66ba5c4

CANN Version

cann-9.0.0

Driver Version

Not captured.

Host Platform

Linux (aarch64)

Reproduction

The self-contained reproducer follows the existing examples/workers/l3/multi_chip_dispatch vector-add example, with these changes:

1. Add one scalar kernel_repeats argument to the chip/core callable.
2. In the AIV kernel, repeat the existing 128x128 FP32 TLOAD/TADD/TSTORE/pipe_sync body 4096 times. Read the scalar from args[3].
3. In chip orchestration, forward the scalar with params.add_scalar(orch_args.scalar(0)). Scalar indices are independent of tensor indices.
4. Create one level-3 worker with exactly four devices, runtime="tensormap_and_ringbuffer", and num_sub_workers=0.
5. Allocate two sets of shared (a, b, out) tensors, one set for each pipeline slot.
6. Submit one four-member group per logical step and keep two top-level handles in flight:

devices = [int(item) for item in os.environ["TASK_DEVICE"].split(",")]
workers = list(range(4))
worker = Worker(
    level=3,
    platform="a2a3",
    runtime="tensormap_and_ringbuffer",
    device_ids=devices,
    num_sub_workers=0,
)
chip_handle = worker.register(build_repeated_vector_add_callable())
worker.init()

# slot_args has two entries. Each entry contains four TaskArgs objects,
# one per device. Each TaskArgs contains a, b, out, and scalar 4096.
handles = []
for step in range(5 + 10000):
    while len(handles) >= 2:
        handles.pop(0).wait()
    args_for_step = slot_args[step % 2]

    def graph(orch, _args, cfg, group_args=args_for_step):
        orch.submit_next_level_group(
            chip_handle,
            group_args,
            cfg,
            workers=workers,
        )

    handles.append(worker.submit(graph, config=CallConfig()))

for handle in handles:
    handle.wait()
worker.close()

Run on four allocated devices and capture native Simpler STRACE:

export SIMPLER_LOG_LEVEL=TIMING
export TASK_DEVICE=5,7,9,15  # replace with four allocated devices

python repro_step_jitter.py \
  --platform a2a3 \
  --devices "$TASK_DEVICE" \
  --warmup 5 \
  --rounds 10000 \
  --depth 2 \
  --kernel-repeats 4096 \
  > run.log 2>&1

python -m simpler_setup.tools.strace_timing run.log \
  --rounds-table \
  --swimlane swimlane.json

The important workload property is submitting the successor before waiting for the oldest handle. A synchronous Worker.run() loop leaves the device idle between steps and does not model the serving workload.

Expected Performance

After warmup, all four ranks should have stable step latency:

• host runner_run should remain close to its corresponding device-wall duration;
• no single rank should exceed the per-round median by more than 5 ms;
• runner_run start/end skew, the runner-to-validate gap, validate, and complete chip.run latency should remain stable together rather than moving the tail to another phase.

Actual Performance

One real-NPU run completed all 5 warmup + 10,000 measured steps in 72.342 seconds with exact vector-add output validation.

Metric	p50	p95	p99	max
host runner_run	5.922 ms	6.039 ms	6.175 ms	39.198 ms
device wall	5.761 ms	5.849 ms	5.911 ms	5.954 ms
host runner minus device wall	0.154 ms	0.234 ms	0.399 ms	33.455 ms
runner-to-validate gap	0.023 ms	0.049 ms	0.106 ms	4.756 ms
validate	0.018 ms	0.030 ms	0.156 ms	4.800 ms
complete chip.run	6.487 ms	6.727 ms	7.530 ms	41.503 ms

There were 15 single-rank runner tails more than 5 ms above the per-round median.

The worst case was measured round 561 / invocation 566:

Device	host runner	device wall	complete step
5	39.198 ms	5.744 ms	41.503 ms
7	6.143 ms	5.819 ms	7.493 ms
9	6.150 ms	5.827 ms	7.481 ms
15	6.167 ms	5.824 ms	7.483 ms

The resulting runner-end and step-end skew were 34.335 ms and 34.395 ms. The device-wall maximum over all 40,000 measured rank-steps was only 5.954 ms, so the long tail is not explained by longer device kernel execution.

The same run also captured two separate behaviors:

• measured round 4531: all four ranks had a 4.697--4.756 ms gap between host runner completion and validate;
• measured round 647: device 5 spent 4.800 ms inside validate while its runner remained 5.901 ms.

Runner-start skew reached 3.259 ms in this run but did not cross the 5 ms outlier threshold.

Profiling Data (Optional)

For invocation 566 on device 5, the relevant native Simpler markers were:

chip.run.bind       dur=0.875 ms
chip.run.runner_run dur=39.198 ms
chip.run.validate   dur=0.031 ms
chip.run.runner_run.device_wall dur=5.744 ms
chip.run            dur=41.503 ms

The host runner_run span starts before attach_current_thread() / launch_execution() and ends after drain_execution(). drain_execution() includes the stream synchronization and device-phase readback. The current trace does not split this 33.455 ms excess into CPU scheduling delay, ACL/driver blocking, stream wait, or readback/cleanup.

Additional Context

CPU/host scheduling is a strong hypothesis, but it is not yet proven to be caused by high CPU utilization:

• the worst tail is isolated to one chip process while all four device-wall durations remain stable;
• the four-rank common runner-to-validate gap suggests a separate shared-host scheduling or blocking event;
• no CPU utilization, /proc/<tid>/schedstat, involuntary context-switch, or sched_switch trace was captured in this run.

A useful next diagnostic would record thread CPU time and scheduler run-delay at each host phase boundary. A controlled A/B with an isolated cpuset versus explicit CPU stress could then distinguish CPU run-queue contention from ACL/driver or logging I/O waits. The fix should be accepted only if runner, gap, validate, and complete-step tails all improve under the same workload.

Related: #1853

Related implementation attempts and evidence: #1945, #1967, #1987.

[high-cloud]

A self-contained Simpler-only reproducer is now available in #1997. It does not depend on PyPTO or a serving stack.

Permanent source snapshot:

• Run instructions
• Four-chip workload
• Four-card wrapper
• STRACE analyzer and Perfetto exporter

From a Simpler checkout:

gh pr checkout 1997 --repo hw-native-sys/simpler

TASK_DEVICE=0,1,2,3 PYTHON=.venv/bin/python \
  bash examples/workers/l3/step_jitter_repro/run_4card.sh \
  /tmp/simpler-step-jitter 10000 4096

This writes:

• /tmp/simpler-step-jitter/run.log
• /tmp/simpler-step-jitter/analysis.json
• /tmp/simpler-step-jitter/swimlane.json

The workload keeps two four-chip groups in flight so the next group is submitted before the oldest handle is retired. It also performs exact output validation.

A 10000-round real-NPU run completed successfully in task_20260824_024201_148434813863 on devices 5,7,9,15. The observed maximums were:

• host runner_run: 39.198 ms
• device wall time: 5.954 ms
• host excess over device wall: 33.455 ms
• runner-to-validate gap: 4.756 ms
• validate: 4.800 ms
• complete step: 41.503 ms

There were 15 runner_long_tail outliers above the per-round median plus 5 ms.