object debugging infrastructure

We can see an ever repeating problem pattern with objects of any kind in the kernel:

1) free of active objects
2) reinitialization of active objects

Both problems can be hard to debug because the symptoms surface at a point where we have no chance to decode the root cause anymore. One problem spot are kernel timers, where the detection of the problem often happens in interrupt context and usually causes the machine to panic.

While working on a timer related bug report I had to hack in specialized code into the timer subsystem to get a reasonable hint for the root cause. This debug hack was fine for temporary use, but far from a mergeable solution due to the intrusiveness into the timer code and the lack of the ability to detect and report the root cause instantly and at the same time keeping the system operational so that we have a decent chance to get hold of the debug information without special debugging aids like serial consoles.

The problems described above are not restricted to timers, but timers tend to expose it usually in a full system crash. Other objects are less explosive, but the symptoms caused by such mistakes can be even harder to debug.

Instead of creating specialized debugging code for the timer subsystem a generic infrastructure is created which allows developers to verify their code and provides an easy to enable debug facility for users in case of trouble.

The debugobjects core code keeps track of operations on static and dynamic objects by inserting them into a hashed list and sanity checking them on object operations and providing additional checks whenever kernel memory is freed.

The tracked object operations are:
- initializing an object
- adding an object to a subsystem list
- deleting an object from a subsystem list

Each operation is sanity checked before the operation is executed and the subsystem specific code can provide a fixup function which prevents the damage of the operation. When the sanity check triggers a warning message and a stack trace is printed.

The list of operations can be extended if the need arises. For now it's limited to the requirements of the first user (timers).

The core code enqueues the objects into hash buckets. The hash index is generated from the address of the object to simplify the lookup for the check on k/vfree. Each bucket has it's own spinlock to avoid contention on a global lock.

The debug code can be compiled in without being active. The runtime overhead is minimal and could be optimized by asm alternatives. A kernel command line option enables the debugging code.

A recent real world debugging session shows the usefulness:

Initial bug report:

BUG: unable to handle kernel NULL pointer dereference at 00000000
IP: [<c0131f3e>] get_next_timer_interrupt+0xfe/0x210
....
Call Trace:
 [<c014627c>] ? tick_nohz_stop_sched_tick+0x13c/0x350

....

The reporter was asked to enable list debugging:

kernel BUG at lib/list_debug.c:33!
...
[<c0131776>] ? internal_add_timer+0x36/0xb0
[<c01434ca>] ? clocksource_watchdog+0x22a/0x240
....

Enabling slab poisoning identified the problem as use after free:

BUG: unable to handle kernel paging request at 6b6b6b6b
IP: [<c0131f3e>] get_next_timer_interrupt+0xfe/0x210

....

The above debug informations had to be transscripted from the monitor due to a full machine crash and at no point it gave any useful hint of the root cause.

Enabling the object debugging code gave:

Feb 27 07:24:22 kkbox kernel: ODEBUG: free active object: timer_list
Feb 27 07:24:22 kkbox kernel: WARNING: at lib/debugobjects.c:63 debug_print_object+0x64/0x66()
...
Feb 27 07:24:22 kkbox kernel:  [<c01f57e6>] debug_print_object+0x64/0x66
Feb 27 07:24:22 kkbox kernel:  [<c01f5860>] debug_check_no_obj_freed+0x78/0xd5
Feb 27 07:24:22 kkbox kernel:  [<c017dc04>] kfree+0x6c/0xce
Feb 27 07:24:22 kkbox kernel:  [<f9077cbb>] ? l2cap_conn_del+0x5c/0x64 [l2cap]
Feb 27 07:24:22 kkbox kernel:  [<f9077cbb>] l2cap_conn_del+0x5c/0x64 [l2cap]
Feb 27 07:24:22 kkbox kernel:  [<f9077ce5>] l2cap_disconn_ind+0x22/0x27 [l2cap]
Feb 27 07:24:22 kkbox kernel:  [<f8e552fd>] hci_event_packet+0x628/0x19b7 [bluetooth]

The debug information was retrieved from the syslog on a full operational system, because the fixup code deactivated the timer before returning to the calling code. The location of the culprit was exactly pointed out by the stack trace.

Comments, suggestions are welcome as usual.

Thanks,
tglx

We can see an ever repeating problem pattern with objects of any kind in the kernel:

1) free of active objects
2) reinitialization of active objects

Both problems can be hard to debug because the crash happens at a point where we have no chance to decode the root cause anymore. One problem spot are kernel timers, where the detection of the problem often happens in interrupt context and usually causes the machine to panic.

While working on a timer related bug report I had to hack in specialized code into the timer subsystem to get a reasonable hint for the root cause. This debug hack was fine for temporary use, but far from a mergeable solution due to the intrusiveness into the timer code and the lack of the ability to detect and report the root cause instantly and at the same time keeping the system operational so that we have a decent chance to get hold of the debug information without special debugging aids like serial consoles.

The problems described above are not restricted to timers, but timers tend to expose it usually in a full system crash. Other objects are less explosive, but the symptoms caused by such mistakes can be even harder to debug.

Instead of creating specialized debugging code for the timer subsystem a generic infrastructure is created which allows developers to verify their code and provides an easy to enable debug facility for users in case of trouble.

The debugobjects core code keeps track of operations on static and dynamic objects by inserting them into a hashed list and sanity checking them on object operations and provides additional checks whenever kernel memory is freed.

The tracked object operations are:
- initializing an object
- adding an object to a subsystem list
- deleting an object from a subsystem list

Each operation is sanity checked before the operation is executed and the subsystem specific code can provide a fixup function which prevents the damage of the operation. When the sanity check triggers a warning message and a stack trace is printed.

The list of operations can be extended if the need arises. For now it's limited to the requirements of the first user (timers).

The core code enqueues the objects into hash buckets. The hash index is generated from the address of the object to simplify the lookup for the check on k/vfree. Each bucket has it's own spinlock to avoid contention on a global lock.

The debug code can be compiled in without being active. The runtime overhead is minimal and could be optimized by asm alternatives. A kernel command line option enables the debugging code.

---
 Documentation/kernel-parameters.txt |    2 
 include/linux/debugobjects.h        |   47 ++++++
 include/linux/mm.h                  |    1 
 init/main.c                         |    2 
 lib/Kconfig.debug                   |   16 ++
 lib/Makefile                        |    1 
 lib/debugobjects.c                  |  256 ++++++++++++++++++++++++++++++++++++
 mm/page_alloc.c                     |    9 -
 mm/slab.c                           |    2 
 mm/slub.c                           |    1 
 mm/vmalloc.c                        |    1 
 11 files changed, 336 insertions(+), 2 deletions(-)

Index: linux-2.6/Documentation/kernel-parameters.txt
===================================================================
@@ -554,6 +554,8 @@ and is between 256 and 4096 characters. 
 			1 will print _a lot_ more information - normally
 			only useful to kernel developers.
 
+	debug_objects	[KNL] Enable object debugging
+
 	decnet.addr=	[HW,NET]
 			Format: <area>[,<node>]
 			See also Documentation/networking/decnet.txt.

Index: linux-2.6/include/linux/mm.h
===================================================================
@@ -11,6 +11,7 @@
 #include <linux/rbtree.h>
 #include <linux/prio_tree.h>
 #include <linux/debug_locks.h>
+#include <linux/debugobjects.h>
 #include <linux/mm_types.h>
 
 struct mempolicy;

Index: linux-2.6/init/main.c
===================================================================
@@ -52,6 +52,7 @@
 #include <linux/unwind.h>
 #include <linux/buffer_head.h>
 #include <linux/debug_locks.h>
+#include <linux/debugobjects.h>
 #include <linux/lockdep.h>
 #include <linux/pid_namespace.h>
 #include <linux/device.h>

@@ -523,6 +524,7 @@ asmlinkage void __init start_kernel(void
 	 */
 	unwind_init();
 	lockdep_init();
+	debug_objects_init();
 	cgroup_init_early();
 
 	local_irq_disable();

Index: linux-2.6/lib/Kconfig.debug
===================================================================
@@ -183,6 +183,22 @@ config TIMER_STATS
 	  (it defaults to deactivated on bootup and will only be activated
 	  if some application like powertop activates it explicitly).
 
+config DEBUG_OBJECT_OPS
+       bool "Debug object operations"
+       depends on DEBUG_KERNEL
+       help
+	 If you say Y here, additional code will be inserted into the
+	 kernel to validate operations on various objects.
+
+config DEBUG_OBJECT_FREE
+       bool "Debug objects in freed memory"
+       depends on DEBUG_OBJECT_OPS
+       help
+         This enables checks whether a k/v free operation frees an area
+	 which contains an object which has not been deactivated
+	 properly.  This can make kmalloc/kfree-intensive workloads
+	 much slower.
+
 config DEBUG_SLAB
 	bool "Debug slab memory allocations"
 	depends on DEBUG_KERNEL && SLAB

Index: linux-2.6/lib/Makefile
===================================================================
@@ -36,6 +36,7 @@ obj-$(CONFIG_LOCK_KERNEL) += kernel_lock
 obj-$(CONFIG_PLIST) += plist.o
 obj-$(CONFIG_DEBUG_PREEMPT) += smp_processor_id.o
 obj-$(CONFIG_DEBUG_LIST) += list_debug.o
+obj-$(CONFIG_DEBUG_OBJECT_OPS) += debugobjects.o
 
 ifneq ($(CONFIG_HAVE_DEC_LOCK),y)
   lib-y += dec_and_lock.o

Index: linux-2.6/mm/page_alloc.c
===================================================================
@@ -524,8 +524,11 @@ static void __free_pages_ok(struct page 
 	if (reserved)
 		return;
 
-	if (!PageHighMem(page))
+	if (!PageHighMem(page)) {
 		debug_check_no_locks_freed(page_address(page),PAGE_SIZE<<order);
+		debug_check_no_obj_freed(page_address(page),
+					   PAGE_SIZE << order);
+	}
 	arch_free_page(page, order);
 	kernel_map_pages(page, 1 << order, 0);
 

@@ -986,8 +989,10 @@ static void free_hot_cold_page(struct pa
 	if (free_pages_check(page))
 		return;
 
-	if (!PageHighMem(page))
+	if (!PageHighMem(page)) {
 		debug_check_no_locks_freed(page_address(page), PAGE_SIZE);
+		debug_check_no_obj_freed(page_address(page), PAGE_SIZE);
+	}
 	VM_BUG_ON(page_get_page_cgroup(page));
 	arch_free_page(page, 0);
 	kernel_map_pages(page, 1, 0);

Index: linux-2.6/mm/slab.c
===================================================================
@@ -3766,6 +3766,7 @@ void kmem_cache_free(struct kmem_cache *
 
 	local_irq_save(flags);
 	debug_check_no_locks_freed(objp, obj_size(cachep));
+	debug_check_no_obj_freed(objp, obj_size(cachep));
 	__cache_free(cachep, objp);
 	local_irq_restore(flags);
 }

@@ -3791,6 +3792,7 @@ void kfree(const void *objp)
 	kfree_debugcheck(objp);
 	c = virt_to_cache(objp);
 	debug_check_no_locks_freed(objp, obj_size(c));
+	debug_check_no_obj_freed(objp, obj_size(c));
 	__cache_free(c, (void *)objp);
 	local_irq_restore(flags);
 }

Index: linux-2.6/mm/slub.c
===================================================================
@@ -1725,6 +1725,7 @@ static __always_inline void slab_free(st
 
 	local_irq_save(flags);
 	debug_check_no_locks_freed(object, s->objsize);
+	debug_check_no_obj_freed(object, s->objsize);
 	c = get_cpu_slab(s, smp_processor_id());
 	if (likely(page == c->page && c->node >= 0)) {
 		object[c->offset] = c->freelist;

Index: linux-2.6/mm/vmalloc.c
===================================================================
@@ -383,6 +383,7 @@ static void __vunmap(const void *addr, i
 	}
 
 	debug_check_no_locks_freed(addr, area->size);
+	debug_check_no_obj_freed(addr, area->size);
 
 	if (deallocate_pages) {
 		int i;

hm.

The enabled-via-command-line thing is a bit sad. I guess runtime switchability would be hard.

The proof of this pudding is "how many subsystems use it". If things like the fault-injection framework are a guide, the answer is "zero unless Thomas does it". Call me an experienced cynic.

Yes, keeping track of such stuff from some random state is not really a good idea.

Hey, I'm as much a cynic as you. It just bothered me to hack this solely into the timer code with the knowledge that there are other potential users lurking.

And I want to have it in the timer code for a simple reason: Everytime when the timer list code explodes due to some stupid timer_list user, I'm the moron who has to apply hackery to help the users to identify the root cause. This happened more than 5 times in the last 3 month and I'm fed up with keeping my ugly debug hackery up to date and instruct bug reporters how to use it. The delta to get down to the cause of the problem in the example case is:

one mail versus five.
zero patch vs. finding and updating the old version

I have better ways to waste my sparse leisure time :)

You can be sure, that I will add the specific debug code to other parts of the kernel whenever I trap over a problem which smells like the kfree'd or reinitialized timer wreckage.

Will do.

I did not bother with a dynamic register interface before getting some feedback on the idea in general. Will do when there is some agreement that this is a useful infrastructure in general.

Well, I'm lazy as hell and I found the debug_locks.h include already, which was added for the same reason: not adding the include to all the affected files in mm/

Btw. DEBUG_LOCK_ALLOC is a perfect candidate to move over to this as the current code only detects locks held by the calling thread, while debugobjects detects also a lock held by any owner.

The hash is not a randomized hash as one would expect. It's purely generated from the object address to simplify the lookup during the free check. So the power of 2 size is a good thing :) /me adds comment.

Good point.

Same here. As usual I copied it from some other place assuming that it was correct there. Will check.

Hehehe.

Thanks for the review,

tglx

Power of two buckets work when used along with a golden ratio based hash map - as done by linux/hash.h.

Power of two hash maps otoh suck royally.

Well, using a real hash algorithm sucks royally if you need to do the reverse check on *free(). With the direct object address to hash bucket mapping we have usually only one bucket to look at, otherwise we end up looking at multiple buckets and doing the list walk on each of them. We have to decide which suckage is worse :)

Thanks,
tglx

Add calls to the generic object debugging infrastructure and provide a fixup function which allows to keep the system alive when recoverable problems have been detected by the object debugging core code. Add a selftest, which covers the two possible mistakes: free/init of an active timer.

---
 include/linux/debugobjects.h |    1 
 include/linux/timer.h        |   22 +++++++++++
 kernel/timer.c               |   85 +++++++++++++++++++++++++++++++++++++++++++
 lib/Kconfig.debug            |    7 +++
 lib/debugobjects.c           |   18 ++++++++-
 5 files changed, 131 insertions(+), 2 deletions(-)

Index: linux-2.6/include/linux/debugobjects.h
===================================================================
@@ -14,6 +14,7 @@ enum debug_obj_op {
 
 enum {
 	ODEBUG_TYPE_UNKNOWN,
+	ODEBUG_TYPE_TIMER,
 	ODEBUG_MAX_TYPES
 };
 

Index: linux-2.6/include/linux/timer.h
===================================================================
@@ -4,6 +4,7 @@
 #include <linux/list.h>
 #include <linux/ktime.h>
 #include <linux/stddef.h>
+#include <linux/debugobjects.h>
 
 struct tvec_base;
 

@@ -20,6 +21,9 @@ struct timer_list {
 	char start_comm[16];
 	int start_pid;
 #endif
+#ifdef CONFIG_DEBUG_OBJECT_TIMERS
+	struct debug_obj dobj;
+#endif
 };
 
 extern struct tvec_base boot_tvec_bases;

@@ -164,5 +168,23 @@ unsigned long __round_jiffies_relative(u
 unsigned long round_jiffies(unsigned long j);
 unsigned long round_jiffies_relative(unsigned long j);
 
+#ifdef CONFIG_DEBUG_OBJECT_TIMERS
+static inline void
+debug_timer_object_op(struct timer_list *timer, enum debug_obj_op mode)
+{
+	timer->dobj.type = ODEBUG_TYPE_TIMER;
+	debug_object_op(&timer->dobj, mode);
+}
+extern int timer_fixup_object(struct debug_obj *obj, enum debug_obj_op mode);
+extern int timer_debug_object_selftest(void);
+#else
+static inline void
+debug_timer_object_op(struct timer_list *timer, enum debug_obj_op mode)
+{
+}
+# define timer_fixup_object NULL
+static inline int timer_debug_object_selftest(void) { return 0; }
+#endif
+
 
 #endif

Index: linux-2.6/lib/Kconfig.debug
===================================================================
@@ -199,6 +199,13 @@ config DEBUG_OBJECT_FREE
 	 properly.  This can make kmalloc/kfree-intensive workloads
 	 much slower.
 
+config DEBUG_OBJECT_TIMERS
+	bool "Debug timer objects"
+       	depends on DEBUG_OBJECT_OPS
+       	help
+	  If you say Y here, additional code will be inserted into the
+	  timer routines to validate the timer operations.
+
 config DEBUG_SLAB
 	bool "Debug slab memory allocations"
 	depends on DEBUG_KERNEL && SLAB

Index: linux-2.6/lib/debugobjects.c
===================================================================
@@ -12,6 +12,7 @@
 #include <linux/debugfs.h>
 #include <linux/debugobjects.h>
 #include <linux/seq_file.h>
+#include <linux/timer.h>
 
 #define ODEBUG_HASH_SIZE	4096
 #define ODEBUG_HASH_MASK	(ODEBUG_HASH_SIZE - 1)

@@ -48,11 +49,13 @@ static struct odebug *object_get_hash(un
 }
 
 static const void * const debug_fixup[ODEBUG_MAX_TYPES] = {
+	[ODEBUG_TYPE_TIMER] = timer_fixup_object,
 };
 
 static const char * const obj_types[ODEBUG_MAX_TYPES] = {
 
 	[ODEBUG_TYPE_UNKNOWN] = "unknown type",
+	[ODEBUG_TYPE_TIMER] = "timer_list",
 };
 
 static void debug_print_object(struct debug_obj *obj, char *msg)

@@ -246,11 +249,22 @@ void __init debug_objects_init(void)
 
 int __init debug_objects_do_selftest(void)
 {
+	int res;
+
 	if (!debug_objects_enabled)
 		return 0;
 
 	debug_objects_init_debugfs();
-	printk(KERN_INFO "ODEBUG: Selftest pass\n");
-	return 0;
+
+	debug_objects_selftest = 1;
+
+	res = timer_debug_object_selftest();
+
+	debug_objects_selftest = 0;
+
+	if (!res)
+		printk(KERN_INFO "ODEBUG: Selftest pass\n");
+
+	return res;
 }
 __initcall(debug_objects_do_selftest);

Ah, this looks nice. For kobjects I would like to track the above, as well as:
- use of initialized objects
- use of "freed" objects
- objects that are never destroyed, yet the code controlling them thinks they are.

I say "freed" as sometimes kobjects are in static structures and are not in memory that ends up being kfree() so slab poisoning doesn't help.

Do you think that would be able to worked into this framework? At first glance, it seems like it would be easy to add, but would like to make sure.

If so, I'll gladly add this to the kobjects to help with issues there.

thanks,

greg k-h

Good point. I try to come up with the infrastructure for that.

Yes, that should be possible

kobjects came to my mind as well, when I was thinking about possible use cases.

Thanks,

tglx

Nice idea to make this generic.

If you push this it would be also good to consider some variant of the "crasher" code that is in SUSE Kernels to include with it.

It was originally written by Chris Mason and it also makes it easier to stabilize such bugs. The basic idea is that a background thread allocates lots of slabs and pages always poisons them and checks them in the background. If someone corrupts memory that is noticed earlier then

Basically it extends what your patchkit is doing to free memory too.

Chris' old patch:
http://firstfloor.org/~andi/crasher-26.diff
(various variants of that have existed over time)

-Andi