kmemleak: Early log buffer exceeded

kmemleak: Early log buffer exceeded

[Jaswinder Singh Rajput]

Currently this reporting seems not very impressive and not giving much
useful information :

kmemleak: Early log buffer exceeded
kmemleak: Kernel memory leak detector disabled

It should be something like this because it is an error and this will
disable Kernel memory leak detector :

[    0.000173] ------------[ cut here ]------------
[    0.000186] WARNING: at mm/kmemleak.c:726 log_early+0x39/0xa9()
[    0.000189] Hardware name:         
[    0.000192] Early log buffer exceeded, please increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE
[    0.000195] Modules linked in:
[    0.000202] Pid: 0, comm: swapper Not tainted 2.6.31-rc3 #51
[    0.000206] Call Trace:
[    0.000216]  [<c102cf74>] warn_slowpath_common+0x60/0x90
[    0.000222]  [<c102cfd8>] warn_slowpath_fmt+0x24/0x27
[    0.000227]  [<c109614b>] log_early+0x39/0xa9
[    0.000232]  [<c109682d>] kmemleak_alloc+0x41/0x4c
[    0.000241]  [<c1093b63>] __kmalloc+0xcb/0x153
[    0.000247]  [<c1093c04>] alloc_arraycache+0x19/0x50
[    0.000253]  [<c1093e44>] do_tune_cpucache+0x209/0x35d
[    0.000259]  [<c10940ee>] enable_cpucache+0x58/0x9a
[    0.000267]  [<c14bc6e5>] kmem_cache_init_late+0x21/0xc2
[    0.000274]  [<c14a8a20>] start_kernel+0x1e5/0x2ba
[    0.000280]  [<c14a8340>] i386_start_kernel+0x6a/0x6f
[    0.000380] ---[ end trace 4eaa2a86a8e2da22 ]---
[    0.000384] kmemleak: Kernel memory leak detector disabled

Currently default value of DEBUG_KMEMLEAK_EARLY_LOG_SIZE is 400 which
can be easily exceed-able if debugging is on.

These issues can be fixed like this :

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 12327b2..2eaf8bc 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -362,14 +362,15 @@ config DEBUG_KMEMLEAK
 config DEBUG_KMEMLEAK_EARLY_LOG_SIZE
 	int "Maximum kmemleak early log entries"
 	depends on DEBUG_KMEMLEAK
-	range 200 2000
-	default 400
+	range 256 2048
+	default 512
 	help
 	  Kmemleak must track all the memory allocations to avoid
 	  reporting false positives. Since memory may be allocated or
 	  freed before kmemleak is initialised, an early log buffer is
-	  used to store these actions. If kmemleak reports "early log
-	  buffer exceeded", please increase this value.
+	  used to store these actions. You need to increase this value,
+	  if kmemleak reports "Early log buffer exceeded, please increase
+	  DEBUG_KMEMLEAK_EARLY_LOG_SIZE".
 
 config DEBUG_KMEMLEAK_TEST
 	tristate "Simple test for the kernel memory leak detector"
diff --git a/mm/kmemleak.c b/mm/kmemleak.c
index 5aabd41..084e927 100644
--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -722,7 +722,8 @@ static void log_early(int op_type, const void *ptr, size_t size,
 	struct early_log *log;
 
 	if (crt_early_log >= ARRAY_SIZE(early_log)) {
-		pr_warning("Early log buffer exceeded\n");
+		WARN_ONCE(1, KERN_ERR "Early log buffer exceeded, "
+			  "please increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE\n");
 		kmemleak_disable();
 		return;
 	}

--
JSR

Re: kmemleak: Early log buffer exceeded

[Catalin Marinas]

On Wed, 2009-07-15 at 22:47 +0530, Jaswinder Singh Rajput wrote:
> Currently this reporting seems not very impressive and not giving much
> useful information :
> 
> kmemleak: Early log buffer exceeded
> kmemleak: Kernel memory leak detector disabled
> 
> It should be something like this because it is an error and this will
> disable Kernel memory leak detector :
> 
> [    0.000173] ------------[ cut here ]------------
> [    0.000186] WARNING: at mm/kmemleak.c:726 log_early+0x39/0xa9()
> [    0.000189] Hardware name:         
> [    0.000192] Early log buffer exceeded, please increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE
> [    0.000195] Modules linked in:
> [    0.000202] Pid: 0, comm: swapper Not tainted 2.6.31-rc3 #51
> [    0.000206] Call Trace:
> [    0.000216]  [<c102cf74>] warn_slowpath_common+0x60/0x90
> [    0.000222]  [<c102cfd8>] warn_slowpath_fmt+0x24/0x27
> [    0.000227]  [<c109614b>] log_early+0x39/0xa9
> [    0.000232]  [<c109682d>] kmemleak_alloc+0x41/0x4c
> [    0.000241]  [<c1093b63>] __kmalloc+0xcb/0x153
> [    0.000247]  [<c1093c04>] alloc_arraycache+0x19/0x50
> [    0.000253]  [<c1093e44>] do_tune_cpucache+0x209/0x35d
> [    0.000259]  [<c10940ee>] enable_cpucache+0x58/0x9a
> [    0.000267]  [<c14bc6e5>] kmem_cache_init_late+0x21/0xc2
> [    0.000274]  [<c14a8a20>] start_kernel+0x1e5/0x2ba
> [    0.000280]  [<c14a8340>] i386_start_kernel+0x6a/0x6f
> [    0.000380] ---[ end trace 4eaa2a86a8e2da22 ]---
> [    0.000384] kmemleak: Kernel memory leak detector disabled

I'm OK with mentioning DEBUG_KMEMLEAK_EARLY_LOG_SIZE but the stack trace
is not relevant here, it can happen in any place which allocates some
memory.

> Currently default value of DEBUG_KMEMLEAK_EARLY_LOG_SIZE is 400 which
> can be easily exceed-able if debugging is on.

That's why I made it configurable. We can indeed set it to a higher
value but that's after 2.6.31. I have a patch in to mark this buffer as
__initdata so that it is freed.

> These issues can be fixed like this :
> 
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 12327b2..2eaf8bc 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -362,14 +362,15 @@ config DEBUG_KMEMLEAK
>  config DEBUG_KMEMLEAK_EARLY_LOG_SIZE
>  	int "Maximum kmemleak early log entries"
>  	depends on DEBUG_KMEMLEAK
> -	range 200 2000
> -	default 400
> +	range 256 2048
> +	default 512

The power of 2 boundaries is not relevant as this represents the number
of elements in an array rather than a size in bytes.

>  	help
>  	  Kmemleak must track all the memory allocations to avoid
>  	  reporting false positives. Since memory may be allocated or
>  	  freed before kmemleak is initialised, an early log buffer is
> -	  used to store these actions. If kmemleak reports "early log
> -	  buffer exceeded", please increase this value.
> +	  used to store these actions. You need to increase this value,
> +	  if kmemleak reports "Early log buffer exceeded, please increase
> +	  DEBUG_KMEMLEAK_EARLY_LOG_SIZE".
>  
>  config DEBUG_KMEMLEAK_TEST
>  	tristate "Simple test for the kernel memory leak detector"
> diff --git a/mm/kmemleak.c b/mm/kmemleak.c
> index 5aabd41..084e927 100644
> --- a/mm/kmemleak.c
> +++ b/mm/kmemleak.c
> @@ -722,7 +722,8 @@ static void log_early(int op_type, const void *ptr, size_t size,
>  	struct early_log *log;
>  
>  	if (crt_early_log >= ARRAY_SIZE(early_log)) {
> -		pr_warning("Early log buffer exceeded\n");
> +		WARN_ONCE(1, KERN_ERR "Early log buffer exceeded, "
> +			  "please increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE\n");
>  		kmemleak_disable();
>  		return;
>  	}

As I said above, I wouldn't want a stack trace here. Initially, this
code called kmemleak_panic() but changed it since the stack trace isn't
relevant.

Thanks.

-- 
Catalin

kmemleak: Early log buffer exceeded

[Sergey Senozhatsky]

>2. When (crt_early_log >= ARRAY_SIZE(early_log)) == 1 we just can see stack.
>Since we have "full" early_log maybe it'll be helpfull to see it?

Sorry, sent you wrong message. Right one has no 'to see it' part.
I meant 'to do something more than just print stack'.

	Sergey

kmemleak: Early log buffer exceeded

[Sergey Senozhatsky]

Hello.
I can see on my both machines

[    0.000135] kmemleak: Early log buffer exceeded
[    0.000140] Pid: 0, comm: swapper Not tainted 2.6.30-dbginfo-nv-git19 #7
[    0.000144] Call Trace:
[    0.000153]  [<c1418ecc>] ? printk+0x23/0x36
[    0.000160]  [<c10f7c12>] log_early+0xf2/0x110
[    0.000165]  [<c10f8788>] kmemleak_alloc+0x1f8/0x2c0
[    0.000171]  [<c10f28fb>] ? cache_alloc_debugcheck_after+0xeb/0x1e0
[    0.000176]  [<c10f496a>] ? __kmalloc+0xfa/0x240
[    0.000182]  [<c10761fc>] ? trace_hardirqs_on_caller+0x14c/0x1a0
[    0.000187]  [<c10f4a15>] __kmalloc+0x1a5/0x240
[    0.000192]  [<c10f4d8d>] ? alloc_arraycache+0x2d/0x80
[    0.000198]  [<c10f4d8d>] alloc_arraycache+0x2d/0x80
[    0.000203]  [<c10f4e7c>] do_tune_cpucache+0x9c/0x3a0
[    0.000208]  [<c10f5322>] enable_cpucache+0x42/0x110
[    0.000215]  [<c15ff7c4>] kmem_cache_init_late+0x32/0x82
[    0.000221]  [<c15e2995>] start_kernel+0x24c/0x366
[    0.000226]  [<c15e2517>] ? unknown_bootoption+0x0/0x1dd
[    0.000231]  [<c15e2088>] __init_begin+0x88/0xa1

mm/kmemleak.c
static struct early_log early_log[200];

static void log_early(int op_type, const void *ptr, size_t size,
		      int min_count, unsigned long offset, size_t length)
{
...
	if (crt_early_log >= ARRAY_SIZE(early_log)) {
		print  Early log buffer exceeded;
		call dump_stack, etc.

So, my questions are:
1. Is 200 really enough? Why 200 not 512, 1024 (for example)?
//If this has been already discussed - please point me.

2. When (crt_early_log >= ARRAY_SIZE(early_log)) == 1 we just can see stack.
Since we have "full" early_log maybe it'll be helpfull to see it? 
//For example like at void __init kmemleak_init(void)

	Sergey

Re: kmemleak: Early log buffer exceeded

[Catalin Marinas]

On Tue, 2009-06-23 at 22:26 +0100, Sergey Senozhatsky wrote:
> I can see on my both machines
> 
> [    0.000135] kmemleak: Early log buffer exceeded
[...]
> mm/kmemleak.c
> static struct early_log early_log[200];
> 
> static void log_early(int op_type, const void *ptr, size_t size,
>                       int min_count, unsigned long offset, size_t length)
> {
> ...
>         if (crt_early_log >= ARRAY_SIZE(early_log)) {
>                 print  Early log buffer exceeded;
>                 call dump_stack, etc.
> 
> So, my questions are:
> 1. Is 200 really enough? Why 200 not 512, 1024 (for example)?

It seems that in your case it isn't. It is fine on the machines I tested
it on but choosing this figure wasn't too scientific.

I initially had it bigger and marked with the __init attribute to free
it after initialisation but this was causing (harmless) section mismatch
warnings.

What kind of hardware do you have?

> 2. When (crt_early_log >= ARRAY_SIZE(early_log)) == 1 we just can see stack.
> Since we have "full" early_log maybe it'll be helpfull to see it?

I recall allocating this dynamically didn't work properly but I'll give
it another try. Otherwise, I can make it configurable and print a better
message (probably without the stack dump).

-- 
Catalin

Re: kmemleak: Early log buffer exceeded

[Sergey Senozhatsky]

On (06/24/09 10:35), Catalin Marinas wrote:
> > So, my questions are:
> > 1. Is 200 really enough? Why 200 not 512, 1024 (for example)?
> 
> It seems that in your case it isn't. It is fine on the machines I tested
> it on but choosing this figure wasn't too scientific.
> 
> I initially had it bigger and marked with the __init attribute to free
> it after initialisation but this was causing (harmless) section mismatch
> warnings.
>
Hello. 

Why not configure it?

//EXAMPLE
config DEBUG_KMEMLEAK_EARLY_LOG_SIZE
	int "Maximum early log entries"
	range 200 2000
	default "300"
	depends on DEBUG_KMEMLEAK
	help
	  Specify early_log size (200,400,etc.).

kmemleak.c
static struct early_log early_log[CONFIG_DEBUG_KMEMLEAK_EARLY_LOG_SIZE];

(Well, CONFIG_DEBUG_KMEMLEAK_EARLY_LOG_SIZE is a bit ugly.)


> What kind of hardware do you have?
>
Most of time - ASUS F3Jc laptop.

 
> > 2. When (crt_early_log >= ARRAY_SIZE(early_log)) == 1 we just can see stack.
> > Since we have "full" early_log maybe it'll be helpfull to see it?
> 
> I recall allocating this dynamically didn't work properly but I'll give
> it another try. Otherwise, I can make it configurable and print a better
> message (probably without the stack dump).
> 
> -- 
> Catalin
> 

	Sergey

Re: kmemleak: Early log buffer exceeded

[Catalin Marinas]

On Wed, 2009-06-24 at 13:08 +0300, Sergey Senozhatsky wrote:
> On (06/24/09 10:35), Catalin Marinas wrote:
> > > So, my questions are:
> > > 1. Is 200 really enough? Why 200 not 512, 1024 (for example)?
> > 
> > It seems that in your case it isn't. It is fine on the machines I tested
> > it on but choosing this figure wasn't too scientific.
> > 
> > I initially had it bigger and marked with the __init attribute to free
> > it after initialisation but this was causing (harmless) section mismatch
> > warnings.
> 
> Why not configure it?

Yes, that's the best approach for now. As for dynamic allocation,
alloc_bootmem is the only option but it needs more testing to make sure
it doesn't fail in certain circumstances.

> (Well, CONFIG_DEBUG_KMEMLEAK_EARLY_LOG_SIZE is a bit ugly.)

I couldn't come up with a better one either. Here's the patch:


kmemleak: Allow the early log buffer to be configurable.

From: Catalin Marinas <catalin.marinas@arm.com>

Kmemleak needs to track all the memory allocations but some of these
happen before kmemleak is initialised. These are stored in an internal
buffer which may be exceeded in some kernel configurations. This patch
adds a configuration option with a default value of 300 and removes the
stack dump when the kmemleak early log buffer is exceeded.

Signed-off-by: Catalin Marinas <catalin.marinas@arm.com>
---
 lib/Kconfig.debug |   12 ++++++++++++
 mm/kmemleak.c     |    5 +++--
 2 files changed, 15 insertions(+), 2 deletions(-)

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 4c32b1a..5cba26f 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -359,6 +359,18 @@ config DEBUG_KMEMLEAK
 	  In order to access the kmemleak file, debugfs needs to be
 	  mounted (usually at /sys/kernel/debug).
 
+config DEBUG_KMEMLEAK_EARLY_LOG_SIZE
+	int "Maximum kmemleak early log entries"
+	depends on DEBUG_KMEMLEAK
+	range 200 2000
+	default 300
+	help
+	  Kmemleak must track all the memory allocations to avoid
+	  reporting false positives. Since memory may be allocated or
+	  freed before kmemleak is initialised, an early log buffer is
+	  used to store these actions. If kmemleak reports "early log
+	  buffer exceeded", please increase this value.
+
 config DEBUG_KMEMLEAK_TEST
 	tristate "Simple test for the kernel memory leak detector"
 	depends on DEBUG_KMEMLEAK
diff --git a/mm/kmemleak.c b/mm/kmemleak.c
index c96f2c8..17096d1 100644
--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -235,7 +235,7 @@ struct early_log {
 };
 
 /* early logging buffer and current position */
-static struct early_log early_log[200];
+static struct early_log early_log[CONFIG_DEBUG_KMEMLEAK_EARLY_LOG_SIZE];
 static int crt_early_log;
 
 static void kmemleak_disable(void);
@@ -696,7 +696,8 @@ static void log_early(int op_type, const void *ptr, size_t size,
 	struct early_log *log;
 
 	if (crt_early_log >= ARRAY_SIZE(early_log)) {
-		kmemleak_stop("Early log buffer exceeded\n");
+		pr_warning("Early log buffer exceeded\n");
+		kmemleak_disable();
 		return;
 	}
 

Thanks.

-- 
Catalin