BUG: soft lockup in __run_timer_base (2)

Status: moderation: reported on 2026/11/01 05:21
Subsystems: trace
Labels: prio:low
[Documentation on labels]
Reported-by: syzbot+f8f7a3e9f115cfef26b7@syzkaller.appspotmail.com
First crash: 4d05h, last: 3h18m
✨ AI-generated root cause summary:

A soft lockup occurred on CPU 1 while executing dup_mmap() -> copy_page_range() -> copy_pte_range() during a process clone, compounded by softirq timer handling in __run_timers(). In this debug kernel configuration, copying present page table entries exercised page_table_check_set(), which invoked rcu_read_lock()/rcu_read_unlock(), triggering trace_lock_release(), perf_trace_lock(), and extensive KASAN memory checks under non-preemptible PTE spinlocks for every PTE. When interrupted, CPU 1 entered run_timer_softirq() to process accumulated timers, keeping preemption disabled long enough to trigger the 112-second soft lockup watchdog and delay handling of a TLB flush IPI from CPU 0. In a production build without debugging sanitizers and tracing overhead, copy_pte_range() periodically checks need_resched() and yields via cond_resched(), preventing any lockup.

▶ ▼ ✨ Full AI root cause analysis
Based on kernel commit 9ce722236a20:

Detailed Technical Explanation

1. Context and Bug Manifestation

The bug report indicates a soft lockup on CPU 1 lasting for 112 seconds (watchdog: BUG: soft lockup - CPU#1 stuck for 112s! [syz-executor:5638]). When the watchdog fired on CPU 1, it sent an NMI to CPU 0 to capture all CPU traces:

  • CPU 1 (Task Context): Task syz-executor:5638 was executing kernel_clone() $\to$ copy_process() $\to$ copy_mm() $\to$ dup_mm() $\to$ dup_mmap() $\to$ copy_page_range() $\to$ copy_pmd_range() $\to$ copy_pte_range(). Within copy_pte_range(), it traversed present page table entries (PTEs) via copy_present_ptes() $\to$ __copy_present_ptes() $\to$ set_ptes() $\to$ page_table_check_ptes_set() $\to$ page_table_check_set().
  • CPU 1 (Interrupt/Softirq Context): The task on CPU 1 was interrupted by the APIC timer (sysvec_apic_timer_interrupt()), which invoked softirqs on interrupt exit (__irq_exit_rcu() $\to$ invoke_softirq() $\to$ __do_softirq() $\to$ run_timer_softirq() $\to$ __run_timer_base() $\to$ __run_timers() $\to$ expire_timers()).
  • CPU 0: Task syz-executor:5627 was in exit_mmap() $\to$ arch_exit_mmap() $\to$ free_ldt_pgtables() $\to$ tlb_finish_mmu() $\to$ flush_tlb_mm_range() $\to$ flush_tlb_multi() $\to$ smp_call_function_many_cond(), waiting in csd_lock_wait() for CPU 1 to complete a synchronous TLB flush cross-call.

2. Root Cause and Mechanism

  1. Sanitizer and Tracing Multiplication under Spinlocks: In mm/memory.c, copy_pte_range() acquires source and destination PTE spinlocks (src_ptl and dst_ptl), which disable preemption. The function iterates through up to 32 PTEs (if (++progress >= 32)) before checking need_resched() || spin_needbreak(...) to drop the spinlocks and invoke cond_resched(). With CONFIG_PAGE_TABLE_CHECK, lockdep, perf lock tracing (CONFIG_LOCKDEP, perf_trace_lock), and KASAN (CONFIG_KASAN) simultaneously enabled:

    • For every single mapped PTE, page_table_check_set() in mm/page_table_check.c performs an rcu_read_lock() and rcu_read_unlock().
    • Each rcu_read_unlock() calls lock_release() $\to$ trace_lock_release() $\to$ perf_trace_lock() $\to$ perf_trace_buf_alloc().
    • Allocating and zeroing the perf trace buffer invokes __asan_memset() and kasan_check_range(). This introduces massive per-PTE overhead under non-preemptible spinlock sections when duplicating large address spaces.
  2. Softirq Timer Starvation: When CPU 1 was interrupted by the timer interrupt, softirqs were serviced. Because CPU 1 had accumulated expired timer ticks, run_timer_softirq() called __run_timers(), which loops in kernel/time/timer.c:

    while (time_after_eq(jiffies, base->clk) &&
           time_after_eq(jiffies, base->next_expiry))
    

    Softirq execution runs with preemption disabled. Inside expire_timers(), _raw_spin_unlock_irq() temporarily re-enables hard interrupts around timer callback execution, but softirq context is maintained. Because the softlockup watchdog stopper thread (migration/1 / softlockup_fn) requires task preemption to run and update watchdog_touch_ts, it remained starved across the combined runtime of the heavy PTE duplication loop and the subsequent timer expiration processing.

  3. CPU 0 Cross-Call Serialization: While CPU 1 was cycling through timers with local hard interrupts disabled during raw_spin_lock_irq(&base->lock) acquisitions, CPU 0 attempted to execute an SMP function call (flush_tlb_multi()) to flush lazy TLB entries during free_ldt_pgtables(). CPU 0 waited in csd_lock_wait() for CPU 1 to process the interrupt, leading to mutual delay until the watchdog threshold was exceeded.

3. Runtime Consequences in Production Kernels

In a production kernel without debugging sanitizers (CONFIG_PAGE_TABLE_CHECK disabled or dormant, CONFIG_KASAN=n, CONFIG_LOCKDEP=n, lock tracing disabled):

  • rcu_read_lock() / rcu_read_unlock() inside page table modifications are zero-cost compiler barriers.

  • copy_pte_range() processes PTE copies in nanoseconds per entry and reliably yields every 32 PTEs via cond_resched() if a higher-priority task (such as the migration/watchdog thread) is queued.

  • The soft lockup timeout (112 seconds) is purely an artifact of debug sanitizer and tracing amplification; it does not occur in production builds.

  • MemoryCorruption: false — There are no out-of-bounds writes, use-after-free conditions, wild pointers, or corrupted reference counters.

  • InfoLeak: "none" — No uninitialized or sensitive kernel memory is leaked to userspace or external observers.

  • RawDenialOfService: false — In a production kernel build without sanitizers, copy_pte_range() efficiently relinquishes the CPU via cond_resched(), preventing system hangs or watchdog timeouts.

  • IsNetCandidate: false — Networking is not involved in this process duplication and timer execution path.

  • IsKVMCandidate: false — Virtualization / KVM subsystems are not involved.

▶ ▼ ✨ AI Jobs (1)
ID Workflow Result Correct Bug Created Started Finished Revision
837af891 assessment-security DenialOfService: ❌ Exploitable: ❌ FilesystemTrigger: ❌ FuzzingArtifact: ✅ MemoryCorruption: ❌ NetworkNeedsSetup: ❌ NetworkTrigger: ❌ PeripheralTrigger: ❌ RemoteTrigger: ❌ Unprivileged: ❌ UserNamespace: ❌ VMGuestTrigger: ❌ VMHostTrigger: ❌ ❓ BUG: soft lockup in __run_timer_base (2) 2026/10/29 02:31 2026/10/29 02:31 2026/10/29 03:49 b1d00f76
▶ ▼ Similar bugs (4)
Kernel Title Rank 🛈 Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: rcu detected stall in __run_timer_base (3) kasan mm 1 6 480d 656d 0/29 auto-obsoleted due to no activity on 2025/10/06 12:53
upstream BUG: soft lockup in __run_timer_base prio:high kernel 1 1 251d 247d 0/29 auto-obsoleted due to no activity on 2026/05/24 04:21
upstream INFO: rcu detected stall in __run_timer_base usb 1 syz, C done done 10 863d 931d 26/29 fixed on 2024/07/31 23:31
upstream INFO: rcu detected stall in __run_timer_base (2) exfat 1 1 779d 779d 0/29 auto-obsoleted due to no activity on 2024/12/12 02:02

Sample crash report:
watchdog: BUG: soft lockup - CPU#0 stuck for 172s! [udevd:5001]
Modules linked in:
irq event stamp: 899899
hardirqs last  enabled at (899898): [<ffffffff8c066ec3>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:219 [inline]
hardirqs last  enabled at (899898): [<ffffffff8c066ec3>] _raw_spin_unlock_irq+0x23/0x50 kernel/locking/spinlock.c:229
hardirqs last disabled at (899899): [<ffffffff8c039c6e>] sysvec_apic_timer_interrupt+0xe/0xc0 arch/x86/kernel/apic/apic.c:1062
softirqs last  enabled at (878736): [<ffffffff89c5845d>] local_bh_disable include/linux/bottom_half.h:20 [inline]
softirqs last  enabled at (878736): [<ffffffff89c5845d>] __alloc_skb+0x18d/0x7a0 net/core/skbuff.c:698
softirqs last disabled at (878777): [<ffffffff81896196>] __do_softirq kernel/softirq.c:703 [inline]
softirqs last disabled at (878777): [<ffffffff81896196>] invoke_softirq kernel/softirq.c:542 [inline]
softirqs last disabled at (878777): [<ffffffff81896196>] __irq_exit_rcu+0xc6/0x220 kernel/softirq.c:786
CPU: 0 UID: 0 PID: 5001 Comm: udevd Not tainted syzkaller #0 PREEMPT(full) 
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/07/2026
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:220 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x29/0x50 kernel/locking/spinlock.c:229
Code: 90 f3 0f 1e fa 53 48 89 fb 48 83 c7 18 48 8b 74 24 08 e8 0a de 9d f5 48 89 df e8 c2 55 9e f5 e8 fd f6 ca f5 fb bf 01 00 00 00 <e8> f2 49 8f f5 65 48 8b 05 3a 61 da 08 48 85 c0 74 07 5b e9 7f 4a
RSP: 0018:ffffc90000007d90 EFLAGS: 00000206
RAX: 00000000000dbb3a RBX: ffff8880b8226480 RCX: 0000000000000102
RDX: 0000000000000002 RSI: ffffffff8e6a6798 RDI: 0000000000000001
RBP: ffffc90000007f08 R08: ffffffff91bdd6bf R09: 1ffffffff237bad7
R10: dffffc0000000000 R11: fffffbfff237bad8 R12: ffff8880b8226480
R13: 1ffff92000000fcc R14: ffff88803555a7d0 R15: ffffc90000007e60
FS:  00007f0f417a5880(0000) GS:ffff888123413000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fffc6c8e778 CR3: 000000007e316000 CR4: 00000000003526f0
Call Trace:
 <IRQ>
 expire_timers kernel/time/timer.c:1799 [inline]
 __run_timers kernel/time/timer.c:2375 [inline]
 __run_timer_base+0x642/0x8b0 kernel/time/timer.c:2387
 run_timer_base kernel/time/timer.c:2396 [inline]
 run_timer_softirq+0xb7/0x170 kernel/time/timer.c:2406
 handle_softirqs+0x265/0x8d0 kernel/softirq.c:669
 __do_softirq kernel/softirq.c:703 [inline]
 invoke_softirq kernel/softirq.c:542 [inline]
 __irq_exit_rcu+0xc6/0x220 kernel/softirq.c:786
 irq_exit_rcu+0x9/0x30 kernel/softirq.c:809
 instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1062 [inline]
 sysvec_apic_timer_interrupt+0xa6/0xc0 arch/x86/kernel/apic/apic.c:1062
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:674
RIP: 0010:rcu_is_watching_curr_cpu include/linux/context_tracking.h:128 [inline]
RIP: 0010:rcu_is_watching+0x16/0xb0 kernel/rcu/tree.c:753
Code: 00 00 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 41 57 41 56 53 65 48 ff 05 2f 5c 33 13 e8 2a 50 56 0a <89> c3 83 f8 08 73 66 49 bf 00 00 00 00 00 fc ff df 4c 8d 34 dd d0
RSP: 0018:ffffc90002fa7840 EFLAGS: 00000202
RAX: 0000000000000000 RBX: 0000000000000001 RCX: 8000000000000001
RDX: ffff88807e3a3e80 RSI: ffffffff8c8e9e60 RDI: ffffffff8c8e9e20
RBP: ffffc90002fa7960 R08: ffffffff91bdd6bf R09: 1ffffffff237bad7
R10: dffffc0000000000 R11: fffffbfff237bad8 R12: dffffc0000000000
R13: ffff8880329d7ba0 R14: 0000000000000000 R15: 00000000179b5940
 trace_ctime_ns_xchg include/trace/events/timestamp.h:52 [inline]
 inode_set_ctime_current+0x749/0xb60 fs/inode.c:2928
 shmem_mknod+0x270/0x340 mm/shmem.c:4049
 lookup_open+0xedc/0x1970 fs/namei.c:4569
 open_last_lookups fs/namei.c:4768 [inline]
 path_openat+0x70c/0x20f0 fs/namei.c:5007
 do_file_open+0x23e/0x4a0 fs/namei.c:5039
 do_sys_openat2+0x115/0x200 fs/open.c:1442
 do_sys_open fs/open.c:1448 [inline]
 __do_sys_openat fs/open.c:1464 [inline]
 __se_sys_openat fs/open.c:1459 [inline]
 __x64_sys_openat+0x138/0x170 fs/open.c:1459
 do_syscall_x64 arch/x86/entry/syscall_64.c:61 [inline]
 do_syscall_64+0x166/0x520 arch/x86/entry/syscall_64.c:84
 entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f0f410a7407
Code: 48 89 fa 4c 89 df e8 38 aa 00 00 8b 93 08 03 00 00 59 5e 48 83 f8 fc 74 1a 5b c3 0f 1f 84 00 00 00 00 00 48 8b 44 24 10 0f 05 <5b> c3 0f 1f 80 00 00 00 00 83 e2 39 83 fa 08 75 de e8 23 ff ff ff
RSP: 002b:00007fffc6c96bf0 EFLAGS: 00000202 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 00007f0f417a5880 RCX: 00007f0f410a7407
RDX: 0000000000080141 RSI: 00005627d4a8102e RDI: ffffffffffffff9c
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 00000000000001a4 R11: 0000000000000202 R12: 00000000ffffffff
R13: 00000000ffffffff R14: ffffffffffffffff R15: 0000000000000000
 </TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 UID: 0 PID: 5296 Comm: dhcpcd Not tainted syzkaller #0 PREEMPT(full) 
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/07/2026
RIP: 0010:csd_lock_wait kernel/smp.c:389 [inline]
RIP: 0010:csd_lock kernel/smp.c:422 [inline]
RIP: 0010:smp_call_function_many_cond+0x61e/0x1500 kernel/smp.c:970
Code: b6 04 04 84 c0 0f 85 d5 03 00 00 44 8b 3b 44 89 fe 83 e6 01 31 ff e8 51 7a 0c 00 41 83 e7 01 75 07 e8 36 75 0c 00 eb 3f f3 90 <48> b8 00 00 00 00 00 fc ff df 41 0f b6 04 04 84 c0 75 0f f7 03 01
RSP: 0018:ffffc90002f97420 EFLAGS: 00000293
RAX: ffffffff81bca0ee RBX: ffff8880b8244028 RCX: ffff888028fe0000
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000000
RBP: ffffc90002f97570 R08: ffff888028fe159f R09: 1ffff110051fc2b3
R10: dffffc0000000000 R11: 0000000000000000 R12: 1ffff11017048805
R13: 0000000000000000 R14: ffff8880b8244020 R15: 0000000000000001
FS:  00007fbb47bce780(0000) GS:ffff888123513000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000055f5d96d9168 CR3: 0000000077a9c000 CR4: 00000000003526f0
Call Trace:
 <TASK>
 __flush_tlb_multi arch/x86/include/asm/paravirt.h:46 [inline]
 flush_tlb_multi arch/x86/mm/tlb.c:1361 [inline]
 flush_tlb_mm_range+0x910/0x10b0 arch/x86/mm/tlb.c:1435
 dup_mmap+0x17dd/0x1e10 mm/mmap.c:1884
 dup_mm kernel/fork.c:1542 [inline]
 copy_mm+0x115/0x470 kernel/fork.c:1594
 copy_process+0x1ecc/0x44b0 kernel/fork.c:2320
 kernel_clone+0x2d7/0x940 kernel/fork.c:2784
 __do_sys_clone kernel/fork.c:2926 [inline]
 __se_sys_clone kernel/fork.c:2910 [inline]
 __x64_sys_clone+0x1b6/0x230 kernel/fork.c:2910
 do_syscall_x64 arch/x86/entry/syscall_64.c:61 [inline]
 do_syscall_64+0x166/0x520 arch/x86/entry/syscall_64.c:84
 entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fbb47ca2636
Code: 89 df e8 6d e8 f6 ff 45 31 c0 31 d2 31 f6 64 48 8b 04 25 10 00 00 00 bf 11 00 20 01 4c 8d 90 d0 02 00 00 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 52 89 c5 85 c0 75 31 64 48 8b 04 25 10 00 00
RSP: 002b:00007ffce56a90b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
RAX: ffffffffffffffda RBX: 00007ffce56a90b8 RCX: 00007fbb47ca2636
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
RBP: 00007ffce56c9600 R08: 0000000000000000 R09: 0000000000000001
R10: 00007fbb47bcea50 R11: 0000000000000246 R12: 00007ffce56a91f0
R13: 0000000000000000 R14: 0000000000000000 R15: 000055f5c88a7ac0
 </TASK>

Crashes (2):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2026/11/01 07:35 bpf bcd07fd1673b 25a0ae84 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-bpf-kasan-gce BUG: soft lockup in __run_timer_base
2026/10/28 05:19 bpf 9ce722236a20 96923c60 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-bpf-kasan-gce BUG: soft lockup in __run_timer_base
* Struck through repros no longer work on HEAD.