Date:   Thu, 4 Nov 2021 22:38:09 +0800
From:   kernel test robot <oliver.sang@...el.com>
To:     Nicolas Saenz Julienne <nsaenzju@...hat.com>
Cc:     lkp@...ts.01.org, lkp@...el.com, akpm@...ux-foundation.org,
        linux-kernel@...r.kernel.org, linux-mm@...ck.org,
        frederic@...nel.org, tglx@...utronix.de, peterz@...radead.org,
        mtosatti@...hat.com, nilal@...hat.com, mgorman@...e.de,
        linux-rt-users@...r.kernel.org, vbabka@...e.cz, cl@...ux.com,
        ppandit@...hat.com, Nicolas Saenz Julienne <nsaenzju@...hat.com>
Subject: [mm/page_alloc]  5541e53659: BUG:spinlock_bad_magic_on_CPU



Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 5541e5365954069e4c7b649831c0e41bc9e5e081 ("[PATCH v2 2/3] mm/page_alloc: Convert per-cpu lists' local locks to per-cpu spin locks")
url: https://github.com/0day-ci/linux/commits/Nicolas-Saenz-Julienne/mm-page_alloc-Remote-per-cpu-page-list-drain-support/20211104-010825
base: https://github.com/hnaz/linux-mm master
patch link: https://lore.kernel.org/lkml/20211103170512.2745765-3-nsaenzju@redhat.com

in testcase: boot

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):


+--------------------------------------------+------------+------------+
|                                            | 69c421f2b4 | 5541e53659 |
+--------------------------------------------+------------+------------+
| boot_successes                             | 11         | 0          |
| boot_failures                              | 0          | 11         |
| BUG:spinlock_bad_magic_on_CPU              | 0          | 11         |
| BUG:using_smp_processor_id()in_preemptible | 0          | 11         |
+--------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <oliver.sang@...el.com>


[    0.161872][    T0] BUG: spinlock bad magic on CPU#0, swapper/0
[    0.162248][    T0]  lock: 0xeb24bef0, .magic: 00000000, .owner: swapper/0, .owner_cpu: 0
[    0.162767][    T0] CPU: 0 PID: 0 Comm: swapper Not tainted 5.15.0-rc7-mm1-00437-g5541e5365954 #1
[    0.163325][    T0] Call Trace:
[ 0.163524][ T0] dump_stack_lvl (lib/dump_stack.c:107 (discriminator 4)) 
[ 0.163802][ T0] dump_stack (lib/dump_stack.c:114) 
[ 0.164050][ T0] spin_bug (kernel/locking/spinlock_debug.c:70 kernel/locking/spinlock_debug.c:77) 
[ 0.164296][ T0] do_raw_spin_unlock (arch/x86/include/asm/atomic.h:29 include/linux/atomic/atomic-instrumented.h:28 include/asm-generic/qspinlock.h:28 kernel/locking/spinlock_debug.c:100 kernel/locking/spinlock_debug.c:140) 
[ 0.164624][ T0] _raw_spin_unlock_irqrestore (include/linux/spinlock_api_smp.h:160 kernel/locking/spinlock.c:194) 
[ 0.164971][ T0] free_unref_page (include/linux/spinlock.h:423 mm/page_alloc.c:3400) 
[ 0.165253][ T0] free_the_page (mm/page_alloc.c:699) 
[ 0.165521][ T0] __free_pages (mm/page_alloc.c:5453) 
[ 0.165785][ T0] add_highpages_with_active_regions (include/linux/mm.h:2511 arch/x86/mm/init_32.c:416) 
[ 0.166179][ T0] set_highmem_pages_init (arch/x86/mm/highmem_32.c:30) 
[ 0.166501][ T0] mem_init (arch/x86/mm/init_32.c:749 (discriminator 2)) 
[ 0.166749][ T0] start_kernel (init/main.c:842 init/main.c:988) 
[ 0.167026][ T0] ? early_idt_handler_common (arch/x86/kernel/head_32.S:417) 
[ 0.167369][ T0] i386_start_kernel (arch/x86/kernel/head32.c:57) 
[ 0.167662][ T0] startup_32_smp (arch/x86/kernel/head_32.S:328) 
[    1.272601][    T0] Initializing Movable for node 0 (00000000:00000000)
[    1.563704][    T0] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    1.564312][    T0] Memory: 2895940K/3145208K available (8028K kernel code, 4874K rwdata, 4088K rodata, 2016K init, 8452K bss, 249268K reserved, 0K cma-reserved, 2252680K highmem)
[ 1.565333][ T0] random: get_random_u32 called from __kmem_cache_create+0x13/0x3b8 with crng_init=0 
[    1.565532][    T0] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    1.566585][    T0] Stack Depot allocating hash table with kvmalloc
[    1.567566][    T0] Node 0, zone      DMA: page owner found early allocated 0 pages
[    1.569258][    T0] Node 0, zone   Normal: page owner found early allocated 1057 pages
[    1.574666][    T0] Node 0, zone  HighMem: page owner found early allocated 0 pages
[    1.575421][    T0] ODEBUG: selftest passed
[    1.575737][    T0] trace event string verifier disabled
[    1.576126][    T0] Dynamic Preempt: none
[    1.576450][    T0] Running RCU self tests
[    1.576727][    T0] rcu: Preemptible hierarchical RCU implementation.
[    1.577149][    T0] rcu: 	RCU event tracing is enabled.
[    1.577483][    T0] rcu: 	RCU lockdep checking is enabled.
[    1.577833][    T0] rcu: 	RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=2.
[    1.578294][    T0] rcu: 	RCU callback double-/use-after-free debug enabled.
[    1.578744][    T0] rcu: 	RCU debug extended QS entry/exit.
[    1.579100][    T0] 	RCU CPU stall warnings timeout set to 100 (rcu_cpu_stall_timeout).
[    1.579611][    T0] 	Trampoline variant of Tasks RCU enabled.
[    1.579978][    T0] 	Rude variant of Tasks RCU enabled.
[    1.580311][    T0] 	Tracing variant of Tasks RCU enabled.
[    1.580666][    T0] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    1.581199][    T0] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
[    1.583788][    T0] NR_IRQS: 2304, nr_irqs: 56, preallocated irqs: 16
[    1.584542][    T0] kfence: initialized - using 2097152 bytes for 255 objects at 0x(ptrval)-0x(ptrval)
[    1.585258][    T0] printk: console [ttyS0] enabled
[    1.585891][    T0] printk: bootconsole [earlyser0] disabled
[    1.586621][    T0] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    1.587173][    T0] ... MAX_LOCKDEP_SUBCLASSES:  8
[    1.587491][    T0] ... MAX_LOCK_DEPTH:          48
[    1.587814][    T0] ... MAX_LOCKDEP_KEYS:        8192
[    1.588146][    T0] ... CLASSHASH_SIZE:          4096
[    1.588477][    T0] ... MAX_LOCKDEP_ENTRIES:     32768
[    1.588821][    T0] ... MAX_LOCKDEP_CHAINS:      65536
[    1.589167][    T0] ... CHAINHASH_SIZE:          32768
[    1.589504][    T0]  memory used by lock dependency info: 4061 kB
[    1.589904][    T0]  memory used for stack traces: 2112 kB
[    1.590264][    T0]  per task-struct memory footprint: 2112 bytes
[    1.590671][    T0] ACPI: Core revision 20210930
[    1.591135][    T0] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    1.591886][    T0] APIC: Switch to symmetric I/O mode setup
[    1.592284][    T0] Enabling APIC mode:  Flat.  Using 1 I/O APICs
[    1.592710][    T0] masked ExtINT on CPU#0
[    1.593593][    T0] ENABLING IO-APIC IRQs
[    1.593859][    T0] init IO_APIC IRQs
[    1.594227][    T0]  apic 0 pin 0 not connected
[    1.594688][    T0] IOAPIC[0]: Preconfigured routing entry (0-1 -> IRQ 1 Level:0 ActiveLow:0)
[    1.595534][    T0] IOAPIC[0]: Preconfigured routing entry (0-2 -> IRQ 0 Level:0 ActiveLow:0)
[    1.596221][    T0] IOAPIC[0]: Preconfigured routing entry (0-3 -> IRQ 3 Level:0 ActiveLow:0)
[    1.596774][    T0] IOAPIC[0]: Preconfigured routing entry (0-4 -> IRQ 4 Level:0 ActiveLow:0)
[    1.597320][    T0] IOAPIC[0]: Preconfigured routing entry (0-5 -> IRQ 5 Level:1 ActiveLow:0)
[    1.597865][    T0] IOAPIC[0]: Preconfigured routing entry (0-6 -> IRQ 6 Level:0 ActiveLow:0)
[    1.598409][    T0] IOAPIC[0]: Preconfigured routing entry (0-7 -> IRQ 7 Level:0 ActiveLow:0)
[    1.598954][    T0] IOAPIC[0]: Preconfigured routing entry (0-8 -> IRQ 8 Level:0 ActiveLow:0)
[    1.599498][    T0] IOAPIC[0]: Preconfigured routing entry (0-9 -> IRQ 9 Level:1 ActiveLow:0)
[    1.600052][    T0] IOAPIC[0]: Preconfigured routing entry (0-10 -> IRQ 10 Level:1 ActiveLow:0)
[    1.600618][    T0] IOAPIC[0]: Preconfigured routing entry (0-11 -> IRQ 11 Level:1 ActiveLow:0)
[    1.601195][    T0] IOAPIC[0]: Preconfigured routing entry (0-12 -> IRQ 12 Level:0 ActiveLow:0)
[    1.601760][    T0] IOAPIC[0]: Preconfigured routing entry (0-13 -> IRQ 13 Level:0 ActiveLow:0)
[    1.602312][    T0] IOAPIC[0]: Preconfigured routing entry (0-14 -> IRQ 14 Level:0 ActiveLow:0)
[    1.602865][    T0] IOAPIC[0]: Preconfigured routing entry (0-15 -> IRQ 15 Level:0 ActiveLow:0)
[    1.603415][    T0]  apic 0 pin 16 not connected
[    1.603712][    T0]  apic 0 pin 17 not connected
[    1.604020][    T0]  apic 0 pin 18 not connected
[    1.604316][    T0]  apic 0 pin 19 not connected
[    1.604617][    T0]  apic 0 pin 20 not connected
[    1.604922][    T0]  apic 0 pin 21 not connected
[    1.605219][    T0]  apic 0 pin 22 not connected
[    1.605516][    T0]  apic 0 pin 23 not connected
[    1.605913][    T0] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    1.606361][    T0] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x1fa3704c1a9, max_idle_ns: 440795296692 ns
[    1.607077][    T0] Calibrating delay loop (skipped) preset value.. 4389.83 BogoMIPS (lpj=8779664)
[    1.607658][    T0] pid_max: default: 4096 minimum: 301
[    1.611130][    T0] LSM: Security Framework initializing
[    1.611497][    T0] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    1.613263][    T0] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    1.615945][    T0] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    1.616341][    T0] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    1.616763][    T0] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    1.617348][    T0] Spectre V2 : Spectre mitigation: kernel not compiled with retpoline; no mitigation available!
[    1.617350][    T0] Speculative Store Bypass: Vulnerable
[    1.618335][    T0] L1TF: Kernel not compiled for PAE. No mitigation for L1TF
[    1.618788][    T0] MDS: Vulnerable: Clear CPU buffers attempted, no microcode
[    1.619423][    T0] Freeing SMP alternatives memory: 16K
[    1.619943][    T1] smpboot: CPU0: Intel Xeon E312xx (Sandy Bridge) (family: 0x6, model: 0x2a, stepping: 0x1)


To reproduce:

        # build kernel
	cd linux
	cp config-5.15.0-rc7-mm1-00437-g5541e5365954 .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


View attachment "config-5.15.0-rc7-mm1-00437-g5541e5365954" of type "text/plain" (127969 bytes)

View attachment "job-script" of type "text/plain" (4885 bytes)

Download attachment "dmesg.xz" of type "application/x-xz" (23060 bytes)

Powered by blists - more mailing lists