bisecting fixing commit since f4cc0ed9b2c72687303b035379c5824a02224354
building syzkaller on 7509bf360eba1461ac6059e4cacfbc29c9d2d4c7
testing commit f4cc0ed9b2c72687303b035379c5824a02224354 with gcc (GCC) 8.1.0
kernel signature: fb8f40da8a634cac3eb3035ca293b0570b5ffc7c2ca29f9eb8aef4c2d646c2ec
run #0: crashed: INFO: rcu detected stall in sendfile64
run #1: crashed: INFO: rcu detected stall in corrupted
run #2: crashed: INFO: rcu detected stall in corrupted
run #3: crashed: INFO: rcu detected stall in corrupted
run #4: crashed: INFO: rcu detected stall in corrupted
run #5: crashed: INFO: rcu detected stall in corrupted
run #6: crashed: INFO: rcu detected stall in corrupted
run #7: crashed: INFO: rcu detected stall in corrupted
run #8: crashed: INFO: rcu detected stall in corrupted
run #9: crashed: INFO: rcu detected stall in corrupted
testing current HEAD 9fa690a2a016e1b55356835f047b952e67d3d73a
testing commit 9fa690a2a016e1b55356835f047b952e67d3d73a with gcc (GCC) 8.1.0
kernel signature: 48a7a7781571e948e96883fa79ef88b2234de516e59f70c74b64f564ebcaac6e
run #0: crashed: INFO: rcu detected stall in sendfile64
run #1: crashed: INFO: rcu detected stall in ext4_file_write_iter
run #2: crashed: INFO: rcu detected stall in corrupted
run #3: crashed: INFO: rcu detected stall in corrupted
run #4: crashed: INFO: rcu detected stall in corrupted
run #5: crashed: INFO: rcu detected stall in ext4_file_write_iter
run #6: crashed: INFO: rcu detected stall in corrupted
run #7: crashed: INFO: rcu detected stall in ext4_file_write_iter
run #8: crashed: INFO: rcu detected stall in corrupted
run #9: crashed: INFO: rcu detected stall in ext4_file_write_iter
revisions tested: 2, total time: 26m59.841525178s (build: 16m22.006021284s, test: 9m49.105149827s)
the crash still happens on HEAD
commit msg: Linux 4.14.169
crash: INFO: rcu detected stall in ext4_file_write_iter
IPv6: ADDRCONF(NETDEV_CHANGE): team_slave_1: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_to_hsr: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): hsr_slave_0: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_to_hsr: link becomes ready
INFO: rcu_sched self-detected stall on CPU
1-...: (10499 ticks this GP) idle=8ee/140000000000001/0 softirq=10996/10997 fqs=0
(t=10500 jiffies g=761 c=760 q=3)
rcu_sched kthread starved for 10500 jiffies! g761 c760 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x0 ->cpu=1
rcu_sched R running task 29832 9 2 0x80000000
Call Trace:
context_switch kernel/sched/core.c:2808 [inline]
__schedule+0x780/0x1d20 kernel/sched/core.c:3384
schedule+0x7f/0x1b0 kernel/sched/core.c:3428
schedule_timeout+0x40c/0xcc0 kernel/time/timer.c:1746
rcu_gp_kthread+0xbbf/0x1e00 kernel/rcu/tree.c:2255
kthread+0x338/0x400 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
NMI backtrace for cpu 1
CPU: 1 PID: 6936 Comm: syz-executor.5 Not tainted 4.14.169-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0xf7/0x13b lib/dump_stack.c:58
nmi_cpu_backtrace.cold.4+0x3e/0x76 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0xe5/0x119 lib/nmi_backtrace.c:62
arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
trigger_single_cpu_backtrace include/linux/nmi.h:158 [inline]
rcu_dump_cpu_stacks+0x172/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:3390 [inline]
rcu_pending kernel/rcu/tree.c:3452 [inline]
rcu_check_callbacks.cold.77+0x415/0xcfa kernel/rcu/tree.c:2792
update_process_times+0x2a/0x60 kernel/time/timer.c:1590
tick_sched_handle+0x7b/0x140 kernel/time/tick-sched.c:165
tick_sched_timer+0x34/0xf0 kernel/time/tick-sched.c:1223
__run_hrtimer kernel/time/hrtimer.c:1223 [inline]
__hrtimer_run_queues+0x297/0xaf0 kernel/time/hrtimer.c:1287
hrtimer_interrupt+0x1ae/0x600 kernel/time/hrtimer.c:1321
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1075 [inline]
smp_apic_timer_interrupt+0x11f/0x5d0 arch/x86/kernel/apic/apic.c:1100
apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:lock_is_held_type+0x18b/0x210 kernel/locking/lockdep.c:4034
RSP: 0018:ffff8880744c7080 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
RAX: dffffc0000000000 RBX: 0000000000000282 RCX: 0000000000000000
RDX: 1ffffffff0f22d39 RSI: ffffffff87991020 RDI: 0000000000000282
RBP: ffff8880744c70a0 R08: ffff8880a56d8ac8 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff8880a56d8200
R13: 0000000000000000 R14: 0000000000000565 R15: ffff888075c499d8
lock_is_held include/linux/lockdep.h:437 [inline]
___might_sleep+0x1fe/0x2a0 kernel/sched/core.c:6006
__might_sleep+0x93/0xb0 kernel/sched/core.c:5994
__getblk_gfp+0x3a/0x5f0 fs/buffer.c:1381
sb_getblk include/linux/buffer_head.h:325 [inline]
__ext4_get_inode_loc+0x32b/0xe30 fs/ext4/inode.c:4511
ext4_get_inode_loc fs/ext4/inode.c:4624 [inline]
ext4_reserve_inode_write+0xd7/0x220 fs/ext4/inode.c:5753
ext4_mark_inode_dirty+0x12b/0x7b0 fs/ext4/inode.c:5920
ext4_dirty_inode+0x63/0x90 fs/ext4/inode.c:5959
__mark_inode_dirty+0x542/0xe80 fs/fs-writeback.c:2144
mark_inode_dirty include/linux/fs.h:2019 [inline]
generic_write_end+0x162/0x220 fs/buffer.c:2218
ext4_da_write_end+0x2d6/0x9e0 fs/ext4/inode.c:3196
generic_perform_write+0x318/0x450 mm/filemap.c:3058
__generic_file_write_iter+0x201/0x580 mm/filemap.c:3172
ext4_file_write_iter+0x279/0xe70 fs/ext4/file.c:268
call_write_iter include/linux/fs.h:1777 [inline]
do_iter_readv_writev+0x460/0x900 fs/read_write.c:675
do_iter_write+0x12b/0x520 fs/read_write.c:954
vfs_iter_write+0x5b/0xb0 fs/read_write.c:967
iter_file_splice_write+0x540/0xc20 fs/splice.c:749
do_splice_from fs/splice.c:851 [inline]
direct_splice_actor+0x104/0x1c0 fs/splice.c:1018
splice_direct_to_actor+0x27c/0x750 fs/splice.c:973
do_splice_direct+0x144/0x250 fs/splice.c:1061
do_sendfile+0x463/0xd00 fs/read_write.c:1441
SYSC_sendfile64 fs/read_write.c:1496 [inline]
SyS_sendfile64+0x97/0x110 fs/read_write.c:1488
do_syscall_64+0x1c7/0x5b0 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x459519
RSP: 002b:00007fb781f8ac78 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 0000000000459519
RDX: 0000000020000000 RSI: 0000000000000003 RDI: 0000000000000003
RBP: 000000000075bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 00008080fffffffe R11: 0000000000000246 R12: 00007fb781f8b6d4
R13: 00000000004c6af0 R14: 00000000004dbd68 R15: 00000000ffffffff
INFO: rcu_preempt detected stalls on CPUs/tasks:
(detected by 1, t=10559 jiffies, g=1322, c=1321, q=292)
All QSes seen, last rcu_preempt kthread activity 10559 (4294953655-4294943096), jiffies_till_next_fqs=1, root ->qsmask 0x0
syz-executor.5 R running task 27000 6936 6884 0x00000008
Call Trace:
sched_show_task.cold.89+0x2e1/0x342 kernel/sched/core.c:5168
print_other_cpu_stall kernel/rcu/tree.c:1501 [inline]
check_cpu_stall kernel/rcu/tree.c:1616 [inline]
__rcu_pending kernel/rcu/tree.c:3390 [inline]
rcu_pending kernel/rcu/tree.c:3452 [inline]
rcu_check_callbacks.cold.77+0xc96/0xcfa kernel/rcu/tree.c:2792
update_process_times+0x2a/0x60 kernel/time/timer.c:1590
tick_sched_handle+0x7b/0x140 kernel/time/tick-sched.c:165
tick_sched_timer+0x34/0xf0 kernel/time/tick-sched.c:1223
__run_hrtimer kernel/time/hrtimer.c:1223 [inline]
__hrtimer_run_queues+0x297/0xaf0 kernel/time/hrtimer.c:1287
hrtimer_interrupt+0x1ae/0x600 kernel/time/hrtimer.c:1321
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1075 [inline]
smp_apic_timer_interrupt+0x11f/0x5d0 arch/x86/kernel/apic/apic.c:1100
apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:lock_is_held_type+0x18b/0x210 kernel/locking/lockdep.c:4034
RSP: 0018:ffff8880744c7080 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
RAX: dffffc0000000000 RBX: 0000000000000282 RCX: 0000000000000000
RDX: 1ffffffff0f22d39 RSI: ffffffff87991020 RDI: 0000000000000282
RBP: ffff8880744c70a0 R08: ffff8880a56d8ac8 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff8880a56d8200
R13: 0000000000000000 R14: 0000000000000565 R15: ffff888075c499d8
lock_is_held include/linux/lockdep.h:437 [inline]
___might_sleep+0x1fe/0x2a0 kernel/sched/core.c:6006
__might_sleep+0x93/0xb0 kernel/sched/core.c:5994
__getblk_gfp+0x3a/0x5f0 fs/buffer.c:1381
sb_getblk include/linux/buffer_head.h:325 [inline]
__ext4_get_inode_loc+0x32b/0xe30 fs/ext4/inode.c:4511
ext4_get_inode_loc fs/ext4/inode.c:4624 [inline]
ext4_reserve_inode_write+0xd7/0x220 fs/ext4/inode.c:5753
ext4_mark_inode_dirty+0x12b/0x7b0 fs/ext4/inode.c:5920
ext4_dirty_inode+0x63/0x90 fs/ext4/inode.c:5959
__mark_inode_dirty+0x542/0xe80 fs/fs-writeback.c:2144
mark_inode_dirty include/linux/fs.h:2019 [inline]
generic_write_end+0x162/0x220 fs/buffer.c:2218
ext4_da_write_end+0x2d6/0x9e0 fs/ext4/inode.c:3196
generic_perform_write+0x318/0x450 mm/filemap.c:3058
__generic_file_write_iter+0x201/0x580 mm/filemap.c:3172
ext4_file_write_iter+0x279/0xe70 fs/ext4/file.c:268
call_write_iter include/linux/fs.h:1777 [inline]
do_iter_readv_writev+0x460/0x900 fs/read_write.c:675
do_iter_write+0x12b/0x520 fs/read_write.c:954
vfs_iter_write+0x5b/0xb0 fs/read_write.c:967
iter_file_splice_write+0x540/0xc20 fs/splice.c:749
do_splice_from fs/splice.c:851 [inline]
direct_splice_actor+0x104/0x1c0 fs/splice.c:1018
splice_direct_to_actor+0x27c/0x750 fs/splice.c:973
do_splice_direct+0x144/0x250 fs/splice.c:1061
do_sendfile+0x463/0xd00 fs/read_write.c:1441
SYSC_sendfile64 fs/read_write.c:1496 [inline]
SyS_sendfile64+0x97/0x110 fs/read_write.c:1488
do_syscall_64+0x1c7/0x5b0 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x459519
RSP: 002b:00007fb781f8ac78 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 0000000000459519
RDX: 0000000020000000 RSI: 0000000000000003 RDI: 0000000000000003
RBP: 000000000075bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 00008080fffffffe R11: 0000000000000246 R12: 00007fb781f8b6d4
R13: 00000000004c6af0 R14: 00000000004dbd68 R15: 00000000ffffffff
rcu_preempt kthread starved for 10559 jiffies! g1322 c1321 f0x2 RCU_GP_WAIT_FQS(3) ->state=0x0 ->cpu=1
rcu_preempt R running task 29720 8 2 0x80000000
Call Trace:
context_switch kernel/sched/core.c:2808 [inline]
__schedule+0x780/0x1d20 kernel/sched/core.c:3384
schedule+0x7f/0x1b0 kernel/sched/core.c:3428
schedule_timeout+0x40c/0xcc0 kernel/time/timer.c:1746
rcu_gp_kthread+0xbbf/0x1e00 kernel/rcu/tree.c:2255
kthread+0x338/0x400 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404