Fix: emit each sim device-log record atomically (#1697) - #1699
ChaoZheng109 merged 2 commits into
Conversation
Fixes hw-native-sys#1697 The sim AICPU device-log backend emitted one logical record via three unlocked stdio calls (fprintf prefix + vfprintf body + fputc newline). glibc locks the FILE per call but not across the sequence, so any concurrent writer could land its output between the three parts. Sim runs AICPU as host threads (aicpu_thread_num up to 4/7) and also forks chip workers sharing the captured stderr fd, so records merged onto one line or split across two — corrupting the SIMPLER_DFX Total/Orch/Sched markers and log_stall_diagnostics output that device-log triage relies on. The multi-threaded path needs no fork; aicpu_thread_num > 1 suffices. Adopt the shape both sibling backends already use: format the whole record "[TAG] func: body\n" into one stack buffer and emit it with a single write(2). The buffer caps the record at 2048 bytes, below Linux PIPE_BUF (4096), so a record is delivered atomically both within a process (one syscall) and across processes (PIPE_BUF) when stderr is a shared pipe. Output is byte-identical to before, so no consumer changes. Add test_sim_device_log (no_hardware) as the regression barrier: a multi-threaded and a forked variant each drive concurrent writers through a pipe and assert every physical line is one intact expected record. Both fail against the pre-fix three-call body. Update the device_log.h comment and docs/logging.md, which called the sim backend "buffer-free (single vfprintf)" — inaccurate already and doubly so now.
|
Important Review skippedAuto incremental reviews are disabled on this repository. Please check the settings in the CodeRabbit UI or the ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Plus Run ID: You can disable this status message by setting the Use the checkbox below for a quick retry:
📝 WalkthroughWalkthroughThe simulator device-log backend now formats complete records into a bounded stack buffer and emits each record with one ChangesSimulator device logging
Estimated code review effort: 3 (Moderate) | ~30 minutes Poem
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 2
🧹 Nitpick comments (1)
tests/ut/cpp/common/test_sim_device_log.cpp (1)
177-180: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winAssert the child exit status.
waitpidreturns a status that the test discards. If a child crashes or exits non-zero,expect_intactreports only "records never arrived intact", which hides the real cause. Check the status to get a direct failure message.♻️ Proposed change
for (pid_t pid : pids) { int status = 0; - waitpid(pid, &status, 0); + ASSERT_EQ(waitpid(pid, &status, 0), pid); + EXPECT_TRUE(WIFEXITED(status)) << "child terminated abnormally"; + EXPECT_EQ(WEXITSTATUS(status), 0); }🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@tests/ut/cpp/common/test_sim_device_log.cpp` around lines 177 - 180, Update the child-wait loop in expect_intact to assert the result of waitpid and the child’s exit status, so crashes or non-zero exits fail directly with a clear diagnostic instead of only reporting missing records.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@docs/logging.md`:
- Around line 142-147: Update the file layout description for the sim backend in
docs/logging.md so it no longer says `fprintf to stderr`; replace it with the
current single-write stderr behavior described by the logging implementation,
using the existing sim backend wording nearby for consistency. Keep the rest of
the layout block unchanged and only correct the stale sim logging entry.
In `@src/common/platform/sim/aicpu/device_log.cpp`:
- Around line 90-92: Update the logging write path around write(STDERR_FILENO,
buffer, len) to include <cerrno> and retry until the entire buffer is emitted,
handling EINTR and continuing after short writes. Preserve the complete record,
including its terminating newline, and handle terminal write failure without
silently treating a partial record as complete.
---
Nitpick comments:
In `@tests/ut/cpp/common/test_sim_device_log.cpp`:
- Around line 177-180: Update the child-wait loop in expect_intact to assert the
result of waitpid and the child’s exit status, so crashes or non-zero exits fail
directly with a clear diagnostic instead of only reporting missing records.
🪄 Autofix
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro Plus
Run ID: e0763f5e-3571-4c21-9ed5-3704bb2dded2
📒 Files selected for processing (5)
docs/logging.mdsrc/common/platform/include/aicpu/device_log.hsrc/common/platform/sim/aicpu/device_log.cpptests/ut/cpp/CMakeLists.txttests/ut/cpp/common/test_sim_device_log.cpp
| layer. Each backend then formats one whole record and emits it in a single | ||
| call: the sim backend writes it with one `write(2)`, kept under `PIPE_BUF` so | ||
| concurrent AICPU sim threads or forked chip workers sharing `stderr` never | ||
| interleave partial records; the onboard backend buffers into a stack `char` | ||
| array and issues one `dlog_*` because CANN's `dlog` is variadic only (no | ||
| `va_list` variant). |
There was a problem hiding this comment.
📐 Maintainability & Code Quality | 🟡 Minor | ⚡ Quick win
Update the stale backend description in the file layout block.
The new text at Lines 142-147 is accurate. Line 64 of the same file still describes the sim backend as sim backend (fprintf to stderr). That description is now wrong, and the PR objective asks for the inaccurate sim logging documentation to be corrected.
📝 Proposed doc fix (Line 64)
-└── sim/aicpu/device_log.cpp sim backend (fprintf to stderr)
+└── sim/aicpu/device_log.cpp sim backend (one write(2) to stderr)🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@docs/logging.md` around lines 142 - 147, Update the file layout description
for the sim backend in docs/logging.md so it no longer says `fprintf to stderr`;
replace it with the current single-write stderr behavior described by the
logging implementation, using the existing sim backend wording nearby for
consistency. Keep the rest of the layout block unchanged and only correct the
stale sim logging entry.
| buffer[len++] = '\n'; | ||
| ssize_t written = write(STDERR_FILENO, buffer, len); | ||
| (void)written; |
There was a problem hiding this comment.
🩺 Stability & Availability | 🟡 Minor | ⚡ Quick win
Retry the write call on EINTR and short writes.
write(2) can return -1 with errno == EINTR if a signal arrives before any byte is transferred. The record is then lost silently. A short write is also possible if STDERR_FILENO is not a pipe, for example a regular file or a socket. The current code discards the return value, so a partial record can be emitted without a newline, which breaks the one-record-per-line contract the test asserts.
♻️ Proposed retry loop
- buffer[len++] = '\n';
- ssize_t written = write(STDERR_FILENO, buffer, len);
- (void)written;
+ buffer[len++] = '\n';
+ size_t off = 0;
+ while (off < len) {
+ ssize_t written = write(STDERR_FILENO, buffer + off, len - off);
+ if (written < 0) {
+ if (errno == EINTR) {
+ continue;
+ }
+ break; // nothing useful to do from the device-log backend
+ }
+ off += static_cast<size_t>(written);
+ }This needs #include <cerrno>.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@src/common/platform/sim/aicpu/device_log.cpp` around lines 90 - 92, Update
the logging write path around write(STDERR_FILENO, buffer, len) to include
<cerrno> and retry until the entire buffer is emitted, handling EINTR and
continuing after short writes. Preserve the complete record, including its
terminating newline, and handle terminal write failure without silently treating
a partial record as complete.
Address review feedback on the sim device-log atomicity fix: - write(2) can be interrupted (EINTR) or short on a non-pipe stderr (regular file, socket), which would drop a record or leave it without its terminating newline. Retry until the whole record is emitted. On a pipe the record is <= PIPE_BUF and still transfers atomically in one call, so the loop iterates only for non-pipe fds. - Correct the remaining stale "sim backend (fprintf to stderr)" entry in the docs/logging.md file-layout block. - Assert the forked children's waitpid status in the regression test so an abnormal child exit fails with a direct diagnostic instead of only surfacing as missing records.
1 participant
Fixes #1697.
Problem
The sim AICPU device-log backend (
src/common/platform/sim/aicpu/device_log.cpp) emitted one logical record via three separate, unlocked stdio calls:glibc locks the
FILEper call but not across the three, so any concurrent writer can land its output between the prefix, body, and newline — producing records merged onto one line or split across two. There are two concurrency sources in sim and only one needsfork:aicpu_thread_num > 1(up to 4 on a2a3, 7 on a5) is enough to tear records.stderrfd.This corrupts the
SIMPLER_DFXTotal/Orch/Schedmarkers andlog_stall_diagnostics— the ground truth for stall/deadlock triage. Sim was strictly worse than the other two backends, which already emit one record per call (onboard buffers intochar buffer[2048]then onedlog_*; host serializes its stdio under astd::mutex). This is the sim sibling of #1690 / #1691.Fix
Adopt the onboard shape: format the whole record
"[TAG] func: body\n"into one stack buffer and emit it with a singlewrite(2). The buffer caps the record at 2048 bytes, below LinuxPIPE_BUF(4096), so a record is delivered atomically both within a process (one syscall) and across processes (PIPE_BUF) whenstderris a shared pipe. Output is byte-identical to before — no consumer/parse change.Test
New
test_sim_device_log(no_hardware) is the regression barrier:MultiThreadedRecordsStayIntact— 4 threads × 200 unique records concurrently.ForkedProcessesEmitWholeRecords— 8 forked children × 100 records through a shared pipe.Each drives concurrent writers into a pipe and asserts every physical line is exactly one expected record (torn/merged lines match nothing). Both fail against the pre-fix three-call body and pass after the fix.
test_onboard_device_log_levelandtest_host_log_offstill pass (shared header touched).Docs
device_log.handdocs/logging.mdcalled the sim backend "buffer-free (singlevfprintf)" — inaccurate already (three calls) and updated to the single-writerecord-atomic model, per.claude/rules/doc-consistency.md.