[PATCH] kmemleak: Show where early_log issues come from

[PATCH] kmemleak: Show where early_log issues come from

[Catalin Marinas]

Based on initial patch by Steven Rostedt.

Early kmemleak warnings did not show where the actual kmemleak API had
been called from but rather just a backtrace to the kmemleak_init()
function. By having all early kmemleak logs record the stack_trace, we
can have kmemleak_init() write exactly where the problem occurred. This
patch adds the setting of the kmemleak_warning variable every time a
kmemleak warning is issued. The kmemleak_init() function checks this
variable during early log replaying and prints the log trace if there
was any warning.

Reported-by: Steven Rostedt <rostedt@goodmis.org>
Cc: Andrew Morton <akpm@google.com>
Signed-off-by: Catalin Marinas <catalin.marinas@arm.com>
---

Steven, a simpler implementation of your idea. Basically we have
kmemleak_warn() called in several places where errors actually occur. We
can just reuse this for printing the early log information rather than
changing the function prototypes to return an error code.

 mm/kmemleak.c |   37 ++++++++++++++++++++++++++++---------
 1 files changed, 28 insertions(+), 9 deletions(-)

diff --git a/mm/kmemleak.c b/mm/kmemleak.c
index d6880f5..573152e 100644
--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -196,7 +196,9 @@ static atomic_t kmemleak_enabled = ATOMIC_INIT(0);
 static atomic_t kmemleak_initialized = ATOMIC_INIT(0);
 /* enables or disables early logging of the memory operations */
 static atomic_t kmemleak_early_log = ATOMIC_INIT(1);
-/* set if a fata kmemleak error has occurred */
+/* set if a kmemleak warning was issued */
+static atomic_t kmemleak_warning = ATOMIC_INIT(0);
+/* set if a fatal kmemleak error has occurred */
 static atomic_t kmemleak_error = ATOMIC_INIT(0);
 
 /* minimum and maximum address that may be valid pointers */
@@ -259,9 +261,10 @@ static void kmemleak_disable(void);
 /*
  * Print a warning and dump the stack trace.
  */
-#define kmemleak_warn(x...)	do {	\
-	pr_warning(x);			\
-	dump_stack();			\
+#define kmemleak_warn(x...)	do {		\
+	pr_warning(x);				\
+	dump_stack();				\
+	atomic_set(&kmemleak_warning, 1);	\
 } while (0)
 
 /*
@@ -403,8 +406,8 @@ static struct kmemleak_object *lookup_object(unsigned long ptr, int alias)
 		object = prio_tree_entry(node, struct kmemleak_object,
 					 tree_node);
 		if (!alias && object->pointer != ptr) {
-			pr_warning("Found object by alias at 0x%08lx\n", ptr);
-			dump_stack();
+			kmemleak_warn("Found object by alias at 0x%08lx\n",
+				      ptr);
 			dump_object_info(object);
 			object = NULL;
 		}
@@ -811,8 +814,7 @@ static void __init log_early(int op_type, const void *ptr, size_t size,
 	log->ptr = ptr;
 	log->size = size;
 	log->min_count = min_count;
-	if (op_type == KMEMLEAK_ALLOC)
-		log->trace_len = __save_stack_trace(log->trace);
+	log->trace_len = __save_stack_trace(log->trace);
 	crt_early_log++;
 	local_irq_restore(flags);
 }
@@ -1659,6 +1661,17 @@ static int kmemleak_boot_config(char *str)
 }
 early_param("kmemleak", kmemleak_boot_config);
 
+static void __init print_log_trace(struct early_log *log)
+{
+	struct stack_trace trace;
+
+	trace.nr_entries = log->trace_len;
+	trace.entries = log->trace;
+
+	pr_notice("Early log backtrace:\n");
+	print_stack_trace(&trace, 2);
+}
+
 /*
  * Kmemleak initialization.
  */
@@ -1720,7 +1733,13 @@ void __init kmemleak_init(void)
 			kmemleak_no_scan(log->ptr);
 			break;
 		default:
-			WARN_ON(1);
+			kmemleak_warn("Unknown early log operation: %d\n",
+				      log->op_type);
+		}
+
+		if (atomic_read(&kmemleak_warning)) {
+			print_log_trace(log);
+			atomic_set(&kmemleak_warning, 0);
 		}
 	}
 }

Re: [PATCH] kmemleak: Show where early_log issues come from

[Steven Rostedt]

On Wed, 2011-09-28 at 14:07 +0100, Catalin Marinas wrote:
> Based on initial patch by Steven Rostedt.
> 
> Early kmemleak warnings did not show where the actual kmemleak API had
> been called from but rather just a backtrace to the kmemleak_init()
> function. By having all early kmemleak logs record the stack_trace, we
> can have kmemleak_init() write exactly where the problem occurred. This
> patch adds the setting of the kmemleak_warning variable every time a
> kmemleak warning is issued. The kmemleak_init() function checks this
> variable during early log replaying and prints the log trace if there
> was any warning.
> 
> Reported-by: Steven Rostedt <rostedt@goodmis.org>
> Cc: Andrew Morton <akpm@google.com>
> Signed-off-by: Catalin Marinas <catalin.marinas@arm.com>
> ---
> 
> Steven, a simpler implementation of your idea. Basically we have
> kmemleak_warn() called in several places where errors actually occur. We
> can just reuse this for printing the early log information rather than
> changing the function prototypes to return an error code.

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

[PATCH] kmemleak: Show where early_log issues come from

[Steven Rostedt]

I triggered the following warning from kmemleak:

kmemleak: Trying to color unknown object at 0xf5840000 as Grey
Pid: 0, comm: swapper Not tainted 3.0.0-test #12
Call Trace:
 [<c17e34e6>] ? printk+0x1d/0x1f^M
 [<c10e2941>] paint_ptr+0x4f/0x78
 [<c178ab57>] kmemleak_not_leak+0x58/0x7d
 [<c108ae9f>] ? __rcu_read_unlock+0x9/0x7d
 [<c1cdb462>] kmemleak_init+0x19d/0x1e9
 [<c1cbf771>] start_kernel+0x346/0x3ec
 [<c1cbf1b4>] ? loglevel+0x18/0x18
 [<c1cbf0aa>] i386_start_kernel+0xaa/0xb0

The backtrace is from where the problem was detected, not where the
problem occurred. I also noticed that the logs that are stored include a
stack_trace dump. But this trace is only added when ALLOC is done.

The above issues ended up being from the cgroup code calling
kmemleak_not_leak(), which does not store the trace. But that didn't
matter, because even if it did, the trace is not printed out here
leaving the above output still unhelpful in finding where the problem
occurred.

By having all early kmemleak logs record the stack_trace, and by having
the above error message / detection bubble up the call stack that an
error occurred. We can have kmemleak_init() write exactly where the
problem occurred.

With the patch, I now have this:

allocated 8388608 bytes of page_cgroup
please try 'cgroup_disable=memory' option if you don't want memory cgroups
kmemleak: Trying to color unknown object at 0xf5840000 as Grey
Pid: 0, comm: swapper Not tainted 3.0.0-test+ #14
Call Trace:
 [<c17e3516>] ? printk+0x1d/0x1f
 [<c10e2941>] paint_ptr+0x4f/0x7d
 [<c10e32f5>] __kmemleak_not_leak+0x59/0x86
 [<c108ae9f>] ? __rcu_read_unlock+0x9/0x7d
 [<c1cdb48b>] kmemleak_init+0x19d/0x1f4
 [<c1cbf771>] start_kernel+0x346/0x3ec
 [<c1cbf1b4>] ? loglevel+0x18/0x18
 [<c1cbf0aa>] i386_start_kernel+0xaa/0xb0
kmemleak:   object backtrace:
     [<c10e3319>] __kmemleak_not_leak+0x7d/0x86
     [<c178ad87>] kmemleak_not_leak+0xd/0xf
     [<c1cdb0bd>] page_cgroup_init+0x86/0x142
     [<c1cbf76c>] start_kernel+0x341/0x3ec
     [<c1cbf0aa>] i386_start_kernel+0xaa/0xb0
     [<ffffffff>] 0xffffffff

Which would have saved me about an hour in tracking this down.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/mm/kmemleak.c b/mm/kmemleak.c
index aacee45..4ed3b7f 100644
--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -686,7 +686,7 @@ static void paint_it(struct kmemleak_object *object, int color)
 	spin_unlock_irqrestore(&object->lock, flags);
 }
 
-static void paint_ptr(unsigned long ptr, int color)
+static int paint_ptr(unsigned long ptr, int color)
 {
 	struct kmemleak_object *object;
 
@@ -696,28 +696,29 @@ static void paint_ptr(unsigned long ptr, int color)
 			      "at 0x%08lx as %s\n", ptr,
 			      (color == KMEMLEAK_GREY) ? "Grey" :
 			      (color == KMEMLEAK_BLACK) ? "Black" : "Unknown");
-		return;
+		return -1;
 	}
 	paint_it(object, color);
 	put_object(object);
+	return 0;
 }
 
 /*
  * Mark an object permanently as gray-colored so that it can no longer be
  * reported as a leak. This is used in general to mark a false positive.
  */
-static void make_gray_object(unsigned long ptr)
+static int make_gray_object(unsigned long ptr)
 {
-	paint_ptr(ptr, KMEMLEAK_GREY);
+	return paint_ptr(ptr, KMEMLEAK_GREY);
 }
 
 /*
  * Mark the object as black-colored so that it is ignored from scans and
  * reporting.
  */
-static void make_black_object(unsigned long ptr)
+static int make_black_object(unsigned long ptr)
 {
-	paint_ptr(ptr, KMEMLEAK_BLACK);
+	return paint_ptr(ptr, KMEMLEAK_BLACK);
 }
 
 /*
@@ -811,8 +812,7 @@ static void __init log_early(int op_type, const void *ptr, size_t size,
 	log->ptr = ptr;
 	log->size = size;
 	log->min_count = min_count;
-	if (op_type == KMEMLEAK_ALLOC)
-		log->trace_len = __save_stack_trace(log->trace);
+	log->trace_len = __save_stack_trace(log->trace);
 	crt_early_log++;
 	local_irq_restore(flags);
 }
@@ -917,14 +917,20 @@ EXPORT_SYMBOL_GPL(kmemleak_free_part);
  * Calling this function on an object will cause the memory block to no longer
  * be reported as leak and always be scanned.
  */
-void __ref kmemleak_not_leak(const void *ptr)
+static int __kmemleak_not_leak(const void *ptr)
 {
 	pr_debug("%s(0x%p)\n", __func__, ptr);
 
 	if (atomic_read(&kmemleak_enabled) && ptr && !IS_ERR(ptr))
-		make_gray_object((unsigned long)ptr);
+		return make_gray_object((unsigned long)ptr);
 	else if (atomic_read(&kmemleak_early_log))
 		log_early(KMEMLEAK_NOT_LEAK, ptr, 0, 0);
+	return 0;
+}
+
+void __ref kmemleak_not_leak(const void *ptr)
+{
+	__kmemleak_not_leak(ptr);
 }
 EXPORT_SYMBOL(kmemleak_not_leak);
 
@@ -937,14 +943,19 @@ EXPORT_SYMBOL(kmemleak_not_leak);
  * it is known that the corresponding block is not a leak and does not contain
  * any references to other allocated memory blocks.
  */
-void __ref kmemleak_ignore(const void *ptr)
+static int __kmemleak_ignore(const void *ptr)
 {
 	pr_debug("%s(0x%p)\n", __func__, ptr);
 
 	if (atomic_read(&kmemleak_enabled) && ptr && !IS_ERR(ptr))
-		make_black_object((unsigned long)ptr);
+		return make_black_object((unsigned long)ptr);
 	else if (atomic_read(&kmemleak_early_log))
 		log_early(KMEMLEAK_IGNORE, ptr, 0, 0);
+	return 0;
+}
+void __ref kmemleak_ignore(const void *ptr)
+{
+	__kmemleak_ignore(ptr);
 }
 EXPORT_SYMBOL(kmemleak_ignore);
 
@@ -1659,6 +1670,17 @@ static int kmemleak_boot_config(char *str)
 }
 early_param("kmemleak", kmemleak_boot_config);
 
+static void __init print_log_stack(struct early_log *log)
+{
+	struct stack_trace trace;
+
+	trace.nr_entries = log->trace_len;
+	trace.entries = log->trace;
+
+	pr_notice("  object backtrace:\n");
+	print_stack_trace(&trace, 4);
+}
+
 /*
  * Kmemleak initialization.
  */
@@ -1708,10 +1730,12 @@ void __init kmemleak_init(void)
 			kmemleak_free_part(log->ptr, log->size);
 			break;
 		case KMEMLEAK_NOT_LEAK:
-			kmemleak_not_leak(log->ptr);
+			if (__kmemleak_not_leak(log->ptr) < 0)
+				print_log_stack(log);
 			break;
 		case KMEMLEAK_IGNORE:
-			kmemleak_ignore(log->ptr);
+			if (__kmemleak_ignore(log->ptr) < 0)
+				print_log_stack(log);
 			break;
 		case KMEMLEAK_SCAN_AREA:
 			kmemleak_scan_area(log->ptr, log->size, GFP_KERNEL);

Re: [PATCH] kmemleak: Show where early_log issues come from

[Catalin Marinas]

Hi Steven,

On Tue, Jul 26, 2011 at 06:33:56PM +0100, Steven Rostedt wrote:
> The backtrace is from where the problem was detected, not where the
> problem occurred. I also noticed that the logs that are stored include a
> stack_trace dump. But this trace is only added when ALLOC is done.
> 
> The above issues ended up being from the cgroup code calling
> kmemleak_not_leak(), which does not store the trace. But that didn't
> matter, because even if it did, the trace is not printed out here
> leaving the above output still unhelpful in finding where the problem
> occurred.
> 
> By having all early kmemleak logs record the stack_trace, and by having
> the above error message / detection bubble up the call stack that an
> error occurred. We can have kmemleak_init() write exactly where the
> problem occurred.
...
> @@ -1708,10 +1730,12 @@ void __init kmemleak_init(void)
>  			kmemleak_free_part(log->ptr, log->size);
>  			break;
>  		case KMEMLEAK_NOT_LEAK:
> -			kmemleak_not_leak(log->ptr);
> +			if (__kmemleak_not_leak(log->ptr) < 0)
> +				print_log_stack(log);
>  			break;
>  		case KMEMLEAK_IGNORE:
> -			kmemleak_ignore(log->ptr);
> +			if (__kmemleak_ignore(log->ptr) < 0)
> +				print_log_stack(log);
>  			break;
>  		case KMEMLEAK_SCAN_AREA:
>  			kmemleak_scan_area(log->ptr, log->size, GFP_KERNEL);

Thanks for the patch, it makes sense. I was wondering whether we should
extend the above to the other early kmemleak API calls (apart from
KMEMLEAK_ALLOC). Also, to avoid some code duplication, maybe something
like below:

diff --git a/mm/kmemleak.c b/mm/kmemleak.c
index d6880f5..afec4cb 100644
--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -1696,32 +1696,37 @@ void __init kmemleak_init(void)
 	 */
 	for (i = 0; i < crt_early_log; i++) {
 		struct early_log *log = &early_log[i];
+		int ret = 0;
 
 		switch (log->op_type) {
 		case KMEMLEAK_ALLOC:
 			early_alloc(log);
 			break;
 		case KMEMLEAK_FREE:
-			kmemleak_free(log->ptr);
+			ret = __kmemleak_free(log->ptr);
 			break;
 		case KMEMLEAK_FREE_PART:
-			kmemleak_free_part(log->ptr, log->size);
+			ret = __kmemleak_free_part(log->ptr, log->size);
 			break;
 		case KMEMLEAK_NOT_LEAK:
-			kmemleak_not_leak(log->ptr);
+			ret = __kmemleak_not_leak(log->ptr);
 			break;
 		case KMEMLEAK_IGNORE:
-			kmemleak_ignore(log->ptr);
+			ret = __kmemleak_ignore(log->ptr);
 			break;
 		case KMEMLEAK_SCAN_AREA:
-			kmemleak_scan_area(log->ptr, log->size, GFP_KERNEL);
+			ret = __kmemleak_scan_area(log->ptr, log->size,
+						   GFP_KERNEL);
 			break;
 		case KMEMLEAK_NO_SCAN:
-			kmemleak_no_scan(log->ptr);
+			ret = __kmemleak_no_scan(log->ptr);
 			break;
 		default:
 			WARN_ON(1);
 		}
+
+		if (ret < 0)
+			print_log_stack(log);
 	}
 }
 

Thanks.

-- 
Catalin

Re: [PATCH] kmemleak: Show where early_log issues come from

[Steven Rostedt]

On Fri, 2011-08-12 at 10:40 +0100, Catalin Marinas wrote:

> Thanks for the patch, it makes sense. I was wondering whether we should
> extend the above to the other early kmemleak API calls (apart from
> KMEMLEAK_ALLOC). Also, to avoid some code duplication, maybe something
> like below:
> 

Makes sense to me.

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

> +
> +		if (ret < 0)
> +			print_log_stack(log);
>  	}
>  }
>  
> 
> Thanks.
>