2015-08-06 18:15:38

by Fengguang Wu

[permalink] [raw]
Subject: [test_power_init] WARNING: CPU: 1 PID: 1 at lib/debugobjects.c:263 debug_print_object()

Hi Anton,

The warning shows up in linux-next, the earliest commit we can bisect to is

git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

commit a9730fca9946f3697410479e0ef1bd759ba00a77
Author: Christoph Lameter <[email protected]>
AuthorDate: Mon Jun 29 09:28:08 2015 -0500
Commit: Linus Torvalds <[email protected]>
CommitDate: Mon Jun 29 10:49:51 2015 -0700

Fix kmalloc slab creation sequence

This patch restores the slab creation sequence that was broken by commit
4066c33d0308f8 and also reverts the portions that introduced the
KMALLOC_LOOP_XXX macros. Those can never really work since the slab creation
is much more complex than just going from a minimum to a maximum number.

The latest upstream kernel boots cleanly on my machine with a 64 bit x86
configuration under KVM using either SLAB or SLUB.

Fixes: 4066c33d0308f8 ("support the slub_debug boot option")
Reported-by: Theodore Ts'o <[email protected]>
Signed-off-by: Christoph Lameter <[email protected]>
Signed-off-by: Linus Torvalds <[email protected]>

+--------------------------------------------------------------------+------------+------------+------------+
| | 88793e5c77 | a9730fca99 | a87f439ffb |
+--------------------------------------------------------------------+------------+------------+------------+
| boot_successes | 0 | 138 | 69 |
| boot_failures | 1224 | 174 | 76 |
| BUG:kernel_early-boot_crashed_Probing_EDD(edd=off_to_disable)...ok | 1224 | | |
| invoked_oom-killer:gfp_mask=0x | 0 | 171 | 71 |
| Mem-Info | 0 | 171 | 71 |
| Out_of_memory:Kill_process | 0 | 171 | 71 |
| backtrace:vfs_stat | 0 | 79 | 32 |
| backtrace:SyS_stat64 | 0 | 79 | 32 |
| backtrace:vfs_write | 0 | 21 | 14 |
| backtrace:SyS_write | 0 | 21 | 14 |
| backtrace:user_path_at_empty | 0 | 60 | 18 |
| backtrace:SyS_readlinkat | 0 | 65 | 28 |
| backtrace:SyS_readlink | 0 | 65 | 28 |
| backtrace:sock_create | 0 | 33 | 21 |
| backtrace:SyS_socket | 0 | 37 | 22 |
| backtrace:SyS_socketcall | 0 | 37 | 22 |
| backtrace:tty_ldisc_setup | 0 | 13 | 9 |
| backtrace:tty_init_dev | 0 | 13 | 10 |
| backtrace:do_sys_open | 0 | 31 | 21 |
| backtrace:SyS_open | 0 | 31 | 21 |
| backtrace:sock_setsockopt | 0 | 5 | 5 |
| backtrace:SyS_setsockopt | 0 | 5 | 5 |
| backtrace:do_execve | 0 | 4 | 1 |
| backtrace:SyS_execve | 0 | 4 | 1 |
| backtrace:unix_bind | 0 | 1 | |
| backtrace:SyS_bind | 0 | 1 | |
| backtrace:generic_readlink | 0 | 11 | 10 |
| backtrace:sock_alloc_file | 0 | 21 | 13 |
| backtrace:_do_fork | 0 | 9 | 5 |
| backtrace:SyS_clone | 0 | 9 | 5 |
| Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 0 | 58 | 29 |
| backtrace:vfs_read | 0 | 3 | 7 |
| backtrace:SyS_read | 0 | 3 | 7 |
| backtrace:kmem_cache_alloc_trace | 0 | 1 | 1 |
| backtrace:SyS_epoll_create1 | 0 | 3 | 1 |
| backtrace:SyS_faccessat | 0 | 2 | |
| backtrace:SyS_access | 0 | 2 | |
| backtrace:__do_pipe_flags | 0 | 2 | |
| backtrace:SyS_pipe2 | 0 | 2 | |
| backtrace:SyS_pipe | 0 | 2 | |
| backtrace:core_sys_select | 0 | 2 | |
| backtrace:SyS_select | 0 | 2 | |
| backtrace:anon_inode_getfile | 0 | 2 | |
| WARNING:at_lib/debugobjects.c:#debug_print_object() | 0 | 2 | 3 |
| kernel_BUG_at_mm/slab.c | 0 | 2 | 3 |
| invalid_opcode | 0 | 2 | 3 |
| EIP_is_at_check_irq_off | 0 | 2 | 3 |
| Kernel_panic-not_syncing:Fatal_exception | 0 | 3 | 5 |
| backtrace:power_supply_unregister | 0 | 2 | 3 |
| backtrace:test_power_init | 0 | 2 | 3 |
| backtrace:kernel_init_freeable | 0 | 2 | 3 |
| BUG:unable_to_handle_kernel | 0 | 1 | 2 |
| Oops | 0 | 1 | 2 |
| EIP_is_at_power_supply_uevent | 0 | 1 | 1 |
| backtrace:power_supply_changed_work | 0 | 1 | 2 |
| backtrace:pty_unix98_install | 0 | 0 | 1 |
| EIP_is_at_kobject_uevent_env | 0 | 0 | 1 |
| backtrace:unix_stream_connect | 0 | 0 | 1 |
| backtrace:SyS_connect | 0 | 0 | 1 |
| backtrace:unix_dgram_connect | 0 | 0 | 1 |
+--------------------------------------------------------------------+------------+------------+------------+

[ 31.661955] power_supply test_ac: POWER_SUPPLY_NAME=test_ac
[ 31.663026] device: 'test_ac': power_supply_dev_release
[ 31.663799] ------------[ cut here ]------------
[ 31.664489] WARNING: CPU: 1 PID: 1 at lib/debugobjects.c:263 debug_print_object+0xfe/0x11d()
[ 31.675198] ODEBUG: free active (active state 0) object type: work_struct hint: power_supply_changed_work+0x0/0x1f7
[ 31.676951] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.1.0-11344-ga9730fc #1
[ 31.678093] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
[ 31.679384] 00000001 00000000 00000001 80155d24 823bb1e9 80155d50 00000001 82ac7869
[ 31.680587] 80155d40 810cd803 00000107 816194f4 8e849a20 82bda3ec 82aaa11b 80155d58
[ 31.681793] 810cd8e1 00000009 80155d50 82ac782c 80155d6c 80155d8c 816194f4 82ac7869
[ 31.702810] Call Trace:
[ 31.703215] [<823bb1e9>] dump_stack+0x118/0x219
[ 31.703916] [<810cd803>] warn_slowpath_common+0x122/0x163
[ 31.704910] [<816194f4>] ? debug_print_object+0xfe/0x11d
[ 31.705612] [<810cd8e1>] warn_slowpath_fmt+0x47/0x59
[ 31.706278] [<816194f4>] debug_print_object+0xfe/0x11d
[ 31.706972] [<82047647>] ? __power_supply_changed_work+0x99/0x99
[ 31.707770] [<8161974a>] __debug_check_no_obj_freed+0x237/0x4d9
[ 31.708572] [<8161b193>] debug_check_no_obj_freed+0x46/0x58
[ 31.709326] [<813e19ab>] kfree+0x77d/0x9b6
[ 31.709897] [<82047918>] ? power_supply_dev_release+0xda/0xf4
[ 31.710676] [<82047918>] power_supply_dev_release+0xda/0xf4
[ 31.711433] [<81e5a44b>] device_release+0x5f/0x244
[ 31.712093] [<81e5a44b>] ? device_release+0x5f/0x244
[ 31.712774] [<815d7ff9>] kobject_release+0x440/0x51f
[ 31.728316] [<815d7a44>] kobject_put+0x162/0x177
[ 31.729037] [<815d7a44>] ? kobject_put+0x162/0x177
[ 31.729772] [<81e5bf6f>] put_device+0x48/0x59
[ 31.730446] [<81e5d59e>] device_unregister+0xe6/0x100
[ 31.731176] [<82048f10>] power_supply_unregister+0x1ec/0x1ff
[ 31.731922] [<82048f10>] ? power_supply_unregister+0x1ec/0x1ff
[ 31.732690] [<831390b1>] test_power_init+0x121/0x13e
[ 31.733359] [<83138f90>] ? pda_power_pdrv_init+0x2d/0x2d
[ 31.734071] [<8309107a>] do_one_initcall+0x2c9/0x497
[ 31.754234] [<83091667>] kernel_init_freeable+0x41f/0x5d0
[ 31.755445] [<83091667>] ? kernel_init_freeable+0x41f/0x5d0
[ 31.756283] [<823adf21>] kernel_init+0x1c/0x280
[ 31.756970] [<823e8821>] ret_from_kernel_thread+0x21/0x30
[ 31.757768] [<823adf05>] ? rest_init+0x2dd/0x2dd
[ 31.758412] ---[ end trace c7926993aeb9b913 ]---
[ 31.759364] ------------[ cut here ]------------
[ 31.760114] kernel BUG at mm/slab.c:2291!
[ 31.761017] invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 31.762091] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W 4.1.0-11344-ga9730fc #1
[ 31.763380] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
[ 31.764941] task: 80152040 ti: 80154000 task.ti: 80154000
[ 31.765780] EIP: 0060:[<813d79e8>] EFLAGS: 00010246 CPU: 0
[ 31.766636] EIP is at check_irq_off+0x66/0x88
[ 31.767335] EAX: 00000001 EBX: 00000001 ECX: 00000000 EDX: 007cb0ee
[ 31.768319] ESI: 00000001 EDI: 80c17c00 EBP: 80155e1c ESP: 80155e14
[ 31.769306] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 31.770160] CR0: 8005003b CR2: 00000000 CR3: 03307000 CR4: 000006f0
[ 31.771148] Stack:
[ 31.771473] 8009a780 90da1a94 80155e38 813e19e9 00000246 82047918 00000000 80c17c1c
[ 31.776170] 00000001 80155e58 82047918 00000000 80c17c00 80155e60 80c17c24 80c17c1c
[ 31.777274] 80155e68 80155e78 81e5a44b 00000001 81e5a44b 80c0fe00 80c17c40 82cfbda4
[ 31.778390] Call Trace:
[ 31.778712] [<813e19e9>] kfree+0x7bb/0x9b6
[ 31.779242] [<82047918>] ? power_supply_dev_release+0xda/0xf4
[ 31.780057] [<82047918>] power_supply_dev_release+0xda/0xf4
[ 31.780948] [<81e5a44b>] device_release+0x5f/0x244
[ 31.781705] [<81e5a44b>] ? device_release+0x5f/0x244
[ 31.782505] [<815d7ff9>] kobject_release+0x440/0x51f
[ 31.783272] [<815d7a44>] kobject_put+0x162/0x177
[ 31.798864] [<815d7a44>] ? kobject_put+0x162/0x177
[ 31.799646] [<81e5bf6f>] put_device+0x48/0x59
[ 31.800351] [<81e5d59e>] device_unregister+0xe6/0x100
[ 31.801044] [<82048f10>] power_supply_unregister+0x1ec/0x1ff
[ 31.801740] [<82048f10>] ? power_supply_unregister+0x1ec/0x1ff
[ 31.802453] [<831390b1>] test_power_init+0x121/0x13e
[ 31.803068] [<83138f90>] ? pda_power_pdrv_init+0x2d/0x2d
[ 31.803716] [<8309107a>] do_one_initcall+0x2c9/0x497
[ 31.804333] [<83091667>] kernel_init_freeable+0x41f/0x5d0
[ 31.805106] [<83091667>] ? kernel_init_freeable+0x41f/0x5d0
[ 31.805997] [<823adf21>] kernel_init+0x1c/0x280
[ 31.806712] [<823e8821>] ret_from_kernel_thread+0x21/0x30
[ 31.826110] [<823adf05>] ? rest_init+0x2dd/0x2dd
[ 31.826852] Code: b8 e4 9f dd 82 e8 11 91 ee ff 8b 04 b5 cc 17 e9 82 40 89 04 b5 cc 17 e9 82 84 db 74 1e 83 05 c0 6c c4 83 01 83 15 c4 6c c4 83 00 <0f> 0b 83 05 d0
6c c4 83 01 83 15 d4 6c c4 83 00 83 05 c8 6c c4
[ 31.831564] EIP: [<813d79e8>] check_irq_off+0x66/0x88 SS:ESP 0068:80155e14
[ 31.832919] ---[ end trace c7926993aeb9b914 ]---

git bisect start 74d33293e467df61de1b1d8b2fbe29e550dec33b v4.1 --
git bisect bad 9bdc771f2c29a11920f477fba05a58e23ee42554 # 15:32 12- 12 Merge tag 'acpica-4.2-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
git bisect good c13c81006314ad76c2b31824960a900385601b8b # 15:51 310+ 310 Merge tag 'rtc-v4.2-1' of git://git.kernel.org/pub/scm/linux/kernel/git/abelloni/linux
git bisect bad 68b4449d79f00dc3cb6ea1f4bf54cf8e453a53c8 # 16:05 162- 152 Merge tag 'xfs-for-linus-4.2-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/dgc/linux-xfs
git bisect good 4b703b1d4c46ca4a00109ca1a391943ec21991b3 # 16:32 310+ 312 power: axp288_charger: fix for API change
git bisect good 21dc2e6c6d552702736ad3603fe9b074654d3932 # 16:57 310+ 310 Merge branch 'for-linus-4.2-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rw/uml
git bisect good 88793e5c774ec69351ef6b5200bb59f532e41bca # 17:17 300+ 304 Merge tag 'libnvdimm-for-4.2' of git://git.kernel.org/pub/scm/linux/kernel/git/djbw/nvdimm
git bisect bad 6aaf0da8728c55ff627619f933ed161cc89057c6 # 17:42 294- 222 Merge tag 'md/4.2' of git://neil.brown.name/md
git bisect bad a9730fca9946f3697410479e0ef1bd759ba00a77 # 17:51 98- 84 Fix kmalloc slab creation sequence
# first bad commit: [a9730fca9946f3697410479e0ef1bd759ba00a77] Fix kmalloc slab creation sequence
git bisect good 88793e5c774ec69351ef6b5200bb59f532e41bca # 18:37 910+ 1224 Merge tag 'libnvdimm-for-4.2' of git://git.kernel.org/pub/scm/linux/kernel/git/djbw/nvdimm
# extra tests with DEBUG_INFO
git bisect bad a9730fca9946f3697410479e0ef1bd759ba00a77 # 19:22 882- 719 Fix kmalloc slab creation sequence
# extra tests on HEAD of linux-devel/devel-spot-201508042358
git bisect bad a87f439ffb183598cb5e2acafafefa0bb18c29e2 # 19:23 0- 76 0day head guard for 'devel-spot-201508042358'
# extra tests on tree/branch linus/master
git bisect bad 4e6b6ee253ce58aa156d7f1448d1038679b26783 # 20:12 909- 658 Merge tag 'md/4.2-rc5-fixes' of git://neil.brown.name/md
# extra tests on tree/branch linus/master
git bisect bad 4e6b6ee253ce58aa156d7f1448d1038679b26783 # 20:12 0- 658 Merge tag 'md/4.2-rc5-fixes' of git://neil.brown.name/md
# extra tests on tree/branch linux-next/master
git bisect bad a5b4661b8bc23f3a10eca2206daad84014b768ec # 20:32 256- 258 Add linux-next specific files for 20150805


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/raw/master/initrd/$initrd

kvm=(
qemu-system-x86_64
-enable-kvm
-cpu kvm64
-kernel $kernel
-initrd $initrd
-m 300
-smp 2
-device e1000,netdev=net0
-netdev user,id=net0
-boot order=nc
-no-reboot
-watchdog i6300esb
-rtc base=localtime
-serial stdio
-display none
-monitor null
)

append=(
hung_task_panic=1
earlyprintk=ttyS0,115200
systemd.log_level=err
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[*]}"
----------------------------------------------------------------------------

---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/lkp Intel Corporation


Attachments:
(No filename) (16.58 kB)
dmesg-quantal-vp-9:20150805175121:i386-randconfig-b0-08051304:4.1.0-11344-ga9730fc:1 (36.56 kB)
dmesg-quantal-intel12-13:20150805170526:i386-randconfig-b0-08051304:4.1.0-11343-g88793e5:2 (2.52 kB)
config-4.1.0-11344-ga9730fc (67.84 kB)
Download all attachments
Subject: Re: [test_power_init] WARNING: CPU: 1 PID: 1 at lib/debugobjects.c:263 debug_print_object()

On Fri, 7 Aug 2015, Fengguang Wu wrote:

> [ 31.664489] WARNING: CPU: 1 PID: 1 at lib/debugobjects.c:263 debug_print_object+0xfe/0x11d()
> [ 31.675198] ODEBUG: free active (active state 0) object type: work_struct hint: power_supply_changed_work+0x0/0x1f7

Ok this is slab independent object validation. No idea what this
means. A free of an active object should be ok. Or is the object somehow
tracked in a different way to be active that prevents its freeing? Has a
refcount or so?

> [ 31.760114] kernel BUG at mm/slab.c:2291!

Interrupts not disabled as they ought to be.

Subject: Re: [test_power_init] WARNING: CPU: 1 PID: 1 at lib/debugobjects.c:263 debug_print_object()

Hmmmm... Okay so someone is holding a lock on the structure that is being
freed. Has nothing to do with slab allocation.