Message-ID: <20150301085840.GA13693@wfg-t540p.sh.intel.com>
Date:	Sun, 1 Mar 2015 16:58:40 +0800
From:	Fengguang Wu <fengguang.wu@...el.com>
To:	Peter Zijlstra <peterz@...radead.org>
Cc:	fengguang.wu@...el.com, LKP <lkp@...org>,
	linux-kernel@...r.kernel.org
Subject: [lockdep] WARNING: CPU: 0 PID: 1 at kernel/locking/lockdep.c:705
 lockdep_init_map()

Greetings,

0day kernel testing robot got the below dmesg and the first bad commit is

git://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git

commit 08ba96d4bd019d873ec73798248f5255768318ac
Author:     Peter Zijlstra <peterz@...radead.org>
AuthorDate: Thu Feb 26 16:23:11 2015 +0100
Commit:     Peter Zijlstra <peterz@...radead.org>
CommitDate: Fri Feb 27 18:53:11 2015 +0100

    lockdep: Fix module unload
    
    Module unload calls lockdep_free_key_range(), which removes entries
    from the data structures. Most of the lockdep code OTOH assumes the
    data structures are append only; in specific see the comments in
    add_lock_to_list() and look_up_lock_class().
    
    Clearly this has only worked by accident; make it work proper. The
    actual scenario to make it go boom would involve the memory freed by
    the module unlock being re-allocated and re-used for a lock inside of
    a rcu-sched grace period. This is a very unlikely scenario, still
    better plug the hole.
    
    Use RCU list iteration in all places and ammend the comments.
    
    Change lockdep_free_key_range() to issue a sync_sched() between
    removal from the lists and returning -- which results in the memory
    being freed. Further ensure the callers are placed correctly and
    comment the requirements.
    
    Cc: Rusty Russell <rusty@...tcorp.com.au>
    Cc: Andrey Tsyvarev <tsyvarev@...ras.ru>
    Reviewed-by: Ingo Molnar <mingo@...nel.org>
    Signed-off-by: Peter Zijlstra (Intel) <peterz@...radead.org>

+---------------------------------------------------------+------------+------------+------------+
|                                                         | 4f671fe2f9 | 08ba96d4bd | 35f6e81a75 |
+---------------------------------------------------------+------------+------------+------------+
| boot_successes                                          | 60         | 0          | 0          |
| boot_failures                                           | 0          | 20         | 14         |
| WARNING:at_kernel/locking/lockdep.c:#lockdep_init_map() | 0          | 20         | 14         |
| backtrace:lockdep_init_map                              | 0          | 20         | 14         |
| backtrace:warn_slowpath_fmt                             | 0          | 20         | 14         |
| backtrace:__alloc_workqueue_key                         | 0          | 20         | 14         |
| backtrace:init_workqueues                               | 0          | 20         | 14         |
| backtrace:kernel_init_freeable                          | 0          | 20         | 14         |
+---------------------------------------------------------+------------+------------+------------+

no PMU driver, software events only.
[    0.134356] ------------[ cut here ]------------
[    0.134356] ------------[ cut here ]------------
[    0.135012] WARNING: CPU: 0 PID: 1 at kernel/locking/lockdep.c:705 lockdep_init_map+0x434/0xc41()
[    0.135012] WARNING: CPU: 0 PID: 1 at kernel/locking/lockdep.c:705 lockdep_init_map+0x434/0xc41()
[    0.136021] DEBUG_LOCKS_WARN_ON(!irqs_disabled())
[    0.136021] DEBUG_LOCKS_WARN_ON(!irqs_disabled())

[    0.137028] CPU: 0 PID: 1 Comm: swapper Not tainted 4.0.0-rc1-00037-g08ba96d #4
[    0.137028] CPU: 0 PID: 1 Comm: swapper Not tainted 4.0.0-rc1-00037-g08ba96d #4
[    0.138018]  00000000
[    0.138018]  00000000 8b46de10 8b46de10 8b46dde4 8b46dde4 86fd1b26 86fd1b26 8b46de00 8b46de00 85c5c7b0 85c5c7b0 000002c1 000002c1 85c9f4e4 85c9f4e4

[    0.140751]  00000a4d
[    0.140751]  00000a4d 8b426ef0 8b426ef0 87f0dae8 87f0dae8 8b46de18 8b46de18 85c5c884 85c5c884 00000009 00000009 8b46de10 8b46de10 875ce58b 875ce58b

[    0.143068]  8b46de2c
[    0.143068]  8b46de2c 8b46de50 8b46de50 85c9f4e4 85c9f4e4 875ce8f8 875ce8f8 000002c1 000002c1 875ce58b 875ce58b 875ceb72 875ceb72 8b46de38 8b46de38

[    0.145076] Call Trace:
[    0.145076] Call Trace:
[    0.145773]  [<86fd1b26>] dump_stack+0x40/0x5e
[    0.145773]  [<86fd1b26>] dump_stack+0x40/0x5e
[    0.146013]  [<85c5c7b0>] warn_slowpath_common+0xc8/0x109
[    0.146013]  [<85c5c7b0>] warn_slowpath_common+0xc8/0x109
[    0.147012]  [<85c9f4e4>] ? lockdep_init_map+0x434/0xc41
[    0.147012]  [<85c9f4e4>] ? lockdep_init_map+0x434/0xc41
[    0.148012]  [<85c5c884>] warn_slowpath_fmt+0x42/0x54
[    0.148012]  [<85c5c884>] warn_slowpath_fmt+0x42/0x54
[    0.149011]  [<85c9f4e4>] lockdep_init_map+0x434/0xc41
[    0.149011]  [<85c9f4e4>] lockdep_init_map+0x434/0xc41
[    0.150012]  [<85c7bcbd>] ? alloc_workqueue_attrs+0x24/0x92
[    0.150012]  [<85c7bcbd>] ? alloc_workqueue_attrs+0x24/0x92
[    0.152015]  [<85c7bebc>] ? init_worker_pool+0x191/0x1ca
[    0.152015]  [<85c7bebc>] ? init_worker_pool+0x191/0x1ca
[    0.153011]  [<85c7c2bb>] alloc_unbound_pwq+0x3c6/0x5ce
[    0.153011]  [<85c7c2bb>] alloc_unbound_pwq+0x3c6/0x5ce
[    0.154012]  [<85c7c6d1>] apply_workqueue_attrs+0x180/0x4f4
[    0.154012]  [<85c7c6d1>] apply_workqueue_attrs+0x180/0x4f4
[    0.155011]  [<85c7d46a>] __alloc_workqueue_key+0x397/0x5df
[    0.155011]  [<85c7d46a>] __alloc_workqueue_key+0x397/0x5df
[    0.156013]  [<87bd5ed5>] init_workqueues+0x315/0x4c0
[    0.156013]  [<87bd5ed5>] init_workqueues+0x315/0x4c0
[    0.157012]  [<87bd5bc0>] ? wq_sysfs_init+0x2d/0x2d
[    0.157012]  [<87bd5bc0>] ? wq_sysfs_init+0x2d/0x2d
[    0.158012]  [<87bbc850>] do_one_initcall+0x21a/0x325
[    0.158012]  [<87bbc850>] do_one_initcall+0x21a/0x325
[    0.159013]  [<86ff4a00>] ? wait_for_common+0x186/0x21e
[    0.159013]  [<86ff4a00>] ? wait_for_common+0x186/0x21e
[    0.160011]  [<86ffadce>] ? _raw_spin_unlock_irq+0x47/0x80
[    0.160011]  [<86ffadce>] ? _raw_spin_unlock_irq+0x47/0x80
[    0.161010]  [<86ff4a80>] ? wait_for_common+0x206/0x21e
[    0.161010]  [<86ff4a80>] ? wait_for_common+0x206/0x21e
[    0.162011]  [<85c88286>] ? finish_task_switch+0x92/0x1cd
[    0.162011]  [<85c88286>] ? finish_task_switch+0x92/0x1cd
[    0.163013]  [<86ffadce>] ? _raw_spin_unlock_irq+0x47/0x80
[    0.163013]  [<86ffadce>] ? _raw_spin_unlock_irq+0x47/0x80
[    0.164012]  [<87bbc9de>] kernel_init_freeable+0x83/0x38b
[    0.164012]  [<87bbc9de>] kernel_init_freeable+0x83/0x38b
[    0.165012]  [<87bbc9de>] ? kernel_init_freeable+0x83/0x38b
[    0.165012]  [<87bbc9de>] ? kernel_init_freeable+0x83/0x38b
[    0.166012]  [<86fca0b7>] kernel_init+0x16/0x1e7
[    0.166012]  [<86fca0b7>] kernel_init+0x16/0x1e7
[    0.167011]  [<86ffc300>] ret_from_kernel_thread+0x20/0x30
[    0.167011]  [<86ffc300>] ret_from_kernel_thread+0x20/0x30
[    0.168012]  [<86fca0a1>] ? rest_init+0x158/0x158
[    0.168012]  [<86fca0a1>] ? rest_init+0x158/0x158
[    0.169017] ---[ end trace 5d61d852fc7e12ba ]---
[    0.169017] ---[ end trace 5d61d852fc7e12ba ]---

git bisect start 35f6e81a75db2562acdd99d21dd53eed797b0c9a 575daeea39a3d4b636098e0117505dad143124e0 --
git bisect good f180b755d1a82b1d04defc7b5351f585088d5bff  # 02:31     18+      0  Merge branch 'sched/urgent'
git bisect  bad f916b29c6f3946c76e38d82dad1593fb073647ba  # 02:36      0-     18  Merge branch 'locking/urgent'
git bisect  bad 08ba96d4bd019d873ec73798248f5255768318ac  # 02:47      0-     20  lockdep: Fix module unload
# first bad commit: [08ba96d4bd019d873ec73798248f5255768318ac] lockdep: Fix module unload
git bisect good 4f671fe2f9523a1ea206f63fe60a7c7b3a56d5c7  # 02:51     60+      0  Merge tag 'hwmon-for-linus-v4.0-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/groeck/linux-staging
# extra tests with DEBUG_INFO
git bisect  bad 08ba96d4bd019d873ec73798248f5255768318ac  # 02:58      0-      2  lockdep: Fix module unload
# extra tests on HEAD of peterz-queue/master
git bisect  bad 35f6e81a75db2562acdd99d21dd53eed797b0c9a  # 02:58      0-     14  Merge branch 'perf/core'
# extra tests on tree/branch peterz-queue/locking/urgent
git bisect  bad 08ba96d4bd019d873ec73798248f5255768318ac  # 02:58      0-     20  lockdep: Fix module unload
# extra tests with first bad commit reverted
# extra tests on tree/branch linus/master
git bisect good 4f671fe2f9523a1ea206f63fe60a7c7b3a56d5c7  # 03:00     60+      0  Merge tag 'hwmon-for-linus-v4.0-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/groeck/linux-staging
# extra tests on tree/branch next/master
git bisect good 1d97b73f7fa098ff1f3e1f6f671ea280d31d8a35  # 03:14     60+      0  Add linux-next specific files for 20150227


This script may reproduce the error.

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

kernel=$1
initrd=yocto-minimal-i386.cgz

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

kvm=(
	qemu-system-x86_64
	-cpu kvm64
	-enable-kvm
	-kernel $kernel
	-initrd $initrd
	-m 320
	-smp 1
	-net nic,vlan=1,model=e1000
	-net user,vlan=1
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-rtc base=localtime
	-serial stdio
	-display none
	-monitor null 
)

append=(
	hung_task_panic=1
	earlyprintk=ttyS0,115200
	rd.udev.log-priority=err
	systemd.log_target=journal
	systemd.log_level=warning
	debug
	apic=debug
	sysrq_always_enabled
	rcupdate.rcu_cpu_stall_timeout=100
	panic=-1
	softlockup_panic=1
	nmi_watchdog=panic
	oops=panic
	load_ramdisk=2
	prompt_ramdisk=0
	console=ttyS0,115200
	console=tty0
	vga=normal
	root=/dev/ram0
	rw
	drbd.minor_count=8
)

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

Thanks,
Fengguang

View attachment "dmesg-yocto-client7-5:20150228024642:i386-randconfig-x1-02280040:4.0.0-rc1-00037-g08ba96d:4" of type "text/plain" (271769 bytes)

View attachment "config-4.0.0-rc1-00037-g08ba96d" of type "text/plain" (87541 bytes)

Powered by blists - more mailing lists