[PATCHv2] kmemleak: Add option to print warnings to dmesg

[PATCHv2] kmemleak: Add option to print warnings to dmesg

[Vincent Whitchurch]

Currently, kmemleak only prints the number of suspected leaks to dmesg
but requires the user to read a debugfs file to get the actual stack
traces of the objects' allocation points.  Add an option to print the
full object information to dmesg too.  This allows easier integration of
kmemleak into automated test systems since those kind of systems
presumably already save kernel logs.

Signed-off-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
---
v2: Print hex dump too.

 lib/Kconfig.debug |  9 +++++++++
 mm/kmemleak.c     | 37 ++++++++++++++++++++++++++++++-------
 2 files changed, 39 insertions(+), 7 deletions(-)

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index ab1b599202bc..9a3fc905b8bd 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -593,6 +593,15 @@ config DEBUG_KMEMLEAK_DEFAULT_OFF
 	  Say Y here to disable kmemleak by default. It can then be enabled
 	  on the command line via kmemleak=on.
 
+config DEBUG_KMEMLEAK_WARN
+	bool "Print kmemleak object warnings to log buffer"
+	depends on DEBUG_KMEMLEAK
+	help
+	  Say Y here to make kmemleak print information about unreferenced
+	  objects (including stacktraces) as warnings to the kernel log buffer.
+	  Otherwise this information is only available by reading the kmemleak
+	  debugfs file.
+
 config DEBUG_STACK_USAGE
 	bool "Stack utilization instrumentation"
 	depends on DEBUG_KERNEL && !IA64
diff --git a/mm/kmemleak.c b/mm/kmemleak.c
index 9a085d525bbc..22662715a3dc 100644
--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -181,6 +181,7 @@ struct kmemleak_object {
 /* flag set to not scan the object */
 #define OBJECT_NO_SCAN		(1 << 2)
 
+#define HEX_PREFIX		"    "
 /* number of bytes to print per line; must be 16 or 32 */
 #define HEX_ROW_SIZE		16
 /* number of bytes to print at a time (1, 2, 4, 8) */
@@ -299,6 +300,25 @@ static void kmemleak_disable(void);
 	kmemleak_disable();		\
 } while (0)
 
+#define warn_or_seq_printf(seq, fmt, ...)	do {	\
+	if (seq)					\
+		seq_printf(seq, fmt, ##__VA_ARGS__);	\
+	else						\
+		pr_warn(fmt, ##__VA_ARGS__);		\
+} while (0)
+
+static void warn_or_seq_hex_dump(struct seq_file *seq, int prefix_type,
+				 int rowsize, int groupsize, const void *buf,
+				 size_t len, bool ascii)
+{
+	if (seq)
+		seq_hex_dump(seq, HEX_PREFIX, prefix_type, rowsize, groupsize,
+			     buf, len, ascii);
+	else
+		print_hex_dump(KERN_WARNING, pr_fmt(HEX_PREFIX), prefix_type,
+			       rowsize, groupsize, buf, len, ascii);
+}
+
 /*
  * Printing of the objects hex dump to the seq file. The number of lines to be
  * printed is limited to HEX_MAX_LINES to prevent seq file spamming. The
@@ -314,10 +334,10 @@ static void hex_dump_object(struct seq_file *seq,
 	/* limit the number of lines to HEX_MAX_LINES */
 	len = min_t(size_t, object->size, HEX_MAX_LINES * HEX_ROW_SIZE);
 
-	seq_printf(seq, "  hex dump (first %zu bytes):\n", len);
+	warn_or_seq_printf(seq, "  hex dump (first %zu bytes):\n", len);
 	kasan_disable_current();
-	seq_hex_dump(seq, "    ", DUMP_PREFIX_NONE, HEX_ROW_SIZE,
-		     HEX_GROUP_SIZE, ptr, len, HEX_ASCII);
+	warn_or_seq_hex_dump(seq, DUMP_PREFIX_NONE, HEX_ROW_SIZE,
+			     HEX_GROUP_SIZE, ptr, len, HEX_ASCII);
 	kasan_enable_current();
 }
 
@@ -365,17 +385,17 @@ static void print_unreferenced(struct seq_file *seq,
 	int i;
 	unsigned int msecs_age = jiffies_to_msecs(jiffies - object->jiffies);
 
-	seq_printf(seq, "unreferenced object 0x%08lx (size %zu):\n",
+	warn_or_seq_printf(seq, "unreferenced object 0x%08lx (size %zu):\n",
 		   object->pointer, object->size);
-	seq_printf(seq, "  comm \"%s\", pid %d, jiffies %lu (age %d.%03ds)\n",
+	warn_or_seq_printf(seq, "  comm \"%s\", pid %d, jiffies %lu (age %d.%03ds)\n",
 		   object->comm, object->pid, object->jiffies,
 		   msecs_age / 1000, msecs_age % 1000);
 	hex_dump_object(seq, object);
-	seq_printf(seq, "  backtrace:\n");
+	warn_or_seq_printf(seq, "  backtrace:\n");
 
 	for (i = 0; i < object->trace_len; i++) {
 		void *ptr = (void *)object->trace[i];
-		seq_printf(seq, "    [<%p>] %pS\n", ptr, ptr);
+		warn_or_seq_printf(seq, "    [<%p>] %pS\n", ptr, ptr);
 	}
 }
 
@@ -1598,6 +1618,9 @@ static void kmemleak_scan(void)
 		if (unreferenced_object(object) &&
 		    !(object->flags & OBJECT_REPORTED)) {
 			object->flags |= OBJECT_REPORTED;
+#ifdef CONFIG_DEBUG_KMEMLEAK_WARN
+			print_unreferenced(NULL, object);
+#endif
 			new_leaks++;
 		}
 		spin_unlock_irqrestore(&object->lock, flags);
-- 
2.11.0

Re: [PATCHv2] kmemleak: Add option to print warnings to dmesg

[Andrew Morton]

On Mon, 27 Aug 2018 10:38:21 +0200 Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:

> Currently, kmemleak only prints the number of suspected leaks to dmesg
> but requires the user to read a debugfs file to get the actual stack
> traces of the objects' allocation points.  Add an option to print the
> full object information to dmesg too.  This allows easier integration of
> kmemleak into automated test systems since those kind of systems
> presumably already save kernel logs.

"presumably" is a bit rubbery.  Are you sure this change is sufficienty
useful to justify including it?  Do you have use-cases for it?

> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -593,6 +593,15 @@ config DEBUG_KMEMLEAK_DEFAULT_OFF
>  	  Say Y here to disable kmemleak by default. It can then be enabled
>  	  on the command line via kmemleak=on.
>  
> +config DEBUG_KMEMLEAK_WARN
> +	bool "Print kmemleak object warnings to log buffer"
> +	depends on DEBUG_KMEMLEAK
> +	help
> +	  Say Y here to make kmemleak print information about unreferenced
> +	  objects (including stacktraces) as warnings to the kernel log buffer.
> +	  Otherwise this information is only available by reading the kmemleak
> +	  debugfs file.

Why add the config option?  Why not simply make the change for all
configs?

>  config DEBUG_STACK_USAGE
>  	bool "Stack utilization instrumentation"
>  	depends on DEBUG_KERNEL && !IA64
> diff --git a/mm/kmemleak.c b/mm/kmemleak.c
> index 9a085d525bbc..22662715a3dc 100644
> --- a/mm/kmemleak.c
> +++ b/mm/kmemleak.c
> @@ -181,6 +181,7 @@ struct kmemleak_object {
>  /* flag set to not scan the object */
>  #define OBJECT_NO_SCAN		(1 << 2)
>  
> +#define HEX_PREFIX		"    "
>  /* number of bytes to print per line; must be 16 or 32 */
>  #define HEX_ROW_SIZE		16
>  /* number of bytes to print at a time (1, 2, 4, 8) */
> @@ -299,6 +300,25 @@ static void kmemleak_disable(void);
>  	kmemleak_disable();		\
>  } while (0)
>  
> +#define warn_or_seq_printf(seq, fmt, ...)	do {	\
> +	if (seq)					\
> +		seq_printf(seq, fmt, ##__VA_ARGS__);	\
> +	else						\
> +		pr_warn(fmt, ##__VA_ARGS__);		\
> +} while (0)
> +
> +static void warn_or_seq_hex_dump(struct seq_file *seq, int prefix_type,
> +				 int rowsize, int groupsize, const void *buf,
> +				 size_t len, bool ascii)
> +{
> +	if (seq)
> +		seq_hex_dump(seq, HEX_PREFIX, prefix_type, rowsize, groupsize,
> +			     buf, len, ascii);
> +	else
> +		print_hex_dump(KERN_WARNING, pr_fmt(HEX_PREFIX), prefix_type,
> +			       rowsize, groupsize, buf, len, ascii);
> +}

This will print to the logs OR to the debugfs file, won't it?

If so, should we continue to print to the debugfs file when we're also
printing to the log?  That sounds potentially useful and will avoid
breaking things which expect the debugfs file to still be working.

>
> ...
>

Re: [PATCHv2] kmemleak: Add option to print warnings to dmesg

[Vincent Whitchurch]

On Mon, Aug 27, 2018 at 03:16:41PM -0700, Andrew Morton wrote:
> On Mon, 27 Aug 2018 10:38:21 +0200 Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:
> 
> > Currently, kmemleak only prints the number of suspected leaks to dmesg
> > but requires the user to read a debugfs file to get the actual stack
> > traces of the objects' allocation points.  Add an option to print the
> > full object information to dmesg too.  This allows easier integration of
> > kmemleak into automated test systems since those kind of systems
> > presumably already save kernel logs.
> 
> "presumably" is a bit rubbery.  Are you sure this change is sufficienty
> useful to justify including it?  Do you have use-cases for it?

We (like every one else) have automated test infrastructure which test
our Linux systems.  With this option, running our tests with kmemleak is
as simple as enabling kmemleak and this option; the test infrastructure
knows how to save kernel logs, which will now include kmemleak reports.
Without this option, the test infrastructure needs to be specifically
taught to read out the kmemleak debugfs file.  Removing this need for
special handling makes kmemleak more similar to other kernel debug
options (slab debugging, debug objects, etc).

> 
> > --- a/lib/Kconfig.debug
> > +++ b/lib/Kconfig.debug
> > @@ -593,6 +593,15 @@ config DEBUG_KMEMLEAK_DEFAULT_OFF
> >  	  Say Y here to disable kmemleak by default. It can then be enabled
> >  	  on the command line via kmemleak=on.
> >  
> > +config DEBUG_KMEMLEAK_WARN
> > +	bool "Print kmemleak object warnings to log buffer"
> > +	depends on DEBUG_KMEMLEAK
> > +	help
> > +	  Say Y here to make kmemleak print information about unreferenced
> > +	  objects (including stacktraces) as warnings to the kernel log buffer.
> > +	  Otherwise this information is only available by reading the kmemleak
> > +	  debugfs file.
> 
> Why add the config option?  Why not simply make the change for all
> configs?

No particular reason other than preserving the current behaviour for
existing users.  I can remove the config option if Catalin is fine with
it.

> 
> >  config DEBUG_STACK_USAGE
> >  	bool "Stack utilization instrumentation"
> >  	depends on DEBUG_KERNEL && !IA64
> > diff --git a/mm/kmemleak.c b/mm/kmemleak.c
> > index 9a085d525bbc..22662715a3dc 100644
> > --- a/mm/kmemleak.c
> > +++ b/mm/kmemleak.c
> > @@ -181,6 +181,7 @@ struct kmemleak_object {
> >  /* flag set to not scan the object */
> >  #define OBJECT_NO_SCAN		(1 << 2)
> >  
> > +#define HEX_PREFIX		"    "
> >  /* number of bytes to print per line; must be 16 or 32 */
> >  #define HEX_ROW_SIZE		16
> >  /* number of bytes to print at a time (1, 2, 4, 8) */
> > @@ -299,6 +300,25 @@ static void kmemleak_disable(void);
> >  	kmemleak_disable();		\
> >  } while (0)
> >  
> > +#define warn_or_seq_printf(seq, fmt, ...)	do {	\
> > +	if (seq)					\
> > +		seq_printf(seq, fmt, ##__VA_ARGS__);	\
> > +	else						\
> > +		pr_warn(fmt, ##__VA_ARGS__);		\
> > +} while (0)
> > +
> > +static void warn_or_seq_hex_dump(struct seq_file *seq, int prefix_type,
> > +				 int rowsize, int groupsize, const void *buf,
> > +				 size_t len, bool ascii)
> > +{
> > +	if (seq)
> > +		seq_hex_dump(seq, HEX_PREFIX, prefix_type, rowsize, groupsize,
> > +			     buf, len, ascii);
> > +	else
> > +		print_hex_dump(KERN_WARNING, pr_fmt(HEX_PREFIX), prefix_type,
> > +			       rowsize, groupsize, buf, len, ascii);
> > +}
> 
> This will print to the logs OR to the debugfs file, won't it?

No, the information is always available in the debugfs file, even after
this patch.  The dmesg printing is in addition to that.  The code is
called with and without seq == NULL in different code paths.

Re: [PATCHv2] kmemleak: Add option to print warnings to dmesg

[Catalin Marinas]

On Tue, Aug 28, 2018 at 12:14:12PM +0200, Vincent Whitchurch wrote:
> On Mon, Aug 27, 2018 at 03:16:41PM -0700, Andrew Morton wrote:
> > On Mon, 27 Aug 2018 10:38:21 +0200 Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:
> > > --- a/lib/Kconfig.debug
> > > +++ b/lib/Kconfig.debug
> > > @@ -593,6 +593,15 @@ config DEBUG_KMEMLEAK_DEFAULT_OFF
> > >  	  Say Y here to disable kmemleak by default. It can then be enabled
> > >  	  on the command line via kmemleak=on.
> > >  
> > > +config DEBUG_KMEMLEAK_WARN
> > > +	bool "Print kmemleak object warnings to log buffer"
> > > +	depends on DEBUG_KMEMLEAK
> > > +	help
> > > +	  Say Y here to make kmemleak print information about unreferenced
> > > +	  objects (including stacktraces) as warnings to the kernel log buffer.
> > > +	  Otherwise this information is only available by reading the kmemleak
> > > +	  debugfs file.
> > 
> > Why add the config option?  Why not simply make the change for all
> > configs?
> 
> No particular reason other than preserving the current behaviour for
> existing users.  I can remove the config option if Catalin is fine with
> it.

IIRC, in the early kmemleak days, people complained about it being to
noisy (the false positives rate was also much higher), so the default
behaviour was changed to monitor (almost) quietly with the details
available via debugfs. I'd like to keep this default behaviour but we
could have a "verbose" command via both debugfs and kernel parameter (as
we do with "off" and "on"). Would this work for you?

-- 
Catalin

Re: [PATCHv2] kmemleak: Add option to print warnings to dmesg

[Vincent Whitchurch]

On Tue, Aug 28, 2018 at 11:26:22AM +0100, Catalin Marinas wrote:
> On Tue, Aug 28, 2018 at 12:14:12PM +0200, Vincent Whitchurch wrote:
> > On Mon, Aug 27, 2018 at 03:16:41PM -0700, Andrew Morton wrote:
> > > On Mon, 27 Aug 2018 10:38:21 +0200 Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:
> > > > +config DEBUG_KMEMLEAK_WARN
> > > > +	bool "Print kmemleak object warnings to log buffer"
> > > > +	depends on DEBUG_KMEMLEAK
> > > > +	help
> > > > +	  Say Y here to make kmemleak print information about unreferenced
> > > > +	  objects (including stacktraces) as warnings to the kernel log buffer.
> > > > +	  Otherwise this information is only available by reading the kmemleak
> > > > +	  debugfs file.
> > > 
> > > Why add the config option?  Why not simply make the change for all
> > > configs?
> > 
> > No particular reason other than preserving the current behaviour for
> > existing users.  I can remove the config option if Catalin is fine with
> > it.
> 
> IIRC, in the early kmemleak days, people complained about it being to
> noisy (the false positives rate was also much higher), so the default
> behaviour was changed to monitor (almost) quietly with the details
> available via debugfs. I'd like to keep this default behaviour but we
> could have a "verbose" command via both debugfs and kernel parameter (as
> we do with "off" and "on"). Would this work for you?

Either a config option or a parameter are usable for me.  How about
something like this?  It can be enabled with kmemleak.verbose=1 or "echo
1 > /sys/module/kmemleak/parameters/verbose":

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 9a3fc905b8bd..ab1b599202bc 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -593,15 +593,6 @@ config DEBUG_KMEMLEAK_DEFAULT_OFF
 	  Say Y here to disable kmemleak by default. It can then be enabled
 	  on the command line via kmemleak=on.
 
-config DEBUG_KMEMLEAK_WARN
-	bool "Print kmemleak object warnings to log buffer"
-	depends on DEBUG_KMEMLEAK
-	help
-	  Say Y here to make kmemleak print information about unreferenced
-	  objects (including stacktraces) as warnings to the kernel log buffer.
-	  Otherwise this information is only available by reading the kmemleak
-	  debugfs file.
-
 config DEBUG_STACK_USAGE
 	bool "Stack utilization instrumentation"
 	depends on DEBUG_KERNEL && !IA64
diff --git a/mm/kmemleak.c b/mm/kmemleak.c
index 22662715a3dc..c91d43738596 100644
--- a/mm/kmemleak.c
+++ b/mm/kmemleak.c
@@ -86,6 +86,7 @@
 #include <linux/seq_file.h>
 #include <linux/cpumask.h>
 #include <linux/spinlock.h>
+#include <linux/module.h>
 #include <linux/mutex.h>
 #include <linux/rcupdate.h>
 #include <linux/stacktrace.h>
@@ -236,6 +237,9 @@ static int kmemleak_skip_disable;
 /* If there are leaks that can be reported */
 static bool kmemleak_found_leaks;
 
+static bool kmemleak_verbose;
+module_param_named(verbose, kmemleak_verbose, bool, 0600);
+
 /*
  * Early object allocation/freeing logging. Kmemleak is initialized after the
  * kernel allocator. However, both the kernel allocator and kmemleak may
@@ -1618,9 +1622,10 @@ static void kmemleak_scan(void)
 		if (unreferenced_object(object) &&
 		    !(object->flags & OBJECT_REPORTED)) {
 			object->flags |= OBJECT_REPORTED;
-#ifdef CONFIG_DEBUG_KMEMLEAK_WARN
-			print_unreferenced(NULL, object);
-#endif
+
+			if (kmemleak_verbose)
+				print_unreferenced(NULL, object);
+
 			new_leaks++;
 		}
 		spin_unlock_irqrestore(&object->lock, flags);

Re: [PATCHv2] kmemleak: Add option to print warnings to dmesg

[Catalin Marinas]

On Thu, Aug 30, 2018 at 09:43:27AM +0200, Vincent Whitchurch wrote:
> On Tue, Aug 28, 2018 at 11:26:22AM +0100, Catalin Marinas wrote:
> > On Tue, Aug 28, 2018 at 12:14:12PM +0200, Vincent Whitchurch wrote:
> > > On Mon, Aug 27, 2018 at 03:16:41PM -0700, Andrew Morton wrote:
> > > > On Mon, 27 Aug 2018 10:38:21 +0200 Vincent Whitchurch <vincent.whitchurch@axis.com> wrote:
> > > > > +config DEBUG_KMEMLEAK_WARN
> > > > > +	bool "Print kmemleak object warnings to log buffer"
> > > > > +	depends on DEBUG_KMEMLEAK
> > > > > +	help
> > > > > +	  Say Y here to make kmemleak print information about unreferenced
> > > > > +	  objects (including stacktraces) as warnings to the kernel log buffer.
> > > > > +	  Otherwise this information is only available by reading the kmemleak
> > > > > +	  debugfs file.
> > > > 
> > > > Why add the config option?  Why not simply make the change for all
> > > > configs?
> > > 
> > > No particular reason other than preserving the current behaviour for
> > > existing users.  I can remove the config option if Catalin is fine with
> > > it.
> > 
> > IIRC, in the early kmemleak days, people complained about it being to
> > noisy (the false positives rate was also much higher), so the default
> > behaviour was changed to monitor (almost) quietly with the details
> > available via debugfs. I'd like to keep this default behaviour but we
> > could have a "verbose" command via both debugfs and kernel parameter (as
> > we do with "off" and "on"). Would this work for you?
> 
> Either a config option or a parameter are usable for me.  How about
> something like this?  It can be enabled with kmemleak.verbose=1 or "echo
> 1 > /sys/module/kmemleak/parameters/verbose":

Works for me (slightly inconsistent with "echo ... >
/sys/kernel/debug/kmemleak" but a module_param seems to work better here
as it's a configuration rather than an action).

-- 
Catalin