Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: 933ada2c3310aa88807e65c8d498b74a2159a9a2 ("rcu: IPI all CPUs at GP start for strict GPs")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
in testcase: trinity
version: trinity-i386-4d2343bd-1_20200320
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
[ 2099.508600] WARNING: CPU: 0 PID: 456 at kernel/rcu/tree_stall.h:752 rcu_check_gp_start_stall+0x12f/0x1c0
[ 2099.509643] Modules linked in: crc32_pclmul crc32c_intel aesni_intel crypto_simd cryptd rapl input_leds serio_raw bochs_drm button
[ 2099.511042] CPU: 0 PID: 456 Comm: time Not tainted 5.9.0-rc1-00008-g933ada2c3310a #1
[ 2099.511831] EIP: rcu_check_gp_start_stall+0x12f/0x1c0
[ 2099.512430] Code: 42 39 c7 79 55 a1 d8 11 42 42 01 d0 39 c1 78 4a a1 d4 11 42 42 01 c2 39 d1 78 3f b8 01 00 00 00 87 05 64 5a ce 42 85 c0 75 28 <0f> 0b 81 fb c0 04 42 42 74 0a b8 c0 04 42 42 e8 bd 37 ce 00 89 f2
All code
========
0: 42 39 c7 rex.X cmp %eax,%edi
3: 79 55 jns 0x5a
5: a1 d8 11 42 42 01 d0 movabs 0xc139d001424211d8,%eax
c: 39 c1
e: 78 4a js 0x5a
10: a1 d4 11 42 42 01 c2 movabs 0xd139c201424211d4,%eax
17: 39 d1
19: 78 3f js 0x5a
1b: b8 01 00 00 00 mov $0x1,%eax
20: 87 05 64 5a ce 42 xchg %eax,0x42ce5a64(%rip) # 0x42ce5a8a
26: 85 c0 test %eax,%eax
28: 75 28 jne 0x52
2a:* 0f 0b ud2 <-- trapping instruction
2c: 81 fb c0 04 42 42 cmp $0x424204c0,%ebx
32: 74 0a je 0x3e
34: b8 c0 04 42 42 mov $0x424204c0,%eax
39: e8 bd 37 ce 00 callq 0xce37fb
3e: 89 f2 mov %esi,%edx
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 81 fb c0 04 42 42 cmp $0x424204c0,%ebx
8: 74 0a je 0x14
a: b8 c0 04 42 42 mov $0x424204c0,%eax
f: e8 bd 37 ce 00 callq 0xce37d1
14: 89 f2 mov %esi,%edx
[ 2099.514260] EAX: 00000000 EBX: 424204c0 ECX: 00083c8b EDX: 00083c43
[ 2099.514920] ESI: 00000246 EDI: 00011ac4 EBP: 40037fa0 ESP: 40037f90
[ 2099.515552] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00010046
[ 2099.516250] CR0: 80050033 CR2: 37e343e2 CR3: 99b6b000 CR4: 00040690
[ 2099.516900] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 2099.517548] DR6: fffe0ff0 DR7: 00000400
[ 2099.517964] Call Trace:
[ 2099.518228] <SOFTIRQ>
[ 2099.518493] ? rcu_core (kbuild/src/consumer/kernel/rcu/tree.c:2682)
[ 2099.518862] ? rcu_core_si (kbuild/src/consumer/kernel/rcu/tree.c:2694)
[ 2099.519241] ? __do_softirq (kbuild/src/consumer/arch/x86/include/asm/jump_label.h:25 kbuild/src/consumer/include/linux/jump_label.h:200 kbuild/src/consumer/include/trace/events/irq.h:142 kbuild/src/consumer/kernel/softirq.c:299)
[ 2099.519651] ? __softirqentry_text_start (kbuild/src/consumer/kernel/softirq.c:256)
[ 2099.520144] ? call_on_stack (kbuild/src/consumer/arch/x86/kernel/irq_32.c:59)
[ 2099.520547] </SOFTIRQ>
[ 2099.520816] ? irq_exit_rcu (kbuild/src/consumer/kernel/softirq.c:393 kbuild/src/consumer/kernel/softirq.c:423 kbuild/src/consumer/kernel/softirq.c:435)
[ 2099.521207] ? sysvec_apic_timer_interrupt (kbuild/src/consumer/arch/x86/kernel/apic/apic.c:1091)
[ 2099.521722] ? handle_exception (kbuild/src/consumer/arch/x86/entry/entry_32.S:1179)
[ 2099.522166] ? finish_task_switch (kbuild/src/consumer/kernel/sched/core.c:3634)
[ 2099.525832] ? rcu_read_unlock (kbuild/src/consumer/include/linux/rcupdate.h:684 (discriminator 5))
[ 2099.526254] ? _raw_spin_unlock_irq (kbuild/src/consumer/include/linux/spinlock_api_smp.h:169 kbuild/src/consumer/kernel/locking/spinlock.c:199)
[ 2099.526730] ? rcu_read_unlock (kbuild/src/consumer/include/linux/rcupdate.h:684 (discriminator 5))
[ 2099.527152] ? sysvec_call_function_single (kbuild/src/consumer/arch/x86/kernel/apic/apic.c:1091)
[ 2099.527674] ? _raw_spin_unlock_irq (kbuild/src/consumer/include/linux/spinlock_api_smp.h:169 kbuild/src/consumer/kernel/locking/spinlock.c:199)
[ 2099.528134] ? finish_task_switch (kbuild/src/consumer/kernel/sched/core.c:3634)
[ 2099.528582] ? finish_task_switch (kbuild/src/consumer/kernel/sched/core.c:3488 kbuild/src/consumer/kernel/sched/core.c:3616)
[ 2099.529033] ? __switch_to (kbuild/src/consumer/arch/x86/kernel/process_32.c:164)
[ 2099.529424] ? __schedule (kbuild/src/consumer/kernel/sched/core.c:3781 kbuild/src/consumer/kernel/sched/core.c:4527)
[ 2099.529814] ? sysvec_call_function_single (kbuild/src/consumer/arch/x86/kernel/apic/apic.c:1091)
[ 2099.530333] ? sysvec_call_function_single (kbuild/src/consumer/arch/x86/kernel/apic/apic.c:1091)
[ 2099.530850] ? preempt_schedule_irq (kbuild/src/consumer/arch/x86/include/asm/irqflags.h:49 (discriminator 1) kbuild/src/consumer/arch/x86/include/asm/irqflags.h:89 (discriminator 1) kbuild/src/consumer/kernel/sched/core.c:4786 (discriminator 1))
[ 2099.531292] ? irqentry_exit_cond_resched (??:?)
[ 2099.531836] ? irqentry_exit (kbuild/src/consumer/kernel/entry/common.c:374 kbuild/src/consumer/kernel/entry/common.c:362)
[ 2099.532227] ? sysvec_apic_timer_interrupt (kbuild/src/consumer/arch/x86/kernel/apic/apic.c:1091)
[ 2099.532746] ? handle_exception (kbuild/src/consumer/arch/x86/entry/entry_32.S:1179)
[ 2099.533193] ? preempt_schedule (kbuild/src/consumer/kernel/sched/core.c:4709)
[ 2099.533618] ? preempt_schedule_common (kbuild/src/consumer/arch/x86/include/asm/bitops.h:207 kbuild/src/consumer/include/asm-generic/bitops/instrumented-non-atomic.h:111 kbuild/src/consumer/include/linux/thread_info.h:84 kbuild/src/consumer/include/linux/sched.h:1864 kbuild/src/consumer/kernel/sched/core.c:4691)
[ 2099.534101] ? sysvec_call_function_single (kbuild/src/consumer/arch/x86/kernel/apic/apic.c:1091)
[ 2099.534631] ? preempt_schedule_common (kbuild/src/consumer/arch/x86/include/asm/bitops.h:207 kbuild/src/consumer/include/asm-generic/bitops/instrumented-non-atomic.h:111 kbuild/src/consumer/include/linux/thread_info.h:84 kbuild/src/consumer/include/linux/sched.h:1864 kbuild/src/consumer/kernel/sched/core.c:4691)
[ 2099.535115] ? preempt_schedule (kbuild/src/consumer/kernel/sched/core.c:4709)
[ 2099.535539] ? preempt_schedule_thunk (kbuild/src/consumer/arch/x86/entry/thunk_32.S:38)
[ 2099.536012] ? _raw_spin_unlock (kbuild/src/consumer/kernel/locking/spinlock.c:184)
[ 2099.536439] ? dentry_unlink_inode (kbuild/src/consumer/fs/dcache.c:369)
[ 2099.536899] ? __dentry_kill (kbuild/src/consumer/fs/dcache.c:582)
[ 2099.537306] ? shrink_dentry_list (kbuild/src/consumer/include/linux/list.h:282 kbuild/src/consumer/fs/dcache.c:1119)
[ 2099.537757] ? shrink_dcache_parent (kbuild/src/consumer/fs/dcache.c:1592)
[ 2099.538227] ? d_invalidate (kbuild/src/consumer/fs/dcache.c:1677 kbuild/src/consumer/fs/dcache.c:1662)
[ 2099.538632] ? d_find_any_alias (kbuild/src/consumer/fs/dcache.c:989)
[ 2099.539070] ? proc_invalidate_siblings_dcache (kbuild/src/consumer/fs/proc/inode.c:151)
[ 2099.539645] ? proc_flush_pid (kbuild/src/consumer/fs/proc/base.c:3319)
[ 2099.540055] ? release_task (kbuild/src/consumer/kernel/exit.c:222)
[ 2099.540465] ? wait_task_zombie (kbuild/src/consumer/kernel/exit.c:1088)
[ 2099.540909] ? wait_consider_task (kbuild/src/consumer/kernel/exit.c:1315)
[ 2099.541368] ? _raw_read_lock (kbuild/src/consumer/kernel/locking/spinlock.c:224)
[ 2099.541779] ? do_wait (kbuild/src/consumer/kernel/exit.c:1380 kbuild/src/consumer/kernel/exit.c:1449)
[ 2099.542140] ? kernel_wait4 (kbuild/src/consumer/kernel/exit.c:1621)
[ 2099.542562] ? kill_orphaned_pgrp (kbuild/src/consumer/kernel/exit.c:1403)
[ 2099.543029] ? __ia32_sys_wait4 (kbuild/src/consumer/kernel/exit.c:1649 kbuild/src/consumer/kernel/exit.c:1645 kbuild/src/consumer/kernel/exit.c:1645)
[ 2099.543443] ? do_int80_syscall_32 (kbuild/src/consumer/arch/x86/entry/common.c:84 kbuild/src/consumer/arch/x86/entry/common.c:94)
[ 2099.543876] ? entry_INT80_32 (kbuild/src/consumer/arch/x86/entry/entry_32.S:1064)
[ 2099.544281] irq event stamp: 133715011
[ 2099.544682] hardirqs last enabled at (133715010): rcu_core (kbuild/src/consumer/arch/x86/include/asm/irqflags.h:41 (discriminator 2) kbuild/src/consumer/arch/x86/include/asm/irqflags.h:84 (discriminator 2) kbuild/src/consumer/kernel/rcu/tree.c:2676 (discriminator 2))
[ 2099.545470] hardirqs last disabled at (133715011): _raw_spin_lock_irqsave (kbuild/src/consumer/include/linux/spinlock_api_smp.h:109 kbuild/src/consumer/kernel/locking/spinlock.c:159)
[ 2099.546368] softirqs last enabled at (133714602): __do_softirq (kbuild/src/consumer/arch/x86/include/asm/preempt.h:26 kbuild/src/consumer/kernel/softirq.c:326)
[ 2099.547218] softirqs last disabled at (133715005): call_on_stack (kbuild/src/consumer/arch/x86/kernel/irq_32.c:59)
[ 2099.548036] ---[ end trace 74aafb1e11890695 ]---
[ 2099.548569] rcu: rcu_preempt: wait state: RCU_GP_WAIT_GPS(1) ->state: 0x0 delta ->gp_activity 31584 ->gp_req_activity 31512 ->gp_wake_time 31512 ->gp_wake_seq 72388 ->gp_seq 72388 ->gp_seq_needed 72392 ->gp_flags 0x1
[ 2099.550565] rcu: rcu_node 0:1 ->gp_seq 72388 ->gp_seq_needed 72392
[ 2099.551239] rcu: RCU callbacks invoked since boot: 151744
[ 2099.551802] rcu_tasks: RTGS_INIT(0) since 539800 g:0 i:0/0 k.
[ 2099.552424] rcu_tasks_rude: RTGS_INIT(0) since 539800 g:0 i:0/0 k.
[ 2099.553077] rcu_tasks_trace: RTGS_INIT(0) since 539800 g:0 i:0/0 k. N0 h:0/0/0
BUG: kernel hang in test stage
Kboot worker: lkp-worker36
Elapsed time: 4020
kvm=(
qemu-system-i386
-enable-kvm
-cpu SandyBridge
-kernel $kernel
-initrd initrd-vm-snb-i386-16.cgz
-m 16384
-smp 2
-device e1000,netdev=net0
-netdev user,id=net0,hostfwd=tcp::32032-:22
-boot order=nc
-no-reboot
-watchdog i6300esb
-watchdog-action debug
-rtc base=localtime
-serial stdio
-display none
-monitor null
)
append=(
ip=::::vm-snb-i386-16::dhcp
root=/dev/ram0
user=lkp
job=/job-script
ARCH=i386
kconfig=i386-randconfig-r005-20210110
branch=linus/master
commit=933ada2c3310aa88807e65c8d498b74a2159a9a2
BOOT_IMAGE=/pkg/linux/i386-randconfig-r005-20210110/gcc-9/933ada2c3310aa88807e65c8d498b74a2159a9a2/vmlinuz-5.9.0-rc1-00008-g933ada2c3310a
vmalloc=512M
max_uptime=2100
RESULT_ROOT=/result/trinity/300s/vm-snb-i386/debian-i386-20191205.cgz/i386-randconfig-r005-20210110/gcc-9/933ada2c3310aa88807e65c8d498b74a2159a9a2/136
result_service=tmpfs
selinux=0
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
net.ifnames=0
printk.devkmsg=on
panic=-1
To reproduce:
# build kernel
cd linux
cp config-5.9.0-rc1-00008-g933ada2c3310a .config
make HOSTCC=gcc-9 CC=gcc-9 ARCH=i386 olddefconfig prepare modules_prepare bzImage
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
---
0DAY/LKP+ Test Infrastructure Open Source Technology Center
https://lists.01.org/hyperkitty/list/[email protected] Intel Corporation
Thanks,
Oliver Sang