Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: d792962d3d4fdefcd21abcd238dddfe9481bf326 ("printk: move console printing to
kthreads")
https://git.kernel.org/cgit/linux/kernel/git/rt/linux-rt-devel.git linux-5.14.y-rt
in testcase: boot
on test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+----------------------------------------------------------+------------+------------+
| | 8bab77c4bd | d792962d3d |
+----------------------------------------------------------+------------+------------+
| boot_successes | 6 | 0 |
| boot_failures | 0 | 6 |
| WARNING:at_kernel/time/clocksource-wdtest.c:#wdtest_func | 0 | 6 |
| EIP:wdtest_func | 0 | 6 |
+----------------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <oliver.sang(a)intel.com>
[ 37.052390][ T105] WARNING: CPU: 0 PID: 105 at kernel/time/clocksource-wdtest.c:163
wdtest_func (kernel/time/clocksource-wdtest.c:163 (discriminator 1))
[ 37.052404][ T105] Modules linked in: crc32c_intel aesni_intel crypto_simd input_leds
led_class pcspkr qemu_fw_cfg
[ 37.052421][ T105] CPU: 0 PID: 105 Comm: wdtest Not tainted
5.14.0-rc3-00020-gd792962d3d4f #1 8b633a590536ecd13269ffa750772a6565cf629f
[ 37.052427][ T105] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.12.0-1 04/01/2014
[ 37.052430][ T105] EIP: wdtest_func (kernel/time/clocksource-wdtest.c:163 (discriminator
1))
[ 37.052435][ T105] Code: c4 73 1f c8 31 d2 b8 18 92 35 c8 83 e3 40 0f 94 c2 31 c9 c7 04
24 00 00 00 00 89 55 f4 e8 ed 65 03 00 85 db 8b 55 f4 58 75 02 <0f> 0b 31 c9 b8 00
92 35 c8 6a 00 e8 d5 65 03 00 b8 80 73 1f c8 e8
All code
========
0: c4 (bad)
1: 73 1f jae 0x22
3: c8 31 d2 b8 enterq $0xd231,$0xb8
7: 18 92 35 c8 83 e3 sbb %dl,-0x1c7c37cb(%rdx)
d: 40 0f 94 c2 sete %dl
11: 31 c9 xor %ecx,%ecx
13: c7 04 24 00 00 00 00 movl $0x0,(%rsp)
1a: 89 55 f4 mov %edx,-0xc(%rbp)
1d: e8 ed 65 03 00 callq 0x3660f
22: 85 db test %ebx,%ebx
24: 8b 55 f4 mov -0xc(%rbp),%edx
27: 58 pop %rax
28: 75 02 jne 0x2c
2a:* 0f 0b ud2 <-- trapping instruction
2c: 31 c9 xor %ecx,%ecx
2e: b8 00 92 35 c8 mov $0xc8359200,%eax
33: 6a 00 pushq $0x0
35: e8 d5 65 03 00 callq 0x3660f
3a: b8 80 73 1f c8 mov $0xc81f7380,%eax
3f: e8 .byte 0xe8
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 31 c9 xor %ecx,%ecx
4: b8 00 92 35 c8 mov $0xc8359200,%eax
9: 6a 00 pushq $0x0
b: e8 d5 65 03 00 callq 0x365e5
10: b8 80 73 1f c8 mov $0xc81f7380,%eax
15: e8 .byte 0xe8
[ 37.052439][ T105] EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000001
[ 37.052442][ T105] ESI: 00000005 EDI: 00000000 EBP: c418ff88 ESP: c418ff78
[ 37.052445][ T105] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010246
[ 37.052449][ T105] CR0: 80050033 CR2: 03daa000 CR3: 34803000 CR4: 000406d0
[ 37.052456][ T105] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 37.052458][ T105] DR6: fffe0ff0 DR7: 00000400
[ 37.052461][ T105] Call Trace:
[ 37.052481][ T105] kthread (kernel/kthread.c:321)
[ 37.052492][ T105] ? wdtest_ktime_read (kernel/time/clocksource-wdtest.c:106)
[ 37.052500][ T105] ? set_kthread_struct (kernel/kthread.c:272)
[ 37.052512][ T105] ret_from_fork (arch/x86/entry/entry_32.S:775)
[ 37.052570][ T105] irq event stamp: 253
[ 37.052572][ T105] hardirqs last enabled at (255): vprintk_store
(arch/x86/include/asm/irqflags.h:29 (discriminator 3) arch/x86/include/asm/irqflags.h:70
(discriminator 3) arch/x86/include/asm/irqflags.h:132 (discriminator 3)
kernel/printk/printk.c:2154 (discriminator 3))
[ 37.052577][ T105] hardirqs last disabled at (256): vprintk_store
(arch/x86/include/asm/preempt.h:27 (discriminator 3) kernel/printk/printk.c:1908
(discriminator 3) kernel/printk/printk.c:2057 (discriminator 3))
[ 37.052580][ T105] softirqs last enabled at (0): copy_process (kernel/fork.c:2006)
[ 37.052586][ T105] softirqs last disabled at (0): 0x0
[ 37.052592][ T105] ---[ end trace daeb5df61cb95f4a ]---
[ 37.052599][ T105] clocksource: Checking clocksource wdtest-ktime synchronization from
CPU 0 to CPUs 1.
[ 37.052618][ T105] clocksource: CPUs 1 ahead of CPU 0 for clocksource
wdtest-ktime.
[ 37.052621][ T105] clocksource: CPU 0 check durations 13686ns - 13686ns for
clocksource wdtest-ktime.
[ 37.052630][ T105] clocksource_wdtest: --- Done with test.
[ 37.596591][ T406] _warn_unseeded_randomness: 29 callbacks suppressed
[ 37.596601][ T406] random: get_random_u32 called from copy_process+0x271/0x1899 with
crng_init=1
[ 37.614173][ T510] random: get_random_u32 called from arch_rnd+0x34/0x45 with crng_init=1
[ 37.614194][ T510] random: get_random_u32 called from randomize_stack_top+0x1c/0x37 with
crng_init=1
[ 38.083005][ T263]
[ 38.303649][ T263] mount: mount point /sys/kernel/debug does not exist
[ 38.303668][ T263]
[ 38.663469][ T406] _warn_unseeded_randomness: 13 callbacks suppressed
[ 38.663479][ T406] random: get_random_u32 called from copy_process+0x271/0x1899 with
crng_init=1
[ 38.665905][ T513] random: get_random_u32 called from arch_rnd+0x34/0x45 with crng_init=1
[ 38.665923][ T513] random: get_random_u32 called from randomize_stack_top+0x1c/0x37 with
crng_init=1
[ 39.686093][ T406] _warn_unseeded_randomness: 13 callbacks suppressed
[ 39.686102][ T406] random: get_random_u32 called from copy_process+0x271/0x1899 with
crng_init=1
[ 39.691153][ T516] random: get_random_u32 called from arch_rnd+0x34/0x45 with crng_init=1
[ 39.691171][ T516] random: get_random_u32 called from randomize_stack_top+0x1c/0x37 with
crng_init=1
[ 40.344544][ T261] install debs round one: dpkg -i --force-confdef --force-depends
/opt/deb/gawk_1%3a4.1.4+dfsg-1_i386.deb
[ 40.344561][ T261]
[ 40.346875][ T261] Selecting previously unselected package gawk.
[ 40.346892][ T261]
[ 40.350671][ T261] (Reading database ... 16210 files and directories currently
installed.)
[ 40.350682][ T261]
[ 40.353935][ T261] Preparing to unpack .../gawk_1%3a4.1.4+dfsg-1_i386.deb ...
[ 40.353948][ T261]
[ 40.355803][ T261] Unpacking gawk (1:4.1.4+dfsg-1) ...
[ 40.355814][ T261]
[ 40.357780][ T261] Setting up gawk (1:4.1.4+dfsg-1) ...
[ 40.357792][ T261]
[ 40.359827][ T261] mount debug /sys/kernel/debug -t debugfs
[ 40.359837][ T261]
[ 40.361298][ T261] none on / type rootfs (rw)
[ 40.361308][ T261]
[ 40.365686][ T261] sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
[ 40.365700][ T261]
[ 40.369392][ T261] proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
[ 40.369405][ T261]
[ 40.373579][ T261] devtmpfs on /dev type devtmpfs
(rw,nosuid,size=1455760k,nr_inodes=163686,mode=755)
[ 40.373592][ T261]
[ 40.387629][ T261] securityfs on /sys/kernel/security type securityfs
(rw,nosuid,nodev,noexec,relatime)
[ 40.387646][ T261]
[ 40.390075][ T261] tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev)
[ 40.390088][ T261]
[ 40.400550][ T261] devpts on /dev/pts type devpts
(rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
[ 40.400565][ T261]
[ 40.405066][ T261] tmpfs on /run type tmpfs (rw,nosuid,nodev,mode=755)
[ 40.405081][ T261]
[ 40.408919][ T261] tmpfs on /run/lock type tmpfs
(rw,nosuid,nodev,noexec,relatime,size=5120k)
[ 40.408932][ T261]
[ 40.413348][ T261] tmpfs on /sys/fs/cgroup type tmpfs
(ro,nosuid,nodev,noexec,mode=755)
[ 40.413415][ T261]
[ 40.749169][ T406] _warn_unseeded_randomness: 14 callbacks suppressed
[ 40.749179][ T406] random: get_random_u32 called from copy_process+0x271/0x1899 with
crng_init=1
[ 40.790247][ T519] random: get_random_u32 called from arch_rnd+0x34/0x45 with crng_init=1
[ 40.790267][ T519] random: get_random_u32 called from randomize_stack_top+0x1c/0x37 with
crng_init=1
[ 41.818088][ T406] _warn_unseeded_randomness: 13 callbacks suppressed
[ 41.818098][ T406] random: get_random_u32 called from copy_process+0x271/0x1899 with
crng_init=1
[ 41.827438][ T522] random: get_random_u32 called from arch_rnd+0x34/0x45 with crng_init=1
[ 41.827456][ T522] random: get_random_u32 called from randomize_stack_top+0x1c/0x37 with
crng_init=1
[ 42.862513][ T406] _warn_unseeded_randomness: 13 callbacks suppressed
[ 42.862523][ T406] random: get_random_u32 called from copy_process+0x271/0x1899 with
crng_init=1
[ 42.864776][ T525] random: get_random_u32 called from arch_rnd+0x34/0x45 with crng_init=1
[ 42.864792][ T525] random: get_random_u32 called from randomize_stack_top+0x1c/0x37 with
crng_init=1
[ 43.890265][ T406] _warn_unseeded_randomness: 14 callbacks suppressed
[ 43.890275][ T406] random: get_random_u32 called from copy_process+0x271/0x1899 with
crng_init=1
[ 43.895818][ T528] random: get_random_u32 called from arch_rnd+0x34/0x45 with crng_init=1
[ 43.895836][ T528] random: get_random_u32 called from randomize_stack_top+0x1c/0x37 with
crng_init=1
[ 44.175104][ T261] cgroup on /sys/fs/cgroup/systemd type cgroup
(rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
[ 44.175180][ T261]
[ 44.184164][ T261] pstore on /sys/fs/pstore type pstore
(rw,nosuid,nodev,noexec,relatime)
[ 44.184181][ T261]
[ 44.191573][ T261] cgroup on /sys/fs/cgroup/pids type cgroup
(rw,nosuid,nodev,noexec,relatime,pids)
[ 44.191588][ T261]
[ 44.196240][ T261] cgroup on /sys/fs/cgroup/net_cls type cgroup
(rw,nosuid,nodev,noexec,relatime,net_cls)
[ 44.196257][ T261]
[ 44.213036][ T261] cgroup on /sys/fs/cgroup/blkio type cgroup
(rw,nosuid,nodev,noexec,relatime,blkio)
[ 44.213052][ T261]
[ 44.221804][ T261] cgroup on /sys/fs/cgroup/cpu type cgroup
(rw,nosuid,nodev,noexec,relatime,cpu)
[ 44.221823][ T261]
[ 44.235501][ T261] systemd-1 on /proc/sys/fs/binfmt_misc type autofs
(rw,relatime,fd=28,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=28486)
[ 44.235515][ T261]
[ 44.242221][ T261] sunrpc on /run/rpc_pipefs type rpc_pipefs (rw,relatime)
[ 44.242236][ T261]
[ 44.247841][ T261] fusectl on /sys/fs/fuse/connections type fusectl (rw,relatime)
[ 44.247855][ T261]
[ 44.251314][ T261] tmp on /tmp type tmpfs (rw,relatime)
[ 44.251331][ T261]
[ 44.251974][ T261] nodev sysfs
[ 44.251988][ T261]
[ 44.259535][ T261] nodev tmpfs
[ 44.259550][ T261]
[ 44.260094][ T261] nodev bdev
[ 44.260105][ T261]
[ 44.261384][ T261] nodev proc
[ 44.261399][ T261]
To reproduce:
# build kernel
cd linux
cp config-5.14.0-rc3-00020-gd792962d3d4f .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
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
---
0DAY/LKP+ Test Infrastructure Open Source Technology Center
https://lists.01.org/hyperkitty/list/lkp@lists.01.org Intel Corporation
Thanks,
Oliver Sang