[Bug] L3 multi-rank STRACE records interleave on shared stderr and corrupt benchmark timing

[sunkaixuan2018]

Platform

a2a3 (Ascend 910B/C hardware)

Runtime Variant

tensormap_and_ringbuffer

Description

L3 multi-rank benchmark timing is unreliable because forked chip-worker processes write [STRACE] records concurrently to the same captured stderr file descriptor.

HostLogger::emit writes one logical log record through multiple stdio calls. Its mutex is local to each HostLogger instance and therefore does not serialize writers from different forked processes. Records from different ranks can consequently be interleaved into the same physical line.

The STRACE parser extracts only one record from each physical line. Interleaved records are therefore lost, causing:

• Missing orchestrator or scheduler spans
• effective_us=0.0 for valid dispatches
• Fewer reported ranks than the actual world size
• Unstable and systematically inflated median/mean latency

The MoE computation itself completes successfully and passes correctness checks. This is an instrumentation output problem, not a kernel performance regression.

Steps to Reproduce

Use the following configuration:

source <CANN_INSTALLATION>/set_env.sh

export PYTHONPATH=<WORKSPACE>/pypto-lib
export TORCH_DEVICE_BACKEND_AUTOLOAD=0
export PYPTO_BENCH=1
export PYPTO_BENCH_WARMUP=2
export PYPTO_BENCH_ROUNDS=8
export PYPTO_BENCH_RAW=1
export DSV4_HC_PRE_IMPL=separate
export PYPTO_ROUTE_HASH_IMPL=aiv
export PTO2_RING_DEP_POOL=16384
export PTO2_RING_TASK_WINDOW=16384
export PTO2_RING_HEAP=1073741824

.venv/bin/python models/deepseek/v4-flash/moe.py \
    -p a2a3 \
    --ep 8 \
    -d 0,2,4,6,8,10,12,14 \
    --balanced-routing \
    --enable-l2-swimlane 0

Parallel configuration:

• Expert parallel size: 8
• World size: 8
• Participating devices: 0,2,4,6,8,10,12,14
• Mapping: rank 0 -> device 0, rank 1 -> device 2, ..., rank 7 -> device 14
• Warmup rounds: 2
• Measured rounds: 8
• Routing: balanced
• HcPre implementation: separate
• Route hash implementation: AIV

The issue reproduces consistently in three independent runs.

Expected Behavior

For 8 ranks and 8 measured rounds:

• All 64 (rank, round) cells should contain a valid effective_us value.
• The reported rank count should be 8.
• Median and mean latency should remain stable across repeated runs.
• Results should be comparable with the approximately 477 us reference baseline for this configuration.
• Missing STRACE spans should be reported as invalid instrumentation data rather than silently converted to 0.0.

Actual Behavior

All three runs complete successfully in approximately 35-44 seconds. Correctness passes with x_next ratio_reldiff < 0.003.

There are no runtime errors, timeouts, or device failures: no 507018, 507014, 507899, HandleTaskTimeout, or FATAL records.

However, most benchmark timing samples are missing:

Run	Reported ranks	Non-zero samples out of 64	Minimum effective_us	Median effective_us	host_union_mean
v3	7	14	476.0 us	unavailable	2773 us
v4	7	13	476.1 us	958.8 us	2678 us
v5	8	20	472.8 us	1210.6 us	2631 us

In v5, all eight participating ranks contain missing 0.0 cells. One participating worker has all eight measured rounds reported as 0.0.

The minimum non-zero values from the three runs agree with the approximately 477 us reference within about 1%, indicating that kernel performance itself is not regressed. The median and mean values are corrupted by missing or incorrectly parsed spans.

Git Commit ID

simpler: 9922afdb08cc6f203eaf39328661e2f2648d333d

Related versions:

• pypto-lib: fc9993fb26732bc1e718d952f65abc6b3fa2a227
• pypto: 1784c635b5ea750c5666dde0fe132aa2c1d10a34
• pto-isa: 83d01313d9bfc247c4b7c8bcf969d1019f0d106f
• PTOAS: 0.48
• pypto-serving: not used

CANN Version

9.0.0, timestamp 20260428

Driver Version

26.0.rc1

Firmware version is not reported by the board. The reported software version is 26.0.rc1.

Host Platform

Linux (aarch64)

• OS: openEuler 24.03 SP1
• Kernel: 6.6.0-72.0.0.76.oe2403sp1.aarch64
• Python: 3.11.6
• PyTorch: 2.8.0+cpu
• NumPy: 2.2.6
• NPU: Ascend910, Product IT22HMDA_2_S
• PCI Device ID: 0xD803
• HBM: 64 GB per chip

Additional Context

Root-cause evidence

At the affected commit, src/common/log/host_log.cpp:86-92 emits one logical record using several operations:

fprintf(stderr, ...);
vfprintf(stderr, fmt, args);
fputc('\n', stderr);
fflush(stderr);

The surrounding std::scoped_lock protects only threads using the same HostLogger instance. Each forked L3 chip-worker process has its own logger and mutex, so it does not prevent cross-process writes to the shared captured stderr descriptor.

In simpler_setup/tools/strace_timing.py:51-55,98-113, parse_spans performs one _STRACE_RE.search per physical line. The greedy attrs=.* portion can consume the remainder of a line containing another interleaved STRACE record. The second record is not recovered.

When an orchestrator or scheduler span is lost, the benchmark reports effective_us=0.0. If all samples for a rank are lost, that rank is omitted from the reported rank count.

Suggested fixes

1. Format each host log record into a contiguous buffer and emit it with one cross-process-safe write. STRACE records written to a captured pipe should remain within PIPE_BUF so each record is atomic.
2. Harden parse_spans to detect multiple STRACE markers or malformed interleaved records instead of silently accepting partial input.
3. Validate the expected rank and round counts before calculating statistics.
4. Mark missing spans as invalid samples and report an instrumentation error; do not represent them as 0.0.
5. Add an L3 multi-process test in which several child processes concurrently emit STRACE records to the same captured descriptor.

Workaround

Capture each rank's stderr into a separate file and parse the files independently before aggregating benchmark results. PYPTO_BENCH_RAW=1 alone does not prevent shared-descriptor interleaving.