Re: [locking/qspinlock] 45877ea393: BUG:spinlock_already_unlocked_on_CPU

[Waiman Long]

On 7/17/20 3:39 AM, kernel test robot wrote:
> Greeting,
>
> FYI, we noticed the following commit (built with gcc-9):
>
> commit: 45877ea3934b977dd4fd9fa8b4b7e9a2a8925d38 ("[PATCH v2 4/5] locking/qspinlock: Make qspinhlock store lock holder cpu number")
> url: https://github.com/0day-ci/linux/commits/Waiman-Long/x86-locking-qspinlock-Allow-lock-to-store-lock-holder-cpu-number/20200717-033319
> base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git f9ad4a5f3f20bee022b1bdde94e5ece6dc0b0edc
>
> 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-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> +--------------------------------------+------------+------------+
> |                                      | a104f8329b | 45877ea393 |
> +--------------------------------------+------------+------------+
> | boot_successes                       | 6          | 0          |
> | boot_failures                        | 0          | 8          |
> | BUG:spinlock_already_unlocked_on_CPU | 0          | 8          |
> +--------------------------------------+------------+------------+
>
>
> If you fix the issue, kindly add following tag
> Reported-by: kernel test robot <lkp@xxxxxxxxx>
>
>
> [    0.174207] BUG: spinlock already unlocked on CPU#0, swapper/0
> [    0.174208]  lock: logbuf_lock+0x0/0x40, .magic: dead4ead, .owner: swapper/0, .owner_cpu: 0
> [    0.174209] CPU: 0 PID: 0 Comm: swapper Not tainted 5.8.0-rc4-00016-g45877ea3934b9 #1
> [    0.174210] Call Trace:
> [    0.174210]  ? dump_stack+0x96/0xd0
> [    0.174211]  ? do_raw_spin_unlock+0x81/0xc0
> [    0.174211]  ? _raw_spin_unlock+0x1f/0x40
> [    0.174212]  ? vprintk_emit+0x141/0x370
> [    0.174212]  ? printk+0x58/0x6f
> [    0.174213]  ? start_kernel+0x60/0x664
> [    0.174213]  ? x86_family+0x5/0x20
> [    0.174214]  ? secondary_startup_64+0xb6/0xc0
> [    0.174215] BUG: spinlock already unlocked on CPU#0, swapper/0
> [    0.174216]  lock: logbuf_lock+0x0/0x40, .magic: dead4ead, .owner: swapper/0, .owner_cpu: 0
> [    0.174217] CPU: 0 PID: 0 Comm: swapper Not tainted 5.8.0-rc4-00016-g45877ea3934b9 #1
> [    0.174217] Call Trace:
> [    0.174218]  ? dump_stack+0x96/0xd0
> [    0.174218]  ? do_raw_spin_unlock+0x81/0xc0
> [    0.174219]  ? _raw_spin_unlock+0x1f/0x40
> [    0.174219]  ? vprintk_emit+0x141/0x370
> [    0.174220]  ? printk+0x58/0x6f
> [    0.174220]  ? start_kernel+0x60/0x664
> [    0.174221]  ? x86_family+0x5/0x20
> [    0.174222]  ? secondary_startup_64+0xb6/0xc0
> [    0.179324] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)
> [    0.203325] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
> [    0.204873] mem auto-init: stack:off, heap alloc:off, heap free:off
> [    0.303179] Memory: 2330956K/16776640K available (16390K kernel code, 3578K rwdata, 9300K rodata, 2508K init, 17536K bss, 1290512K reserved, 0K cma-reserved)
> [    0.306358] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
> [    0.307555] Kernel/User page tables isolation: enabled
> [    0.308477] ftrace: allocating 49199 entries in 193 pages
> [    0.334062] ftrace: allocated 193 pages with 3 groups
> [    0.335730] Running RCU self tests
> [    0.336314] rcu: Preemptible hierarchical RCU implementation.
> [    0.337275] rcu: 	RCU lockdep checking is enabled.
> [    0.338117] rcu: 	RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=2.
> [    0.339252] 	RCU CPU stall warnings timeout set to 100 (rcu_cpu_stall_timeout).
> [    0.340525] 	Trampoline variant of Tasks RCU enabled.
> [    0.341420] 	Rude variant of Tasks RCU enabled.
> [    0.342120] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
> [    0.343410] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
> [    0.350046] NR_IRQS: 524544, nr_irqs: 440, preallocated irqs: 16
> [    0.351568] random: get_random_bytes called from start_kernel+0x47c/0x664 with crng_init=0
> [    0.360133] Console: colour VGA+ 80x25
> [    0.488053] printk: console [tty0] enabled
> [    0.489397] printk: console [ttyS0] enabled
> [    0.491484] printk: bootconsole [earlyser0] disabled
> [    0.493957] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
> [    0.496330] ... MAX_LOCKDEP_SUBCLASSES:  8
> [    0.497667] ... MAX_LOCK_DEPTH:          48
> [    0.498992] ... MAX_LOCKDEP_KEYS:        8192
> [    0.500345] ... CLASSHASH_SIZE:          4096
> [    0.501709] ... MAX_LOCKDEP_ENTRIES:     32768
> [    0.502983] ... MAX_LOCKDEP_CHAINS:      65536
> [    0.504225] ... CHAINHASH_SIZE:          32768
> [    0.505597]  memory used by lock dependency info: 6301 kB
> [    0.507170]  memory used for stack traces: 4224 kB
> [    0.508622]  per task-struct memory footprint: 1920 bytes
> [    0.510320] ACPI: Core revision 20200528
> [    0.511870] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
> [    0.514831] APIC: Switch to symmetric I/O mode setup
> [    0.516572] x2apic enabled
> [    0.517835] Switched APIC routing to physical x2apic.
> [    0.519267] masked ExtINT on CPU#0
> [    0.521620] ENABLING IO-APIC IRQs
> [    0.522862] init IO_APIC IRQs
> [    0.523904]  apic 0 pin 0 not connected
> [    0.525142] IOAPIC[0]: Set routing entry (0-1 -> 0xef -> IRQ 1 Mode:0 Active:0 Dest:0)
> [    0.527588] IOAPIC[0]: Set routing entry (0-2 -> 0x30 -> IRQ 0 Mode:0 Active:0 Dest:0)
> [    0.530160] IOAPIC[0]: Set routing entry (0-3 -> 0xef -> IRQ 3 Mode:0 Active:0 Dest:0)
> [    0.532595] IOAPIC[0]: Set routing entry (0-4 -> 0xef -> IRQ 4 Mode:0 Active:0 Dest:0)
> [    0.535040] IOAPIC[0]: Set routing entry (0-5 -> 0xef -> IRQ 5 Mode:1 Active:0 Dest:0)
> [    0.537473] IOAPIC[0]: Set routing entry (0-6 -> 0xef -> IRQ 6 Mode:0 Active:0 Dest:0)
> [    0.539907] IOAPIC[0]: Set routing entry (0-7 -> 0xef -> IRQ 7 Mode:0 Active:0 Dest:0)
> [    0.542375] IOAPIC[0]: Set routing entry (0-8 -> 0xef -> IRQ 8 Mode:0 Active:0 Dest:0)
> [    0.544872] IOAPIC[0]: Set routing entry (0-9 -> 0xef -> IRQ 9 Mode:1 Active:0 Dest:0)
> [    0.547321] IOAPIC[0]: Set routing entry (0-10 -> 0xef -> IRQ 10 Mode:1 Active:0 Dest:0)
> [    0.549764] IOAPIC[0]: Set routing entry (0-11 -> 0xef -> IRQ 11 Mode:1 Active:0 Dest:0)
> [    0.552139] IOAPIC[0]: Set routing entry (0-12 -> 0xef -> IRQ 12 Mode:0 Active:0 Dest:0)
> [    0.554509] IOAPIC[0]: Set routing entry (0-13 -> 0xef -> IRQ 13 Mode:0 Active:0 Dest:0)
> [    0.556877] IOAPIC[0]: Set routing entry (0-14 -> 0xef -> IRQ 14 Mode:0 Active:0 Dest:0)
> [    0.559407] IOAPIC[0]: Set routing entry (0-15 -> 0xef -> IRQ 15 Mode:0 Active:0 Dest:0)
> [    0.561851]  apic 0 pin 16 not connected
> [    0.563100]  apic 0 pin 17 not connected
> [    0.564382]  apic 0 pin 18 not connected
> [    0.565667]  apic 0 pin 19 not connected
> [    0.566978]  apic 0 pin 20 not connected
> [    0.568223]  apic 0 pin 21 not connected
> [    0.569546]  apic 0 pin 22 not connected
> [    0.574439]  apic 0 pin 23 not connected
> [    0.575852] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
> [    0.577696] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x26d349e8249, max_idle_ns: 440795288087 ns
> [    0.580936] Calibrating delay loop (skipped) preset value.. 5387.01 BogoMIPS (lpj=2693508)
> [    0.581945] pid_max: default: 32768 minimum: 301
> [    0.583003] LSM: Security Framework initializing
> [    0.583943] Yama: becoming mindful.
> [    0.585038] Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
> [    0.586506] Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
> Poking KASLR using RDTSC...
> [    0.589007] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
> [    0.589936] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
> [    0.590943] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
> [    0.591952] Spectre V2 : Mitigation: Full generic retpoline
> [    0.592937] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
> [    0.593941] Speculative Store Bypass: Vulnerable
> [    0.594944] MDS: Vulnerable: Clear CPU buffers attempted, no microcode
> [    0.597034] Freeing SMP alternatives memory: 40K
> [    0.600063] smpboot: CPU0: Intel Xeon E312xx (Sandy Bridge) (family: 0x6, model: 0x2a, stepping: 0x1)
> [    0.601429] Performance Events: unsupported p6 CPU model 42 no PMU driver, software events only.
> [    0.602098] rcu: Hierarchical SRCU implementation.
> [    0.604237] NMI watchdog: Perf NMI watchdog permanently disabled
> [    0.605187] smp: Bringing up secondary CPUs ...
> [    0.606363] x86: Booting SMP configuration:
>
>
> To reproduce:
>
>          # build kernel
> 	cd linux
> 	cp config-5.8.0-rc4-00016-g45877ea3934b9 .config
> 	make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 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
>
>
>
> Thanks,
> lkp
Thanks for the test. The first locking call is earlier than I expected. 
There is a simple fix for that and I will put that in the next v3 patch.

Cheers,
Longman