[PATCH] dma-debug: print some unfreed allocations

[PATCH] dma-debug: print some unfreed allocations

[Johannes Berg]

From: Johannes Berg <johannes.berg@intel.com>

When a driver unbinds and still has allocations,
we print them out but there's no indication where
they came from. If stacktrace support is built
into the kernel, we can print out their traces.

Unfortunately, if you're unloading the module the
traces will be useless, but once you find such an
error you can manually unbind the device instead
to see where the allocations came from.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
 lib/dma-debug.c |   47 +++++++++++++++++++++++++++++++++++++----------
 1 file changed, 37 insertions(+), 10 deletions(-)

--- a/lib/dma-debug.c	2011-05-10 20:25:11.000000000 +0200
+++ b/lib/dma-debug.c	2011-05-10 20:36:55.000000000 +0200
@@ -649,7 +649,9 @@ out_err:
 	return -ENOMEM;
 }
 
-static int device_dma_allocations(struct device *dev)
+#define DMA_DEBUG_NUM_PRINT_UNFREED		10
+
+static void check_device_dma_allocations(struct device *dev)
 {
 	struct dma_debug_entry *entry;
 	unsigned long flags;
@@ -666,27 +668,52 @@ static int device_dma_allocations(struct
 		spin_unlock(&dma_entry_hash[i].lock);
 	}
 
-	local_irq_restore(flags);
+	if (count > 1) {
+		err_printk(dev, NULL, "DMA-API: device driver has pending "
+			   "DMA allocations while released from device "
+			   "[count=%d]\n", count);
+#ifdef CONFIG_STACKTRACE
+		count = 0;
+		/*
+		 * If we have, print out some stack traces for the allocations.
+		 * In case of module unload, the stack traces will be useless,
+		 * but instead of unloading the module you can manually unbind
+		 * the driver instead and get useful traces.
+		 */
+		printk(KERN_WARNING "Showing traces for %d allocations:\n",
+		       DMA_DEBUG_NUM_PRINT_UNFREED);
+
+		for (i = 0; i < HASH_SIZE; ++i) {
+			spin_lock(&dma_entry_hash[i].lock);
+			list_for_each_entry(entry, &dma_entry_hash[i].list,
+					    list) {
+				if (entry->dev == dev)
+					count += 1;
+				if (count > DMA_DEBUG_NUM_PRINT_UNFREED)
+					break;
+				dump_entry_trace(entry);
+			}
+			spin_unlock(&dma_entry_hash[i].lock);
+
+			if (count > DMA_DEBUG_NUM_PRINT_UNFREED)
+				break;
+		}
+#endif
+	}
 
-	return count;
+	local_irq_restore(flags);
 }
 
 static int dma_debug_device_change(struct notifier_block *nb, unsigned long action, void *data)
 {
 	struct device *dev = data;
-	int count;
 
 	if (global_disable)
 		return 0;
 
 	switch (action) {
 	case BUS_NOTIFY_UNBOUND_DRIVER:
-		count = device_dma_allocations(dev);
-		if (count == 0)
-			break;
-		err_printk(dev, NULL, "DMA-API: device driver has pending "
-				"DMA allocations while released from device "
-				"[count=%d]\n", count);
+		check_device_dma_allocations(dev);
 		break;
 	default:
 		break;

[PATCH v2] dma-debug: print some unfreed allocations

[Johannes Berg]

From: Johannes Berg <johannes.berg@intel.com>

When a driver unbinds and still has allocations,
we print them out but there's no indication where
they came from. If stacktrace support is built
into the kernel, we can print out their traces.

Unfortunately, if you're unloading the module the
traces will be useless, but once you find such an
error you can manually unbind the device instead
to see where the allocations came from.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
v2: fix stupid error -- v1 printed almost everything *BUT* the device I wanted

 lib/dma-debug.c |   48 ++++++++++++++++++++++++++++++++++++++----------
 1 file changed, 38 insertions(+), 10 deletions(-)

--- a/lib/dma-debug.c	2011-05-11 12:44:22.000000000 +0200
+++ b/lib/dma-debug.c	2011-05-11 14:47:02.000000000 +0200
@@ -649,7 +649,9 @@ out_err:
 	return -ENOMEM;
 }
 
-static int device_dma_allocations(struct device *dev)
+#define DMA_DEBUG_NUM_PRINT_UNFREED		10
+
+static void check_device_dma_allocations(struct device *dev)
 {
 	struct dma_debug_entry *entry;
 	unsigned long flags;
@@ -666,27 +668,53 @@ static int device_dma_allocations(struct
 		spin_unlock(&dma_entry_hash[i].lock);
 	}
 
-	local_irq_restore(flags);
+	if (count > 1) {
+		err_printk(dev, NULL, "DMA-API: device driver has pending "
+			   "DMA allocations while released from device "
+			   "[count=%d]\n", count);
+#ifdef CONFIG_STACKTRACE
+		count = 0;
+		/*
+		 * If we have, print out some stack traces for the allocations.
+		 * In case of module unload, the stack traces will be useless,
+		 * but instead of unloading the module you can manually unbind
+		 * the driver instead and get useful traces.
+		 */
+		printk(KERN_WARNING "Showing traces for %d allocations:\n",
+		       DMA_DEBUG_NUM_PRINT_UNFREED);
+
+		for (i = 0; i < HASH_SIZE; ++i) {
+			spin_lock(&dma_entry_hash[i].lock);
+			list_for_each_entry(entry, &dma_entry_hash[i].list,
+					    list) {
+				if (entry->dev != dev)
+					continue;
+				count += 1;
+				if (count > DMA_DEBUG_NUM_PRINT_UNFREED)
+					break;
+				dump_entry_trace(entry);
+			}
+			spin_unlock(&dma_entry_hash[i].lock);
 
-	return count;
+			if (count > DMA_DEBUG_NUM_PRINT_UNFREED)
+				break;
+		}
+#endif
+	}
+
+	local_irq_restore(flags);
 }
 
 static int dma_debug_device_change(struct notifier_block *nb, unsigned long action, void *data)
 {
 	struct device *dev = data;
-	int count;
 
 	if (global_disable)
 		return 0;
 
 	switch (action) {
 	case BUS_NOTIFY_UNBOUND_DRIVER:
-		count = device_dma_allocations(dev);
-		if (count == 0)
-			break;
-		err_printk(dev, NULL, "DMA-API: device driver has pending "
-				"DMA allocations while released from device "
-				"[count=%d]\n", count);
+		check_device_dma_allocations(dev);
 		break;
 	default:
 		break;

Re: [PATCH v2] dma-debug: print some unfreed allocations

[Roedel, Joerg]

On Wed, May 11, 2011 at 08:47:57AM -0400, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>

> +#ifdef CONFIG_STACKTRACE
> +		count = 0;
> +		/*
> +		 * If we have, print out some stack traces for the allocations.
> +		 * In case of module unload, the stack traces will be useless,
> +		 * but instead of unloading the module you can manually unbind
> +		 * the driver instead and get useful traces.
> +		 */
> +		printk(KERN_WARNING "Showing traces for %d allocations:\n",
> +		       DMA_DEBUG_NUM_PRINT_UNFREED);
> +
> +		for (i = 0; i < HASH_SIZE; ++i) {
> +			spin_lock(&dma_entry_hash[i].lock);
> +			list_for_each_entry(entry, &dma_entry_hash[i].list,
> +					    list) {
> +				if (entry->dev != dev)
> +					continue;
> +				count += 1;
> +				if (count > DMA_DEBUG_NUM_PRINT_UNFREED)
> +					break;
> +				dump_entry_trace(entry);
> +			}
> +			spin_unlock(&dma_entry_hash[i].lock);
>  
> -	return count;
> +			if (count > DMA_DEBUG_NUM_PRINT_UNFREED)
> +				break;
> +		}
> +#endif
> +	}
> +
> +	local_irq_restore(flags);
>  }

This is surely useful to developers, but can trash the dmesg if done
unconditionally. I would prefer this verbose output to be configurable
and off by default.

	Joerg

Re: [PATCH v2] dma-debug: print some unfreed allocations

[Johannes Berg]

On Mon, 2011-05-16 at 13:00 +0200, Roedel, Joerg wrote:
> > +		/*
> > +		 * If we have, print out some stack traces for the allocations.
> > +		 * In case of module unload, the stack traces will be useless,
> > +		 * but instead of unloading the module you can manually unbind
> > +		 * the driver instead and get useful traces.
> > +		 */
> > +		printk(KERN_WARNING "Showing traces for %d allocations:\n",
> > +		       DMA_DEBUG_NUM_PRINT_UNFREED);

> This is surely useful to developers, but can trash the dmesg if done
> unconditionally. I would prefer this verbose output to be configurable
> and off by default.

Are you thinking of runtime or compile time configuration? Kconfig entry
depending on stacktrace (or selecting it, depending on have_stacktrace)
would be easy enough.

johannes

Re: [PATCH v2] dma-debug: print some unfreed allocations

[Roedel, Joerg]

On Wed, May 18, 2011 at 06:48:28PM -0400, Johannes Berg wrote:
> On Mon, 2011-05-16 at 13:00 +0200, Roedel, Joerg wrote:
> > > +		/*
> > > +		 * If we have, print out some stack traces for the allocations.
> > > +		 * In case of module unload, the stack traces will be useless,
> > > +		 * but instead of unloading the module you can manually unbind
> > > +		 * the driver instead and get useful traces.
> > > +		 */
> > > +		printk(KERN_WARNING "Showing traces for %d allocations:\n",
> > > +		       DMA_DEBUG_NUM_PRINT_UNFREED);
> 
> > This is surely useful to developers, but can trash the dmesg if done
> > unconditionally. I would prefer this verbose output to be configurable
> > and off by default.
> 
> Are you thinking of runtime or compile time configuration? Kconfig entry
> depending on stacktrace (or selecting it, depending on have_stacktrace)
> would be easy enough.

It should be configurable at runtime. DMA-debugging already has a
debugfs interface which you can use for that. By default dma-debugging
should only print out the message about leaked entries. The developer
can then reproduce it and find the cause by enabling the verbose output.

Note that there is documentation in Documentation/DMA-API.txt to
document the debugfs interface. Please make sure to update that too.

Regards,

	Joerg

[PATCH v3] dma-debug: print some unfreed allocations

[Johannes Berg]

From: Johannes Berg <johannes.berg@intel.com>

When a driver unbinds and still has allocations,
we print out that they exist but there's nothing
to indicate where they came from. If stacktrace
support is built into the kernel, we can print
out their traces. The number of traces that will
be printed is configurable in debugfs, with the
default being zero.

Unfortunately, if you're unloading the module the
traces will be useless, but once you find such an
error you can manually unbind the device instead
to see where the allocations came from.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
 Documentation/DMA-API.txt |   10 +++++++
 lib/dma-debug.c           |   62 ++++++++++++++++++++++++++++++++++++++--------
 2 files changed, 62 insertions(+), 10 deletions(-)

--- a/lib/dma-debug.c	2011-05-20 08:59:55.000000000 -0700
+++ b/lib/dma-debug.c	2011-05-20 09:36:29.000000000 -0700
@@ -102,6 +102,12 @@ static struct dentry *num_free_entries_d
 static struct dentry *min_free_entries_dent __read_mostly;
 static struct dentry *filter_dent           __read_mostly;
 
+#ifdef CONFIG_STACKTRACE
+/* Show stack traces for this many pending allocations */
+static u32 num_show_pending __read_mostly;
+static struct dentry *num_show_pending_dent __read_mostly;
+#endif
+
 /* per-driver filter related state */
 
 #define NAME_MAX_LEN	64
@@ -641,6 +647,14 @@ static int dma_debug_fs_init(void)
 	if (!filter_dent)
 		goto out_err;
 
+#ifdef CONFIG_STACKTRACE
+	num_show_pending_dent = debugfs_create_u32("num_show_pending", 0644,
+						   dma_debug_dent,
+						   &num_show_pending);
+	if (!num_show_pending_dent)
+		goto out_err;
+#endif
+
 	return 0;
 
 out_err:
@@ -649,7 +663,7 @@ out_err:
 	return -ENOMEM;
 }
 
-static int device_dma_allocations(struct device *dev)
+static void check_device_dma_allocations(struct device *dev)
 {
 	struct dma_debug_entry *entry;
 	unsigned long flags;
@@ -666,27 +680,55 @@ static int device_dma_allocations(struct
 		spin_unlock(&dma_entry_hash[i].lock);
 	}
 
-	local_irq_restore(flags);
+	if (count > 1)
+		err_printk(dev, NULL, "DMA-API: device driver has pending "
+			   "DMA allocations while released from device "
+			   "[count=%d]\n", count);
 
-	return count;
+#ifdef CONFIG_STACKTRACE
+	if (count > 1 && num_show_pending > 0) {
+		count = 0;
+		/*
+		 * If we have, print out some stack traces for the allocations.
+		 * In case of module unload, the stack traces will be useless,
+		 * but instead of unloading the module you can manually unbind
+		 * the driver instead and get useful traces.
+		 */
+		printk(KERN_WARNING "Showing traces for %d allocations:\n",
+		       num_show_pending);
+
+		for (i = 0; i < HASH_SIZE; ++i) {
+			spin_lock(&dma_entry_hash[i].lock);
+			list_for_each_entry(entry, &dma_entry_hash[i].list,
+					    list) {
+				if (entry->dev != dev)
+					continue;
+				count += 1;
+				if (count > num_show_pending)
+					break;
+				dump_entry_trace(entry);
+			}
+			spin_unlock(&dma_entry_hash[i].lock);
+
+			if (count > num_show_pending)
+				break;
+		}
+	}
+#endif
+
+	local_irq_restore(flags);
 }
 
 static int dma_debug_device_change(struct notifier_block *nb, unsigned long action, void *data)
 {
 	struct device *dev = data;
-	int count;
 
 	if (global_disable)
 		return 0;
 
 	switch (action) {
 	case BUS_NOTIFY_UNBOUND_DRIVER:
-		count = device_dma_allocations(dev);
-		if (count == 0)
-			break;
-		err_printk(dev, NULL, "DMA-API: device driver has pending "
-				"DMA allocations while released from device "
-				"[count=%d]\n", count);
+		check_device_dma_allocations(dev);
 		break;
 	default:
 		break;
--- a/Documentation/DMA-API.txt	2011-05-20 09:33:24.000000000 -0700
+++ b/Documentation/DMA-API.txt	2011-05-20 09:35:34.000000000 -0700
@@ -655,6 +655,16 @@ this directory the following files can c
 				that file to disable the filter and see
 				all errors again.
 
+	dma-api/num_show_pending
+				This file is only present if CONFIG_STACKTRACE
+				is enabled in the kernel, and allows debugging
+				unfreed allocations in that it prints out the
+				stack traces for this many (default 0) unfreed
+				allocations if there are any. Note that these
+				traces may be useless if you're unregistering
+				by unloading the module; work around that by
+				unbinding the driver in sysfs instead.
+
 If you have this code compiled into your kernel it will be enabled by default.
 If you want to boot without the bookkeeping anyway you can provide
 'dma_debug=off' as a boot parameter. This will disable DMA-API debugging.

Re: [PATCH v3] dma-debug: print some unfreed allocations

[Roedel, Joerg]

On Fri, May 20, 2011 at 12:36:58PM -0400, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
>  #define NAME_MAX_LEN	64
> @@ -641,6 +647,14 @@ static int dma_debug_fs_init(void)
>  	if (!filter_dent)
>  		goto out_err;
>  
> +#ifdef CONFIG_STACKTRACE
> +	num_show_pending_dent = debugfs_create_u32("num_show_pending", 0644,
> +						   dma_debug_dent,
> +						   &num_show_pending);
> +	if (!num_show_pending_dent)
> +		goto out_err;
> +#endif

Hmm, thinking more about this, do we need to introduce a new variable at
all? It should fit well into the dma-api/all_errors and
dma-api/num_errors configurables. 

> +#ifdef CONFIG_STACKTRACE
> +	if (count > 1 && num_show_pending > 0) {
> +		count = 0;
> +		/*
> +		 * If we have, print out some stack traces for the allocations.
> +		 * In case of module unload, the stack traces will be useless,
> +		 * but instead of unloading the module you can manually unbind
> +		 * the driver instead and get useful traces.
> +		 */
> +		printk(KERN_WARNING "Showing traces for %d allocations:\n",
> +		       num_show_pending);
> +
> +		for (i = 0; i < HASH_SIZE; ++i) {
> +			spin_lock(&dma_entry_hash[i].lock);
> +			list_for_each_entry(entry, &dma_entry_hash[i].list,
> +					    list) {
> +				if (entry->dev != dev)
> +					continue;
> +				count += 1;
> +				if (count > num_show_pending)
> +					break;
> +				dump_entry_trace(entry);
> +			}
> +			spin_unlock(&dma_entry_hash[i].lock);
> +
> +			if (count > num_show_pending)
> +				break;
> +		}
> +	}
> +#endif

This duplicates the loop above. The prints can be folded into one loop.
How about doing it this way (patch is only compile-tested):

diff --git a/lib/dma-debug.c b/lib/dma-debug.c
index db07bfd..ee21ef0 100644
--- a/lib/dma-debug.c
+++ b/lib/dma-debug.c
@@ -187,11 +187,14 @@ static bool driver_filter(struct device *dev)
 	return ret;
 }
 
-#define err_printk(dev, entry, format, arg...) do {			\
+#define err_warn(format, arg...)		WARN(1, format, ## arg)
+#define err_no_warn(format, arg...)		pr_err(format, ## arg)
+
+#define __err_printk(func, dev, entry, format, arg...) do {		\
 		error_count += 1;					\
 		if (driver_filter(dev) &&				\
 		    (show_all_errors || show_num_errors > 0)) {		\
-			WARN(1, "%s %s: " format,			\
+			func("%s %s: " format,				\
 			     dev ? dev_driver_string(dev) : "NULL",	\
 			     dev ? dev_name(dev) : "NULL", ## arg);	\
 			dump_entry_trace(entry);			\
@@ -200,6 +203,12 @@ static bool driver_filter(struct device *dev)
 			show_num_errors -= 1;				\
 	} while (0);
 
+#define err_printk(dev, entry, format, arg...)				\
+	__err_printk(err_warn, dev, entry, format, ## arg)
+
+#define err_printk_no_warn(dev, entry, format, arg...)			\
+	__err_printk(err_no_warn, dev, entry, format, ## arg)
+
 /*
  * Hash related functions
  *
@@ -649,52 +658,38 @@ out_err:
 	return -ENOMEM;
 }
 
-static int device_dma_allocations(struct device *dev, struct dma_debug_entry **out_entry)
+static void check_device_dma_allocations(struct device *dev)
 {
 	struct dma_debug_entry *entry;
 	unsigned long flags;
-	int count = 0, i;
+	int i;
 
 	local_irq_save(flags);
 
 	for (i = 0; i < HASH_SIZE; ++i) {
 		spin_lock(&dma_entry_hash[i].lock);
 		list_for_each_entry(entry, &dma_entry_hash[i].list, list) {
-			if (entry->dev == dev) {
-				count += 1;
-				*out_entry = entry;
-			}
+			if (entry->dev != dev)
+				continue;
+			err_printk_no_warn(dev, entry,
+				"DMA-API: device driver has pending DMA allocation\n");
 		}
 		spin_unlock(&dma_entry_hash[i].lock);
 	}
 
 	local_irq_restore(flags);
-
-	return count;
 }
 
 static int dma_debug_device_change(struct notifier_block *nb, unsigned long action, void *data)
 {
 	struct device *dev = data;
-	struct dma_debug_entry *uninitialized_var(entry);
-	int count;
 
 	if (global_disable)
 		return 0;
 
 	switch (action) {
 	case BUS_NOTIFY_UNBOUND_DRIVER:
-		count = device_dma_allocations(dev, &entry);
-		if (count == 0)
-			break;
-		err_printk(dev, entry, "DMA-API: device driver has pending "
-				"DMA allocations while released from device "
-				"[count=%d]\n"
-				"One of leaked entries details: "
-				"[device address=0x%016llx] [size=%llu bytes] "
-				"[mapped with %s] [mapped as %s]\n",
-			count, entry->dev_addr, entry->size,
-			dir2name[entry->direction], type2name[entry->type]);
+		check_device_dma_allocations(dev);
 		break;
 	default:
 		break;

Re: [PATCH v3] dma-debug: print some unfreed allocations

[Johannes Berg]

On Mon, 2011-05-23 at 14:35 +0200, Roedel, Joerg wrote:

> > +#ifdef CONFIG_STACKTRACE
> > +	num_show_pending_dent = debugfs_create_u32("num_show_pending", 0644,
> > +						   dma_debug_dent,
> > +						   &num_show_pending);
> > +	if (!num_show_pending_dent)
> > +		goto out_err;
> > +#endif
> 
> Hmm, thinking more about this, do we need to introduce a new variable at
> all? It should fit well into the dma-api/all_errors and
> dma-api/num_errors configurables. 

I see something similar was merged printing just the first one (and
without stack trace it seems?). Are you still interested in this?

johannes

Re: [PATCH v3] dma-debug: print some unfreed allocations

[Roedel, Joerg]

On Wed, Jun 08, 2011 at 07:03:36AM -0400, Johannes Berg wrote:
> On Mon, 2011-05-23 at 14:35 +0200, Roedel, Joerg wrote:
> 
> > > +#ifdef CONFIG_STACKTRACE
> > > +	num_show_pending_dent = debugfs_create_u32("num_show_pending", 0644,
> > > +						   dma_debug_dent,
> > > +						   &num_show_pending);
> > > +	if (!num_show_pending_dent)
> > > +		goto out_err;
> > > +#endif
> > 
> > Hmm, thinking more about this, do we need to introduce a new variable at
> > all? It should fit well into the dma-api/all_errors and
> > dma-api/num_errors configurables. 
> 
> I see something similar was merged printing just the first one (and
> without stack trace it seems?). Are you still interested in this?

Sure, still interested. The code which prints out the first entry has
been around for some time, its nothing new afaik.

	Joerg

-- 
AMD Operating System Research Center

Advanced Micro Devices GmbH Einsteinring 24 85609 Dornach
General Managers: Alberto Bozzo, Andrew Bowd
Registration: Dornach, Landkr. Muenchen; Registerger. Muenchen, HRB Nr. 43632

Re: [PATCH v3] dma-debug: print some unfreed allocations

[Johannes Berg]

On Wed, 2011-06-08 at 14:16 +0200, Roedel, Joerg wrote:

> > I see something similar was merged printing just the first one (and
> > without stack trace it seems?). Are you still interested in this?
> 
> Sure, still interested. The code which prints out the first entry has
> been around for some time, its nothing new afaik.

Ok. I was thinking of 
commit ba4b87ad5497cba555954885db99c99627f93748
Author: Stanislaw Gruszka <sgruszka@redhat.com>
Date:   Thu Mar 31 08:08:09 2011 -0400

    dma-debug: print information about leaked entry

which is fairly recent, recent enough that my original patch no longer
applied anyway :-)

johannes

Re: [PATCH v3] dma-debug: print some unfreed allocations

[Roedel, Joerg]

On Wed, Jun 08, 2011 at 08:26:47AM -0400, Johannes Berg wrote:
> On Wed, 2011-06-08 at 14:16 +0200, Roedel, Joerg wrote:
> 
> > > I see something similar was merged printing just the first one (and
> > > without stack trace it seems?). Are you still interested in this?
> > 
> > Sure, still interested. The code which prints out the first entry has
> > been around for some time, its nothing new afaik.
> 
> Ok. I was thinking of 
> commit ba4b87ad5497cba555954885db99c99627f93748
> Author: Stanislaw Gruszka <sgruszka@redhat.com>
> Date:   Thu Mar 31 08:08:09 2011 -0400
> 
>     dma-debug: print information about leaked entry
> 
> which is fairly recent, recent enough that my original patch no longer
> applied anyway :-)

Ah, okay. I thought this change was older :-)

	Joerg

-- 
AMD Operating System Research Center

Advanced Micro Devices GmbH Einsteinring 24 85609 Dornach
General Managers: Alberto Bozzo, Andrew Bowd
Registration: Dornach, Landkr. Muenchen; Registerger. Muenchen, HRB Nr. 43632