[Bug] sim device log splits one record across three stdio calls, so concurrent AICPU threads and forked chip workers interleave partial records

[ChaoZheng109]

Platform

All / Unknown — precisely: a2a3sim + a5sim. The defect is in the shared file src/common/platform/sim/aicpu/device_log.cpp, so both sim variants are affected identically. Onboard (a2a3 / a5) is not affected — see Additional Context.

Runtime Variant

All / Unknown — the sim device-log backend sits at the platform layer and is used by both tensormap_and_ringbuffer and host_build_graph.

Description

The sim platform's device-log backend emits one logical log record via three separate stdio calls, with no lock at all:

// src/common/platform/sim/aicpu/device_log.cpp:61-65 (dev_vlog_debug; info/timing/warn/error identical)
void dev_vlog_debug(const char *func, const char *fmt, va_list args) {
    fprintf(stderr, "[DEBUG] %s: ", func);
    vfprintf(stderr, fmt, args);
    fputc('\n', stderr);
}

glibc locks the FILE for each individual call, but not across the three-call sequence. Any concurrent writer can therefore land its own output between the level/func prefix, the message body, and the terminating newline — producing records that are merged onto one physical line or split across two.

There are two independent concurrency sources in sim, and only one of them requires fork:

1. Intra-process, multi-threaded (the easy one). Sim runs AICPU as host threads — SimDeviceRunnerBase::create_thread (src/common/platform/sim/host/device_runner_base.cpp:240) spawns up to aicpu_thread_num workers (PLATFORM_MAX_AICPU_THREADS = 4 on a2a3, 7 on a5). Every one of those threads calls dev_vlog_* on the same stderr. No fork needed — a single sim process with aicpu_thread_num > 1 is enough.
2. Cross-process, forked chip workers. python/simpler/worker.py forks chip children (_chip_process_loop, _forked_child_main) for sim exactly as it does for onboard; the children share the parent's captured stderr file descriptor.

This is the same defect class as #1690 (host-side HostLogger::emit writing one record via fprintf + vfprintf + fputc + fflush). PR #1691 fixed it for the host backend only — it buffers each record into a contiguous std::string and emits it with a single ::write(STDERR_FILENO, ...). The sim device backend was left unchanged, so the defect survives in src/common/platform/sim/.

Notably, sim is strictly worse than the pre-#1691 host path: HostLogger at least held a process-local std::mutex around its stdio sequence, so single-process multi-threaded output stayed intact. The sim dev_vlog_* functions hold nothing, so they interleave even without fork.

Steps to Reproduce

Multi-threaded path (no fork required):

1. Pick a sim scene test configured with more than one AICPU thread, e.g. tests/st/a5/tensormap_and_ringbuffer/mixed_example/ ("config": {"aicpu_thread_num": 4}) or tests/st/a5/tensormap_and_ringbuffer/mx_fp_gemm/ (aicpu_thread_num: 2).

2. Run it in sim with the device log opened up so several AICPU threads log concurrently, capturing stderr:

   pytest tests/st/a5/tensormap_and_ringbuffer/mixed_example \
       --platform a5sim --log-level debug 2>capture.log

3. Inspect capture.log for torn records — lines carrying two level tags, or a [TIMING]/[DEBUG] prefix with no message body following it:

   grep -cE '\[(DEBUG|INFO|TIMING|WARN|ERROR)\].*\[(DEBUG|INFO|TIMING|WARN|ERROR)\]' capture.log
   grep -nE '\[(DEBUG|INFO|TIMING|WARN|ERROR)\] [A-Za-z_~][A-Za-z0-9_:~]*: *$' capture.log

Being a race, the hit rate scales with log volume and thread count; --log-level debug with aicpu_thread_num at the platform maximum is the strongest signal.

Deterministic regression test. PR #1691 added exactly the right harness shape for the host side in tests/ut/cpp/a5/test_host_log_off.cpp::ForkedProcessesEmitWholePipeRecords (16 forked children x 128 records through a shared pipe, verifying one record per physical line). The same test, retargeted at dev_vlog_* and extended with a pure multi-threaded variant, is the natural regression barrier here.

Expected Behavior

Each dev_vlog_* call produces exactly one intact physical line on stderr, regardless of how many AICPU sim threads or forked chip-worker processes are writing concurrently. This is what both sibling backends already guarantee:

• onboard (src/common/platform/onboard/aicpu/device_log.cpp:53-55) buffers into a single char buffer[2048] and issues one dlog_* call;
• host, after Fix: keep forked host log records intact #1691 (src/common/log/host_log.cpp) buffers into one std::string and issues one ::write.

Actual Behavior

Records from concurrent AICPU sim threads and forked chip workers interleave on the shared stderr, producing merged or split lines. Consequences:

• Device log records become unparseable or silently lost by any line-oriented consumer.
• The SIMPLER_DFX Total / Orch / Sched markers and log_stall_diagnostics output can be corrupted, which is the failure mode that makes device-log triage untrustworthy in the first place (.claude/rules/running-onboard.md documents these as the ground truth for stall/deadlock classification).
• Sim runs of a benchmark are exposed to the same class of instrumentation corruption [Bug] L3 multi-rank STRACE records interleave on shared stderr and corrupt benchmark timing #1690 reported for onboard host output — with the added wrinkle that in sim it needs no multi-rank setup, just aicpu_thread_num > 1.

The kernels themselves compute correctly; this is purely an instrumentation-output defect.

Git Commit ID

c866c82 (upstream/main; src/common/platform/sim/aicpu/device_log.cpp is untouched by PR #1691)

Host Platform

Linux (aarch64)

Additional Context

Backend comparison — sim is the only one that splits a record:

Backend	Emit mechanism	One record per call?
onboard device (onboard/aicpu/device_log.cpp)	vsnprintf into char buffer[2048], then one dlog_*	Yes
host (src/common/log/host_log.cpp), after #1691	format into std::string, then one ::write	Yes
sim device (sim/aicpu/device_log.cpp)	fprintf + vfprintf + fputc, unlocked	No

Suggested fix. Apply the shape the other two backends already use — format into a contiguous buffer, emit once. Keeping the record within PIPE_BUF preserves cross-process atomicity when stderr is a shared captured pipe, the same property PR #1691 relies on. docs/logging.md:142 currently describes the sim backend as "buffer-free (single vfprintf(stderr, ...))"; that line is inaccurate today (there are three calls, not one) and would need updating alongside the fix per .claude/rules/doc-consistency.md.

Note that dev_vlog_* is on the AICPU logging path, so the fix must not introduce per-call heap allocation — a stack buffer sized like onboard's char buffer[2048] plus a single fwrite/write keeps the cost at or below today's, and .claude/rules/codestyle.md §7 already forbids logging on AICPU hot paths, so the volume is bounded by design.

Related: #1690 (host-side variant of this defect), #1691 (fix for the host side only).

Found while reviewing PR #1691.