I was advised to use a vanilla kernel with CONFIG_PROVE_LOCKING and decode the symbols in the report. So I followed https://kernelnewbies.org/OutreachyfirstpatchSetup and here's the result. Thanks, Tetsuo Handa. WARNING: possible circular locking dependency detected 5.19.0-rc6iforce-00194-gf3a76018dd55 #2 Not tainted ------------------------------------------------------ kworker/1:4/392 is trying to acquire lock: ffff8e358419e030 (&iforce->xmit_lock){-...}-{2:2}, at: iforce_serio_xmit (drivers/input/joystick/iforce/iforce-serio.c:38) iforce_serio but task is already holding lock: ffff8e3586c6dec8 (&serport->lock){-...}-{2:2}, at: serport_ldisc_write_wakeup (drivers/input/serio/serport.c:263) serport which lock already depends on the new lock. the existing dependency chain (in reverse order) is: -> #2 (&serport->lock){-...}-{2:2}: _raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:111 kernel/locking/spinlock.c:162) serport_ldisc_write_wakeup (drivers/input/serio/serport.c:263) serport tty_wakeup (drivers/tty/tty_io.c:531) tty_port_default_wakeup (drivers/tty/tty_port.c:52) tty_port_tty_wakeup (drivers/tty/tty_port.c:415) uart_write_wakeup (drivers/tty/serial/serial_core.c:113 (discriminator 2)) serial8250_tx_chars (drivers/tty/serial/8250/8250_port.c:1864) serial8250_handle_irq.part.0 (./include/linux/serial_core.h:531 drivers/tty/serial/8250/8250_port.c:1956) serial8250_default_handle_irq (drivers/tty/serial/8250/8250_port.c:1924 drivers/tty/serial/8250/8250_port.c:1971) serial8250_interrupt (drivers/tty/serial/8250/8250_core.c:125) __handle_irq_event_percpu (kernel/irq/handle.c:158) handle_irq_event_percpu (kernel/irq/handle.c:195) handle_irq_event (kernel/irq/handle.c:212) handle_edge_irq (kernel/irq/chip.c:820) __common_interrupt (./include/asm-generic/irq_regs.h:28 (discriminator 22) arch/x86/kernel/irq.c:263 (discriminator 22)) common_interrupt (arch/x86/kernel/irq.c:240 (discriminator 14)) asm_common_interrupt (./arch/x86/include/asm/idtentry.h:640) __cond_resched (kernel/sched/core.c:8228) iforce_init_device (drivers/input/joystick/iforce/iforce.h:118 drivers/input/joystick/iforce/iforce-main.c:261) iforce iforce_serio_connect (drivers/input/joystick/iforce/iforce-serio.c:207) iforce_serio serio_connect_driver (drivers/input/serio/serio.c:48) serio_driver_probe (drivers/input/serio/serio.c:779) really_probe (drivers/base/dd.c:555 drivers/base/dd.c:634 drivers/base/dd.c:579) __driver_probe_device (drivers/base/dd.c:764) driver_probe_device (drivers/base/dd.c:794) __driver_attach (drivers/base/dd.c:1164) bus_for_each_dev (drivers/base/bus.c:301) driver_attach (drivers/base/dd.c:1181) serio_handle_event (drivers/input/serio/serio.c:808 drivers/input/serio/serio.c:227) process_one_work (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/workqueue.h:108 kernel/workqueue.c:2294) worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2437) kthread (kernel/kthread.c:376) ret_from_fork (arch/x86/entry/entry_64.S:308) -> #1 (&port_lock_key){-...}-{2:2}: _raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:111 kernel/locking/spinlock.c:162) uart_write (drivers/tty/serial/serial_core.c:577 (discriminator 1)) serport_serio_write (drivers/input/serio/serport.c:48) serport iforce_serio_xmit (drivers/input/joystick/iforce/iforce-serio.c:51) iforce_serio iforce_send_packet (drivers/input/joystick/iforce/iforce-packets.c:84) iforce iforce_serio_get_id (./include/linux/kernel.h:110 drivers/input/joystick/iforce/iforce-serio.c:84) iforce_serio iforce_init_device (drivers/input/joystick/iforce/iforce.h:118 drivers/input/joystick/iforce/iforce-main.c:261) iforce iforce_serio_connect (drivers/input/joystick/iforce/iforce-serio.c:207) iforce_serio serio_connect_driver (drivers/input/serio/serio.c:48) serio_driver_probe (drivers/input/serio/serio.c:779) really_probe (drivers/base/dd.c:555 drivers/base/dd.c:634 drivers/base/dd.c:579) __driver_probe_device (drivers/base/dd.c:764) driver_probe_device (drivers/base/dd.c:794) __driver_attach (drivers/base/dd.c:1164) bus_for_each_dev (drivers/base/bus.c:301) driver_attach (drivers/base/dd.c:1181) serio_handle_event (drivers/input/serio/serio.c:808 drivers/input/serio/serio.c:227) process_one_work (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/workqueue.h:108 kernel/workqueue.c:2294) worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2437) kthread (kernel/kthread.c:376) ret_from_fork (arch/x86/entry/entry_64.S:308) -> #0 (&iforce->xmit_lock){-...}-{2:2}: __lock_acquire (kernel/locking/lockdep.c:3096 kernel/locking/lockdep.c:3214 kernel/locking/lockdep.c:3829 kernel/locking/lockdep.c:5053) lock_acquire (kernel/locking/lockdep.c:466 kernel/locking/lockdep.c:5667 kernel/locking/lockdep.c:5630) _raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:111 kernel/locking/spinlock.c:162) iforce_serio_xmit (drivers/input/joystick/iforce/iforce-serio.c:38) iforce_serio iforce_serio_write_wakeup (drivers/input/joystick/iforce/iforce-serio.c:125) iforce_serio serport_ldisc_write_wakeup (./include/linux/serio.h:133 drivers/input/serio/serport.c:265) serport tty_wakeup (drivers/tty/tty_io.c:531) tty_port_default_wakeup (drivers/tty/tty_port.c:52) tty_port_tty_wakeup (drivers/tty/tty_port.c:415) uart_write_wakeup (drivers/tty/serial/serial_core.c:113 (discriminator 2)) serial8250_tx_chars (drivers/tty/serial/8250/8250_port.c:1864) serial8250_handle_irq.part.0 (./include/linux/serial_core.h:531 drivers/tty/serial/8250/8250_port.c:1956) serial8250_default_handle_irq (drivers/tty/serial/8250/8250_port.c:1924 drivers/tty/serial/8250/8250_port.c:1971) serial8250_interrupt (drivers/tty/serial/8250/8250_core.c:125) __handle_irq_event_percpu (kernel/irq/handle.c:158) handle_irq_event_percpu (kernel/irq/handle.c:195) handle_irq_event (kernel/irq/handle.c:212) handle_edge_irq (kernel/irq/chip.c:820) __common_interrupt (./include/asm-generic/irq_regs.h:28 (discriminator 22) arch/x86/kernel/irq.c:263 (discriminator 22)) common_interrupt (arch/x86/kernel/irq.c:240 (discriminator 14)) asm_common_interrupt (./arch/x86/include/asm/idtentry.h:640) __cond_resched (kernel/sched/core.c:8228) iforce_init_device (drivers/input/joystick/iforce/iforce.h:118 drivers/input/joystick/iforce/iforce-main.c:261) iforce iforce_serio_connect (drivers/input/joystick/iforce/iforce-serio.c:207) iforce_serio serio_connect_driver (drivers/input/serio/serio.c:48) serio_driver_probe (drivers/input/serio/serio.c:779) really_probe (drivers/base/dd.c:555 drivers/base/dd.c:634 drivers/base/dd.c:579) __driver_probe_device (drivers/base/dd.c:764) driver_probe_device (drivers/base/dd.c:794) __driver_attach (drivers/base/dd.c:1164) bus_for_each_dev (drivers/base/bus.c:301) driver_attach (drivers/base/dd.c:1181) serio_handle_event (drivers/input/serio/serio.c:808 drivers/input/serio/serio.c:227) process_one_work (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/workqueue.h:108 kernel/workqueue.c:2294) worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2437) kthread (kernel/kthread.c:376) ret_from_fork (arch/x86/entry/entry_64.S:308) other info that might help us debug this: Chain exists of: &iforce->xmit_lock --> &port_lock_key --> &serport->lock Possible unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&serport->lock); lock(&port_lock_key); lock(&serport->lock); lock(&iforce->xmit_lock); *** DEADLOCK *** 9 locks held by kworker/1:4/392: #0: ffff8e358104f548 ((wq_completion)events_long){+.+.}-{0:0}, at: process_one_work (./arch/x86/include/asm/atomic64_64.h:34 ./include/linux/atomic/atomic-long.h:41 ./include/linux/atomic/atomic-instrumented.h:1280 kernel/workqueue.c:636 kernel/workqueue.c:663 kernel/workqueue.c:2260) #1: ffffb437c0efbe48 (serio_event_work){+.+.}-{0:0}, at: process_one_work (./arch/x86/include/asm/atomic64_64.h:34 ./include/linux/atomic/atomic-long.h:41 ./include/linux/atomic/atomic-instrumented.h:1280 kernel/workqueue.c:636 kernel/workqueue.c:663 kernel/workqueue.c:2260) #2: ffffffffae31dd90 (serio_mutex){+.+.}-{3:3}, at: serio_handle_event (drivers/input/serio/serio.c:155 drivers/input/serio/serio.c:205) #3: ffff8e3599326308 (&dev->mutex){....}-{3:3}, at: __device_driver_lock (drivers/base/dd.c:1055) #4: ffff8e35993261e8 (&serio->drv_mutex){+.+.}-{3:3}, at: serio_connect_driver (drivers/input/serio/serio.c:47) #5: ffff8e359e3d5f30 (&i->lock){-...}-{2:2}, at: serial8250_interrupt (drivers/tty/serial/8250/8250_core.c:117) #6: ffffffffaf3c1fb8 (&port_lock_key){-...}-{2:2}, at: serial8250_handle_irq.part.0 (./include/linux/serial_core.h:265 drivers/tty/serial/8250/8250_port.c:1929) #7: ffff8e35833b48a0 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref (drivers/tty/tty_ldisc.c:264) #8: ffff8e3586c6dec8 (&serport->lock){-...}-{2:2}, at: serport_ldisc_write_wakeup (drivers/input/serio/serport.c:263) serport stack backtrace: CPU: 1 PID: 392 Comm: kworker/1:4 Not tainted 5.19.0-rc6iforce-00194-gf3a76018dd55 #2 Hardware name: System manufacturer System Product Name/V-P5G41E, BIOS 0204 12/21/2009 Workqueue: events_long serio_handle_event Call Trace: <IRQ> dump_stack_lvl (lib/dump_stack.c:107) dump_stack (lib/dump_stack.c:114) print_circular_bug.isra.0.cold (kernel/locking/lockdep.c:2053) check_noncircular (kernel/locking/lockdep.c:2178) __lock_acquire (kernel/locking/lockdep.c:3096 kernel/locking/lockdep.c:3214 kernel/locking/lockdep.c:3829 kernel/locking/lockdep.c:5053) lock_acquire (kernel/locking/lockdep.c:466 kernel/locking/lockdep.c:5667 kernel/locking/lockdep.c:5630) ? iforce_serio_xmit (drivers/input/joystick/iforce/iforce-serio.c:38) iforce_serio ? find_held_lock (kernel/locking/lockdep.c:5156) _raw_spin_lock_irqsave (./include/linux/spinlock_api_smp.h:111 kernel/locking/spinlock.c:162) ? iforce_serio_xmit (drivers/input/joystick/iforce/iforce-serio.c:38) iforce_serio iforce_serio_xmit (drivers/input/joystick/iforce/iforce-serio.c:38) iforce_serio iforce_serio_write_wakeup (drivers/input/joystick/iforce/iforce-serio.c:125) iforce_serio serport_ldisc_write_wakeup (./include/linux/serio.h:133 drivers/input/serio/serport.c:265) serport tty_wakeup (drivers/tty/tty_io.c:531) tty_port_default_wakeup (drivers/tty/tty_port.c:52) tty_port_tty_wakeup (drivers/tty/tty_port.c:415) uart_write_wakeup (drivers/tty/serial/serial_core.c:113 (discriminator 2)) serial8250_tx_chars (drivers/tty/serial/8250/8250_port.c:1864) serial8250_handle_irq.part.0 (./include/linux/serial_core.h:531 drivers/tty/serial/8250/8250_port.c:1956) serial8250_default_handle_irq (drivers/tty/serial/8250/8250_port.c:1924 drivers/tty/serial/8250/8250_port.c:1971) serial8250_interrupt (drivers/tty/serial/8250/8250_core.c:125) __handle_irq_event_percpu (kernel/irq/handle.c:158) handle_irq_event_percpu (kernel/irq/handle.c:195) handle_irq_event (kernel/irq/handle.c:212) handle_edge_irq (kernel/irq/chip.c:820) __common_interrupt (./include/asm-generic/irq_regs.h:28 (discriminator 22) arch/x86/kernel/irq.c:263 (discriminator 22)) common_interrupt (arch/x86/kernel/irq.c:240 (discriminator 14)) </IRQ> <TASK> asm_common_interrupt (./arch/x86/include/asm/idtentry.h:640) RIP: 0010:__cond_resched (kernel/sched/core.c:8228) Code: 52 a9 ff ff ff 7f 74 01 c3 9c 58 f6 c4 02 74 f8 55 48 89 e5 e8 51 ff ff ff 5d c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 <0f> 1f 44 00 00 65 8b 15 14 60 ab 52 85 d2 74 03 31 c0 c3 55 48 89 All code ======== 0: 52 push %rdx 1: a9 ff ff ff 7f test $0x7fffffff,%eax 6: 74 01 je 0x9 8: c3 retq 9: 9c pushfq a: 58 pop %rax b: f6 c4 02 test $0x2,%ah e: 74 f8 je 0x8 10: 55 push %rbp 11: 48 89 e5 mov %rsp,%rbp 14: e8 51 ff ff ff callq 0xffffffffffffff6a 19: 5d pop %rbp 1a: c3 retq 1b: 66 66 2e 0f 1f 84 00 data16 nopw %cs:0x0(%rax,%rax,1) 22: 00 00 00 00 26: 0f 1f 40 00 nopl 0x0(%rax) 2a:* 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1) <-- trapping instruction 2f: 65 8b 15 14 60 ab 52 mov %gs:0x52ab6014(%rip),%edx # 0x52ab604a 36: 85 d2 test %edx,%edx 38: 74 03 je 0x3d 3a: 31 c0 xor %eax,%eax 3c: c3 retq 3d: 55 push %rbp 3e: 48 rex.W 3f: 89 .byte 0x89 Code starting with the faulting instruction =========================================== 0: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1) 5: 65 8b 15 14 60 ab 52 mov %gs:0x52ab6014(%rip),%edx # 0x52ab6020 c: 85 d2 test %edx,%edx e: 74 03 je 0x13 10: 31 c0 xor %eax,%eax 12: c3 retq 13: 55 push %rbp 14: 48 rex.W 15: 89 .byte 0x89 RSP: 0018:ffffb437c0efbbb8 EFLAGS: 00000286 RAX: 0000000000000000 RBX: ffff8e358419e000 RCX: 0000000000000000 RDX: 0000000000000001 RSI: ffffffffaddc1e7a RDI: 00000000ffffffff RBP: ffffb437c0efbc20 R08: 0000000000000001 R09: 0000000000000001 R10: 0000000000000001 R11: 0000000000000253 R12: 0000000000000014 R13: ffffb437c0efbc48 R14: ffff8e35841c6000 R15: ffffb437c0efbc38 ? iforce_serio_get_id (drivers/input/joystick/iforce/iforce-serio.c:84) iforce_serio ? debug_mutex_init (kernel/locking/mutex-debug.c:89) iforce_init_device (drivers/input/joystick/iforce/iforce.h:118 drivers/input/joystick/iforce/iforce-main.c:261) iforce ? serport_serio_open (drivers/input/serio/serport.c:60) serport iforce_serio_connect (drivers/input/joystick/iforce/iforce-serio.c:207) iforce_serio serio_connect_driver (drivers/input/serio/serio.c:48) serio_driver_probe (drivers/input/serio/serio.c:779) really_probe (drivers/base/dd.c:555 drivers/base/dd.c:634 drivers/base/dd.c:579) __driver_probe_device (drivers/base/dd.c:764) driver_probe_device (drivers/base/dd.c:794) __driver_attach (drivers/base/dd.c:1164) ? __device_attach_driver (drivers/base/dd.c:1116) bus_for_each_dev (drivers/base/bus.c:301) driver_attach (drivers/base/dd.c:1181) serio_handle_event (drivers/input/serio/serio.c:808 drivers/input/serio/serio.c:227) process_one_work (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./include/trace/events/workqueue.h:108 kernel/workqueue.c:2294) worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2437) ? process_one_work (kernel/workqueue.c:2379) kthread (kernel/kthread.c:376) ? kthread_complete_and_exit (kernel/kthread.c:331) ret_from_fork (arch/x86/entry/entry_64.S:308) </TASK> 2022-07-11 11:32 GMT+02:00, Greg T <greg.iforce@xxxxxxxxx>: > That problem vanishes if we don't call iforce_process_packet directly > from iforce_serio_irq, but from a tasklet. Is that a right approach?
