Re: usb/gadget: stalls in dummy_timer

[Alan Stern]

On Mon, 11 Sep 2017, Andrey Konovalov wrote:

> Hi!
> 
> I've been getting stall reports like this one while fuzzing the USB
> stack with gadgetfs. I'm wondering whether this is a bug in gadgetfs
> or is this report induced by the changes I've made to the USB core
> code. I didn't touch gadgetfs code though (except for adding a few
> printk's).
> 
> I'm on commit 81a84ad3cb5711cec79f4dd53a4ce026b092c432

It's possible that this was caused by commit f16443a034c7 ("USB: 
gadgetfs, dummy-hcd, net2280: fix locking for callbacks").  I've been 
meaning to repair the commit but haven't done it yet.

Can you test with that commit reverted?  You may end up seeing other 
problems instead -- the ones that commit was intended to solve -- but 
perhaps the stalls won't occur.

Alan Stern

> usbtouchscreen 2-1:8.0: usbtouch_irq - usb_submit_urb failed with result: -12
> INFO: rcu_sched self-detected stall on CPU
> INFO: rcu_sched detected stalls on CPUs/tasks:
> 2-...: (1 GPs behind) idle=ba2/140000000000002/0 softirq=100255/100259 fqs=2
> (detected by 1, t=48363 jiffies, g=20668, c=20667, q=2875)
> Sending NMI from CPU 1 to CPUs 2:
> NMI backtrace for cpu 2
> CPU: 2 PID: 9620 Comm: udevd Not tainted 4.13.0+ #87
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> task: ffff88003a414e00 task.stack: ffff88003aaa8000
> RIP: 0010:inb arch/x86/include/asm/io.h:340 [inline]
> RIP: 0010:io_serial_in+0x70/0x90 drivers/tty/serial/8250/8250_port.c:430
> RSP: 0018:ffff88006dc05638 EFLAGS: 00000002
> RAX: dffffc0000000060 RBX: 00000000000003fd RCX: 0000000000000000
> RDX: 00000000000003fd RSI: 0000000000000005 RDI: ffffffff88791fe8
> RBP: ffff88006dc05648 R08: fffffbfff0fe0100 R09: fffffbfff0fe0100
> R10: 0000000000000007 R11: fffffbfff0fe00ff R12: ffffffff88791fe0
> R13: 0000000000000020 R14: fffffbfff10f2438 R15: fffffbfff10f23ff
> FS:  00007f88402d27a0(0000) GS:ffff88006dc00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007f88402d9000 CR3: 000000003d4ec000 CR4: 00000000000006e0
> Call Trace:
>  <IRQ>
>  serial_in drivers/tty/serial/8250/8250.h:115 [inline]
>  wait_for_xmitr+0x8e/0x1d0 drivers/tty/serial/8250/8250_port.c:2015
>  serial8250_console_putchar+0x24/0x60 drivers/tty/serial/8250/8250_port.c:3149
>  uart_console_write+0x5c/0xf0 drivers/tty/serial/serial_core.c:1856
>  serial8250_console_write+0x319/0x670 drivers/tty/serial/8250/8250_port.c:3215
>  univ8250_console_write+0x6b/0x80 drivers/tty/serial/8250/8250_core.c:594
>  call_console_drivers kernel/printk/printk.c:1586 [inline]
>  console_unlock+0x8a1/0xcd0 kernel/printk/printk.c:2245
>  vprintk_emit+0x567/0x5d0 kernel/printk/printk.c:1769
>  vprintk_default+0x2d/0x40 kernel/printk/printk.c:1808
>  vprintk_func+0x5c/0xd0 kernel/printk/printk_safe.c:382
>  printk+0xcd/0xfe kernel/printk/printk.c:1841
>  print_cpu_stall_info_begin kernel/rcu/tree_plugin.h:1643 [inline]
>  print_cpu_stall+0x1a4/0x6d0 kernel/rcu/tree.c:1524
>  check_cpu_stall.isra.72+0x707/0xe90 kernel/rcu/tree.c:1604
>  __rcu_pending kernel/rcu/tree.c:3457 [inline]
>  rcu_pending kernel/rcu/tree.c:3519 [inline]
>  rcu_check_callbacks+0x241/0xa50 kernel/rcu/tree.c:2861
>  update_process_times+0x35/0x70 kernel/time/timer.c:1590
>  tick_sched_handle+0xf5/0x160 kernel/time/tick-sched.c:161
>  tick_sched_timer+0x47/0x120 kernel/time/tick-sched.c:1190
>  __run_hrtimer kernel/time/hrtimer.c:1213 [inline]
>  __hrtimer_run_queues+0x3f4/0x970 kernel/time/hrtimer.c:1277
>  hrtimer_interrupt+0x22a/0x720 kernel/time/hrtimer.c:1311
>  local_apic_timer_interrupt+0x74/0xe0 arch/x86/kernel/apic/apic.c:1019
>  smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:1043
>  apic_timer_interrupt+0x89/0x90 arch/x86/entry/entry_64.S:482
> RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:814 [inline]
> RIP: 0010:__raw_spin_unlock_irqrestore
> include/linux/spinlock_api_smp.h:160 [inline]
> RIP: 0010:_raw_spin_unlock_irqrestore+0xf5/0x160 kernel/locking/spinlock.c:191
> RSP: 0018:ffff88006dc06c40 EFLAGS: 00000a06 ORIG_RAX: ffffffffffffff10
> RAX: 1ffff1000db80d95 RBX: 1ffff1000db80d89 RCX: dffffc0000000000
> RDX: dffffc0000000000 RSI: 0000000000000a06 RDI: 0000000000000a06
> RBP: ffff88006dc06d48 R08: fffffbfff0fe0104 R09: fffffbfff0fe0104
> R10: ffff88006dc06420 R11: fffffbfff0fe0103 R12: 1ffff1000db80d9d
> R13: 1ffff1000db80d8d R14: ffff88006ac48000 R15: ffff88006c172b08
>  spin_unlock_irqrestore include/linux/spinlock.h:354 [inline]
>  dummy_timer+0x1aa8/0x38c0 drivers/usb/gadget/udc/dummy_hcd.c:1938
>  call_timer_fn+0xba/0x390 kernel/time/timer.c:1281
>  expire_timers kernel/time/timer.c:1320 [inline]
>  __run_timers+0x9d0/0xda0 kernel/time/timer.c:1620
>  run_timer_softirq+0x51/0xb0 kernel/time/timer.c:1646
>  __do_softirq+0x258/0x7ac kernel/softirq.c:284
>  invoke_softirq kernel/softirq.c:364 [inline]
>  irq_exit+0x14e/0x180 kernel/softirq.c:405
>  exiting_irq arch/x86/include/asm/apic.h:638 [inline]
>  smp_apic_timer_interrupt+0x7b/0xa0 arch/x86/kernel/apic/apic.c:1044
> Lost 134 message(s)!
> rcu_sched kthread starved for 48353 jiffies! g20668 c20667 f0x0
> RCU_GP_WAIT_FQS(3) ->state=0x1
> rcu_sched       S18936     9      2 0x00000000
> Call Trace:
>  context_switch kernel/sched/core.c:2771 [inline]
>  __schedule+0x6fa/0x1780 kernel/sched/core.c:3332
>  schedule+0x106/0x450 kernel/sched/core.c:3391
>  schedule_timeout+0x1d8/0x440 kernel/time/timer.c:1743
>  rcu_gp_kthread+0x1edd/0x47e0 kernel/rcu/tree.c:2242
>  kthread+0x324/0x3f0 kernel/kthread.c:231
>  ret_from_fork+0x25/0x30 arch/x86/entry/entry_64.S:425
> 2-...: (1 GPs behind) idle=ba2/140000000000002/0 softirq=100255/100259 fqs=3
> (t=48363 jiffies g=20668 c=20667 q=2875)
> NMI backtrace for cpu 2
> CPU: 2 PID: 9620 Comm: udevd Not tainted 4.13.0+ #87
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> Call Trace:
>  <IRQ>
>  __dump_stack lib/dump_stack.c:16 [inline]
>  dump_stack+0x192/0x22c lib/dump_stack.c:52
>  nmi_cpu_backtrace+0x1f5/0x220 lib/nmi_backtrace.c:102
>  nmi_trigger_cpumask_backtrace+0x108/0x160 lib/nmi_backtrace.c:61
>  arch_trigger_cpumask_backtrace+0x19/0x20 arch/x86/kernel/apic/hw_nmi.c:37
>  trigger_single_cpu_backtrace include/linux/nmi.h:123 [inline]
>  rcu_dump_cpu_stacks+0x272/0x306 kernel/rcu/tree.c:1390
>  print_cpu_stall+0x3b5/0x6d0 kernel/rcu/tree.c:1536
>  check_cpu_stall.isra.72+0x707/0xe90 kernel/rcu/tree.c:1604
>  __rcu_pending kernel/rcu/tree.c:3457 [inline]
>  rcu_pending kernel/rcu/tree.c:3519 [inline]
>  rcu_check_callbacks+0x241/0xa50 kernel/rcu/tree.c:2861
>  update_process_times+0x35/0x70 kernel/time/timer.c:1590
>  tick_sched_handle+0xf5/0x160 kernel/time/tick-sched.c:161
>  tick_sched_timer+0x47/0x120 kernel/time/tick-sched.c:1190
>  __run_hrtimer kernel/time/hrtimer.c:1213 [inline]
>  __hrtimer_run_queues+0x3f4/0x970 kernel/time/hrtimer.c:1277
>  hrtimer_interrupt+0x22a/0x720 kernel/time/hrtimer.c:1311
>  local_apic_timer_interrupt+0x74/0xe0 arch/x86/kernel/apic/apic.c:1019
>  smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:1043
>  apic_timer_interrupt+0x89/0x90 arch/x86/entry/entry_64.S:482
> RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:814 [inline]
> RIP: 0010:__raw_spin_unlock_irqrestore
> include/linux/spinlock_api_smp.h:160 [inline]
> RIP: 0010:_raw_spin_unlock_irqrestore+0xf5/0x160 kernel/locking/spinlock.c:191
> RSP: 0018:ffff88006dc06c40 EFLAGS: 00000a06 ORIG_RAX: ffffffffffffff10
> RAX: 1ffff1000db80d95 RBX: 1ffff1000db80d89 RCX: dffffc0000000000
> RDX: dffffc0000000000 RSI: 0000000000000a06 RDI: 0000000000000a06
> RBP: ffff88006dc06d48 R08: fffffbfff0fe0104 R09: fffffbfff0fe0104
> R10: ffff88006dc06420 R11: fffffbfff0fe0103 R12: 1ffff1000db80d9d
> R13: 1ffff1000db80d8d R14: ffff88006ac48000 R15: ffff88006c172b08
>  spin_unlock_irqrestore include/linux/spinlock.h:354 [inline]
>  dummy_timer+0x1aa8/0x38c0 drivers/usb/gadget/udc/dummy_hcd.c:1938
>  call_timer_fn+0xba/0x390 kernel/time/timer.c:1281
>  expire_timers kernel/time/timer.c:1320 [inline]
>  __run_timers+0x9d0/0xda0 kernel/time/timer.c:1620
>  run_timer_softirq+0x51/0xb0 kernel/time/timer.c:1646
>  __do_softirq+0x258/0x7ac kernel/softirq.c:284
>  invoke_softirq kernel/softirq.c:364 [inline]
>  irq_exit+0x14e/0x180 kernel/softirq.c:405
>  exiting_irq arch/x86/include/asm/apic.h:638 [inline]
>  smp_apic_timer_interrupt+0x7b/0xa0 arch/x86/kernel/apic/apic.c:1044
>  apic_timer_interrupt+0x89/0x90 arch/x86/entry/entry_64.S:482
> RIP: 0010:_copy_from_iter_full+0x399/0x1240 lib/iov_iter.c:597
> RSP: 0018:ffff88003aaaf570 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
> RAX: 0000000000000000 RBX: 0000000000000001 RCX: ffffed0007555ec1
> RDX: 0000000000000000 RSI: 1ffff10007555e7f RDI: ffffed0007555ec9
> RBP: ffff88003aaafa10 R08: ffffed00076640cb R09: ffffed00076640cb
> R10: 0000000000000000 R11: ffffed00076640ca R12: ffffed0007555f2d
> R13: dffffc0000000000 R14: 0000000000000000 R15: ffff88003aaaf9e8
>  </IRQ>
>  copy_from_iter_full include/linux/uio.h:126 [inline]
>  memcpy_from_msg include/linux/skbuff.h:3176 [inline]
>  netlink_sendmsg+0x9c7/0xe40 net/netlink/af_netlink.c:1839
>  sock_sendmsg_nosec net/socket.c:633 [inline]
>  sock_sendmsg+0xcf/0x110 net/socket.c:643
>  ___sys_sendmsg+0x97e/0xb30 net/socket.c:2035
>  __sys_sendmsg+0x13d/0x320 net/socket.c:2069
>  SYSC_sendmsg net/socket.c:2080 [inline]
>  SyS_sendmsg+0x32/0x50 net/socket.c:2076
>  entry_SYSCALL_64_fastpath+0x1a/0xa5
> RIP: 0033:0x7f883f9e7320
> RSP: 002b:00007ffcad3d23a8 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
> RAX: ffffffffffffffda RBX: 00000000024b5850 RCX: 00007f883f9e7320
> RDX: 0000000000000000 RSI: 00007ffcad3d23f0 RDI: 000000000000000b
> RBP: 0000000000000000 R08: 00000000ffffffff R09: 0000000000000000
> R10: 73752f302e646368 R11: 0000000000000246 R12: 00000000ffffffff
> R13: 00000000024b4030 R14: 00007ffcad3d1f50 R15: 0000000000000001
> dummy_hcd dummy_hcd.0: timer fired with no URBs pending?
>