Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751662AbdIKLPe (ORCPT ); Mon, 11 Sep 2017 07:15:34 -0400 Received: from mail-io0-f179.google.com ([209.85.223.179]:36214 "EHLO mail-io0-f179.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751065AbdIKLPb (ORCPT ); Mon, 11 Sep 2017 07:15:31 -0400 X-Google-Smtp-Source: AOwi7QAWiwUv8lqzxk4Gr3jyNTk9GszZ16snIMmm8T+8N5+7Ty/uo7Z309gTW+JBTy1Y/ksCLEYqF2JWGH5OjgbxVro= MIME-Version: 1.0 From: Andrey Konovalov Date: Mon, 11 Sep 2017 13:15:29 +0200 Message-ID: Subject: usb/gadget: stalls in dummy_timer To: Felipe Balbi , Greg Kroah-Hartman , Alan Stern , Johan Hovold , Peter Chen , Yuyang Du , USB list , LKML Cc: Dmitry Vyukov , Kostya Serebryany , syzkaller Content-Type: text/plain; charset="UTF-8" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 9204 Lines: 169 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 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: 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: __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 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?