[PATCH 1/8] debug printk infrastructure -base patch

From: Jason Baron
Date: Thu May 22 2008 - 17:17:01 EST


Signed-off-by: Jason Baron <jbaron@xxxxxxxxxx>
---
include/asm-generic/vmlinux.lds.h | 14 ++-
include/linux/device.h | 16 ++
include/linux/dynamic_printk.h | 44 +++++
include/linux/kernel.h | 16 ++
include/linux/module.h | 5 +
kernel/module.c | 20 +++
lib/Kconfig.debug | 46 +++++
lib/Makefile | 2 +
lib/dynamic_printk.c | 327 +++++++++++++++++++++++++++++++++++++
9 files changed, 489 insertions(+), 1 deletions(-)
create mode 100644 include/linux/dynamic_printk.h
create mode 100644 lib/dynamic_printk.c

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index f054778..9516de4 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -168,6 +168,18 @@
*(__ksymtab_strings) \
} \
\
+ /* dynamic printk sections: strings */ \
+ __verbose_strings : AT(ADDR(__verbose_strings) - LOAD_OFFSET) { \
+ *(__verbose_strings) \
+ } \
+ \
+ /* dynamic printk sections: strings */ \
+ __verbose : AT(ADDR(__verbose) - LOAD_OFFSET) { \
+ VMLINUX_SYMBOL(__start___verbose) = .; \
+ *(__verbose) \
+ VMLINUX_SYMBOL(__stop___verbose) = .; \
+ } \
+ \
/* __*init sections */ \
__init_rodata : AT(ADDR(__init_rodata) - LOAD_OFFSET) { \
*(.ref.rodata) \
diff --git a/include/linux/device.h b/include/linux/device.h
index 1a06026..8f3ca1f 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -595,6 +595,22 @@ extern const char *dev_driver_string(struct device *dev);
#ifdef DEBUG
#define dev_dbg(dev, format, arg...) \
dev_printk(KERN_DEBUG , dev , format , ## arg)
+#elif defined(CONFIG_DYNAMIC_PRINTK_DEBUG)
+#define dev_dbg(dev, format, ...) do { \
+ static char bar[] \
+ __attribute__((section("__verbose_strings"))) \
+ = KBUILD_MODNAME; \
+ static struct mod_debug foobar \
+ __used \
+ __attribute__((section("__verbose"), unused)) = \
+ { bar }; \
+ int hash = dynamic_name_hash(KBUILD_MODNAME); \
+ if (dynamic_printk_enabled[smp_processor_id()] & (1 << hash)) \
+ dynamic_printk(KBUILD_MODNAME, \
+ KERN_DEBUG KBUILD_MODNAME ": %s %s: " format,\
+ dev_driver_string(dev), (dev)->bus_id, \
+ ##__VA_ARGS__); \
+ } while (0)
#else
#define dev_dbg(dev, format, arg...) \
({ if (0) dev_printk(KERN_DEBUG, dev, format, ##arg); 0; })
diff --git a/include/linux/dynamic_printk.h b/include/linux/dynamic_printk.h
new file mode 100644
index 0000000..b1afef3
--- /dev/null
+++ b/include/linux/dynamic_printk.h
@@ -0,0 +1,44 @@
+#ifndef _DYNAMIC_PRINTK_H
+#define _DYNAMIC_PRINTK_H
+
+#ifdef __KERNEL__
+
+#include <linux/string.h>
+
+#define DYNAMIC_HASH_BITS 5
+#define FILE_TABLE_SIZE (1 << DYNAMIC_HASH_BITS)
+
+struct mod_debug {
+ char *modname;
+};
+
+void add_module(char *);
+int remove_module(char *);
+
+extern int dynamic_printk_enabled[];
+extern void dynamic_printk(char *, char *, ...);
+
+static inline unsigned long
+dynamic_partial_name_hash(unsigned long c, unsigned long prevhash)
+{
+ return (prevhash + (c << 4) + (c >> 4)) * 11;
+}
+
+
+static inline unsigned int
+dynamic_full_name_hash(const unsigned char *name, unsigned int len)
+{
+ unsigned long hash = 0;
+ while (len--)
+ hash = dynamic_partial_name_hash(*name++, hash);
+ return hash;
+}
+
+static inline unsigned int dynamic_name_hash(char *name)
+{
+ unsigned int hash = dynamic_full_name_hash(name, strlen(name));
+ return (hash & ((1 << DYNAMIC_HASH_BITS) - 1));
+}
+
+#endif
+#endif
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index cd6d02c..8acf1fc 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -14,6 +14,7 @@
#include <linux/compiler.h>
#include <linux/bitops.h>
#include <linux/log2.h>
+#include <linux/dynamic_printk.h>
#include <asm/byteorder.h>
#include <asm/bug.h>

@@ -292,6 +293,21 @@ extern void print_hex_dump_bytes(const char *prefix_str, int prefix_type,
/* If you are writing a driver, please use dev_dbg instead */
#define pr_debug(fmt, arg...) \
printk(KERN_DEBUG fmt, ##arg)
+#elif defined(CONFIG_DYNAMIC_PRINTK_DEBUG)
+#define pr_debug(fmt, ...) do { \
+ static char bar[] \
+ __attribute__((section("__verbose_strings"))) \
+ = KBUILD_MODNAME; \
+ static struct mod_debug foobar \
+ __used \
+ __attribute__((section("__verbose"), unused)) = \
+ { bar }; \
+ int hash = dynamic_name_hash(KBUILD_MODNAME); \
+ if (dynamic_printk_enabled[smp_processor_id()] & (1 << hash)) \
+ dynamic_printk(KBUILD_MODNAME, \
+ KERN_DEBUG KBUILD_MODNAME ": " fmt,\
+ ##__VA_ARGS__); \
+ } while (0)
#else
#define pr_debug(fmt, arg...) \
({ if (0) printk(KERN_DEBUG fmt, ##arg); 0; })
diff --git a/include/linux/module.h b/include/linux/module.h
index 819c4e8..5536f2d 100644
--- a/include/linux/module.h
+++ b/include/linux/module.h
@@ -16,6 +16,7 @@
#include <linux/kobject.h>
#include <linux/moduleparam.h>
#include <linux/marker.h>
+#include <linux/dynamic_printk.h>
#include <asm/local.h>

#include <asm/module.h>
@@ -359,6 +360,10 @@ struct module
struct marker *markers;
unsigned int num_markers;
#endif
+#ifdef CONFIG_DYNAMIC_PRINTK_DEBUG
+ struct mod_debug *verbose;
+ unsigned int num_verbose;
+#endif
};
#ifndef MODULE_ARCH_INIT
#define MODULE_ARCH_INIT {}
diff --git a/kernel/module.c b/kernel/module.c
index 8d6cccc..2dd2ef6 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -42,6 +42,7 @@
#include <linux/string.h>
#include <linux/mutex.h>
#include <linux/unwind.h>
+#include <linux/dynamic_printk.h>
#include <asm/uaccess.h>
#include <asm/cacheflush.h>
#include <linux/license.h>
@@ -744,6 +745,9 @@ sys_delete_module(const char __user *name_user, unsigned int flags)
}
/* Store the name of the last unloaded module for diagnostic purposes */
strlcpy(last_unloaded_module, mod->name, sizeof(last_unloaded_module));
+#ifdef CONFIG_DYNAMIC_PRINTK_DEBUG
+ remove_module(mod->name);
+#endif
free_module(mod);

out:
@@ -1717,6 +1721,9 @@ static struct module *load_module(void __user *umod,
unsigned int unusedgplcrcindex;
unsigned int markersindex;
unsigned int markersstringsindex;
+ unsigned int verboseindex;
+ unsigned int verbosestringsindex;
+ struct mod_debug *iter;
struct module *mod;
long err = 0;
void *percpu = NULL, *ptr = NULL; /* Stops spurious gcc warning */
@@ -1993,6 +2000,9 @@ static struct module *load_module(void __user *umod,
markersindex = find_sec(hdr, sechdrs, secstrings, "__markers");
markersstringsindex = find_sec(hdr, sechdrs, secstrings,
"__markers_strings");
+ verboseindex = find_sec(hdr, sechdrs, secstrings, "__verbose");
+ verbosestringsindex = find_sec(hdr, sechdrs, secstrings,
+ "__verbose_strings");

/* Now do relocations. */
for (i = 1; i < hdr->e_shnum; i++) {
@@ -2020,6 +2030,11 @@ static struct module *load_module(void __user *umod,
mod->num_markers =
sechdrs[markersindex].sh_size / sizeof(*mod->markers);
#endif
+#ifdef CONFIG_DYNAMIC_PRINTK_DEBUG
+ mod->verbose = (void *)sechdrs[verboseindex].sh_addr;
+ mod->num_verbose =
+ sechdrs[verboseindex].sh_size / sizeof(*mod->verbose);
+#endif

/* Find duplicate symbols */
err = verify_export_symbols(mod);
@@ -2043,6 +2058,11 @@ static struct module *load_module(void __user *umod,
marker_update_probe_range(mod->markers,
mod->markers + mod->num_markers);
#endif
+#ifdef CONFIG_DYNAMIC_PRINTK_DEBUG
+ for (iter = mod->verbose; iter < mod->verbose+mod->num_verbose; iter++) {
+ add_module(iter->modname);
+ }
+#endif
err = module_finalize(hdr, sechdrs, mod);
if (err < 0)
goto cleanup;
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 623ef24..a6f6d8f 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -632,6 +632,52 @@ config FIREWIRE_OHCI_REMOTE_DMA

If unsure, say N.

+config PRINTK_DEBUG
+ bool "Enable centralized debug printk() call support"
+ default n
+ depends on PRINTK
+
+config DYNAMIC_PRINTK_DEBUG
+ bool "Enable dynamic printk() call support"
+ default n
+ depends on PRINTK
+ select PRINTK_DEBUG
+ help
+
+ Allows pr_debug() and dev_dbg() calls to be dynamically enabled based
+ upon their source module. Traditionally, these calls are only
+ enabled if one set #define DEBUG and recompiled the kernel. This
+ option obviates time consuming re-compiles.
+
+ The impact of this compile option is a larger kerenl text size ~1%.
+ However, if CONFIG_IMMEDIATE is set, the run-time impact is
+ negligible. Without CONFIG_IMMEDIATE set, a global variable is
+ referenced for each pr_debug() and dev_dbg() calls.
+
+ Usage:
+
+ The printing of pr_debug() and dev_dbg() is controlled by the
+ debugfs file, dynamic_printk/modules. This file contains a list of
+ the active modules. To add and remove modules:
+
+ echo "add <module_name>" > dynamic_printk/modules
+ echo "remove <module_name>" > dynamic_printk/modules
+
+ For example:
+
+ echo "add kobject" > dynamic_printk/modules
+ /sbin/modprobe <module>
+
+ This will cause kobject debug messages to spew out. Also, a special
+ "all" value will print all pr_debug() and dev_dbg() calls. I.e.:
+
+ echo "add all" > dynamic_printk/modules
+ echo "remove all" > dynamic_printk/modules
+
+ Finally, passing "dynamic_printk" at the command line enables all
+ pr_debug() and dev_dbg() call to come out (same as "all"). This mode
+ can be disabled via a "remove all".
+
source "samples/Kconfig"

source "lib/Kconfig.kgdb"
diff --git a/lib/Makefile b/lib/Makefile
index bf8000f..ff1e3eb 100644
--- a/lib/Makefile
+++ b/lib/Makefile
@@ -66,6 +66,8 @@ obj-$(CONFIG_SWIOTLB) += swiotlb.o
obj-$(CONFIG_IOMMU_HELPER) += iommu-helper.o
obj-$(CONFIG_FAULT_INJECTION) += fault-inject.o

+obj-$(CONFIG_PRINTK_DEBUG) += dynamic_printk.o
+
lib-$(CONFIG_GENERIC_BUG) += bug.o

obj-$(CONFIG_HAVE_LMB) += lmb.o
diff --git a/lib/dynamic_printk.c b/lib/dynamic_printk.c
new file mode 100644
index 0000000..3eaf874
--- /dev/null
+++ b/lib/dynamic_printk.c
@@ -0,0 +1,327 @@
+/*
+ * lib/dynamic_printk.c
+ *
+ * make pr_debug()/dev_dbg() calls runtime configurable based upon their
+ * their source module.
+ *
+ * Copyright (C) 2008 Red Hat, Inc., Jason Baron <jbaron@xxxxxxxxxx>
+ */
+
+#include <linux/kernel.h>
+#include <linux/module.h>
+#include <linux/uaccess.h>
+#include <linux/seq_file.h>
+#include <linux/debugfs.h>
+#include <linux/fs.h>
+#include <linux/hash.h>
+#include <linux/dynamic_printk.h>
+
+extern struct mod_debug __start___verbose[];
+extern struct mod_debug __stop___verbose[];
+
+static int num_enabled;
+static struct hlist_head module_table[FILE_TABLE_SIZE] =
+ { [0 ... FILE_TABLE_SIZE-1] = HLIST_HEAD_INIT };
+static DECLARE_MUTEX(debug_list_mutex);
+static int nr_entries;
+
+int dynamic_printk_enabled[NR_CPUS];
+EXPORT_SYMBOL_GPL(dynamic_printk_enabled);
+
+struct debug_name {
+ struct hlist_node hlist;
+ char *name;
+ unsigned int num_uses;
+ int enable;
+ int flags;
+ int level;
+ int ratelimit;
+};
+
+static struct debug_name *find_debug_file(char *module_name)
+{
+ int found = 0;
+ struct hlist_head *head;
+ struct hlist_node *node;
+ struct debug_name *element;
+
+ head = &module_table[dynamic_name_hash(module_name)];
+ rcu_read_lock();
+ hlist_for_each_entry_rcu(element, node, head, hlist) {
+ if (!strcmp(element->name, module_name)) {
+ found = 1;
+ break;
+ }
+ }
+ rcu_read_unlock();
+ if (found)
+ return element;
+ return NULL;
+}
+
+static int add_debug_file(char *module_name)
+{
+ struct debug_name *new;
+
+ if (find_debug_file(module_name))
+ return -EINVAL;
+ new = kzalloc(sizeof(struct debug_name), GFP_KERNEL);
+ if (!new)
+ return -ENOMEM;
+ INIT_HLIST_NODE(&new->hlist);
+ new->name = module_name;
+ hlist_add_head_rcu(&new->hlist,
+ &module_table[dynamic_name_hash(new->name)]);
+ nr_entries++;
+ return 0;
+}
+
+void add_module(char *mod_name)
+{
+ struct debug_name *elem;
+ char *module_name;
+
+ module_name = kmalloc(strlen(mod_name) + 1, GFP_KERNEL);
+ module_name = strcpy(module_name, mod_name);
+ module_name[strlen(mod_name)] = '\0';
+ /* add error checking */
+ down(&debug_list_mutex);
+ add_debug_file(module_name);
+ elem = find_debug_file(module_name);
+ elem->num_uses++;
+ up(&debug_list_mutex);
+}
+EXPORT_SYMBOL_GPL(add_module);
+
+int remove_debug_file(char *module_name)
+{
+ struct debug_name *element;
+
+ element = find_debug_file(module_name);
+ if (element == NULL)
+ return -EINVAL;
+ hlist_del_rcu(&element->hlist);
+ synchronize_rcu();
+ kfree(element->name);
+ kfree(element);
+ nr_entries--;
+ return 0;
+}
+
+int remove_module(char *mod_name)
+{
+ down(&debug_list_mutex);
+ remove_debug_file(mod_name);
+ up(&debug_list_mutex);
+ return 0;
+}
+EXPORT_SYMBOL_GPL(remove_module);
+
+#ifdef CONFIG_DYNAMIC_PRINTK_DEBUG
+
+void dynamic_printk(char *module_name, char *fmt, ...)
+{
+ va_list args;
+ struct debug_name *elem;
+
+ va_start(args, fmt);
+ if (elem = find_debug_file(module_name)) {
+ if (elem->enable)
+ vprintk(fmt, args);
+ }
+ va_end(args);
+}
+EXPORT_SYMBOL_GPL(dynamic_printk);
+
+static void set_all(int enable)
+{
+ struct debug_name *e;
+ struct hlist_node *node;
+ int i, cpu, enable_mask;
+
+ for (i = 0; i < FILE_TABLE_SIZE; i++) {
+ if (module_table[i].first != NULL) {
+ hlist_for_each_entry(e, node, &module_table[i], hlist) {
+ e->enable = enable;
+ }
+ }
+ }
+ if (enable)
+ enable_mask = UINT_MAX;
+ else
+ enable_mask = 0;
+ for (i = 0; i < NR_CPUS; i++)
+ dynamic_printk_enabled[i] = enable_mask;
+}
+
+#define enable_all() set_all(1)
+#define disable_all() set_all(0)
+
+static int disabled_hash(int i)
+{
+ struct debug_name *e;
+ struct hlist_node *node;
+
+ hlist_for_each_entry(e, node, &module_table[i], hlist) {
+ if (e->enable)
+ return 0;
+ }
+ return 1;
+}
+
+static ssize_t pr_debug_write(struct file *file, const char __user *buf,
+ size_t length, loff_t *ppos)
+{
+ char *buffer, *s;
+ int err, hash, i;
+ struct debug_name *elem;
+
+ if (!buf || length > PAGE_SIZE || length < 0)
+ return -EINVAL;
+
+ buffer = (char *)__get_free_page(GFP_KERNEL);
+ if (!buffer)
+ return -ENOMEM;
+
+ err = -EFAULT;
+ if (copy_from_user(buffer, buf, length))
+ goto out;
+
+ err = -EINVAL;
+ if (length < PAGE_SIZE)
+ buffer[length] = '\0';
+ else if (buffer[PAGE_SIZE-1])
+ goto out;
+
+ err = -EINVAL;
+ down(&debug_list_mutex);
+ if (!strncmp("enable all", buffer, 10)) {
+ if (nr_entries) {
+ enable_all();
+ num_enabled = nr_entries;
+ err = 0;
+ }
+ } else if (!strncmp("disable all", buffer, 11)) {
+ disable_all();
+ num_enabled = 0;
+ err = 0;
+ } else if (!strncmp("enable ", buffer, 7)) {
+ s = strstrip(buffer + 7);
+ if (elem = find_debug_file(s)) {
+ if (elem->enable == 0) {
+ hash = dynamic_name_hash(s);
+ for (i = 0; i < NR_CPUS; i++)
+ dynamic_printk_enabled[i] |= (1 << hash);
+ elem->enable = 1;
+ num_enabled++;
+ }
+ err = 0;
+ }
+ } else if (!strncmp("disable ", buffer, 8)) {
+ s = strstrip(buffer + 8);
+ if (elem = find_debug_file(s)) {
+ if (elem->enable == 1) {
+ elem->enable = 0;
+ num_enabled--;
+ if (disabled_hash(dynamic_name_hash(s))) {
+ for (i = 0; i < NR_CPUS; i++)
+ dynamic_printk_enabled[i] |= ~(1 << hash);
+ }
+ }
+ err = 0;
+ }
+ }
+ if (!err)
+ err = length;
+
+ up(&debug_list_mutex);
+out:
+ free_page((unsigned long)buffer);
+ return err;
+}
+
+static void *pr_debug_seq_start(struct seq_file *f, loff_t *pos)
+{
+ return (*pos < FILE_TABLE_SIZE) ? pos : NULL;
+}
+
+static void *pr_debug_seq_next(struct seq_file *s, void *v, loff_t *pos)
+{
+ (*pos)++;
+ if (*pos >= FILE_TABLE_SIZE)
+ return NULL;
+ return pos;
+}
+
+static void pr_debug_seq_stop(struct seq_file *s, void *v)
+{
+ /* Nothing to do */
+}
+
+static int pr_debug_seq_show(struct seq_file *s, void *v)
+{
+ struct hlist_head *head;
+ struct hlist_node *node;
+ struct debug_name *element;
+ unsigned int i = *(loff_t *) v;
+
+ rcu_read_lock();
+ head = &module_table[i];
+ hlist_for_each_entry_rcu(element, node, head, hlist)
+ seq_printf(s, "%s %d %d\n", element->name, element->enable,
+ element->num_uses);
+ rcu_read_unlock();
+ return 0;
+}
+
+static struct seq_operations pr_debug_seq_ops = {
+ .start = pr_debug_seq_start,
+ .next = pr_debug_seq_next,
+ .stop = pr_debug_seq_stop,
+ .show = pr_debug_seq_show
+};
+
+static int pr_debug_open(struct inode *inode, struct file *filp)
+{
+ return seq_open(filp, &pr_debug_seq_ops);
+}
+
+static const struct file_operations pr_debug_operations = {
+ .open = pr_debug_open,
+ .read = seq_read,
+ .write = pr_debug_write,
+ .llseek = seq_lseek,
+ .release = seq_release,
+};
+
+int __init dynamic_printk_init(void)
+{
+ struct dentry *dir, *file;
+ struct mod_debug *iter;
+
+ dir = debugfs_create_dir("dynamic_printk", NULL);
+ if (!dir)
+ return -ENOMEM;
+ file = debugfs_create_file("modules", 0644, dir, NULL,
+ &pr_debug_operations);
+ if (!file) {
+ debugfs_remove(dir);
+ return -ENOMEM;
+ }
+ for (iter = __start___verbose; iter < __stop___verbose; iter++) {
+ add_module(iter->modname);
+ }
+ return 0;
+}
+__initcall(dynamic_printk_init);
+
+static int __init dynamic_printk_setup(char *str)
+{
+ if (str)
+ return -ENOENT;
+ set_all(1);
+ return 0;
+}
+early_param("dynamic_printk", dynamic_printk_setup);
+
+#endif /* CONFIG_DYNAMIC_PRINTK_DEBUG */
--
1.5.4.5

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/