FYI, we noticed the following commit:
commit: 3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91 ("x86,tsc: Feed refined TSC
calibration into sched_clock")
https://git.kernel.org/cgit/linux/kernel/git/peterz/queue.git sched/core
in testcase: trinity
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 -smp 2 -m 320M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-----------------------------------------------------------------------------------+------------+------------+
| |
f1844e5954 | 3d2d1b9d2d |
+-----------------------------------------------------------------------------------+------------+------------+
| boot_successes | 30
| 4 |
| boot_failures | 2
| 30 |
| invoked_oom-killer:gfp_mask=0x | 2
| 4 |
| Mem-Info | 2
| 4 |
| Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 2
| 4 |
| INFO:rcu_preempt_detected_stalls_on_CPUs/tasks | 0
| 9 |
| EIP:set_cyc2ns_scale | 0
| 7 |
| INFO:rcu_sched_detected_expedited_stalls_on_CPUs/tasks:{#-...}#jiffies_s:#root:#/ | 0
| 24 |
| BUG:kernel_hang_in_boot_stage | 0
| 26 |
| EIP:native_safe_halt | 0
| 2 |
+-----------------------------------------------------------------------------------+------------+------------+
[ 102.303164] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 102.303164] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 102.306476] (detected by 1, t=100002 jiffies, g=-100, c=-101, q=23)
[ 102.306476] (detected by 1, t=100002 jiffies, g=-100, c=-101, q=23)
[ 102.308165] All QSes seen, last rcu_preempt kthread activity 100002 (-197791--297793),
jiffies_till_next_fqs=3, root ->qsmask 0x0
[ 102.308165] All QSes seen, last rcu_preempt kthread activity 100002 (-197791--297793),
jiffies_till_next_fqs=3, root ->qsmask 0x0
[ 102.312118] swapper/1 R running task 0 0 1 0x00000000
[ 102.312118] swapper/1 R running task 0 0 1 0x00000000
[ 102.315817] Call Trace:
[ 102.315817] Call Trace:
[ 102.317684] sched_show_task+0xc5/0xd6
[ 102.317684] sched_show_task+0xc5/0xd6
[ 102.318621] rcu_check_callbacks+0x598/0x717
[ 102.318621] rcu_check_callbacks+0x598/0x717
[ 102.319904] update_process_times+0x28/0x4a
[ 102.319904] update_process_times+0x28/0x4a
[ 102.325452] tick_nohz_handler+0x95/0xd6
[ 102.325452] tick_nohz_handler+0x95/0xd6
[ 102.326426] local_apic_timer_interrupt+0x40/0x45
[ 102.326426] local_apic_timer_interrupt+0x40/0x45
[ 102.327668] smp_apic_timer_interrupt+0x33/0x42
[ 102.327668] smp_apic_timer_interrupt+0x33/0x42
[ 102.328776] apic_timer_interrupt+0x37/0x3c
[ 102.328776] apic_timer_interrupt+0x37/0x3c
[ 102.337498] EIP: native_safe_halt+0x5/0x7
[ 102.337498] EIP: native_safe_halt+0x5/0x7
[ 102.338509] EFLAGS: 00200246 CPU: 1
[ 102.338509] EFLAGS: 00200246 CPU: 1
[ 102.341545] EAX: 00000001 EBX: c668c840 ECX: 01000000 EDX: c17ad179
[ 102.341545] EAX: 00000001 EBX: c668c840 ECX: 01000000 EDX: c17ad179
[ 102.343252] ESI: 00000001 EDI: c66c1fb4 EBP: c66c1f4c ESP: c66c1f4c
[ 102.343252] ESI: 00000001 EDI: c66c1fb4 EBP: c66c1f4c ESP: c66c1f4c
[ 102.346251] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 102.346251] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 102.352681] default_idle+0x5a/0xd9
[ 102.352681] default_idle+0x5a/0xd9
[ 102.353511] arch_cpu_idle+0xe/0x10
[ 102.353511] arch_cpu_idle+0xe/0x10
[ 102.355846] default_idle_call+0x30/0x37
[ 102.355846] default_idle_call+0x30/0x37
[ 102.356951] do_idle+0x8f/0xfb
[ 102.356951] do_idle+0x8f/0xfb
[ 102.357664] cpu_startup_entry+0x1e/0x20
[ 102.357664] cpu_startup_entry+0x1e/0x20
[ 102.360040] start_secondary+0x11f/0x143
[ 102.360040] start_secondary+0x11f/0x143
[ 102.362676] startup_32_smp+0x16b/0x16d
[ 102.362676] startup_32_smp+0x16b/0x16d
[ 102.363583] ? startup_32_smp+0x16b/0x16d
[ 102.363583] ? startup_32_smp+0x16b/0x16d
[ 102.366855] rcu_preempt kthread starved for 100002 jiffies! g4294967196 c4294967195
f0x2 RCU_GP_WAIT_FQS(3) ->state=0x100
[ 102.366855] rcu_preempt kthread starved for 100002 jiffies! g4294967196 c4294967195
f0x2 RCU_GP_WAIT_FQS(3) ->state=0x100
[ 102.371855] rcu_preempt W 0 8 2 0x00000000
[ 102.371855] rcu_preempt W 0 8 2 0x00000000
[ 102.375186] Call Trace:
[ 102.375186] Call Trace:
[ 102.377102] __schedule+0x29a/0x512
[ 102.377102] __schedule+0x29a/0x512
[ 102.377935] schedule+0x78/0x8b
[ 102.377935] schedule+0x78/0x8b
[ 102.380544] schedule_timeout+0x225/0x26d
[ 102.380544] schedule_timeout+0x225/0x26d
[ 102.381738] ? del_timer_sync+0x41/0x41
[ 102.381738] ? del_timer_sync+0x41/0x41
[ 102.384186] rcu_gp_kthread+0x46a/0x7b8
[ 102.384186] rcu_gp_kthread+0x46a/0x7b8
[ 102.385095] kthread+0xf8/0xfd
[ 102.385095] kthread+0xf8/0xfd
[ 102.388478] ? force_qs_rnp+0x169/0x169
[ 102.388478] ? force_qs_rnp+0x169/0x169
[ 102.391622] ? kthread_create_on_node+0x1f/0x1f
[ 102.391622] ? kthread_create_on_node+0x1f/0x1f
[ 102.394154] ret_from_fork+0x21/0x2c
[ 102.394154] ret_from_fork+0x21/0x2c
[ 123.966184] INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 0-... } 102399
jiffies s: 5 root: 0x1/.
[ 123.966184] INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 0-... } 102399
jiffies s: 5 root: 0x1/.
[ 123.969178] blocking rcu_node structures:
[ 123.969178] blocking rcu_node structures:
[ 123.970732] Task dump for CPU 0:
[ 123.970732] Task dump for CPU 0:
[ 123.971986] kworker/0:1 R running task 0 20 2 0x00000000
[ 123.971986] kworker/0:1 R running task 0 20 2 0x00000000
[ 123.978939] Workqueue: events tsc_refine_calibration_work
[ 123.978939] Workqueue: events tsc_refine_calibration_work
[ 123.982792] Call Trace:
[ 123.982792] Call Trace:
[ 123.988528] ? process_one_work+0x18a/0x31a
[ 123.988528] ? process_one_work+0x18a/0x31a
[ 123.991864] ? worker_thread+0x236/0x30e
[ 123.991864] ? worker_thread+0x236/0x30e
[ 123.998041] ? kthread+0xf8/0xfd
[ 123.998041] ? kthread+0xf8/0xfd
[ 123.999264] ? rescuer_thread+0x26d/0x26d
[ 123.999264] ? rescuer_thread+0x26d/0x26d
[ 124.004894] ? kthread_create_on_node+0x1f/0x1f
[ 124.004894] ? kthread_create_on_node+0x1f/0x1f
[ 124.006744] ? ret_from_fork+0x21/0x2c
[ 124.006744] ? ret_from_fork+0x21/0x2c
[ 402.308172] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 402.308172] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 402.310307] (detected by 1, t=400007 jiffies, g=-100, c=-101, q=23)
[ 402.310307] (detected by 1, t=400007 jiffies, g=-100, c=-101, q=23)
[ 402.311803] All QSes seen, last rcu_preempt kthread activity 400007 (102214--297793),
jiffies_till_next_fqs=3, root ->qsmask 0x0
[ 402.311803] All QSes seen, last rcu_preempt kthread activity 400007 (102214--297793),
jiffies_till_next_fqs=3, root ->qsmask 0x0
[ 402.314481] swapper/1 R running task 0 0 1 0x00000000
[ 402.314481] swapper/1 R running task 0 0 1 0x00000000
[ 402.316303] Call Trace:
[ 402.316303] Call Trace:
[ 402.316886] sched_show_task+0xc5/0xd6
[ 402.316886] sched_show_task+0xc5/0xd6
[ 402.317775] rcu_check_callbacks+0x598/0x717
[ 402.317775] rcu_check_callbacks+0x598/0x717
[ 402.318778] update_process_times+0x28/0x4a
[ 402.318778] update_process_times+0x28/0x4a
[ 402.319763] tick_nohz_handler+0x95/0xd6
[ 402.319763] tick_nohz_handler+0x95/0xd6
[ 402.320696] local_apic_timer_interrupt+0x40/0x45
[ 402.320696] local_apic_timer_interrupt+0x40/0x45
[ 402.322024] smp_apic_timer_interrupt+0x33/0x42
[ 402.322024] smp_apic_timer_interrupt+0x33/0x42
[ 402.323287] apic_timer_interrupt+0x37/0x3c
[ 402.323287] apic_timer_interrupt+0x37/0x3c
[ 402.324459] EIP: native_safe_halt+0x5/0x7
[ 402.324459] EIP: native_safe_halt+0x5/0x7
[ 402.325574] EFLAGS: 00200246 CPU: 1
[ 402.325574] EFLAGS: 00200246 CPU: 1
[ 402.326527] EAX: 00000001 EBX: c668c840 ECX: 01000000 EDX: c17ad179
[ 402.326527] EAX: 00000001 EBX: c668c840 ECX: 01000000 EDX: c17ad179
[ 402.328262] ESI: 00000001 EDI: c66c1fb4 EBP: c66c1f4c ESP: c66c1f4c
[ 402.328262] ESI: 00000001 EDI: c66c1fb4 EBP: c66c1f4c ESP: c66c1f4c
[ 402.329973] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 402.329973] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 402.331483] default_idle+0x5a/0xd9
[ 402.331483] default_idle+0x5a/0xd9
[ 402.332462] arch_cpu_idle+0xe/0x10
[ 402.332462] arch_cpu_idle+0xe/0x10
[ 402.333441] default_idle_call+0x30/0x37
[ 402.333441] default_idle_call+0x30/0x37
[ 402.335061] do_idle+0x8f/0xfb
[ 402.335061] do_idle+0x8f/0xfb
[ 402.335893] cpu_startup_entry+0x1e/0x20
[ 402.335893] cpu_startup_entry+0x1e/0x20
[ 402.337026] start_secondary+0x11f/0x143
[ 402.337026] start_secondary+0x11f/0x143
[ 402.339020] startup_32_smp+0x16b/0x16d
[ 402.339020] startup_32_smp+0x16b/0x16d
[ 402.340127] ? startup_32_smp+0x16b/0x16d
[ 402.340127] ? startup_32_smp+0x16b/0x16d
[ 402.341246] rcu_preempt kthread starved for 400007 jiffies! g4294967196 c4294967195
f0x2 RCU_GP_WAIT_FQS(3) ->state=0x100
[ 402.341246] rcu_preempt kthread starved for 400007 jiffies! g4294967196 c4294967195
f0x2 RCU_GP_WAIT_FQS(3) ->state=0x100
[ 402.344284] rcu_preempt W 0 8 2 0x00000000
[ 402.344284] rcu_preempt W 0 8 2 0x00000000
[ 402.345775] Call Trace:
[ 402.345775] Call Trace:
[ 402.346482] __schedule+0x29a/0x512
[ 402.346482] __schedule+0x29a/0x512
[ 402.347467] schedule+0x78/0x8b
[ 402.347467] schedule+0x78/0x8b
[ 402.348338] schedule_timeout+0x225/0x26d
[ 402.348338] schedule_timeout+0x225/0x26d
[ 402.349434] ? del_timer_sync+0x41/0x41
[ 402.349434] ? del_timer_sync+0x41/0x41
[ 402.350510] rcu_gp_kthread+0x46a/0x7b8
[ 402.350510] rcu_gp_kthread+0x46a/0x7b8
[ 402.351576] kthread+0xf8/0xfd
[ 402.351576] kthread+0xf8/0xfd
[ 402.352406] ? force_qs_rnp+0x169/0x169
[ 402.352406] ? force_qs_rnp+0x169/0x169
[ 402.353493] ? kthread_create_on_node+0x1f/0x1f
[ 402.353493] ? kthread_create_on_node+0x1f/0x1f
[ 402.354716] ret_from_fork+0x21/0x2c
[ 402.354716] ret_from_fork+0x21/0x2c
[ 431.166819] INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 0-... } 409599
jiffies s: 5 root: 0x1/.
[ 431.166819] INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 0-... } 409599
jiffies s: 5 root: 0x1/.
[ 431.173597] blocking rcu_node structures:
[ 431.173597] blocking rcu_node structures:
[ 431.174757] Task dump for CPU 0:
[ 431.174757] Task dump for CPU 0:
[ 431.179513] kworker/0:1 R running task 0 20 2 0x00000000
[ 431.179513] kworker/0:1 R running task 0 20 2 0x00000000
[ 431.182360] Workqueue: events tsc_refine_calibration_work
[ 431.182360] Workqueue: events tsc_refine_calibration_work
[ 431.183888] Call Trace:
[ 431.183888] Call Trace:
[ 431.184594] ? process_one_work+0x18a/0x31a
[ 431.184594] ? process_one_work+0x18a/0x31a
[ 431.187524] ? worker_thread+0x236/0x30e
[ 431.187524] ? worker_thread+0x236/0x30e
[ 431.190252] ? kthread+0xf8/0xfd
[ 431.190252] ? kthread+0xf8/0xfd
[ 431.191145] ? rescuer_thread+0x26d/0x26d
[ 431.191145] ? rescuer_thread+0x26d/0x26d
[ 431.192968] ? kthread_create_on_node+0x1f/0x1f
[ 431.192968] ? kthread_create_on_node+0x1f/0x1f
[ 431.194159] ? ret_from_fork+0x21/0x2c
[ 431.194159] ? ret_from_fork+0x21/0x2c
Elapsed time: 470
BUG: kernel hang in boot stage
initrds=(
/osimage/yocto/yocto-tiny-i386-2016-04-22.cgz
/lkp/scheduled/vm-ivb41-yocto-i386-8/trinity-300s-yocto-tiny-i386-2016-04-22.cgz-3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91-20170427-25062-1vyakhz-29.cgz
/lkp/lkp/lkp-i386.cgz
/osimage/deps/debian-x86_64-2016-08-31.cgz/run-ipconfig.i386_2016-09-03.cgz
/osimage/pkg/static/trinity-i386.cgz
/pkg/linux/i386-randconfig-b0-04270810/gcc-5/3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91/modules.cgz
)
cat "${initrds[@]}" > /fs/sda5/initrd-vm-ivb41-yocto-i386-8
kvm=(
qemu-system-i386
-enable-kvm
-kernel
/pkg/linux/i386-randconfig-b0-04270810/gcc-5/3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91/vmlinuz-4.11.0-rc6-00038-g3d2d1b9
-initrd /fs/sda5/initrd-vm-ivb41-yocto-i386-8
-m 320
-smp 2
-device e1000,netdev=net0
-netdev user,id=net0
-boot order=nc
-no-reboot
-watchdog i6300esb
-watchdog-action debug
-rtc base=localtime
-drive file=/fs/sda5/disk0-vm-ivb41-yocto-i386-8,media=disk,if=virtio
-pidfile /dev/shm/kboot/pid-vm-ivb41-yocto-i386-8
-serial file:/dev/shm/kboot/vm-ivb41-yocto-i386-8/serial
-serial file:/dev/shm/kboot/vm-ivb41-yocto-i386-8/kmsg
-daemonize
-display none
-monitor null
)
append=(
ip=::::vm-ivb41-yocto-i386-8::dhcp
root=/dev/ram0
user=lkp
job=/lkp/scheduled/vm-ivb41-yocto-i386-8/trinity-300s-yocto-tiny-i386-2016-04-22.cgz-3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91-20170427-25062-1vyakhz-29.yaml
ARCH=i386
kconfig=i386-randconfig-b0-04270810
branch=linux-devel/devel-spot-201704270425
commit=3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91
BOOT_IMAGE=/pkg/linux/i386-randconfig-b0-04270810/gcc-5/3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91/vmlinuz-4.11.0-rc6-00038-g3d2d1b9
max_uptime=1500
RESULT_ROOT=/result/trinity/300s/vm-ivb41-yocto-i386/yocto-tiny-i386-2016-04-22.cgz/i386-randconfig-b0-04270810/gcc-5/3d2d1b9d2d2fcd875a0834cbd44b208ac3695c91/29
LKP_SERVER=inn
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
net.ifnames=0
printk.devkmsg=on
panic=-1
softlockup_panic=1
nmi_watchdog=panic
oops=panic
load_ramdisk=2
prompt_ramdisk=0
drbd.minor_count=8
systemd.log_level=err
ignore_loglevel
earlyprintk=ttyS0,115200
console=ttyS0,115200
console=tty0
vga=normal
rw
drbd.minor_count=8
)
"${kvm[@]}" -append "${append[*]}"
To reproduce:
git clone
https://github.com/01org/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this
email
Thanks,
Xiaolong