Skip to contentSkip to conversation

hook tracer to dynamic debug

RFC PATCH In review Jason Baron 3 participants 4 messages Dec 5, 2008 – Dec 9, 2008 Tracing

lore
Share & tools
lore
#0 lore raw

RFC PATCH 1/1 hook tracer to dynamic debug

hi,

Currently, the dynamic debug framework uses 'printk' for output. Here, i've hooked the backend of the dynamic debug framework to the tracing framework. This allows the dynamic debug output to be seaprated from the system log, and allows for higher performance. I've implemented it as a compile time option, but a user might want to be able to toggle b/w 'printk' and the tracer at run-time...other ideas? Patch is against the -tip tree...

thanks,

-Jason

include/linux/dynamic_printk.h +10 -1
index 2d528d0..9d9a38b 100644
@@ -31,6 +31,15 @@ struct mod_debug {
 int register_dynamic_debug_module(char *mod_name, int type, char *share_name,
 					char *flags, int hash, int hash2);
 
+
+#ifdef CONFIG_DYNAMIC_DEBUG_TRACER
+#define dynamic_printk dynamic_debug_trace_printk
+extern void dynamic_debug_trace_printk(const char *fmt, ...);
+#else
+#define dynamic_printk printk
+#endif
+
+
 #if defined(CONFIG_DYNAMIC_PRINTK_DEBUG)
 extern int unregister_dynamic_debug_module(char *mod_name);
 extern int __dynamic_dbg_enabled_helper(char *modname, int type,
@@ -54,7 +63,7 @@ extern int __dynamic_dbg_enabled_helper(char *modname, int type,
 	{ mod_name, mod_name, NULL, TYPE_BOOLEAN, DEBUG_HASH, DEBUG_HASH2 };\
 	if (__dynamic_dbg_enabled(KBUILD_MODNAME, TYPE_BOOLEAN,		    \
 						0, 0, DEBUG_HASH))	    \
-		printk(KERN_DEBUG KBUILD_MODNAME ":" fmt,		    \
+		dynamic_printk(KERN_DEBUG KBUILD_MODNAME ":" fmt,	    \
 				##__VA_ARGS__);				    \
 	} while (0)
 
kernel/trace/Kconfig +7 -0
index bde6f03..e810912 100644
@@ -149,6 +149,13 @@ config CONTEXT_SWITCH_TRACER
 	  This tracer gets called from the context switch and records
 	  all switching of tasks.
 
+config DYNAMIC_DEBUG_TRACER
+	bool "Trace dynamic debug"
+	depends on DEBUG_KERNEL
+	select TRACING
+	help
+	  This tracer records all dynamic debug output.
+
 config BOOT_TRACER
 	bool "Trace boot initcalls"
 	depends on DEBUG_KERNEL
kernel/trace/Makefile +2 -0
index 62dc561..b84337e 100644
@@ -33,5 +33,7 @@ obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += trace_functions_graph.o
 obj-$(CONFIG_TRACE_BRANCH_PROFILING) += trace_branch.o
 obj-$(CONFIG_BTS_TRACER) += trace_bts.o
 obj-$(CONFIG_POWER_TRACER) += trace_power.o
+obj-$(CONFIG_DYNAMIC_DEBUG_TRACER) += trace_dynamic_debug.o
+
 
 libftrace-y := ftrace.o
kernel/trace/trace_dynamic_debug.c new file +142 -0

142 lines not on this page · raw message

#1 lore raw

Hi Jason,

Quoted 20 lines · Jason Baron

hi,

Currently, the dynamic debug framework uses 'printk' for output. Here, i've hooked the backend of the dynamic debug framework to the tracing framework. This allows the dynamic debug output to be seaprated from the system log, and allows for higher performance. I've implemented it as a compile time option, but a user might want to be able to toggle b/w 'printk' and the tracer at run-time...other ideas? Patch is against the -tip tree...

thanks,

(quoted diff) +0 -1
-Jason
include/linux/dynamic_printk.h +0 -0
index 2d528d0..9d9a38b 100644

include/linux/dynamic_printk.h struct mod_debug { · line 40

Quoted 10 lines
include/linux/dynamic_printk.h +7 -0
@@ -31,6 +31,15 @@ struct mod_debug {
 int register_dynamic_debug_module(char *mod_name, int type, char *share_name,
 					char *flags, int hash, int hash2);
 
+
+#ifdef CONFIG_DYNAMIC_DEBUG_TRACER
+#define dynamic_printk dynamic_debug_trace_printk
+extern void dynamic_debug_trace_printk(const char *fmt, ...);
+#else
+#define dynamic_printk printk
+#endif

Actually, why not directly defining dynamic_printk to ftrace_printk if CONFIG_DYNAMIC_DEBUG_TRACER is defined?
That would be much simpler than writing a whole tracer for this. I see that one of the pros of this tracer would be to enable/disable it dynamically by controlling the tracer but you can already do it through the trace_options file by setting the TRACE_ITER_PRINTK flag.
Unless you just want to get rid of the current ip in the message?

Quoted 198 lines
include/linux/dynamic_printk.h +3 -1
+
+
 #if defined(CONFIG_DYNAMIC_PRINTK_DEBUG)
 extern int unregister_dynamic_debug_module(char *mod_name);
 extern int __dynamic_dbg_enabled_helper(char *modname, int type,
@@ -54,7 +63,7 @@ extern int __dynamic_dbg_enabled_helper(char *modname, int type,
 	{ mod_name, mod_name, NULL, TYPE_BOOLEAN, DEBUG_HASH, DEBUG_HASH2 };\
 	if (__dynamic_dbg_enabled(KBUILD_MODNAME, TYPE_BOOLEAN,		    \
 						0, 0, DEBUG_HASH))	    \
-		printk(KERN_DEBUG KBUILD_MODNAME ":" fmt,		    \
+		dynamic_printk(KERN_DEBUG KBUILD_MODNAME ":" fmt,	    \
 				##__VA_ARGS__);				    \
 	} while (0)
 
kernel/trace/Kconfig +7 -0
index bde6f03..e810912 100644
@@ -149,6 +149,13 @@ config CONTEXT_SWITCH_TRACER
 	  This tracer gets called from the context switch and records
 	  all switching of tasks.
 
+config DYNAMIC_DEBUG_TRACER
+	bool "Trace dynamic debug"
+	depends on DEBUG_KERNEL
+	select TRACING
+	help
+	  This tracer records all dynamic debug output.
+
 config BOOT_TRACER
 	bool "Trace boot initcalls"
 	depends on DEBUG_KERNEL
kernel/trace/Makefile +2 -0
index 62dc561..b84337e 100644
@@ -33,5 +33,7 @@ obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += trace_functions_graph.o
 obj-$(CONFIG_TRACE_BRANCH_PROFILING) += trace_branch.o
 obj-$(CONFIG_BTS_TRACER) += trace_bts.o
 obj-$(CONFIG_POWER_TRACER) += trace_power.o
+obj-$(CONFIG_DYNAMIC_DEBUG_TRACER) += trace_dynamic_debug.o
+
 
 libftrace-y := ftrace.o
kernel/trace/trace_dynamic_debug.c new file +142 -1
new file mode 100644
index 0000000..43eaf8a
@@ -0,0 +1,142 @@
+/*
+ * dynamic_debug tracer
+ *
+ * Copyright (C) 2008 Jason Baron <[email protected]>
+ *
+ */
+#include <linux/module.h>
+#include <linux/fs.h>
+#include <linux/debugfs.h>
+#include <linux/kallsyms.h>
+#include <linux/uaccess.h>
+#include <linux/ftrace.h>
+#include <linux/marker.h>
+#include <trace/sched.h>
+
+#include "trace.h"
+
+static struct trace_array	*ctx_trace;
+static int __read_mostly	debug_enabled;
+static int			debug_ref;
+static DEFINE_MUTEX(debug_register_mutex);
+
+void dynamic_debug_trace_printk(const char *fmt, ...)
+{
+	va_list args;
+
+	if (!debug_enabled)
+		return;
+
+	va_start(args, fmt);
+	trace_vprintk(0, -1, fmt, args);
+	va_end(args);
+}
+EXPORT_SYMBOL(dynamic_debug_trace_printk);
+
+static void dynamic_debug_reset(struct trace_array *tr)
+{
+	int cpu;
+
+	tr->time_start = ftrace_now(tr->cpu);
+
+	for_each_online_cpu(cpu)
+		tracing_reset(tr, cpu);
+}
+
+static void tracing_start_dynamic_debug(void)
+{
+	mutex_lock(&debug_register_mutex);
+	debug_ref++;
+	mutex_unlock(&debug_register_mutex);
+}
+
+static void tracing_stop_dynamic_debug(void)
+{
+	mutex_lock(&debug_register_mutex);
+	debug_ref--;
+	mutex_unlock(&debug_register_mutex);
+}
+
+/**
+ * tracing_start_sched_switch_record - start tracing context switches
+ *
+ * Turns on context switch tracing for a tracer.
+ */
+void tracing_start_dynamic_debug_record(void)
+{
+	if (unlikely(!ctx_trace)) {
+		WARN_ON(1);
+		return;
+	}
+
+	tracing_start_dynamic_debug();
+
+	mutex_lock(&debug_register_mutex);
+	debug_enabled++;
+	mutex_unlock(&debug_register_mutex);
+}
+
+/**
+ * tracing_stop_sched_switch_record - start tracing context switches
+ *
+ * Turns off context switch tracing for a tracer.
+ */
+void tracing_stop_dynamic_debug_record(void)
+{
+	mutex_lock(&debug_register_mutex);
+	debug_enabled--;
+	WARN_ON(debug_enabled < 0);
+	mutex_unlock(&debug_register_mutex);
+
+	tracing_stop_dynamic_debug();
+}
+
+static void start_dynamic_debug_trace(struct trace_array *tr)
+{
+	dynamic_debug_reset(tr);
+	tracing_start_dynamic_debug_record();
+}
+
+static void stop_dynamic_debug_trace(struct trace_array *tr)
+{
+	tracing_stop_dynamic_debug_record();
+}
+
+static int dynamic_debug_trace_init(struct trace_array *tr)
+{
+	ctx_trace = tr;
+	start_dynamic_debug_trace(tr);
+	return 0;
+}
+
+static void dynamic_debug_trace_reset(struct trace_array *tr)
+{
+	if (debug_ref)
+		stop_dynamic_debug_trace(tr);
+}
+
+static void dynamic_debug_trace_start(struct trace_array *tr)
+{
+	dynamic_debug_reset(tr);
+	tracing_start_dynamic_debug();
+}
+
+static void dynamic_debug_trace_stop(struct trace_array *tr)
+{
+	tracing_stop_dynamic_debug();
+}
+
+static struct tracer dynamic_debug_trace __read_mostly =
+{
+	.name		= "dynamic_debug",
+	.init		= dynamic_debug_trace_init,
+	.reset		= dynamic_debug_trace_reset,
+	.start		= dynamic_debug_trace_start,
+	.stop		= dynamic_debug_trace_stop,
+};
+
+__init static int init_dynamic_debug_trace(void)
+{
+	return register_tracer(&dynamic_debug_trace);
+}
+device_initcall(init_dynamic_debug_trace);
--

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

#2 lore raw
In reply to Jason Baron
Quoted 6 lines · Jason Baron

hi,

Currently, the dynamic debug framework uses 'printk' for output. Here, i've hooked the backend of the dynamic debug framework to the tracing framework. This allows the dynamic debug output to be seaprated from the system log, and allows for higher performance.

Is this really an issue most of the time?

I know logs can get full, but this seems like a bit of an overkill :)

Quoted 3 lines

I've implemented it as a compile time option, but a user might want to be able to toggle b/w 'printk' and the tracer at run-time...other ideas? Patch is against the -tip tree...

It would have to be a run-time option if you want any distro to ever be able to enable this in their kernels.

thanks,

greg k-h

#3 lore raw
Quoted 10 lines · Greg KH
Quoted 6 lines · Jason Baron

hi,

Currently, the dynamic debug framework uses 'printk' for output. Here, i've hooked the backend of the dynamic debug framework to the tracing framework. This allows the dynamic debug output to be seaprated from the system log, and allows for higher performance.

Is this really an issue most of the time?

Quoted 9 lines

I know logs can get full, but this seems like a bit of an overkill :)

Quoted 3 lines

I've implemented it as a compile time option, but a user might want to be able to toggle b/w 'printk' and the tracer at run-time...other ideas? Patch is against the -tip tree...

It would have to be a run-time option if you want any distro to ever be able to enable this in their kernels.

There haven't been any specfic complaints about this, although the all 'on' case does really spew quite a lot into the logs. Using Frederic's suggestion I'm able to implement this with only a few lines of code...so I'll keep it around if we ever need it...

thanks,

-Jason