Skip to contentSkip to conversation

dma-debug: print some unfreed allocations

PATCH Superseded Johannes Berg 2 participants 11 messages May 10, 2011 – Jun 8, 2011

Subsystems (2)
Documentation Library code
lore
Share & tools
lore

Johannes Berg

author
#0 lore raw

PATCH 1/1 dma-debug: print some unfreed allocations

From: Johannes Berg <[email protected]>

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 <[email protected]>
---
 lib/dma-debug.c |   47 +++++++++++++++++++++++++++++++++++++----------
 1 file changed, 37 insertions(+), 10 deletions(-)
lib/dma-debug.c +37 -10
@@ -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;
author
#1 lore raw

PATCH v2 1/1 dma-debug: print some unfreed allocations

From: Johannes Berg <[email protected]>

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 <[email protected]>

---
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(-)
lib/dma-debug.c +38 -10
@@ -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;
#2 lore raw
Quoted 25 lines · Johannes Berg

From: Johannes Berg <[email protected]>

lib/dma-debug.c +23 -0
+#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);

lib/dma-debug.c static int device_dma_allocations(struct · line 706

Quoted 10 lines
lib/dma-debug.c +7 -1
 
-	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

author
#3 lore raw
Quoted 4 lines · Joerg
Quoted 4 lines
lib/dma-debug.c +4 -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
Quoted 8 lines

lib/dma-debug.c static int device_dma_allocations(struct · line 684

Quoted 4 lines
lib/dma-debug.c +4 -0
+		 * 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

#4 lore raw
Quoted 14 lines · Johannes Berg
Quoted 4 lines · Joerg
Quoted 4 lines
lib/dma-debug.c +4 -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
Quoted 8 lines

lib/dma-debug.c static int device_dma_allocations(struct · line 684

Quoted 4 lines
lib/dma-debug.c +4 -0
+		 * 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.

Quoted 3 lines

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

author
#5 lore raw

PATCH v3 1/1 dma-debug: print some unfreed allocations

From: Johannes Berg <[email protected]>

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 <[email protected]>
---
 Documentation/DMA-API.txt |   10 +++++++
 lib/dma-debug.c           |   62 ++++++++++++++++++++++++++++++++++++++--------
 2 files changed, 62 insertions(+), 10 deletions(-)
lib/dma-debug.c +52 -10
@@ -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;
Documentation/DMA-API.txt +10 -0
@@ -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.
#6 lore raw

Review static int dma_debug_fs_init(void) · line 656

Quoted 13 lines · Johannes Berg

From: Johannes Berg <[email protected]>
#define NAME_MAX_LEN 64

(quoted diff) +7 -0
@@ -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.

Quoted 20 lines
(quoted diff) +20 -0
+#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)

Review static int dma_debug_fs_init(void)

Quoted 10 lines
(quoted diff) +10 -0
+					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):

lib/dma-debug.c +18 -23
index db07bfd..ee21ef0 100644
@@ -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;
author
#7 lore raw
Quoted 11 lines · Joerg

Review

Quoted 7 lines
(quoted diff) +7 -0
+#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

#8 lore raw
Quoted 14 lines · Johannes Berg
Quoted 11 lines · Joerg

Review

Quoted 7 lines
(quoted diff) +7 -0
+#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.

Quoted 2 lines

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

Signature · 5 lines
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
author
#9 lore raw
Quoted 5 lines · Joerg
Quoted 2 lines

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 <[email protected]>
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

#10 lore raw
Quoted 10 lines · Johannes Berg
Quoted 5 lines · Joerg
Quoted 2 lines

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

Quoted 7 lines
Author: Stanislaw Gruszka <[email protected]>
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

Signature · 5 lines
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