tracing/events: Add module tracepoints

Add trace points to trace module_load, module_free, module_get, module_put and module_request, and use trace_event facility to get the trace output. Here's the sample output: TASK-PID CPU# TIMESTAMP FUNCTION | | | | | <...>-42 [000] 1.758380: module_request: fb0 wait=1 call_site=fb_open ... <...>-60 [000] 3.269403: module_load: scsi_wait_scan <...>-60 [000] 3.269432: module_put: scsi_wait_scan call_site=sys_init_module refcnt=0 <...>-61 [001] 3.273168: module_free: scsi_wait_scan ... <...>-1021 [000] 13.836081: module_load: sunrpc <...>-1021 [000] 13.840589: module_put: sunrpc call_site=sys_init_module refcnt=-1 <...>-1027 [000] 13.848098: module_get: sunrpc call_site=try_module_get refcnt=0 <...>-1027 [000] 13.848308: module_get: sunrpc call_site=get_filesystem refcnt=1 <...>-1027 [000] 13.848692: module_put: sunrpc call_site=put_filesystem refcnt=0 ... modprobe-2587 [001] 1088.437213: module_load: trace_events_sample F modprobe-2587 [001] 1088.437786: module_put: trace_events_sample call_site=sys_init_module refcnt=0 Note: - the taints flag can be 'F', 'C' and/or 'P' if mod->taints != 0 - the module refcnt is percpu, so it can be negative in a specific cpu Signed-off-by: Li Zefan <lizf@cn.fujitsu.com> Acked-by: Rusty Russell <rusty@rustcorp.com.au> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Rusty Russell <rusty@rustcorp.com.au> LKML-Reference: <4A891B3C.5030608@cn.fujitsu.com> Signed-off-by: Ingo Molnar <mingo@elte.hu>

tracing/events: Add module tracepoints
Add trace points to trace module_load, module_free, module_get, module_put and module_request, and use trace_event facility to get the trace output. Here's the sample output: TASK-PID CPU# TIMESTAMP FUNCTION | | | | | <...>-42 [000] 1.758380: module_request: fb0 wait=1 call_site=fb_open ... <...>-60 [000] 3.269403: module_load: scsi_wait_scan <...>-60 [000] 3.269432: module_put: scsi_wait_scan call_site=sys_init_module refcnt=0 <...>-61 [001] 3.273168: module_free: scsi_wait_scan ... <...>-1021 [000] 13.836081: module_load: sunrpc <...>-1021 [000] 13.840589: module_put: sunrpc call_site=sys_init_module refcnt=-1 <...>-1027 [000] 13.848098: module_get: sunrpc call_site=try_module_get refcnt=0 <...>-1027 [000] 13.848308: module_get: sunrpc call_site=get_filesystem refcnt=1 <...>-1027 [000] 13.848692: module_put: sunrpc call_site=put_filesystem refcnt=0 ... modprobe-2587 [001] 1088.437213: module_load: trace_events_sample F modprobe-2587 [001] 1088.437786: module_put: trace_events_sample call_site=sys_init_module refcnt=0 Note: - the taints flag can be 'F', 'C' and/or 'P' if mod->taints != 0 - the module refcnt is percpu, so it can be negative in a specific cpu Signed-off-by: Li Zefan <lizf@cn.fujitsu.com> Acked-by: Rusty Russell <rusty@rustcorp.com.au> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Rusty Russell <rusty@rustcorp.com.au> LKML-Reference: <4A891B3C.5030608@cn.fujitsu.com> Signed-off-by: Ingo Molnar <mingo@elte.hu>
Li Zefan · Ingo Molnar
1 parent 60d970c254
Showing 4 changed files with 152 additions and 3 deletions Side-by-side Diff
include/linux/module.h
include/trace/events/module.h
kernel/kmod.c
kernel/module.c
@@ -17,10 +17,12 @@
 #include <linux/moduleparam.h>
 #include <linux/marker.h>
 #include <linux/tracepoint.h>
-#include <asm/local.h>
  
+#include <asm/local.h>
 #include <asm/module.h>
  
+#include <trace/events/module.h>
+
 /* Not Yet Implemented */
 #define MODULE_SUPPORTED_DEVICE(name)
  
@@ -462,7 +464,10 @@
 static inline void __module_get(struct module *module)
 {
 	if (module) {
-		local_inc(__module_ref_addr(module, get_cpu()));
+		unsigned int cpu = get_cpu();
+		local_inc(__module_ref_addr(module, cpu));
+		trace_module_get(module, _THIS_IP_,
+				 local_read(__module_ref_addr(module, cpu)));
 		put_cpu();
 	}
 }
  
@@ -473,8 +478,11 @@
  
 	if (module) {
 		unsigned int cpu = get_cpu();
-		if (likely(module_is_live(module)))
+		if (likely(module_is_live(module))) {
 			local_inc(__module_ref_addr(module, cpu));
+			trace_module_get(module, _THIS_IP_,
+				local_read(__module_ref_addr(module, cpu)));
+		}
 		else
 			ret = 0;
 		put_cpu();
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM module
+
+#if !defined(_TRACE_MODULE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_MODULE_H
+
+#include <linux/tracepoint.h>
+
+#ifdef CONFIG_MODULES
+
+struct module;
+
+#define show_module_flags(flags) __print_flags(flags, "",	\
+	{ (1UL << TAINT_PROPRIETARY_MODULE),	"P" },		\
+	{ (1UL << TAINT_FORCED_MODULE),		"F" },		\
+	{ (1UL << TAINT_CRAP),			"C" })
+
+TRACE_EVENT(module_load,
+
+	TP_PROTO(struct module *mod),
+
+	TP_ARGS(mod),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	taints		)
+		__string(	name,		mod->name	)
+	),
+
+	TP_fast_assign(
+		__entry->taints = mod->taints;
+		__assign_str(name, mod->name);
+	),
+
+	TP_printk("%s %s", __get_str(name), show_module_flags(__entry->taints))
+);
+
+TRACE_EVENT(module_free,
+
+	TP_PROTO(struct module *mod),
+
+	TP_ARGS(mod),
+
+	TP_STRUCT__entry(
+		__string(	name,		mod->name	)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, mod->name);
+	),
+
+	TP_printk("%s", __get_str(name))
+);
+
+TRACE_EVENT(module_get,
+
+	TP_PROTO(struct module *mod, unsigned long ip, int refcnt),
+
+	TP_ARGS(mod, ip, refcnt),
+
+	TP_STRUCT__entry(
+		__field(	unsigned long,	ip		)
+		__field(	int,		refcnt		)
+		__string(	name,		mod->name	)
+	),
+
+	TP_fast_assign(
+		__entry->ip	= ip;
+		__entry->refcnt	= refcnt;
+		__assign_str(name, mod->name);
+	),
+
+	TP_printk("%s call_site=%pf refcnt=%d",
+		  __get_str(name), (void *)__entry->ip, __entry->refcnt)
+);
+
+TRACE_EVENT(module_put,
+
+	TP_PROTO(struct module *mod, unsigned long ip, int refcnt),
+
+	TP_ARGS(mod, ip, refcnt),
+
+	TP_STRUCT__entry(
+		__field(	unsigned long,	ip		)
+		__field(	int,		refcnt		)
+		__string(	name,		mod->name	)
+	),
+
+	TP_fast_assign(
+		__entry->ip	= ip;
+		__entry->refcnt	= refcnt;
+		__assign_str(name, mod->name);
+	),
+
+	TP_printk("%s call_site=%pf refcnt=%d",
+		  __get_str(name), (void *)__entry->ip, __entry->refcnt)
+);
+
+TRACE_EVENT(module_request,
+
+	TP_PROTO(char *name, bool wait, unsigned long ip),
+
+	TP_ARGS(name, wait, ip),
+
+	TP_STRUCT__entry(
+		__field(	bool,		wait		)
+		__field(	unsigned long,	ip		)
+		__string(	name,		name		)
+	),
+
+	TP_fast_assign(
+		__entry->wait	= wait;
+		__entry->ip	= ip;
+		__assign_str(name, name);
+	),
+
+	TP_printk("%s wait=%d call_site=%pf",
+		  __get_str(name), (int)__entry->wait, (void *)__entry->ip)
+);
+
+#endif /* CONFIG_MODULES */
+
+#endif /* _TRACE_MODULE_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
@@ -37,6 +37,8 @@
 #include <linux/suspend.h>
 #include <asm/uaccess.h>
  
+#include <trace/events/module.h>
+
 extern int max_threads;
  
 static struct workqueue_struct *khelper_wq;
@@ -107,6 +109,8 @@
 		atomic_dec(&kmod_concurrent);
 		return -ENOMEM;
 	}
+
+	trace_module_request(module_name, wait, _RET_IP_);
  
 	ret = call_usermodehelper(modprobe_path, argv, envp,
 			wait ? UMH_WAIT_PROC : UMH_WAIT_EXEC);
@@ -55,6 +55,11 @@
 #include <linux/percpu.h>
 #include <linux/kmemleak.h>
  
+#define CREATE_TRACE_POINTS
+#include <trace/events/module.h>
+
+EXPORT_TRACEPOINT_SYMBOL(module_get);
+
 #if 0
 #define DEBUGP printk
 #else
@@ -940,6 +945,8 @@
 	if (module) {
 		unsigned int cpu = get_cpu();
 		local_dec(__module_ref_addr(module, cpu));
+		trace_module_put(module, _RET_IP_,
+				 local_read(__module_ref_addr(module, cpu)));
 		/* Maybe they're waiting for us to drop reference? */
 		if (unlikely(!module_is_live(module)))
 			wake_up_process(module->waiter);
@@ -1491,6 +1498,8 @@
 /* Free a module, remove from lists, etc (must hold module_mutex). */
 static void free_module(struct module *mod)
 {
+	trace_module_free(mod);
+
 	/* Delete from various lists */
 	stop_machine(__unlink_module, mod, NULL);
 	remove_notes_attrs(mod);
@@ -2357,6 +2366,8 @@
  
 	/* Get rid of temporary copy */
 	vfree(hdr);
+
+	trace_module_load(mod);
  
 	/* Done! */
 	return mod;
...	...	@@ -17,10 +17,12 @@
17	17	#include <linux/moduleparam.h>
18	18	#include <linux/marker.h>
19	19	#include <linux/tracepoint.h>
20		-#include <asm/local.h>
21	20
	21	+#include <asm/local.h>
22	22	#include <asm/module.h>
23	23
	24	+#include <trace/events/module.h>
	25	+
24	26	/* Not Yet Implemented */
25	27	#define MODULE_SUPPORTED_DEVICE(name)
26	28
...	...	@@ -462,7 +464,10 @@
462	464	static inline void __module_get(struct module *module)
463	465	{
464	466	if (module) {
465		- local_inc(__module_ref_addr(module, get_cpu()));
	467	+ unsigned int cpu = get_cpu();
	468	+ local_inc(__module_ref_addr(module, cpu));
	469	+ trace_module_get(module, _THIS_IP_,
	470	+ local_read(__module_ref_addr(module, cpu)));
466	471	put_cpu();
467	472	}
468	473	}
469	474
...	...	@@ -473,8 +478,11 @@
473	478
474	479	if (module) {
475	480	unsigned int cpu = get_cpu();
476		- if (likely(module_is_live(module)))
	481	+ if (likely(module_is_live(module))) {
477	482	local_inc(__module_ref_addr(module, cpu));
	483	+ trace_module_get(module, _THIS_IP_,
	484	+ local_read(__module_ref_addr(module, cpu)));
	485	+ }
478	486	else
479	487	ret = 0;
480	488	put_cpu();
	1	+#undef TRACE_SYSTEM
	2	+#define TRACE_SYSTEM module
	3	+
	4	+#if !defined(_TRACE_MODULE_H) \|\| defined(TRACE_HEADER_MULTI_READ)
	5	+#define _TRACE_MODULE_H
	6	+
	7	+#include <linux/tracepoint.h>
	8	+
	9	+#ifdef CONFIG_MODULES
	10	+
	11	+struct module;
	12	+
	13	+#define show_module_flags(flags) __print_flags(flags, "", \
	14	+ { (1UL << TAINT_PROPRIETARY_MODULE), "P" }, \
	15	+ { (1UL << TAINT_FORCED_MODULE), "F" }, \
	16	+ { (1UL << TAINT_CRAP), "C" })
	17	+
	18	+TRACE_EVENT(module_load,
	19	+
	20	+ TP_PROTO(struct module *mod),
	21	+
	22	+ TP_ARGS(mod),
	23	+
	24	+ TP_STRUCT__entry(
	25	+ __field( unsigned int, taints )
	26	+ __string( name, mod->name )
	27	+ ),
	28	+
	29	+ TP_fast_assign(
	30	+ __entry->taints = mod->taints;
	31	+ __assign_str(name, mod->name);
	32	+ ),
	33	+
	34	+ TP_printk("%s %s", __get_str(name), show_module_flags(__entry->taints))
	35	+);
	36	+
	37	+TRACE_EVENT(module_free,
	38	+
	39	+ TP_PROTO(struct module *mod),
	40	+
	41	+ TP_ARGS(mod),
	42	+
	43	+ TP_STRUCT__entry(
	44	+ __string( name, mod->name )
	45	+ ),
	46	+
	47	+ TP_fast_assign(
	48	+ __assign_str(name, mod->name);
	49	+ ),
	50	+
	51	+ TP_printk("%s", __get_str(name))
	52	+);
	53	+
	54	+TRACE_EVENT(module_get,
	55	+
	56	+ TP_PROTO(struct module *mod, unsigned long ip, int refcnt),
	57	+
	58	+ TP_ARGS(mod, ip, refcnt),
	59	+
	60	+ TP_STRUCT__entry(
	61	+ __field( unsigned long, ip )
	62	+ __field( int, refcnt )
	63	+ __string( name, mod->name )
	64	+ ),
	65	+
	66	+ TP_fast_assign(
	67	+ __entry->ip = ip;
	68	+ __entry->refcnt = refcnt;
	69	+ __assign_str(name, mod->name);
	70	+ ),
	71	+
	72	+ TP_printk("%s call_site=%pf refcnt=%d",
	73	+ __get_str(name), (void *)__entry->ip, __entry->refcnt)
	74	+);
	75	+
	76	+TRACE_EVENT(module_put,
	77	+
	78	+ TP_PROTO(struct module *mod, unsigned long ip, int refcnt),
	79	+
	80	+ TP_ARGS(mod, ip, refcnt),
	81	+
	82	+ TP_STRUCT__entry(
	83	+ __field( unsigned long, ip )
	84	+ __field( int, refcnt )
	85	+ __string( name, mod->name )
	86	+ ),
	87	+
	88	+ TP_fast_assign(
	89	+ __entry->ip = ip;
	90	+ __entry->refcnt = refcnt;
	91	+ __assign_str(name, mod->name);
	92	+ ),
	93	+
	94	+ TP_printk("%s call_site=%pf refcnt=%d",
	95	+ __get_str(name), (void *)__entry->ip, __entry->refcnt)
	96	+);
	97	+
	98	+TRACE_EVENT(module_request,
	99	+
	100	+ TP_PROTO(char *name, bool wait, unsigned long ip),
	101	+
	102	+ TP_ARGS(name, wait, ip),
	103	+
	104	+ TP_STRUCT__entry(
	105	+ __field( bool, wait )
	106	+ __field( unsigned long, ip )
	107	+ __string( name, name )
	108	+ ),
	109	+
	110	+ TP_fast_assign(
	111	+ __entry->wait = wait;
	112	+ __entry->ip = ip;
	113	+ __assign_str(name, name);
	114	+ ),
	115	+
	116	+ TP_printk("%s wait=%d call_site=%pf",
	117	+ __get_str(name), (int)__entry->wait, (void *)__entry->ip)
	118	+);
	119	+
	120	+#endif /* CONFIG_MODULES */
	121	+
	122	+#endif /* _TRACE_MODULE_H */
	123	+
	124	+/* This part must be outside protection */
	125	+#include <trace/define_trace.h>
...	...	@@ -37,6 +37,8 @@
37	37	#include <linux/suspend.h>
38	38	#include <asm/uaccess.h>
39	39
	40	+#include <trace/events/module.h>
	41	+
40	42	extern int max_threads;
41	43
42	44	static struct workqueue_struct *khelper_wq;
...	...	@@ -107,6 +109,8 @@
107	109	atomic_dec(&kmod_concurrent);
108	110	return -ENOMEM;
109	111	}
	112	+
	113	+ trace_module_request(module_name, wait, _RET_IP_);
110	114
111	115	ret = call_usermodehelper(modprobe_path, argv, envp,
112	116	wait ? UMH_WAIT_PROC : UMH_WAIT_EXEC);
...	...	@@ -55,6 +55,11 @@
55	55	#include <linux/percpu.h>
56	56	#include <linux/kmemleak.h>
57	57
	58	+#define CREATE_TRACE_POINTS
	59	+#include <trace/events/module.h>
	60	+
	61	+EXPORT_TRACEPOINT_SYMBOL(module_get);
	62	+
58	63	#if 0
59	64	#define DEBUGP printk
60	65	#else
...	...	@@ -940,6 +945,8 @@
940	945	if (module) {
941	946	unsigned int cpu = get_cpu();
942	947	local_dec(__module_ref_addr(module, cpu));
	948	+ trace_module_put(module, _RET_IP_,
	949	+ local_read(__module_ref_addr(module, cpu)));
943	950	/* Maybe they're waiting for us to drop reference? */
944	951	if (unlikely(!module_is_live(module)))
945	952	wake_up_process(module->waiter);
...	...	@@ -1491,6 +1498,8 @@
1491	1498	/* Free a module, remove from lists, etc (must hold module_mutex). */
1492	1499	static void free_module(struct module *mod)
1493	1500	{
	1501	+ trace_module_free(mod);
	1502	+
1494	1503	/* Delete from various lists */
1495	1504	stop_machine(__unlink_module, mod, NULL);
1496	1505	remove_notes_attrs(mod);
...	...	@@ -2357,6 +2366,8 @@
2357	2366
2358	2367	/* Get rid of temporary copy */
2359	2368	vfree(hdr);
	2369	+
	2370	+ trace_module_load(mod);
2360	2371
2361	2372	/* Done! */
2362	2373	return mod;