Date:	Sat, 5 Apr 2014 21:38:56 +0800
From:	Fengguang Wu <fengguang.wu@...el.com>
To:	Greg Price <price@....EDU>
Cc:	Theodore Ts'o <tytso@....edu>, linux-kernel@...r.kernel.org,
	Jet Chen <jet.chen@...el.com>
Subject: [random] BUG: spinlock trylock failure on UP on CPU#0, swapper/1

Greetings,

I got the below dmesg and the first bad commit is

git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git master

commit 11e9ee988e8f951e4dbc765832fdf6f08c2c8b54
Author:     Greg Price <price@....EDU>
AuthorDate: Thu Dec 5 19:32:19 2013 -0500
Commit:     Theodore Ts'o <tytso@....edu>
CommitDate: Wed Mar 5 21:28:10 2014 -0500

    random: simplify accounting code
    
    With this we handle "reserved" in just one place.  As a bonus the
    code becomes less nested, and the "wakeup_write" flag variable
    becomes unnecessary.  The variable "flags" was already unused.
    
    This code behaves identically to the previous version except in
    two pathological cases that don't occur.  If the argument "nbytes"
    is already less than "min", then we didn't previously enforce
    "min".  If r->limit is false while "reserved" is nonzero, then we
    previously applied "reserved" in checking whether we had enough
    bits, even though we don't apply it to actually limit how many we
    take.  The callers of account() never exercise either of these cases.
    
    Before the previous commit, it was possible for "nbytes" to be less
    than "min" if userspace chose a pathological configuration, but no
    longer.
    
    Cc: Jiri Kosina <jkosina@...e.cz>
    Cc: "H. Peter Anvin" <hpa@...or.com>
    Signed-off-by: Greg Price <price@....edu>
    Signed-off-by: "Theodore Ts'o" <tytso@....edu>

+------------------------------------------------+------------+------------+---------------+
|                                                | bdd80011da | 11e9ee988e | next-20140403 |
+------------------------------------------------+------------+------------+---------------+
| boot_successes                                 | 510        | 136        | 16            |
| boot_failures                                  | 106        | 46         | 7             |
| BUG:kernel_boot_hang                           | 106        | 20         | 2             |
| BUG:spinlock_trylock_failure_on_UP_on_CPU      | 0          | 25         | 5             |
| backtrace:prandom_reseed                       | 0          | 16         | 3             |
| backtrace:kernel_init_freeable                 | 0          | 16         | 2             |
| BUG:soft_lockup-CPU_stuck_for_s                | 0          | 1          |               |
| EIP_is_at_native_safe_halt                     | 0          | 1          |               |
| Kernel_panic-not_syncing:softlockup:hung_tasks | 0          | 1          |               |
| backtrace:cpu_startup_entry                    | 0          | 1          |               |
+------------------------------------------------+------------+------------+---------------+

[  583.725561] raid6test: test_disks(62, 63): faila= 62(P)  failb= 63(Q)  OK
[  583.912461] raid6test: 
[  584.110739] raid6test: complete (2429 tests, 0 failures)
[  584.304933] BUG: spinlock trylock failure on UP on CPU#0, swapper/1
[  584.314418]  lock: lock.14477+0x0/0x40, .magic: dead4ead, .owner: swapper/1, .owner_cpu: 0
[  584.314418] CPU: 0 PID: 1 Comm: swapper Not tainted 3.13.0-00009-g11e9ee9 #1
[  584.314418] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[  584.314418]  d0058000 d0058000 d0057d1c c181ac11 d0057d44 c1816b15 c1a51108 c1cc3080
[  584.314418]  dead4ead d00582b0 00000001 00000000 c1cc3080 c1a4c4e5 d0057d54 c1816b37
[  584.314418]  00000000 c1cc3080 d0057d60 c1061c4c c1cc3090 d0057d84 c18269e2 00000000
[  584.314418] Call Trace:
[  584.314418]  [<c181ac11>] dump_stack+0x16/0x18
[  584.314418]  [<c1816b15>] spin_dump+0x90/0x97
[  584.314418]  [<c1816b37>] spin_bug+0x1b/0x1f
[  584.314418]  [<c1061c4c>] do_raw_spin_trylock+0x3c/0x50
[  584.314418]  [<c18269e2>] _raw_spin_lock_irqsave+0x52/0x80
[  584.314418]  [<c1261564>] ? __prandom_reseed+0x14/0xa0
[  584.314418]  [<c1261564>] __prandom_reseed+0x14/0xa0
[  584.314418]  [<c126166d>] prandom_reseed_late+0xd/0x10
[  584.314418]  [<c139918e>] credit_entropy_bits+0x20e/0x230
[  584.314418]  [<c13999ab>] _xfer_secondary_pool+0x7b/0x90

Elapsed time: 580
qemu-system-x86_64 -cpu kvm64 -enable-kvm -kernel /kernel/i386-randconfig-fb0-04031419/11e9ee988e8f951e4dbc765832fdf6f08c2c8b54/vmlinuz-3.13.0-00009-g11e9ee9 -append 'hung_task_panic=1 earlyprintk=ttyS0,115200 debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=10 softlockup_panic=1 nmi_watchdog=panic  prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal  root=/dev/ram0 rw link=/kernel-tests/run-queue/kvm/i386-randconfig-fb0-04031419/next:master:11e9ee988e8f951e4dbc765832fdf6f08c2c8b54:bisect-drm/.vmlinuz-11e9ee988e8f951e4dbc765832fdf6f08c2c8b54-20140405081535-145-loslunas branch=next/master BOOT_IMAGE=/kernel/i386-randconfig-fb0-04031419/11e9ee988e8f951e4dbc765832fdf6f08c2c8b54/vmlinuz-3.13.0-00009-g11e9ee9 drbd.minor_count=8'  -initrd /kernel-tests/initrd/quantal-core-i386.cgz -m 320 -smp 2 -net nic,vlan=1,model=e1000 -net user,vlan=1,hostfwd=tcp::9668-:22 -boot order=nc -no-reboot -watchdog i6300esb -rtc base=localtime -pidfile /dev/shm/kboot/pid-quantal-loslunas-12 -serial file:/dev/shm/kboot/serial-quantal-loslunas-12 -daemonize -display none -monitor null 

git bisect start 79b1d1f5860545973461d0dcb1f0e8d9c32dbdbe v3.14 --
git bisect good 66a79c5033d7e31b2e63c528000ba381df480d45  # 14:10     70+      0  Merge remote-tracking branch 'renesas/next'
git bisect good 48002d979a86f9807826cac79fb4a0c0774af5ba  # 18:55     70+     12  Merge remote-tracking branch 'l2-mtd/master'
git bisect good f1dacec12594c327cc25fe2c2785bae8b086eccb  # 21:57     70+      9  Merge remote-tracking branch 'trivial/for-next'
git bisect good bd87b48bb4b6bad88f1e88d96a1db7c280ea1393  # 23:38     70+      5  Merge remote-tracking branch 'leds/for-next'
git bisect good 0783c1fd1eb05312ff948d2f04b3236661300664  # 00:44     70+     15  Merge remote-tracking branch 'pwm/for-next'
git bisect  bad 578477075e8932bb7fe117e6ad470c3c3cb580c7  # 01:21      4-      5  Merge remote-tracking branch 'random/dev'
git bisect good 1f5db0cb975967a8b904050d7eeac3e05bc89fb3  # 04:05     70+      1  Merge remote-tracking branch 'ktest/for-next'
git bisect good dd6120ce8d3b3606f40f00f3be6f0b2c04a8a6a9  # 05:20     70+     12  Merge remote-tracking branch 'clk/clk-next'
git bisect good bdd80011daa20f828023f511c971a7ba067e6d1b  # 05:47     70+     15  random: tighten bound on random_read_wakeup_thresh
git bisect  bad 5affd0650baee6b535ccbf625bd5814bef49c7dc  # 06:21     65-      5  random: use the architectural HWRNG for the SHA's IV in extract_buf()
git bisect  bad 243f2627816bb018fa945a460bc872a51a3b4fb9  # 07:25     20-      7  random: entropy_bytes is actually bits
git bisect  bad 11e9ee988e8f951e4dbc765832fdf6f08c2c8b54  # 08:25     12-      7  random: simplify accounting code
# first bad commit: [11e9ee988e8f951e4dbc765832fdf6f08c2c8b54] random: simplify accounting code
git bisect good bdd80011daa20f828023f511c971a7ba067e6d1b  # 09:11    546+    106  random: tighten bound on random_read_wakeup_thresh
git bisect  bad 4b22efdd5595f0acb48f02bf664a451ee98f9a2e  # 09:12      0-      7  Add linux-next specific files for 20140403
git bisect  bad 4b22efdd5595f0acb48f02bf664a451ee98f9a2e  # 09:23      0-      7  Add linux-next specific files for 20140403


This script may reproduce the error.

-----------------------------------------------------------------------------
#!/bin/bash

kernel=$1
initrd=quantal-core-i386.cgz

wget --no-clobber https://github.com/fengguang/reproduce-kernel-bug/blob/master/initrd/$initrd

kvm=(
	qemu-system-x86_64 -cpu kvm64 -enable-kvm
	-kernel $kernel
	-initrd $initrd
	-smp 2
	-m 256M
	-net nic,vlan=0,macaddr=00:00:00:00:00:00,model=virtio
	-net user,vlan=0
	-net nic,vlan=1,model=e1000
	-net user,vlan=1
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-serial stdio
	-display none
	-monitor null
)

append=(
	debug
	sched_debug
	apic=debug
	ignore_loglevel
	sysrq_always_enabled
	panic=10
	prompt_ramdisk=0
	earlyprintk=ttyS0,115200
	console=ttyS0,115200
	console=tty0
	vga=normal
	root=/dev/ram0
	rw
)

"${kvm[@]}" --append "${append[*]}"
-----------------------------------------------------------------------------

Thanks,
Fengguang

View attachment "dmesg-quantal-loslunas-12:20140405082625:i386-randconfig-fb0-04031419:3.13.0-00009-g11e9ee9:1" of type "text/plain" (242349 bytes)

Download attachment "i386-randconfig-fb0-04031419-4b22efdd5595f0acb48f02bf664a451ee98f9a2e-BUG:-spinlock-trylock-failure-on-UP-on-CPU-62576.log" of type "application/octet-stream" (43996 bytes)

View attachment "config-3.13.0-00009-g11e9ee9" of type "text/plain" (90804 bytes)

Powered by blists - more mailing lists