Re: [mm/debug_vm_pgtable] 5b79c4a146: initcall_debug_vm_pgtable_returned_with_preemption_imbalance

[Gavin Shan]

Hi Oliver,

On 7/26/21 5:19 PM, kernel test robot wrote:
> Greeting,
>
> FYI, we noticed the following commit (built with gcc-10):
>
> commit: 5b79c4a1469bcc5793a361ef57d5d2e2393cabcc ("mm/debug_vm_pgtable: introduce struct pgtable_debug_args")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
>
>
> in testcase: locktorture
> version:
> with following parameters:
>
> 	runtime: 300s
> 	test: cpuhotplug
>
> test-description: This torture test consists of creating a number of kernel threads which acquire the lock and hold it for specific amount of time, thus simulating different critical region behaviors.
> test-url: https://www.kernel.org/doc/Documentation/locking/locktorture.txt
>
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> +--------------------------------------------------------------+------------+------------+
> |                                                              | a9aac8ea55 | 5b79c4a146 |
> +--------------------------------------------------------------+------------+------------+
> | initcall_debug_vm_pgtable_returned_with_preemption_imbalance | 0          | 6          |
> | WARNING:at_init/main.c:#do_one_initcall                      | 0          | 6          |
> | EIP:do_one_initcall                                          | 0          | 6          |
> | Kernel_panic-not_syncing:No_working_init_found               | 0          | 6          |
> +--------------------------------------------------------------+------------+------------+
>
>
> If you fix the issue, kindly add following tag
> Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
>
>
> [   38.527560][    T1] ------------[ cut here ]------------
> [   38.528444][    T1] initcall debug_vm_pgtable+0x0/0x3cd returned with preemption imbalance
> [   38.529965][    T1] WARNING: CPU: 0 PID: 1 at init/main.c:1295 do_one_initcall+0x227/0x2c0
> [   38.531240][    T1] Modules linked in:
> [   38.531871][    T1] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.14.0-rc2-00027-g5b79c4a1469b #1 a0a7f3ec31aa9416e222f7109d2330341e30c9
> 4a
> [   38.533875][    T1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
> [   38.535237][    T1] EIP: do_one_initcall+0x227/0x2c0
> [   38.536044][    T1] Code: 64 ff 0d 0c 67 ab c3 0f 85 2d fe ff ff e8 69 4a 6a 01 e9 23 fe ff ff 8d 74 26 00 8d 45 b4 50 56 68 5c 2a 06 c3 e8 6d ce 58 0
> 1 <0f> 0b 83 c4 0c e9 64 fe ff ff 8d b4 26 00 00 00 00 64 a1 5c 14 ab
> [   38.538745][    T1] EAX: 00000047 EBX: 00000000 ECX: 00000000 EDX: 00000001
> [   38.539813][    T1] ESI: c39a68f4 EDI: 00000000 EBP: c4d47f74 ESP: c4d47f1c
> [   38.540841][    T1] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010296
> [   38.542035][    T1] CR0: 80050033 CR2: b7dcbbf0 CR3: 03ad9000 CR4: 000406d0
> [   38.543178][    T1] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [   38.544210][    T1] DR6: fffe0ff0 DR7: 00000400
> [   38.544931][    T1] Call Trace:
> [   38.545505][    T1]  ? pmd_advanced_tests+0x14d/0x14d
> [   38.546318][    T1]  ? lock_is_held_type+0xc6/0x120
> [   38.547089][    T1]  ? rcu_read_lock_sched_held+0x41/0x80
> [   38.547929][    T1]  do_initcalls+0xf9/0x11b
> [   38.548631][    T1]  kernel_init_freeable+0xc5/0xf4
> [   38.549427][    T1]  ? rest_init+0x260/0x260
> [   38.550123][    T1]  kernel_init+0x17/0xf0
> [   38.550804][    T1]  ret_from_fork+0x1c/0x30
> [   38.551499][    T1] irq event stamp: 16309295
> [   38.552220][    T1] hardirqs last  enabled at (16309305): [<c10e8f1e>] console_unlock+0x27e/0x3b0
> [   38.553556][    T1] hardirqs last disabled at (16309312): [<c10e8fa5>] console_unlock+0x305/0x3b0
> [   38.554902][    T1] softirqs last  enabled at (16309200): [<c26a5060>] __do_softirq+0x2f0/0x4fa
> [   38.556235][    T1] softirqs last disabled at (16309091): [<c102a885>] call_on_stack+0x45/0x50
> [   38.557543][    T1] ---[ end trace 0025ffb206fe1364 ]---

I'm not sure if this issue is 100% reproducible, but I failed to reproduce it locally
with gcc-8 and gcc-10 with linux-next and the provided kernel configuration. Actually,
there is another warning before this one, as below. It seems the imbalanced preemption
count is caused by mm/debug_vm_pgtable.c::init_args(). However, I would image the
imbalanced preemption count is actually caused by IRQ handler. The interrupt should
be enabled when the init call is executed. If the imbalanced preemption count is
really caused by interrupt handler, it should happen randomly. Could you help to
check if the same warning is reported at various (initcall) spots?

[   38.485968][    T1] .................................... done.
[   38.493971][    T1] sched_clock: Marking stable (38371289248, 120817128)->(38516398292, -24291916)
[   38.497414][    T1] Loading compiled-in X.509 certificates
[   38.498374][    T1] debug_vm_pgtable: [debug_vm_pgtable         ]: Validating architecture page table helpers
[   38.499940][    T1] BUG: sleeping function called from invalid context at mm/page_alloc.c:5170
[   38.501254][    T1] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 1, name: swapper/0
[   38.502577][    T1] no locks held by swapper/0/1.
[   38.503322][    T1] Preemption disabled at:
[   38.503326][    T1] [<c259c408>] kmap_atomic+0x1d/0x36
[   38.504814][    T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.14.0-rc2-00027-g5b79c4a1469b #1 a0a7f3ec31aa9416e222f7109d2330341e30c94a
[   38.506561][    T1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[   38.507922][    T1] Call Trace:
[   38.508478][    T1]  ? show_stack+0x3c/0x44
[   38.509160][    T1]  dump_stack_lvl+0x44/0x57
[   38.509880][    T1]  dump_stack+0xd/0x10
[   38.510555][    T1]  ___might_sleep.cold+0xec/0xfd
[   38.511307][    T1]  ? kmap_atomic+0x1d/0x36
[   38.512001][    T1]  __might_sleep+0x32/0x80
[   38.512703][    T1]  __alloc_pages+0x199/0x2d0
[   38.513414][    T1]  ? pmd_advanced_tests+0x14d/0x14d
[   38.514209][    T1]  init_args+0x1c2/0x214
[   38.514884][    T1]  debug_vm_pgtable+0x25/0x3cd
[   38.515614][    T1]  ? __debugfs_create_file+0x102/0x180
[   38.516423][    T1]  ? __debugfs_create_file+0x102/0x180
[   38.517222][    T1]  ? __this_cpu_preempt_check+0xf/0x11
[   38.518030][    T1]  ? lock_release+0x71/0x150
[   38.518756][    T1]  ? pmd_advanced_tests+0x14d/0x14d
[   38.519550][    T1]  do_one_initcall+0x4f/0x2c0
[   38.520266][    T1]  ? __this_cpu_preempt_check+0xf/0x11
[   38.521058][    T1]  ? lock_is_held_type+0xc6/0x120
[   38.521818][    T1]  ? rcu_read_lock_sched_held+0x41/0x80
[   38.522639][    T1]  do_initcalls+0xf9/0x11b
[   38.523319][    T1]  kernel_init_freeable+0xc5/0xf4
[   38.524071][    T1]  ? rest_init+0x260/0x260
[   38.524753][    T1]  kernel_init+0x17/0xf0
[   38.525424][    T1]  ret_from_fork+0x1c/0x30
[   38.527560][    T1] ------------[ cut here ]------------

> To reproduce:
>
>          # build kernel
> 	cd linux
> 	cp config-5.14.0-rc2-00027-g5b79c4a1469b .config
> 	make HOSTCC=gcc-10 CC=gcc-10 ARCH=i386 olddefconfig prepare modules_prepare bzImage modules
> 	make HOSTCC=gcc-10 CC=gcc-10 ARCH=i386 INSTALL_MOD_PATH=<mod-install-dir> modules_install
> 	cd <mod-install-dir>
> 	find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
>
>
>          git clone https://github.com/intel/lkp-tests.git
>          cd lkp-tests
>          bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email

[...]

Thanks,
Gavin