排查并发卡死 BUG

[Josen-B]

计划及时间安排

• 【第一周】04.09~04.12 收集信息，了解问题现状
• 【第二周】04.13~04.19 分析问题，尝试复现，寻找稳定复现的方法
• 【第三周】04.20~04.26 排查bug原因，尝试解决

正在处理其他任务，暂时搁置……

[Josen-B]

高风险项：
WaitQueue、任务阻塞/唤醒路径、以及 event_listener 封装和 block_on/poll

1. WaitQueue

wait()、wait_until()、wait_timeout_until()、notify_one()、notify_all()

2. 任务阻塞/唤醒与状态迁移

run_queue.rs 和 task.rs：

• blocked_resched()
• future_blocked_resched()
• unblock_task()
• put_task_with_state()
• TaskState::{Running, Ready, Blocked}

尝试复现

1. 把max_cpu_num设置为8，NUM_TASKS= 16; 循环跑wait-queue，调度策略使用sched-rr

for i in $(seq 1 200); do
  echo "round $i"
  cargo xtask arceos qemu \
    --package arceos-wait-queue \
    --target aarch64-unknown-none-softfloat \
    --qemu-config test-suit/arceos/rust/task/wait_queue/qemu-aarch64.toml || break
done

暂时还没出现卡死现象

2. starry执行压力测试

cargo xtask starry test qemu \
  --target aarch64 \
  --shell-init-cmd test-suit/starryos/testcases/stress-ng-0 \
  --timeout 24

出现panic，并没有直接卡死：

Executing busybox-1.37.0-r30.trigger
OK: 13.4 MiB in 21 packages
[197.626859 0:14 starry_kernel::syscall:633] Unimplemented syscall: getcpu
stress-ng: info:  [14] setting to a 10 secs run per stressor
stress-ng: error: [14] no CPUs found in /sys/devices/system/cpu
stress-ng: info:  [14] dispatching hogs: 8 cpu
[199.262800 0:20 starry_kernel::syscall::task::ctl:117] sys_prctl: unsupported option 1
[199.265443 0:20 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[199.267409 0:20 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[199.270933 0:21 starry_kernel::syscall::task::ctl:117] sys_prctl: unsupported option 1
[199.273467 0:21 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[199.275722 0:21 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[199.658065 0:22 starry_kernel::syscall::task::ctl:117] sys_prctl: unsupported option 1
[199.660677 0:22 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[199.662768 0:22 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[209.393069 0:17 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[209.688226 0:15 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[209.712520 0:16 starry_kernel::syscall:633] Unimplemented syscall: getcpu
[209.976141 0:3 starry_kernel::mm::aspace::backend:137] Failed to unmap area: AxErrorKind::InvalidInput
panicked
        === FAIL PATTERN MATCHED: (?i)\bpanic(?:ked)?\b
                                                        at os/StarryOS/kernel/src/mm/aspace/mod.rs:263:40:
called `Result::unwrap()` on an `Err` value: BadState
<backtrace disabled>


✓ 已退出串口终端模式

[Josen-B]

新测例的设计

为了把多个潜在风险同时放大，新建了组合型压力测例：

• test-suit/arceos/rust/task/concurrency_stress

它叠加了多种并发压力：

• WaitQueue 的等待/唤醒竞争
• 带 timeout 的等待
• Mutex 高竞争下的 owner handoff
• 高频 yield_now() / sleep()
• CPU affinity 变化与迁移

测例使用：

• SMP=8 八核

• sched-rr Round-Robin 调度

这个测例不是单点功能测试，而是把多种并发行为交织在一起，持续制造：

• 多个 worker 在每一轮开始前通过 WaitQueue::wait_timeout_until() 等待 start_round
• 进入第一段 critical section 前后频繁 yield_now()
• 在 critical section 中高频竞争同一个 Mutex
• 穿插短时间 sleep(Duration::from_millis(1))
• 在轮次和 section 之间不断变化 CPU affinity
• 在 midway 和 finish 两个阶段分别通过 WaitQueue 做 barrier 式推进

因此它同时覆盖了：

• WaitQueue 正常通知与 timeout 的竞争
• Mutex owner handoff 与 waiter 唤醒
• 远端 CPU 上的 run queue 插入与延迟调度
• 高频让出 CPU、短睡眠、迁移带来的调度抖动

执行命令

cargo xtask arceos qemu \
  --package arceos-concurrency-stress \
  --target x86_64-unknown-none \
  --qemu-config test-suit/arceos/rust/task/concurrency_stress/qemu-x86_64.toml

日志表现

在日志中捕获到一些正常任务和异常任务时的延迟

正常任务

- task running after unblock: task=Task(18, ""), remote=true, delay_ns=17121501
  大约 17.1 ms
- task running after unblock: task=Task(42, ""), remote=true, delay_ns=8997104
  大约 9.0 ms
- task running after unblock: task=Task(18, ""), remote=true, delay_ns=58329255
  大约 58.3 ms

异常任务

- task running after unblock: task=Task(42, ""), remote=true, delay_ns=107366090
  大约 107 ms
- task running after unblock: task=Task(2, "main"), remote=true, delay_ns=125649733
  大约 125.6 ms
- task running after unblock: task=Task(27, ""), remote=true, delay_ns=105773747
  大约 105.8 ms
- task running after unblock: task=Task(48, ""), remote=true, delay_ns=129395236
  大约 129.4 ms

出现卡死时在日志中可以看到任务被重复唤醒

timer callback matched suspicious waitqueue task:
task=Task(48, ""), event_ticket=2414,
in_wait_queue=false, state=Ready, cpu_id=5, block_reason=WaitQueue

task unblock skipped:
task=Task(48, ""), expected_state=Blocked,
actual_state=Ready, in_wait_queue=false, cpu_id=5,
on_cpu=false, ticket=2414, block_reason=WaitQueue

问题分析

在跨核调度时，并不会开启抢占式调度，只有在当前 cpu 时，才触发了 set_preempt_pending。

因此notify的任务 C 只会放到对应 cpu 的 ready queue 的队尾，等待前面的任务都调度完，才轮到它。这需要一段较长的时间，如果超过了timeout，那么timer就会强制去唤醒这个任务。

下图为同 cpu 和跨 cpu 调度任务的简单示意图

然后问题就出现在这里：

正常情况下，任务 C 被放到 ready queue 中很快就会得到cpu，然后把ticket清理掉，此时timeout到来，会被忽略掉。

但是如果任务 C 仍在 ready queue中等待，没有及时清理掉ticket，timeout到来时便会认为任务C还没有被唤醒，因此又去再唤醒任务C，但是任务C 的状态已经脏了，它无法保证能够正常工作，它也无法handoff给下一个任务D。

因为 remote wakeup 只是入队，没有远端 resched / IPI 之类的积极推动机制，调度时机完全依赖目标 CPU 的自然切换，所以在这个窗口期内出现timeout，就会导致duplicate wakeup race。

正常时序

Worker A            WaitQueue               Timer                 Target CPU
   |                    |                     |                        |
   |---- wait(timeout)->|                     |                        |
   |   state=Blocked    |---- set ticket ---->|                        |
   |                    |                     |                        |
   |                    |---- notify_one ---->|                        |
   |                    |  选中 A             |                        |
   |                    |                     |                        |
   |                    |------ unblock ----------------------------->  |
   |                    |                     |                        |
   |                    |                     |          A 很快被调度运行 |
   |                    |                     |<-----------------------|
   |<-------------------|                     |                        |
   | cancel_events()    |                     |                        |
   | ticket expired     |                     |                        |
   |                    |                     |                        |
   |                    |                     |--- old timer arrives -->|
   |                    |                     |   发现 ticket stale     |
   |                    |                     |   直接忽略              |
   |                    |                     |                        |
   |---------------- 系统继续正常推进 ---------------------------------|

异常时序

Worker A            WaitQueue               Timer                 Target CPU
   |                    |                     |                        |
   |---- wait(timeout)->|                     |                        |
   |   state=Blocked    |---- set ticket ---->|                        |
   |                    |                     |                        |
   |                    |---- notify_one ---->|                        |
   |                    |  选中 A             |                        |
   |                    |                     |                        |
   |                    |------ unblock ----------------------------->  |
   |                    |                     |                        |
   |                    |                     |   A 被放进 ready queue   |
   |                    |                     |   但远端 resched 被忽略 |
   |                    |                     |   A 一直没真正跑起来    |
   |                    |                     |                        |
   |                    |                     |--- old timer arrives -->|
   |                    |                     |   ticket 还没失效      |
   |                    |                     |   timer callback 命中   |
   |                    |                     |                        |
   |                    |        duplicate wakeup / 状态竞争 / 队列污染 |
   |                    |                     |                        |
   |---------------------- 某些 waiter 最终永远推进不了 ----------------|

[Josen-B]

这个 ArceOS 压力测试本质上是在“反复制造很多线程同时等待、唤醒、抢锁、迁移 CPU、yield/sleep”的高并发场景，专门放大 SMP 下的竞态窗口。

它主要做了这些事：

• 先按 CPU 数 x 4 创建一批 worker 线程，循环跑 64 轮。
• 每轮开始前，所有 worker 先进入一轮“等待开始”的同步点，主线程再统一 notify_all 放行。
• worker 放行后先跑第一段临界区：频繁抢同一个 Mutex，中间穿插 yield_now()、短暂 sleep(1ms)、忙等自旋。
• 跑到中途后，再进入第二个同步点，主线程再次统一放行。
• 第二段临界区里继续抢锁，但还会不断修改 CPU affinity，让任务在“固定本核 / 排除本核 / 任意 CPU”之间切换，制造迁移和 remote wakeup。
• 所有这些同步点都不是纯忙等，而是通过 WaitQueue::wait_timeout_until() 做“带 timeout 的等待”，这样会同时压到：
  • wait queue 的入队/出队
  • notify 唤醒
  • timer timeout 唤醒
  • 两者之间的竞争
• 测试里还有一个 watchdog 线程，定期检查整个系统是否还在推进；如果长时间没有进展，就直接判定卡死。
• 每轮还会检查计数器和共享数据，确认所有 worker 确实经过了预期的关键路径，而不是“线程早就丢了但测试没发现”。

目前测例和修改已提交PR:

• fix: expire timer ticket early in wait queue wakeup to prevent duplicate wakeup race #279

[Josen-B]

针对PR反馈的意见，测试用例做出了对应的修改：

• 测试轮数 rounds 从 64 提高到 300

• 将清理ticket的时机放在notify_one()，notify_one_with()中，func()之前

• 主线程每次 notify_all() 之后，再补一轮 yield_now()、sleep(0/1ms) 和 busy spin，尽量把 notify 与 timer callback 的时序压近

• 目前有看门狗来负责超时退出，考虑先不使用断言，因为需要加在timeout的callback中，会影响原本的逻辑

修改测例脚本后，在清理和不清理 tickets 的情况下，在本地分别测试 4 个架构各 10 次，结果如下：

清理前：

架构	出现卡死	测例通过
x86_64	9	1
riscv64	10	0
loongarch64	10	0
aarch64	10	0

清理后：

架构	出现卡死	测例通过
x86_64	2	8
riscv64	4	6
loongarch64	1	9
aarch64	10	0

【CI】https://github.com/rcore-os/tgoskits/actions/runs/24715070044

修改完之后除aarch64之外其他平台卡死几率明显降低，但还是会偶发卡死现象，并且连看门狗都没有报超时，直接卡死

另外，会出现偶发的重复获得锁的panic：

panicked at 
            === FAIL PATTERN MATCHED: (?i)\bpanic(?:ked)?\b
                                                           os/arceos/modules/axsync/src/mutex.rs:73:21:
assertion `left != right` failed: Thread(29) tried to acquire mutex it already owns.
  left: 29
 right: 29
<backtrace disabled>

加了一个低频 heartbeat，卡住以后是否还能继续看到 timer heartbeat，说明timer IRQ 还活着，但测试线程和 watchdog 线程都没有再推进

第二轮解决

三个问题

1. aarch64平台比其他平台卡死几率高
2. 仍然出现小概率卡死
3. 小概率出现重复获得锁的panic

第一个问题

ax-percpu(custom-base) 依赖的 per-CPU 基址/读取路径在 aarch64 上和实际布局不完全一致，导致某些 per-CPU 数据被错读

CURRENT_TASK_PTR / per-CPU 路径先坏。
最关键的新证据不是 page fault 本身，而是这次跑出来的日志里 CPU ID 直接变成了一个明显不可能的值：

• 18446462600068350480:2 ... spinlock contention ..

真实系统只有 8 个 CPU，这种值只能说明 ax_log::current_cpu_id() 走到的 per-CPU 读取已经错了。也就是说，在真正 crash 前，per-CPU 基址或 per-CPU 数据读取链路就已经开始返回垃圾值了。这和我们之前看到的：

• ax_log::print_fmt() 里踩坏指针
• CURRENT_TASK_PTR 相关路径可疑
  是完全一致的。

最根本的问题不是 CURRENT_TASK_PTR 这个字段单独写坏了，而是 plat-dyn 当前使用的 someboot legacy per-CPU 布局，把这三样东西放进了同一个每核槽位里：

• linker percpu data
• PerCpuMeta
• boot stack

在 legacy 布局里，每核槽大小正好是 0x41000：

• 栈 0x40000
• 前面只剩大约 0x1000 给 percpu data + meta

而 ArceOS 的 primary main 和 secondary idle 都是 new_init()，没有独立分配 kstack，会长期继续跑在这块 boot stack 上：

• run_queue.rs (line 774)
• run_queue.rs (line 790)

这就意味着，只要 aarch64 上栈更深一点，boot stack 向下长，就会先踩坏同槽里的 percpu data。
一旦 percpu data 被踩，最先坏掉的就是：

• CPU_ID
• CURRENT_TASK_PTR

这正好对应我们已经抓到的现象：

• CPU ID 先变成离谱的大垃圾值
• 然后 ax_log::print_fmt()、spawn_task()、IRQ/调度路径陆续踩到坏指针

为什么 aarch64 更容易中招：

• 它的异常/中断路径和调用栈更重
• 同样压力下更容易把这块 boot stack 往下打穿
• 所以更早把 percpu 数据踩坏，表现成“更高概率卡死”

一句话总结：legacy percpu 布局把 boot stack 和 percpu data 放太近，aarch64 上更容易栈下溢把 percpu 数据踩坏

[ZR233]

在 PR #1118（head 6028515a7c661aa993c06f04740dcacfd1e5a8ce）的 CI 中又观察到一次 Starry QEMU 超时：

• workflow run: https://github.com/rcore-os/tgoskits/actions/runs/26955927032
• job: Test starry riscv64 qemu / run_host
• 命令: cargo xtask starry test qemu --arch riscv64
• 现象: bugfix、c-regression、cgroup-basic、drm、evdev、riscv64-regression 都通过后，smoke 用例在重新启动 QEMU 时 QEMU timed out after 5s，最终 result: 6/7 case(s) passed。
• 相关性判断: fix(starry-ipc): correct ShmidDs layout to match Linux shmid64_ds #1118 只修改 os/StarryOS/kernel/src/syscall/ipc/shm.rs 的 SysV shm ABI 布局；本地 cargo xtask clippy --package starry-kernel 通过，且 x86_64 syscall 组里的 test-shmctl-info 为 21 pass, 0 fail。因此这次 riscv64 smoke 超时看起来更像现有 QEMU/调度/启动超时问题，而不是 PR fix(starry-ipc): correct ShmidDs layout to match Linux shmid64_ds #1118 引入的共享内存 ABI 回归。

[ZR233]

在 PR #1112（head 6f354d735e2fd6f84837e5799768e741b38c885a）的 CI 中又观察到一次同类 Starry riscv64 smoke 超时：

• workflow run: https://github.com/rcore-os/tgoskits/actions/runs/26950552329
• job: Test starry riscv64 qemu / run_host
• 命令: cargo xtask starry test qemu --arch riscv64
• 现象: bugfix、c-regression、cgroup-basic、drm、evdev、riscv64-regression 均通过后，smoke 用例已打印 /root 和 All tests passed!，并匹配成功 regex，但 QEMU 随后仍被判定为 QEMU timed out after 5s，最终 result: 6/7 case(s) passed。
• 相关性判断: fix(ax-plat-x86-pc): enable XCR0 AVX/SSE state for userspace AVX #1112 只修改 platforms/ax-plat-x86-pc 中 x86_64 的 CR4.OSXSAVE / XCR0 初始化；对应的 Test starry x86_64 qemu / run_container 已通过。因此这次 riscv64 smoke 超时看起来仍是现有 Starry riscv64 QEMU/启动超时问题，而不是 fix(ax-plat-x86-pc): enable XCR0 AVX/SSE state for userspace AVX #1112 引入的 x86 平台回归。

[ZR233]

在 PR #1095（head 5943d788ca1082e9986ae68a5eef0283cae97c66）的 CI 中又观察到一次 Starry QEMU smoke 超时：

• workflow run: https://github.com/rcore-os/tgoskits/actions/runs/26957293726
• job: Test starry aarch64 qemu / run_host
• 命令: cargo xtask starry test qemu --arch aarch64
• 现象: usb-audio-iso、usb-storage、bugfix、c-regression、cgroup-basic、drm、evdev 均通过后，smoke 用例启动 QEMU 后在 5s 内没有匹配成功条件，最终报：

failed: smoke: starry qemu test failed for case `smoke`: QEMU timed out after 5s
starry normal qemu test summary:
  PASS usb-audio-iso
  PASS usb-storage
  PASS bugfix
  PASS c-regression
  PASS cgroup-basic
  PASS drm
  PASS evdev
  FAIL smoke (5.49s)
result: 7/8 case(s) passed

相关性判断：#1095 主要修改 scripts/axbuild/src/starry/perf.rs、scripts/axbuild/src/starry/mod.rs，以及 test-suit/starryos/normal/qemu-smp1/smoke/qemu-riscv64.toml 的 riscv64 smoke 超时时间；它没有修改 aarch64 smoke 配置、Starry kernel、调度或 evdev/smoke 测试逻辑。因此这次 aarch64 smoke 5s 超时看起来更像现有 Starry QEMU smoke 启动/调度超时问题，而不是 #1095 引入的 qperf runtime 回归。

同一 run 中 Test starry riscv64 qemu / run_host、Test arceos aarch64 qemu / run_host、Test arceos loongarch64 qemu / run_host 后续为 cancelled，日志表现为 workflow 在失败后清理 orphan process，并未看到可归因到 #1095 改动面的独立失败。

[ZR233]

在 PR #1026 当前 head 61064872d0e4e65129215efbe5b9f3524d5edf18 的 CI 中又观察到一次同类 Starry riscv64 smoke 超时：

• workflow run: https://github.com/rcore-os/tgoskits/actions/runs/26949977287
• job: Test starry riscv64 qemu / run_host
• 命令: cargo xtask starry test qemu --arch riscv64
• 现象: bugfix、c-regression、cgroup-basic、drm、evdev、riscv64-regression 均通过后，smoke 用例启动 Starry 后在 5s 内未完成匹配，最终报 QEMU timed out after 5s，汇总为 result: 6/7 case(s) passed。
• 相关性判断: test(starry): add git stress test suite #1026 只新增 test-suit/starryos/stress/git* stress case；同一 run 中关键相关 job Test starry x86_64 qemu / run_container 已通过，并且本地 cargo xtask starry test qemu --arch x86_64 --stress -c git / -c git-rename 均通过。因此这次 riscv64 normal smoke 超时看起来仍是现有 Starry/QEMU smoke 超时问题，而不是 test(starry): add git stress test suite #1026 引入的 git stress 回归。

同一 run 中 Test starry aarch64 qemu / run_host、Test arceos x86_64/aarch64/riscv64 qemu / run_host 后续显示为 cancelled，没有看到可归因到 #1026 改动面的独立失败。

[ZR233]

在 PR #995（head db68e607ec5ed02712011f333239192c78e7744e）的 CI 中又观察到一次 Starry 并发/网络相关超时：

• workflow run: https://github.com/rcore-os/tgoskits/actions/runs/26574171525
• job: Test starry riscv64 qemu / run_container
• 命令面：cargo xtask starry test qemu --arch riscv64
• 现象：apk-curl、apt 通过后，normal/qemu-smp1/bugfix 中 /usr/bin/bug-tcp-concurrent-connect 在 accept client 3 附近超时，最终日志包含：

FAIL: test timed out
STARRY_GROUPED_TEST_FAILED:
/usr/bin/bug-tcp-concurrent-connect status=124
failed: bugfix: starry qemu test failed for case `bugfix`

相关性判断：#995 只新增 test-suit/starryos/normal/qemu-smp1/syscall/test-compat/c/ 下的 C 测试，不修改 Starry 内核、调度、TCP、bugfix 分组或 riscv64 QEMU 配置；本地针对该 PR head 运行 cargo xtask starry test qemu --arch x86_64 -c syscall 已完成并汇总为 PASS syscall。因此这次 riscv64 bug-tcp-concurrent-connect 超时看起来更像本 issue 跟踪的既有并发/调度/QEMU 超时问题，而不是 #995 引入的 syscall 兼容性测试回归。