Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: 08cb589cb3d2dd9029191135b52ef229e8dcd7ae ("mm/debug_vm_pgtable: introduce struct pgtable_debug_args")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
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):
+----------------------------------------------------------------------+------------+------------+
| | 35c5405269 | 08cb589cb3 |
+----------------------------------------------------------------------+------------+------------+
| boot_successes | 20 | 0 |
| boot_failures | 0 | 18 |
| BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c | 0 | 18 |
| initcall_debug_vm_pgtable_returned_with_preemption_imbalance | 0 | 18 |
| WARNING:at_init/main.c:#do_one_initcall | 0 | 18 |
| EIP:do_one_initcall | 0 | 18 |
| Kernel_panic-not_syncing:No_working_init_found | 0 | 18 |
+----------------------------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
[ 9.433105][ T1] BUG: sleeping function called from invalid context at mm/page_alloc.c:5170
[ 9.434513][ T1] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 1, name: swapper/0
[ 9.436116][ T1] no locks held by swapper/0/1.
[ 9.436923][ T1] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 5.14.0-rc4-00161-g08cb589cb3d2 #1
[ 9.438398][ T1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 9.439880][ T1] Call Trace:
[ 9.440404][ T1] ? dump_stack_lvl (lib/dump_stack.c:106)
[ 9.441154][ T1] ? dump_stack (lib/dump_stack.c:113)
[ 9.441827][ T1] ? ___might_sleep.cold (kernel/sched/core.c:9155)
[ 9.442645][ T1] ? __might_sleep (kernel/sched/core.c:9109 (discriminator 14))
[ 9.444795][ T1] ? __alloc_pages (include/linux/kernel.h:104 mm/page_alloc.c:5170 mm/page_alloc.c:5380)
[ 9.445583][ T1] ? mem_encrypt_init+0x1/0x1
[ 9.446389][ T1] ? destroy_args (mm/debug_vm_pgtable.c:1219)
[ 9.447193][ T1] ? debug_vm_pgtable (mm/debug_vm_pgtable.c:1208 mm/debug_vm_pgtable.c:1237)
[ 9.448076][ T1] ? destroy_args (mm/debug_vm_pgtable.c:1219)
[ 9.448863][ T1] ? do_one_initcall (init/main.c:1282)
[ 9.449676][ T1] ? parse_args (kernel/params.c:190)
[ 9.450470][ T1] ? kernel_init_freeable (init/main.c:1354 init/main.c:1371 init/main.c:1390 init/main.c:1592)
[ 9.451358][ T1] ? rest_init (init/main.c:1476)
[ 9.452063][ T1] ? kernel_init (init/main.c:1486)
[ 9.452759][ T1] ? ret_from_fork (arch/x86/entry/entry_32.S:775)
[ 9.453815][ T1] ------------[ cut here ]------------
[ 9.454758][ T1] initcall debug_vm_pgtable+0x0/0x77f returned with preemption imbalance
[ 9.456186][ T1] WARNING: CPU: 1 PID: 1 at init/main.c:1295 do_one_initcall (init/main.c:1295 (discriminator 1))
[ 9.457445][ T1] Modules linked in:
[ 9.458090][ T1] CPU: 1 PID: 1 Comm: swapper/0 Tainted: G W 5.14.0-rc4-00161-g08cb589cb3d2 #1
[ 9.459706][ T1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 9.461171][ T1] EIP: do_one_initcall (init/main.c:1295 (discriminator 1))
[ 9.462000][ T1] Code: 50 82 c4 41 c6 05 e4 18 21 42 01 e8 30 5e 8a 00 e9 4b ff ff ff 8d b6 00 00 00 00 8d 45 b0 50 56 68 94 85 c4 41 e8 a0 2b 8a 00 <0f> 0b 83 c4 0c e9 3b fe ff ff 8d b4 26 00 00 00 00 0f 0b e9 c4 fd
All code
========
0: 50 push %rax
1: 82 (bad)
2: c4 41 c6 05 (bad)
6: e4 18 in $0x18,%al
8: 21 42 01 and %eax,0x1(%rdx)
b: e8 30 5e 8a 00 callq 0x8a5e40
10: e9 4b ff ff ff jmpq 0xffffffffffffff60
15: 8d b6 00 00 00 00 lea 0x0(%rsi),%esi
1b: 8d 45 b0 lea -0x50(%rbp),%eax
1e: 50 push %rax
1f: 56 push %rsi
20: 68 94 85 c4 41 pushq $0x41c48594
25: e8 a0 2b 8a 00 callq 0x8a2bca
2a:* 0f 0b ud2 <-- trapping instruction
2c: 83 c4 0c add $0xc,%esp
2f: e9 3b fe ff ff jmpq 0xfffffffffffffe6f
34: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi
3b: 0f 0b ud2
3d: e9 .byte 0xe9
3e: c4 .byte 0xc4
3f: fd std
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 83 c4 0c add $0xc,%esp
5: e9 3b fe ff ff jmpq 0xfffffffffffffe45
a: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi
11: 0f 0b ud2
13: e9 .byte 0xe9
14: c4 .byte 0xc4
15: fd std
[ 9.465300][ T1] EAX: 00000047 EBX: 00000000 ECX: 00000000 EDX: 00000000
[ 9.466578][ T1] ESI: 4227f12d EDI: 00000000 EBP: 4308bf80 ESP: 4308bf24
[ 9.467690][ T1] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010202
[ 9.468863][ T1] CR0: 80050033 CR2: 00000000 CR3: 02452000 CR4: 000006d0
[ 9.469987][ T1] Call Trace:
[ 9.470526][ T1] ? destroy_args (mm/debug_vm_pgtable.c:1219)
[ 9.471286][ T1] ? kernel_init_freeable (init/main.c:1354 init/main.c:1371 init/main.c:1390 init/main.c:1592)
[ 9.472186][ T1] ? rest_init (init/main.c:1476)
[ 9.472928][ T1] ? kernel_init (init/main.c:1486)
[ 9.473670][ T1] ? ret_from_fork (arch/x86/entry/entry_32.S:775)
[ 9.474474][ T1] irq event stamp: 691587
[ 9.475423][ T1] hardirqs last enabled at (691599): finish_task_switch (arch/x86/include/asm/irqflags.h:45 arch/x86/include/asm/irqflags.h:80 kernel/sched/sched.h:1319 kernel/sched/core.c:4437 kernel/sched/core.c:4555)
[ 9.476972][ T1] hardirqs last disabled at (691606): console_unlock (kernel/printk/printk.c:2589 (discriminator 1))
[ 9.478454][ T1] softirqs last enabled at (691504): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:402 kernel/softirq.c:587)
[ 9.483939][ T1] softirqs last disabled at (691471): do_softirq_own_stack (arch/x86/kernel/irq_32.c:60 arch/x86/kernel/irq_32.c:149)
[ 9.485605][ T1] ---[ end trace 3b56d1453479e08a ]---
[ 9.486758][ T1] Key type ._fscrypt registered
[ 9.487526][ T1] Key type .fscrypt registered
[ 9.488258][ T1] Key type fscrypt-provisioning registered
[ 9.489550][ T1] fs-verity: Initialized fs-verity
[ 9.493326][ T1] RAS: Correctable Errors collector initialized.
[ 9.515841][ T83] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 9.525083][ T83] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 9.558690][ T1] Sending DHCP requests ., OK
[ 9.596038][ T1] IP-Config: Got DHCP answer from 10.0.2.2, my address is 10.0.2.15
[ 9.597328][ T1] IP-Config: Complete:
[ 9.598008][ T1] device=eth0, hwaddr=52:54:00:12:34:56, ipaddr=10.0.2.15, mask=255.255.255.0, gw=10.0.2.2
[ 9.599711][ T1] host=vm-snb-i386-39, domain=, nis-domain=(none)
[ 9.600844][ T1] bootserver=10.0.2.2, rootserver=10.0.2.2, rootpath=
[ 9.600851][ T1] nameserver0=10.0.2.3
[ 9.608935][ T1] Freeing unused kernel image (initmem) memory: 1980K
[ 9.645491][ T1] Write protecting kernel text and read-only data: 13960k
[ 9.646776][ T1] rodata_test: all tests were successful
[ 9.685428][ T1] Run /init as init process
[ 9.686248][ T1] with arguments:
[ 9.686919][ T1] /init
[ 9.687400][ T1] with environment:
[ 9.688043][ T1] HOME=/
[ 9.688564][ T1] TERM=linux
[ 9.689125][ T1] user=lkp
[ 9.689639][ T1] job=/lkp/jobs/scheduled/vm-snb-i386-39/boot-300-quantal-i386-core-20190426.cgz-08cb589cb3d2dd9029191135b52ef229e8dcd7ae-20210808-22832-1nqlo1e-0.yaml
[ 9.692088][ T1] ARCH=i386
[ 9.692653][ T1] kconfig=i386-randconfig-a014-20210804
[ 9.693604][ T1] branch=linux-devel/devel-catchup-20210807-115448
[ 9.694715][ T1] commit=08cb589cb3d2dd9029191135b52ef229e8dcd7ae
[ 9.696167][ T1] BOOT_IMAGE=/pkg/linux/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/vmlinuz-5.14.0-rc4-00161-g08cb589cb3d2
[ 9.698710][ T1] max_uptime=600
[ 9.699390][ T1] RESULT_ROOT=/result/boot/300/vm-snb-i386/quantal-i386-core-20190426.cgz/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/3
[ 9.702014][ T1] LKP_SERVER=internal-lkp-server
[ 9.711118][ T1] selinux=0
[ 9.711695][ T1] softlockup_panic=1
[ 9.712361][ T1] prompt_ramdisk=0
[ 9.713011][ T1] vga=normal
[ 9.714007][ T1] Failed to execute /init (error -14)
[ 9.715082][ T1] Run /sbin/init as init process
[ 9.715954][ T1] with arguments:
[ 9.716630][ T1] /sbin/init
[ 9.717250][ T1] with environment:
[ 9.717992][ T1] HOME=/
[ 9.718561][ T1] TERM=linux
[ 9.719146][ T1] user=lkp
[ 9.719691][ T1] job=/lkp/jobs/scheduled/vm-snb-i386-39/boot-300-quantal-i386-core-20190426.cgz-08cb589cb3d2dd9029191135b52ef229e8dcd7ae-20210808-22832-1nqlo1e-0.yaml
[ 9.722176][ T1] ARCH=i386
[ 9.722731][ T1] kconfig=i386-randconfig-a014-20210804
[ 9.723691][ T1] branch=linux-devel/devel-catchup-20210807-115448
[ 9.724867][ T1] commit=08cb589cb3d2dd9029191135b52ef229e8dcd7ae
[ 9.726373][ T1] BOOT_IMAGE=/pkg/linux/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/vmlinuz-5.14.0-rc4-00161-g08cb589cb3d2
[ 9.728994][ T1] max_uptime=600
[ 9.729657][ T1] RESULT_ROOT=/result/boot/300/vm-snb-i386/quantal-i386-core-20190426.cgz/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/3
[ 9.732482][ T1] LKP_SERVER=internal-lkp-server
[ 9.733399][ T1] selinux=0
[ 9.733996][ T1] softlockup_panic=1
[ 9.734732][ T1] prompt_ramdisk=0
[ 9.735457][ T1] vga=normal
[ 9.736394][ T1] Starting init: /sbin/init exists but couldn't execute it (error -14)
[ 9.737739][ T1] Run /etc/init as init process
[ 9.738543][ T1] with arguments:
[ 9.739148][ T1] /etc/init
[ 9.739701][ T1] with environment:
[ 9.740337][ T1] HOME=/
[ 9.740855][ T1] TERM=linux
[ 9.741433][ T1] user=lkp
[ 9.741970][ T1] job=/lkp/jobs/scheduled/vm-snb-i386-39/boot-300-quantal-i386-core-20190426.cgz-08cb589cb3d2dd9029191135b52ef229e8dcd7ae-20210808-22832-1nqlo1e-0.yaml
[ 9.744425][ T1] ARCH=i386
[ 9.745124][ T1] kconfig=i386-randconfig-a014-20210804
[ 9.746079][ T1] branch=linux-devel/devel-catchup-20210807-115448
[ 9.747230][ T1] commit=08cb589cb3d2dd9029191135b52ef229e8dcd7ae
[ 9.748302][ T1] BOOT_IMAGE=/pkg/linux/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/vmlinuz-5.14.0-rc4-00161-g08cb589cb3d2
[ 9.750873][ T1] max_uptime=600
[ 9.751480][ T1] RESULT_ROOT=/result/boot/300/vm-snb-i386/quantal-i386-core-20190426.cgz/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/3
[ 9.753917][ T1] LKP_SERVER=internal-lkp-server
[ 9.754729][ T1] selinux=0
[ 9.755430][ T1] softlockup_panic=1
[ 9.756144][ T1] prompt_ramdisk=0
[ 9.756800][ T1] vga=normal
[ 9.757516][ T1] Starting init: /etc/init exists but couldn't execute it (error -13)
[ 9.758892][ T1] Run /bin/init as init process
[ 9.759623][ T1] with arguments:
[ 9.760214][ T1] /bin/init
[ 9.760786][ T1] with environment:
[ 9.761438][ T1] HOME=/
[ 9.761950][ T1] TERM=linux
[ 9.762520][ T1] user=lkp
[ 9.763099][ T1] job=/lkp/jobs/scheduled/vm-snb-i386-39/boot-300-quantal-i386-core-20190426.cgz-08cb589cb3d2dd9029191135b52ef229e8dcd7ae-20210808-22832-1nqlo1e-0.yaml
[ 9.765918][ T1] ARCH=i386
[ 9.766460][ T1] kconfig=i386-randconfig-a014-20210804
[ 9.767445][ T1] branch=linux-devel/devel-catchup-20210807-115448
[ 9.768522][ T1] commit=08cb589cb3d2dd9029191135b52ef229e8dcd7ae
[ 9.769590][ T1] BOOT_IMAGE=/pkg/linux/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/vmlinuz-5.14.0-rc4-00161-g08cb589cb3d2
[ 9.771938][ T1] max_uptime=600
[ 9.772617][ T1] RESULT_ROOT=/result/boot/300/vm-snb-i386/quantal-i386-core-20190426.cgz/i386-randconfig-a014-20210804/gcc-9/08cb589cb3d2dd9029191135b52ef229e8dcd7ae/3
[ 9.775497][ T1] LKP_SERVER=internal-lkp-server
To reproduce:
# build kernel
cd linux
cp config-5.14.0-rc4-00161-g08cb589cb3d2 .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
On 8/9/21 12:25 AM, kernel test robot wrote:
>
[...]
>
> [ 9.433105][ T1] BUG: sleeping function called from invalid context at mm/page_alloc.c:5170
> [ 9.434513][ T1] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 1, name: swapper/0
> [ 9.436116][ T1] no locks held by swapper/0/1.
> [ 9.436923][ T1] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 5.14.0-rc4-00161-g08cb589cb3d2 #1
> [ 9.438398][ T1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
> [ 9.439880][ T1] Call Trace:
> [ 9.440404][ T1] ? dump_stack_lvl (lib/dump_stack.c:106)
> [ 9.441154][ T1] ? dump_stack (lib/dump_stack.c:113)
> [ 9.441827][ T1] ? ___might_sleep.cold (kernel/sched/core.c:9155)
> [ 9.442645][ T1] ? __might_sleep (kernel/sched/core.c:9109 (discriminator 14))
> [ 9.444795][ T1] ? __alloc_pages (include/linux/kernel.h:104 mm/page_alloc.c:5170 mm/page_alloc.c:5380)
> [ 9.445583][ T1] ? mem_encrypt_init+0x1/0x1
> [ 9.446389][ T1] ? destroy_args (mm/debug_vm_pgtable.c:1219)
> [ 9.447193][ T1] ? debug_vm_pgtable (mm/debug_vm_pgtable.c:1208 mm/debug_vm_pgtable.c:1237)
> [ 9.448076][ T1] ? destroy_args (mm/debug_vm_pgtable.c:1219)
> [ 9.448863][ T1] ? do_one_initcall (init/main.c:1282)
> [ 9.449676][ T1] ? parse_args (kernel/params.c:190)
> [ 9.450470][ T1] ? kernel_init_freeable (init/main.c:1354 init/main.c:1371 init/main.c:1390 init/main.c:1592)
> [ 9.451358][ T1] ? rest_init (init/main.c:1476)
> [ 9.452063][ T1] ? kernel_init (init/main.c:1486)
> [ 9.452759][ T1] ? ret_from_fork (arch/x86/entry/entry_32.S:775)
> [ 9.453815][ T1] ------------[ cut here ]------------
[...]
Thanks for reporting the issue. The same issue was reported against v4 series before,
but this time, it's raised on v5 series. Fortunately, this report provides more useful
information so that I can reproduce the issue locally and I'm going to fix the issue
in v6 since I need to address Anshuman's last comment on v5.
As to the root cause, pte_alloc_map() is used in init_args(). The PTE entry is mapped
in atomic mode when CONFIG_HIGHPTE is enabled on i386. It means GFP_KERNEL isn't right
option to be used by alloc_pages() in init_args(). The fix is use pte_alloc() to replace
pte_alloc_map() and args->pte will be mapped when it's used in debug_vm_pgtable() for
PTE modifying tests. We need avoid atomic context lasting for too long.
Thanks,
Gavin