INFO: rcu detected stall in __perf_sw_event

11 views
Skip to first unread message

syzbot

unread,
Apr 12, 2019, 8:00:42 PM4/12/19
to syzkaller-a...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 286f9710 Merge 4.9.168 into android-4.9
git tree: android-4.9
console output: https://syzkaller.appspot.com/x/log.txt?x=168c405b200000
kernel config: https://syzkaller.appspot.com/x/.config?x=416e7ad1468db859
dashboard link: https://syzkaller.appspot.com/bug?extid=bdf025f4455efabda0f0
compiler: gcc (GCC) 9.0.0 20181231 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=12d2c5ed200000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=12abbd4b200000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+bdf025...@syzkaller.appspotmail.com

INFO: rcu_preempt self-detected stall on CPU
0-...: (10498 ticks this GP) idle=a87/140000000000001/0 softirq=3743/3743
fqs=5238
(t=10500 jiffies g=854 c=853 q=11)
Task dump for CPU 0:
syz-executor259 R running task 28408 2445 2161 0x0000000c
ffff8801db607c40 ffffffff813fc9e1 ffffffff813fc7e0 0000000000000001
0000000000000000 ffff8801db621000 dffffc0000000000 ffffffff830d59c8
ffffffff830d5a00 ffff8801db607c60 ffffffff813fceac ffffffff830d5980
Call Trace:
<IRQ> [ 695.475180] [<000000005bf8f675>]
sched_show_task.cold+0x27f/0x327 kernel/sched/core.c:5312
[<00000000dfca9c66>] dump_cpu_task+0x7a/0x7f kernel/sched/core.c:9050
[<00000000f3e05166>] rcu_dump_cpu_stacks+0x193/0x1c3 kernel/rcu/tree.c:1303
[<00000000f8efe9ad>] print_cpu_stall kernel/rcu/tree.c:1446 [inline]
[<00000000f8efe9ad>] check_cpu_stall kernel/rcu/tree.c:1514 [inline]
[<00000000f8efe9ad>] __rcu_pending kernel/rcu/tree.c:3495 [inline]
[<00000000f8efe9ad>] rcu_pending kernel/rcu/tree.c:3559 [inline]
[<00000000f8efe9ad>] rcu_check_callbacks.cold+0x44a/0xd2f
kernel/rcu/tree.c:2888
[<000000004a523ef5>] update_process_times+0x31/0x70
kernel/time/timer.c:1629
[<0000000050bf0eb2>] tick_sched_handle.isra.0+0x4a/0xf0
kernel/time/tick-sched.c:151
[<00000000ea8ad634>] tick_sched_timer+0x7a/0x130
kernel/time/tick-sched.c:1190
[<00000000a9ef483d>] __run_hrtimer kernel/time/hrtimer.c:1255 [inline]
[<00000000a9ef483d>] __hrtimer_run_queues+0x313/0xe00
kernel/time/hrtimer.c:1319
[<0000000030b4301a>] hrtimer_interrupt+0x1b6/0x450
kernel/time/hrtimer.c:1353
[<0000000096e6ed1a>] local_apic_timer_interrupt+0x76/0xa0
arch/x86/kernel/apic/apic.c:937
[<000000000ef29d4a>] smp_apic_timer_interrupt+0x79/0xb0
arch/x86/kernel/apic/apic.c:961
[<00000000f9b433b7>] apic_timer_interrupt+0x9d/0xb0
arch/x86/entry/entry_64.S:648
<EOI> [ 695.592461] [<000000000e9aa601>] ? memcpy_common
kernel/events/internal.h:171 [inline]
<EOI> [ 695.592461] [<000000000e9aa601>] ? __output_copy
kernel/events/internal.h:175 [inline]
<EOI> [ 695.592461] [<000000000e9aa601>] ? perf_output_read_group
kernel/events/core.c:5746 [inline]
<EOI> [ 695.592461] [<000000000e9aa601>] ? perf_output_read+0x776/0x12e0
kernel/events/core.c:5779
[<00000000c936b86c>] memcpy+0x38/0x50 mm/kasan/kasan.c:361
[<000000000e9aa601>] memcpy_common kernel/events/internal.h:171 [inline]
[<000000000e9aa601>] __output_copy kernel/events/internal.h:175 [inline]
[<000000000e9aa601>] perf_output_read_group kernel/events/core.c:5746
[inline]
[<000000000e9aa601>] perf_output_read+0x776/0x12e0
kernel/events/core.c:5779
[<000000002976b91a>] perf_output_sample+0x1142/0x17e0
kernel/events/core.c:5821
[<00000000bf87a6c7>] __perf_event_output kernel/events/core.c:6093 [inline]
[<00000000bf87a6c7>] perf_event_output_forward+0x129/0x240
kernel/events/core.c:6106
[<000000004d74fafa>] __perf_event_overflow+0x121/0x330
kernel/events/core.c:7206
[<00000000e4fec4f8>] perf_swevent_overflow+0x17c/0x210
kernel/events/core.c:7282
[<00000000f8ce4402>] perf_swevent_event+0x1ac/0x280
kernel/events/core.c:7315
[<00000000d36b2678>] do_perf_sw_event kernel/events/core.c:7423 [inline]
[<00000000d36b2678>] ___perf_sw_event+0x299/0x4c0 kernel/events/core.c:7454
[<00000000bc606afc>] __perf_sw_event+0x47/0x90 kernel/events/core.c:7466
[<0000000003893e6b>] perf_sw_event include/linux/perf_event.h:1045 [inline]
[<0000000003893e6b>] __do_page_fault+0x6cd/0xa60 arch/x86/mm/fault.c:1447
[<00000000daba32da>] do_page_fault+0x28/0x30 arch/x86/mm/fault.c:1469
[<00000000caabc158>] page_fault+0x25/0x30 arch/x86/entry/entry_64.S:951
[<0000000051e5e008>] pipe_write+0x25a/0xe40 fs/pipe.c:447
[<000000004d95adaf>] new_sync_write fs/read_write.c:498 [inline]
[<000000004d95adaf>] __vfs_write+0x3c1/0x560 fs/read_write.c:511
[<000000005d0f5efa>] vfs_write+0x185/0x520 fs/read_write.c:559
[<0000000092980a6c>] SYSC_write fs/read_write.c:606 [inline]
[<0000000092980a6c>] SyS_write+0xdc/0x1c0 fs/read_write.c:598
[<0000000065c8804c>] do_syscall_64+0x1ad/0x570 arch/x86/entry/common.c:285
[<000000009cbcc93d>] entry_SYSCALL_64_after_swapgs+0x5d/0xdb


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
syzbot can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches

syzbot

unread,
Apr 12, 2019, 8:01:26 PM4/12/19
to syzkaller-a...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: ff9973a5 ANDROID: arm64: kbuild: only specify code model w..
git tree: android-4.14
console output: https://syzkaller.appspot.com/x/log.txt?x=114819b9400000
kernel config: https://syzkaller.appspot.com/x/.config?x=9b3b342f97278cde
dashboard link: https://syzkaller.appspot.com/bug?extid=1d69d5012af892fa8699
compiler: gcc (GCC) 8.0.1 20180413 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+1d69d5...@syzkaller.appspotmail.com

INFO: rcu_preempt self-detected stall on CPU
1-...: (10499 ticks this GP) idle=dda/140000000000001/0
softirq=14238/14238 fqs=5105
(t=10500 jiffies g=3384 c=3383 q=1552)
NMI backtrace for cpu 1
CPU: 1 PID: 7241 Comm: syz-executor3 Not tainted 4.14.73+ #14
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0xb9/0x11b lib/dump_stack.c:53
nmi_cpu_backtrace.cold.0+0x47/0x85 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x121/0x146 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:156 [inline]
rcu_dump_cpu_stacks+0x171/0x1bf kernel/rcu/tree.c:1396
print_cpu_stall kernel/rcu/tree.c:1542 [inline]
check_cpu_stall kernel/rcu/tree.c:1610 [inline]
__rcu_pending kernel/rcu/tree.c:3373 [inline]
rcu_pending kernel/rcu/tree.c:3435 [inline]
rcu_check_callbacks.cold.56+0x478/0xd99 kernel/rcu/tree.c:2775
update_process_times+0x24/0x60 kernel/time/timer.c:1588
tick_sched_handle.isra.8+0x73/0x150 kernel/time/tick-sched.c:161
tick_sched_timer+0x7e/0x160 kernel/time/tick-sched.c:1321
__run_hrtimer kernel/time/hrtimer.c:1259 [inline]
__hrtimer_run_queues+0x2d0/0xc10 kernel/time/hrtimer.c:1323
hrtimer_interrupt+0x19a/0x440 kernel/time/hrtimer.c:1357
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1037 [inline]
smp_apic_timer_interrupt+0x13a/0x5f0 arch/x86/kernel/apic/apic.c:1062
apic_timer_interrupt+0x84/0x90 arch/x86/entry/entry_64.S:787
</IRQ>
RIP: 0010:rdtsc arch/x86/include/asm/msr.h:191 [inline]
RIP: 0010:rdtsc_ordered arch/x86/include/asm/msr.h:218 [inline]
RIP: 0010:pvclock_clocksource_read+0xc8/0x4d0 arch/x86/kernel/pvclock.c:85
RSP: 0018:ffff8801ccc7f070 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff10
RAX: 00000000319fa038 RBX: ffff88021ffff040 RCX: 0000000000000001
RDX: 0000000000000071 RSI: ffff88021ffff05b RDI: ffff88021ffff05c
RBP: dffffc0000000000 R08: 0000000000000004 R09: ffffed003a3242ae
R10: ffffed0043fffe09 R11: ffff88021ffff057 R12: ffff88021ffff043
R13: ffff88021ffff05d R14: ffff88021ffff050 R15: ffff88021ffff058
kvm_clock_read+0x1f/0x30 arch/x86/kernel/kvmclock.c:94
kvm_sched_clock_read+0x5/0x10 arch/x86/kernel/kvmclock.c:106
paravirt_sched_clock arch/x86/include/asm/paravirt.h:175 [inline]
sched_clock+0x5/0x10 arch/x86/kernel/tsc.c:228
sched_clock_cpu+0x143/0x1c0 kernel/sched/clock.c:363
local_clock include/linux/sched/clock.h:84 [inline]
cpu_clock_event_update kernel/events/core.c:8789 [inline]
cpu_clock_event_read+0x15/0x30 kernel/events/core.c:8822
perf_output_read_group kernel/events/core.c:5864 [inline]
perf_output_read+0x811/0xfb0 kernel/events/core.c:5903
perf_output_sample+0x10dd/0x1780 kernel/events/core.c:5945
__perf_event_output kernel/events/core.c:6255 [inline]
perf_event_output_forward+0x121/0x230 kernel/events/core.c:6268
__perf_event_overflow+0x116/0x320 kernel/events/core.c:7504
perf_swevent_overflow+0x166/0x1f0 kernel/events/core.c:7580
perf_swevent_event+0x19c/0x270 kernel/events/core.c:7613
do_perf_sw_event kernel/events/core.c:7721 [inline]
___perf_sw_event+0x296/0x480 kernel/events/core.c:7752
__perf_sw_event+0x3f/0x70 kernel/events/core.c:7764
perf_sw_event include/linux/perf_event.h:1041 [inline]
__do_page_fault+0x77f/0xb60 arch/x86/mm/fault.c:1466
page_fault+0x22/0x50 arch/x86/entry/entry_64.S:1104
RIP: 0010:fault_in_pages_readable include/linux/pagemap.h:613 [inline]
RIP: 0010:iov_iter_fault_in_readable+0x2b9/0x370 lib/iov_iter.c:421
RSP: 0018:ffff8801ccc7f9f8 EFLAGS: 00010246
RAX: 0000000000000000 RBX: 000000000000007f RCX: 0000000000040000
RDX: ffffffff81b55d83 RSI: ffffc90001d3d000 RDI: ffff8801ccc7fcf8
RBP: 1ffff1003998ff40 R08: 0000000000001000 R09: ffffea0006c75880
R10: ffffffffb267e0d0 R11: ffff8801b1d62fff R12: 0000000000000000
R13: 000000002024653f R14: 0000000000001000 R15: ffff8801ccc7fcf0
generic_perform_write+0x166/0x430 mm/filemap.c:3027
__generic_file_write_iter+0x345/0x540 mm/filemap.c:3162
generic_file_write_iter+0x36f/0x650 mm/filemap.c:3190
call_write_iter include/linux/fs.h:1782 [inline]
new_sync_write fs/read_write.c:471 [inline]
__vfs_write+0x417/0x5c0 fs/read_write.c:484
vfs_write+0x17f/0x4d0 fs/read_write.c:546
SYSC_write fs/read_write.c:593 [inline]
SyS_write+0xc2/0x1a0 fs/read_write.c:585
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x457579
RSP: 002b:00007f826b7b4c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457579
RDX: 00000000fffffda2 RSI: 0000000020000540 RDI: 0000000000000006
RBP: 000000000072bf00 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f826b7b56d4
R13: 00000000004c554e R14: 00000000004d8e68 R15: 00000000ffffffff
INFO: rcu_sched detected stalls on CPUs/tasks:
1-...: (10501 ticks this GP) idle=dda/140000000000001/0
softirq=14238/14238 fqs=5105
(detected by 0, t=10557 jiffies, g=2515, c=2514, q=55)
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 7241 Comm: syz-executor3 Not tainted 4.14.73+ #14
task: ffff8801d302c680 task.stack: ffff8801ccc78000
RIP: 0010:mark_held_locks+0xb2/0x130 kernel/locking/lockdep.c:2841
RSP: 0018:ffff8801ccc7efc8 EFLAGS: 00000002
RAX: 0000000000000002 RBX: 0000000000000004 RCX: 1ffff1003a6059df
RDX: 0000000000000003 RSI: ffff8801d302cf50 RDI: ffff8801d302cf72
RBP: ffff8801d302ceb0 R08: 0000000000000004 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffed003a6059d5
R13: 0000000000000002 R14: dffffc0000000000 R15: ffff8801d302c680
FS: 00007f826b7b5700(0000) GS:ffff8801dbb00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000002024653f CR3: 00000001c89f0006 CR4: 00000000001606a0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
__trace_hardirqs_on_caller kernel/locking/lockdep.c:2871 [inline]
trace_hardirqs_on_caller+0x261/0x520 kernel/locking/lockdep.c:2926
trace_hardirqs_on_thunk+0x1a/0x1c
retint_kernel+0x2d/0x2d
RIP: 0010:bytes_is_nonzero mm/kasan/kasan.c:167 [inline]
RIP: 0010:memory_is_nonzero mm/kasan/kasan.c:184 [inline]
RIP: 0010:memory_is_poisoned_n mm/kasan/kasan.c:210 [inline]
RIP: 0010:memory_is_poisoned mm/kasan/kasan.c:241 [inline]
RIP: 0010:check_memory_region_inline mm/kasan/kasan.c:257 [inline]
RIP: 0010:check_memory_region+0x107/0x1b0 mm/kasan/kasan.c:267
RSP: 0018:ffff8801ccc7f130 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: dffffc0000000001 RBX: 1ffff1003a3242e0 RCX: ffffffffb25e5f08
RDX: 0000000000000001 RSI: 0000000000000008 RDI: ffff8801d1921700
RBP: ffffed003a3242e1 R08: ffffed003a3242e1 R09: ffffed003a3242e0
R10: ffffed003a3242e0 R11: ffff8801d1921707 R12: ffff8801ccc7f240
R13: 0000000000000008 R14: ffff8801ccc7f248 R15: dffffc0000000000
memcpy+0x34/0x50 mm/kasan/kasan.c:303
memcpy include/linux/string.h:344 [inline]
memcpy_common kernel/events/internal.h:172 [inline]
__output_copy kernel/events/internal.h:176 [inline]
perf_output_read_group kernel/events/core.c:5870 [inline]
perf_output_read+0x688/0xfb0 kernel/events/core.c:5903
perf_output_sample+0x10dd/0x1780 kernel/events/core.c:5945
__perf_event_output kernel/events/core.c:6255 [inline]
perf_event_output_forward+0x121/0x230 kernel/events/core.c:6268
__perf_event_overflow+0x116/0x320 kernel/events/core.c:7504
perf_swevent_overflow+0x166/0x1f0 kernel/events/core.c:7580
perf_swevent_event+0x19c/0x270 kernel/events/core.c:7613
do_perf_sw_event kernel/events/core.c:7721 [inline]
___perf_sw_event+0x296/0x480 kernel/events/core.c:7752
__perf_sw_event+0x3f/0x70 kernel/events/core.c:7764
perf_sw_event include/linux/perf_event.h:1041 [inline]
__do_page_fault+0x77f/0xb60 arch/x86/mm/fault.c:1466
page_fault+0x22/0x50 arch/x86/entry/entry_64.S:1104
RIP: 0010:fault_in_pages_readable include/linux/pagemap.h:613 [inline]
RIP: 0010:iov_iter_fault_in_readable+0x2b9/0x370 lib/iov_iter.c:421
RSP: 0018:ffff8801ccc7f9f8 EFLAGS: 00010246
RAX: 0000000000000000 RBX: 000000000000007f RCX: 0000000000040000
RDX: ffffffff81b55d83 RSI: ffffc90001d3d000 RDI: ffff8801ccc7fcf8
RBP: 1ffff1003998ff40 R08: 0000000000001000 R09: ffffea0006c75880
R10: ffffffffb267e0d0 R11: ffff8801b1d62fff R12: 0000000000000000
R13: 000000002024653f R14: 0000000000001000 R15: ffff8801ccc7fcf0
generic_perform_write+0x166/0x430 mm/filemap.c:3027
__generic_file_write_iter+0x345/0x540 mm/filemap.c:3162
generic_file_write_iter+0x36f/0x650 mm/filemap.c:3190
call_write_iter include/linux/fs.h:1782 [inline]
new_sync_write fs/read_write.c:471 [inline]
__vfs_write+0x417/0x5c0 fs/read_write.c:484
vfs_write+0x17f/0x4d0 fs/read_write.c:546
SYSC_write fs/read_write.c:593 [inline]
SyS_write+0xc2/0x1a0 fs/read_write.c:585
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x457579
RSP: 002b:00007f826b7b4c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000457579
RDX: 00000000fffffda2 RSI: 0000000020000540 RDI: 0000000000000006
RBP: 000000000072bf00 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f826b7b56d4
R13: 00000000004c554e R14: 00000000004d8e68 R15: 00000000ffffffff
Code: 74 c5 00 48 8d 7e 22 48 89 f8 48 89 fa 48 c1 e8 03 83 e2 07 42 0f b6
04 30 38 d0 7f 04 84 c0 75 62 0f b6 46 22 8b 54 24 04 a8 03 <41> 0f 44 d5
a8 04 74 0c 4c 89 ff e8 be ef ff ff 85 c0 74 1e 41

syzbot

unread,
Jun 27, 2019, 10:55:03 AM6/27/19
to syzkaller-a...@googlegroups.com
Auto-closing this bug as obsolete.
Crashes did not happen for a while, no reproducer and no activity.
Reply all
Reply to author
Forward
0 new messages