syzbot


possible deadlock in run_timer_base

Status: upstream: reported on 2024/05/25 20:46
Subsystems: kernel
[Documentation on labels]
Reported-by: syzbot+9a474438d0c960487fcf@syzkaller.appspotmail.com
First crash: 26d, last: 26d
Discussions (1)
Title Replies (including bot) Last reply
[syzbot] [kernel?] possible deadlock in run_timer_base 0 (1) 2024/05/25 20:46

Sample crash report:
------------[ cut here ]------------
======================================================
WARNING: possible circular locking dependency detected
6.9.0-syzkaller-10713-g2a8120d7b482 #0 Not tainted
------------------------------------------------------
swapper/0/0 is trying to acquire lock:
ffffffff8dba2e98 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x12/0x70 kernel/locking/semaphore.c:139

but task is already holding lock:
ffff88802c02a858 (&base->lock){-.-.}-{2:2}, at: __run_timer_base kernel/time/timer.c:2427 [inline]
ffff88802c02a858 (&base->lock){-.-.}-{2:2}, at: __run_timer_base kernel/time/timer.c:2421 [inline]
ffff88802c02a858 (&base->lock){-.-.}-{2:2}, at: run_timer_base+0x109/0x190 kernel/time/timer.c:2437

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #3 (&base->lock){-.-.}-{2:2}:
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0x3a/0x60 kernel/locking/spinlock.c:162
       lock_timer_base+0x5d/0x220 kernel/time/timer.c:1051
       __mod_timer+0x426/0xdc0 kernel/time/timer.c:1132
       add_timer_global+0x8a/0xc0 kernel/time/timer.c:1330
       __queue_delayed_work+0x1ba/0x2e0 kernel/workqueue.c:2543
       queue_delayed_work_on+0x12a/0x150 kernel/workqueue.c:2572
       psi_task_change+0x1b4/0x2e0 kernel/sched/psi.c:912
       psi_enqueue kernel/sched/stats.h:139 [inline]
       enqueue_task kernel/sched/core.c:2112 [inline]
       activate_task+0x213/0x400 kernel/sched/core.c:2146
       wake_up_new_task+0x574/0xc90 kernel/sched/core.c:4900
       kernel_clone+0x236/0x980 kernel/fork.c:2828
       user_mode_thread+0xb4/0xf0 kernel/fork.c:2875
       rest_init+0x23/0x2b0 init/main.c:712
       start_kernel+0x3df/0x4c0 init/main.c:1103
       x86_64_start_reservations+0x18/0x30 arch/x86/kernel/head64.c:507
       x86_64_start_kernel+0xb2/0xc0 arch/x86/kernel/head64.c:488
       common_startup_64+0x13e/0x148

-> #2 (&rq->__lock){-.-.}-{2:2}:
       _raw_spin_lock_nested+0x31/0x40 kernel/locking/spinlock.c:378
       raw_spin_rq_lock_nested+0x29/0x130 kernel/sched/core.c:559
       raw_spin_rq_lock kernel/sched/sched.h:1406 [inline]
       rq_lock kernel/sched/sched.h:1702 [inline]
       task_fork_fair+0x73/0x250 kernel/sched/fair.c:12710
       sched_cgroup_fork+0x3cf/0x510 kernel/sched/core.c:4844
       copy_process+0x4710/0x6f50 kernel/fork.c:2499
       kernel_clone+0xfd/0x980 kernel/fork.c:2797
       user_mode_thread+0xb4/0xf0 kernel/fork.c:2875
       rest_init+0x23/0x2b0 init/main.c:712
       start_kernel+0x3df/0x4c0 init/main.c:1103
       x86_64_start_reservations+0x18/0x30 arch/x86/kernel/head64.c:507
       x86_64_start_kernel+0xb2/0xc0 arch/x86/kernel/head64.c:488
       common_startup_64+0x13e/0x148

-> #1 (&p->pi_lock){-.-.}-{2:2}:
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0x3a/0x60 kernel/locking/spinlock.c:162
       class_raw_spinlock_irqsave_constructor include/linux/spinlock.h:553 [inline]
       try_to_wake_up+0x9a/0x13e0 kernel/sched/core.c:4262
       up+0x79/0xb0 kernel/locking/semaphore.c:191
       __up_console_sem kernel/printk/printk.c:340 [inline]
       __console_unlock kernel/printk/printk.c:2731 [inline]
       console_unlock+0x23e/0x290 kernel/printk/printk.c:3050
       vga_remove_vgacon drivers/pci/vgaarb.c:186 [inline]
       vga_remove_vgacon+0x90/0xd0 drivers/pci/vgaarb.c:167
       __aperture_remove_legacy_vga_devices drivers/video/aperture.c:331 [inline]
       aperture_remove_conflicting_pci_devices+0x17f/0x210 drivers/video/aperture.c:374
       bochs_pci_probe+0x101/0x1150 drivers/gpu/drm/tiny/bochs.c:651
       local_pci_probe+0xde/0x1b0 drivers/pci/pci-driver.c:324
       pci_call_probe drivers/pci/pci-driver.c:392 [inline]
       __pci_device_probe drivers/pci/pci-driver.c:417 [inline]
       pci_device_probe+0x294/0x7a0 drivers/pci/pci-driver.c:451
       call_driver_probe drivers/base/dd.c:578 [inline]
       really_probe+0x23e/0xa90 drivers/base/dd.c:656
       __driver_probe_device+0x1de/0x440 drivers/base/dd.c:798
       driver_probe_device+0x4c/0x1b0 drivers/base/dd.c:828
       __driver_attach+0x283/0x580 drivers/base/dd.c:1214
       bus_for_each_dev+0x13c/0x1d0 drivers/base/bus.c:368
       bus_add_driver+0x2ed/0x640 drivers/base/bus.c:673
       driver_register+0x15c/0x4b0 drivers/base/driver.c:246
       drm_pci_register_driver_if_modeset include/drm/drm_module.h:69 [inline]
       bochs_pci_driver_init+0x67/0x80 drivers/gpu/drm/tiny/bochs.c:735
       do_one_initcall+0x128/0x630 init/main.c:1267
       do_initcall_level init/main.c:1329 [inline]
       do_initcalls init/main.c:1345 [inline]
       do_basic_setup init/main.c:1364 [inline]
       kernel_init_freeable+0x660/0xc50 init/main.c:1578
       kernel_init+0x1c/0x2b0 init/main.c:1467
       ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
       ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244

-> #0 ((console_sem).lock){-.-.}-{2:2}:
       check_prev_add kernel/locking/lockdep.c:3134 [inline]
       check_prevs_add kernel/locking/lockdep.c:3253 [inline]
       validate_chain kernel/locking/lockdep.c:3869 [inline]
       __lock_acquire+0x2478/0x3b30 kernel/locking/lockdep.c:5137
       lock_acquire kernel/locking/lockdep.c:5754 [inline]
       lock_acquire+0x1b1/0x560 kernel/locking/lockdep.c:5719
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0x3a/0x60 kernel/locking/spinlock.c:162
       down_trylock+0x12/0x70 kernel/locking/semaphore.c:139
       __down_trylock_console_sem+0x40/0x140 kernel/printk/printk.c:323
       console_trylock kernel/printk/printk.c:2684 [inline]
       console_trylock_spinning kernel/printk/printk.c:1958 [inline]
       vprintk_emit kernel/printk/printk.c:2347 [inline]
       vprintk_emit+0xe4/0x5a0 kernel/printk/printk.c:2303
       vprintk+0x7f/0xa0 kernel/printk/printk_safe.c:45
       _printk+0xc8/0x100 kernel/printk/printk.c:2373
       __report_bug lib/bug.c:195 [inline]
       report_bug+0x4ac/0x580 lib/bug.c:219
       handle_bug+0x3d/0x70 arch/x86/kernel/traps.c:239
       exc_invalid_op+0x17/0x50 arch/x86/kernel/traps.c:260
       asm_exc_invalid_op+0x1a/0x20 arch/x86/include/asm/idtentry.h:621
       expire_timers kernel/time/timer.c:1830 [inline]
       __run_timers+0x8ec/0xaf0 kernel/time/timer.c:2417
       __run_timer_base kernel/time/timer.c:2428 [inline]
       __run_timer_base kernel/time/timer.c:2421 [inline]
       run_timer_base+0x111/0x190 kernel/time/timer.c:2437
       run_timer_softirq+0x1a/0x40 kernel/time/timer.c:2447
       handle_softirqs+0x216/0x8f0 kernel/softirq.c:554
       __do_softirq kernel/softirq.c:588 [inline]
       invoke_softirq kernel/softirq.c:428 [inline]
       __irq_exit_rcu kernel/softirq.c:637 [inline]
       irq_exit_rcu+0xbb/0x120 kernel/softirq.c:649
       instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
       sysvec_apic_timer_interrupt+0x95/0xb0 arch/x86/kernel/apic/apic.c:1043
       asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
       native_safe_halt arch/x86/include/asm/irqflags.h:48 [inline]
       arch_safe_halt arch/x86/include/asm/irqflags.h:86 [inline]
       default_idle+0xf/0x20 arch/x86/kernel/process.c:742
       default_idle_call+0x6d/0xb0 kernel/sched/idle.c:117
       cpuidle_idle_call kernel/sched/idle.c:191 [inline]
       do_idle+0x32c/0x3f0 kernel/sched/idle.c:332
       cpu_startup_entry+0x4f/0x60 kernel/sched/idle.c:430
       rest_init+0x16b/0x2b0 init/main.c:747
       start_kernel+0x3df/0x4c0 init/main.c:1103
       x86_64_start_reservations+0x18/0x30 arch/x86/kernel/head64.c:507
       x86_64_start_kernel+0xb2/0xc0 arch/x86/kernel/head64.c:488
       common_startup_64+0x13e/0x148

other info that might help us debug this:

Chain exists of:
  (console_sem).lock --> &rq->__lock --> &base->lock

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&base->lock);
                               lock(&rq->__lock);
                               lock(&base->lock);
  lock((console_sem).lock);

 *** DEADLOCK ***

1 lock held by swapper/0/0:
 #0: ffff88802c02a858 (&base->lock){-.-.}-{2:2}, at: __run_timer_base kernel/time/timer.c:2427 [inline]
 #0: ffff88802c02a858 (&base->lock){-.-.}-{2:2}, at: __run_timer_base kernel/time/timer.c:2421 [inline]
 #0: ffff88802c02a858 (&base->lock){-.-.}-{2:2}, at: run_timer_base+0x109/0x190 kernel/time/timer.c:2437

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.9.0-syzkaller-10713-g2a8120d7b482 #0
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:114
 check_noncircular+0x31a/0x400 kernel/locking/lockdep.c:2187
 check_prev_add kernel/locking/lockdep.c:3134 [inline]
 check_prevs_add kernel/locking/lockdep.c:3253 [inline]
 validate_chain kernel/locking/lockdep.c:3869 [inline]
 __lock_acquire+0x2478/0x3b30 kernel/locking/lockdep.c:5137
 lock_acquire kernel/locking/lockdep.c:5754 [inline]
 lock_acquire+0x1b1/0x560 kernel/locking/lockdep.c:5719
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0x3a/0x60 kernel/locking/spinlock.c:162
 down_trylock+0x12/0x70 kernel/locking/semaphore.c:139
 __down_trylock_console_sem+0x40/0x140 kernel/printk/printk.c:323
 console_trylock kernel/printk/printk.c:2684 [inline]
 console_trylock_spinning kernel/printk/printk.c:1958 [inline]
 vprintk_emit kernel/printk/printk.c:2347 [inline]
 vprintk_emit+0xe4/0x5a0 kernel/printk/printk.c:2303
 vprintk+0x7f/0xa0 kernel/printk/printk_safe.c:45
 _printk+0xc8/0x100 kernel/printk/printk.c:2373
 __report_bug lib/bug.c:195 [inline]
 report_bug+0x4ac/0x580 lib/bug.c:219
 handle_bug+0x3d/0x70 arch/x86/kernel/traps.c:239
 exc_invalid_op+0x17/0x50 arch/x86/kernel/traps.c:260
 asm_exc_invalid_op+0x1a/0x20 arch/x86/include/asm/idtentry.h:621
RIP: 0010:expire_timers kernel/time/timer.c:1830 [inline]
RIP: 0010:__run_timers+0x8ec/0xaf0 kernel/time/timer.c:2417
Code: 6e 48 e8 77 34 13 00 89 de 31 ff 83 eb 01 e8 6b 2f 13 00 8b 44 24 18 85 c0 0f 85 18 fc ff ff e9 91 fb ff ff e8 55 34 13 00 90 <0f> 0b 90 e9 7b fc ff ff e8 47 34 13 00 90 0f 0b 90 e9 04 fd ff ff
RSP: 0018:ffffc90000007d58 EFLAGS: 00010046
RAX: 0000000000000000 RBX: ffffe8ffad07be10 RCX: ffffffff817b4d49
RDX: ffffffff8d8957c0 RSI: ffffffff817b4ddb RDI: ffffe8ffad07be28
RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000001 R12: ffffc90000007e10
R13: ffffc90000007e10 R14: ffff88802c02a840 R15: dffffc0000000000
 __run_timer_base kernel/time/timer.c:2428 [inline]
 __run_timer_base kernel/time/timer.c:2421 [inline]
 run_timer_base+0x111/0x190 kernel/time/timer.c:2437
 run_timer_softirq+0x1a/0x40 kernel/time/timer.c:2447
 handle_softirqs+0x216/0x8f0 kernel/softirq.c:554
 __do_softirq kernel/softirq.c:588 [inline]
 invoke_softirq kernel/softirq.c:428 [inline]
 __irq_exit_rcu kernel/softirq.c:637 [inline]
 irq_exit_rcu+0xbb/0x120 kernel/softirq.c:649
 instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
 sysvec_apic_timer_interrupt+0x95/0xb0 arch/x86/kernel/apic/apic.c:1043
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
RIP: 0010:native_irq_disable arch/x86/include/asm/irqflags.h:37 [inline]
RIP: 0010:arch_local_irq_disable arch/x86/include/asm/irqflags.h:72 [inline]
RIP: 0010:default_idle+0xf/0x20 arch/x86/kernel/process.c:743
Code: 4c 01 c7 4c 29 c2 e9 72 ff ff ff 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 66 90 0f 00 2d c3 36 48 00 fb f4 <fa> c3 cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 90 90 90 90 90
RSP: 0018:ffffffff8d807e20 EFLAGS: 00000246
RAX: 0000000000140011 RBX: 0000000000000000 RCX: ffffffff8ade3e29
RDX: 0000000000000000 RSI: ffffffff8b2cb6c0 RDI: ffffffff8b8fae60
RBP: fffffbfff1b12af8 R08: 0000000000000001 R09: ffffed1005806fe5
R10: ffff88802c037f2b R11: 0000000000000000 R12: 0000000000000000
R13: ffffffff8d8957c0 R14: ffffffff8fe29810 R15: 0000000000000000
 default_idle_call+0x6d/0xb0 kernel/sched/idle.c:117
 cpuidle_idle_call kernel/sched/idle.c:191 [inline]
 do_idle+0x32c/0x3f0 kernel/sched/idle.c:332
 cpu_startup_entry+0x4f/0x60 kernel/sched/idle.c:430
 rest_init+0x16b/0x2b0 init/main.c:747
 start_kernel+0x3df/0x4c0 init/main.c:1103
 x86_64_start_reservations+0x18/0x30 arch/x86/kernel/head64.c:507
 x86_64_start_kernel+0xb2/0xc0 arch/x86/kernel/head64.c:488
 common_startup_64+0x13e/0x148
 </TASK>
WARNING: CPU: 0 PID: 0 at kernel/time/timer.c:1830 expire_timers kernel/time/timer.c:1830 [inline]
WARNING: CPU: 0 PID: 0 at kernel/time/timer.c:1830 __run_timers+0x8ec/0xaf0 kernel/time/timer.c:2417
Modules linked in:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.9.0-syzkaller-10713-g2a8120d7b482 #0
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
RIP: 0010:expire_timers kernel/time/timer.c:1830 [inline]
RIP: 0010:__run_timers+0x8ec/0xaf0 kernel/time/timer.c:2417
Code: 6e 48 e8 77 34 13 00 89 de 31 ff 83 eb 01 e8 6b 2f 13 00 8b 44 24 18 85 c0 0f 85 18 fc ff ff e9 91 fb ff ff e8 55 34 13 00 90 <0f> 0b 90 e9 7b fc ff ff e8 47 34 13 00 90 0f 0b 90 e9 04 fd ff ff
RSP: 0018:ffffc90000007d58 EFLAGS: 00010046
RAX: 0000000000000000 RBX: ffffe8ffad07be10 RCX: ffffffff817b4d49
RDX: ffffffff8d8957c0 RSI: ffffffff817b4ddb RDI: ffffe8ffad07be28
RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000001 R12: ffffc90000007e10
R13: ffffc90000007e10 R14: ffff88802c02a840 R15: dffffc0000000000
FS:  0000000000000000(0000) GS:ffff88802c000000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000f7493f1c CR3: 0000000054c9e000 CR4: 0000000000350ef0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 __run_timer_base kernel/time/timer.c:2428 [inline]
 __run_timer_base kernel/time/timer.c:2421 [inline]
 run_timer_base+0x111/0x190 kernel/time/timer.c:2437
 run_timer_softirq+0x1a/0x40 kernel/time/timer.c:2447
 handle_softirqs+0x216/0x8f0 kernel/softirq.c:554
 __do_softirq kernel/softirq.c:588 [inline]
 invoke_softirq kernel/softirq.c:428 [inline]
 __irq_exit_rcu kernel/softirq.c:637 [inline]
 irq_exit_rcu+0xbb/0x120 kernel/softirq.c:649
 instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
 sysvec_apic_timer_interrupt+0x95/0xb0 arch/x86/kernel/apic/apic.c:1043
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
RIP: 0010:native_irq_disable arch/x86/include/asm/irqflags.h:37 [inline]
RIP: 0010:arch_local_irq_disable arch/x86/include/asm/irqflags.h:72 [inline]
RIP: 0010:default_idle+0xf/0x20 arch/x86/kernel/process.c:743
Code: 4c 01 c7 4c 29 c2 e9 72 ff ff ff 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 66 90 0f 00 2d c3 36 48 00 fb f4 <fa> c3 cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 90 90 90 90 90
RSP: 0018:ffffffff8d807e20 EFLAGS: 00000246
RAX: 0000000000140011 RBX: 0000000000000000 RCX: ffffffff8ade3e29
RDX: 0000000000000000 RSI: ffffffff8b2cb6c0 RDI: ffffffff8b8fae60
RBP: fffffbfff1b12af8 R08: 0000000000000001 R09: ffffed1005806fe5
R10: ffff88802c037f2b R11: 0000000000000000 R12: 0000000000000000
R13: ffffffff8d8957c0 R14: ffffffff8fe29810 R15: 0000000000000000
 default_idle_call+0x6d/0xb0 kernel/sched/idle.c:117
 cpuidle_idle_call kernel/sched/idle.c:191 [inline]
 do_idle+0x32c/0x3f0 kernel/sched/idle.c:332
 cpu_startup_entry+0x4f/0x60 kernel/sched/idle.c:430
 rest_init+0x16b/0x2b0 init/main.c:747
 start_kernel+0x3df/0x4c0 init/main.c:1103
 x86_64_start_reservations+0x18/0x30 arch/x86/kernel/head64.c:507
 x86_64_start_kernel+0xb2/0xc0 arch/x86/kernel/head64.c:488
 common_startup_64+0x13e/0x148
 </TASK>
----------------
Code disassembly (best guess):
   0:	4c 01 c7             	add    %r8,%rdi
   3:	4c 29 c2             	sub    %r8,%rdx
   6:	e9 72 ff ff ff       	jmp    0xffffff7d
   b:	90                   	nop
   c:	90                   	nop
   d:	90                   	nop
   e:	90                   	nop
   f:	90                   	nop
  10:	90                   	nop
  11:	90                   	nop
  12:	90                   	nop
  13:	90                   	nop
  14:	90                   	nop
  15:	90                   	nop
  16:	90                   	nop
  17:	90                   	nop
  18:	90                   	nop
  19:	90                   	nop
  1a:	90                   	nop
  1b:	f3 0f 1e fa          	endbr64
  1f:	66 90                	xchg   %ax,%ax
  21:	0f 00 2d c3 36 48 00 	verw   0x4836c3(%rip)        # 0x4836eb
  28:	fb                   	sti
  29:	f4                   	hlt
* 2a:	fa                   	cli <-- trapping instruction
  2b:	c3                   	ret
  2c:	cc                   	int3
  2d:	cc                   	int3
  2e:	cc                   	int3
  2f:	cc                   	int3
  30:	66 66 2e 0f 1f 84 00 	data16 cs nopw 0x0(%rax,%rax,1)
  37:	00 00 00 00
  3b:	90                   	nop
  3c:	90                   	nop
  3d:	90                   	nop
  3e:	90                   	nop
  3f:	90                   	nop

Crashes (1):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2024/05/21 20:42 upstream 2a8120d7b482 c2e07261 .config console log report info [disk image (non-bootable)] [vmlinux] [kernel image] ci-qemu-upstream-386 possible deadlock in run_timer_base
* Struck through repros no longer work on HEAD.