[PATCH] tracing/events: Add module tracepoints

[PATCH] tracing/events: Add module tracepoints

[Li Zefan]

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>
---
 include/linux/module.h        |   14 ++++-
 include/trace/events/module.h |  126 +++++++++++++++++++++++++++++++++++++++++
 kernel/kmod.c                 |    4 +
 kernel/module.c               |   11 ++++
 4 files changed, 152 insertions(+), 3 deletions(-)
 create mode 100644 include/trace/events/module.h

diff --git a/include/linux/module.h b/include/linux/module.h
index 7a5c82c..86863cd 100644
--- a/include/linux/module.h
+++ b/include/linux/module.h
@@ -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)
 
@@ -480,7 +482,10 @@ static inline local_t *__module_ref_addr(struct module *mod, int cpu)
 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();
 	}
 }
@@ -491,8 +496,11 @@ static inline int try_module_get(struct module *module)
 
 	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();
diff --git a/include/trace/events/module.h b/include/trace/events/module.h
new file mode 100644
index 0000000..84160fb
--- /dev/null
+++ b/include/trace/events/module.h
@@ -0,0 +1,126 @@
+#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>
+
diff --git a/kernel/kmod.c b/kernel/kmod.c
index 385c31a..a922808 100644
--- a/kernel/kmod.c
+++ b/kernel/kmod.c
@@ -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;
@@ -108,6 +110,8 @@ int __request_module(bool wait, const char *fmt, ...)
 		return -ENOMEM;
 	}
 
+	trace_module_request(module_name, wait, _RET_IP_);
+
 	ret = call_usermodehelper(modprobe_path, argv, envp,
 			wait ? UMH_WAIT_PROC : UMH_WAIT_EXEC);
 	atomic_dec(&kmod_concurrent);
diff --git a/kernel/module.c b/kernel/module.c
index 0a04983..38bf87a 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -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 @@ void module_put(struct module *module)
 	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);
@@ -1490,6 +1497,8 @@ static int __unlink_module(void *_mod)
 /* 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 @@ static noinline struct module *load_module(void __user *umod,
 	/* Get rid of temporary copy */
 	vfree(hdr);
 
+	trace_module_load(mod);
+
 	/* Done! */
 	return mod;
 
-- 
1.6.3

Re: [PATCH] tracing/events: Add module tracepoints

[Steven Rostedt]

On Tue, 21 Jul 2009, Li Zefan wrote:

> 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>

I'm fine with this, but I would like an Acked-by from Rusty before pulling 
it in.

-- Steve


> ---
>  include/linux/module.h        |   14 ++++-
>  include/trace/events/module.h |  126 +++++++++++++++++++++++++++++++++++++++++
>  kernel/kmod.c                 |    4 +
>  kernel/module.c               |   11 ++++
>  4 files changed, 152 insertions(+), 3 deletions(-)
>  create mode 100644 include/trace/events/module.h
> 
> diff --git a/include/linux/module.h b/include/linux/module.h
> index 7a5c82c..86863cd 100644
> --- a/include/linux/module.h
> +++ b/include/linux/module.h
> @@ -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)
>  
> @@ -480,7 +482,10 @@ static inline local_t *__module_ref_addr(struct module *mod, int cpu)
>  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();
>  	}
>  }
> @@ -491,8 +496,11 @@ static inline int try_module_get(struct module *module)
>  
>  	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();
> diff --git a/include/trace/events/module.h b/include/trace/events/module.h
> new file mode 100644
> index 0000000..84160fb
> --- /dev/null
> +++ b/include/trace/events/module.h
> @@ -0,0 +1,126 @@
> +#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>
> +
> diff --git a/kernel/kmod.c b/kernel/kmod.c
> index 385c31a..a922808 100644
> --- a/kernel/kmod.c
> +++ b/kernel/kmod.c
> @@ -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;
> @@ -108,6 +110,8 @@ int __request_module(bool wait, const char *fmt, ...)
>  		return -ENOMEM;
>  	}
>  
> +	trace_module_request(module_name, wait, _RET_IP_);
> +
>  	ret = call_usermodehelper(modprobe_path, argv, envp,
>  			wait ? UMH_WAIT_PROC : UMH_WAIT_EXEC);
>  	atomic_dec(&kmod_concurrent);
> diff --git a/kernel/module.c b/kernel/module.c
> index 0a04983..38bf87a 100644
> --- a/kernel/module.c
> +++ b/kernel/module.c
> @@ -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 @@ void module_put(struct module *module)
>  	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);
> @@ -1490,6 +1497,8 @@ static int __unlink_module(void *_mod)
>  /* 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 @@ static noinline struct module *load_module(void __user *umod,
>  	/* Get rid of temporary copy */
>  	vfree(hdr);
>  
> +	trace_module_load(mod);
> +
>  	/* Done! */
>  	return mod;
>  
> -- 
> 1.6.3
> 
> 

Re: [PATCH] tracing/events: Add module tracepoints

[Rusty Russell]

On Tue, 21 Jul 2009 06:26:33 pm Li Zefan wrote:
> 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.

Hi Li Zefan,

   I don't know anything about tracing, but the module code changes look
simple and fine to me.

Thanks,
Rusty.

Re: [PATCH] tracing/events: Add module tracepoints

[Li Zefan]

Rusty Russell wrote:
> On Tue, 21 Jul 2009 06:26:33 pm Li Zefan wrote:
>> 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.
> 
> Hi Li Zefan,
> 
>    I don't know anything about tracing, but the module code changes look
> simple and fine to me.
> 

I guess I can take this as an ack. :)

Tracing is used to have a deep insight into the system, analyse
performance issue, help debugging, dump info at system panic,
etc..

And those module trace events also can be used with other trace
events and tracers, an example below:

# mount -t debugfs xxx /mnt
# cd /mnt/tracing
# echo module > set_event
# echo scsi_device_get > set_graph_function
# echo scsi_device_put >> set_graph_function
# mount /dev/sda1 /media
# cat trace
# tracer: function_graph                         
#                                                
# CPU  DURATION                  FUNCTION CALLS  
# |     |   |                     |   |   |   |
 0)               |  scsi_device_get() {
 0)   1.215 us    |    get_device();
 0)               |    ftrace_raw_event_module_get() {
 0)   0.870 us    |      strlen();
 0)               |      /* module_get: sata_sis call_site=scsi_device_get refcnt=9 */
 0)   1.003 us    |      strcpy();
 0)   5.821 us    |    }
 0) + 17.304 us   |  }
 1)               |  scsi_device_put() {
 1)   1.807 us    |    module_refcount();
 1)               |    module_put() {
 1)               |      ftrace_raw_event_module_put() {
 1)   0.748 us    |        strlen();
 1)               |        /* module_put: sata_sis call_site=return_to_handler refcnt=-6 */
 1)   0.856 us    |        strcpy();
 1)   4.799 us    |      }
 1)   6.799 us    |    }
 1)   0.771 us    |    put_device();
 1) + 17.464 us   |  }
 ------------------------------------------
 1)   mount-2452   =>  mount.n-2453
 ------------------------------------------

Re: [PATCH] tracing/events: Add module tracepoints

[Steven Rostedt]

On Wed, 22 Jul 2009, Li Zefan wrote:

> Rusty Russell wrote:
> > On Tue, 21 Jul 2009 06:26:33 pm Li Zefan wrote:
> >> 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.
> > 
> > Hi Li Zefan,
> > 
> >    I don't know anything about tracing, but the module code changes look
> > simple and fine to me.
> > 
> 
> I guess I can take this as an ack. :)

I'll take it as an ack too ;-)

> 
> Tracing is used to have a deep insight into the system, analyse
> performance issue, help debugging, dump info at system panic,
> etc..

Looks good. I'm currently doing some maintenance on my systems, but once 
that is done, I'll go ahead and queue up your patches.

Thanks,

-- Steve

Re: [PATCH] tracing/events: Add module tracepoints

[Frederic Weisbecker]

On Tue, Jul 21, 2009 at 04:56:33PM +0800, Li Zefan wrote:
> 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>


Nice.

Just two worries about it.

The ring buffer are flushed on module unloading right?
That won't make it easy to perform module event tracing.

Also the events selftests do a lot of random things to trigger
each kind of events, I guess some new others will be needed to
tests these, unless they will seem to fail on every selftests.
Although I can't imagine a module loading/unloading for
every ftrace event selftest... I guess these will require
a specific treatement and also will need to be selftested once
the filesystem is set to be able to load modules.

Thanks,
Frederic.


> ---
>  include/linux/module.h        |   14 ++++-
>  include/trace/events/module.h |  126 +++++++++++++++++++++++++++++++++++++++++
>  kernel/kmod.c                 |    4 +
>  kernel/module.c               |   11 ++++
>  4 files changed, 152 insertions(+), 3 deletions(-)
>  create mode 100644 include/trace/events/module.h
> 
> diff --git a/include/linux/module.h b/include/linux/module.h
> index 7a5c82c..86863cd 100644
> --- a/include/linux/module.h
> +++ b/include/linux/module.h
> @@ -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)
>  
> @@ -480,7 +482,10 @@ static inline local_t *__module_ref_addr(struct module *mod, int cpu)
>  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();
>  	}
>  }
> @@ -491,8 +496,11 @@ static inline int try_module_get(struct module *module)
>  
>  	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();
> diff --git a/include/trace/events/module.h b/include/trace/events/module.h
> new file mode 100644
> index 0000000..84160fb
> --- /dev/null
> +++ b/include/trace/events/module.h
> @@ -0,0 +1,126 @@
> +#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>
> +
> diff --git a/kernel/kmod.c b/kernel/kmod.c
> index 385c31a..a922808 100644
> --- a/kernel/kmod.c
> +++ b/kernel/kmod.c
> @@ -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;
> @@ -108,6 +110,8 @@ int __request_module(bool wait, const char *fmt, ...)
>  		return -ENOMEM;
>  	}
>  
> +	trace_module_request(module_name, wait, _RET_IP_);
> +
>  	ret = call_usermodehelper(modprobe_path, argv, envp,
>  			wait ? UMH_WAIT_PROC : UMH_WAIT_EXEC);
>  	atomic_dec(&kmod_concurrent);
> diff --git a/kernel/module.c b/kernel/module.c
> index 0a04983..38bf87a 100644
> --- a/kernel/module.c
> +++ b/kernel/module.c
> @@ -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 @@ void module_put(struct module *module)
>  	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);
> @@ -1490,6 +1497,8 @@ static int __unlink_module(void *_mod)
>  /* 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 @@ static noinline struct module *load_module(void __user *umod,
>  	/* Get rid of temporary copy */
>  	vfree(hdr);
>  
> +	trace_module_load(mod);
> +
>  	/* Done! */
>  	return mod;
>  
> -- 
> 1.6.3
> 

Re: [PATCH] tracing/events: Add module tracepoints

[Li Zefan]

Frederic Weisbecker wrote:
> On Tue, Jul 21, 2009 at 04:56:33PM +0800, Li Zefan wrote:
>> 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>
> 
> 
> Nice.
> 
> Just two worries about it.
> 
> The ring buffer are flushed on module unloading right?
> That won't make it easy to perform module event tracing.
> 

Yes, but only when the module has "_ftrace_events" section.
They are ext4 and gfs2 for the current kernel.

> Also the events selftests do a lot of random things to trigger
> each kind of events, I guess some new others will be needed to
> tests these, unless they will seem to fail on every selftests.
> Although I can't imagine a module loading/unloading for
> every ftrace event selftest... I guess these will require
> a specific treatement and also will need to be selftested once
> the filesystem is set to be able to load modules.
> 

It's nice to have more selftests but I don't think it is a
necessity.

Actually the events selftests just confirm the events won't
crash the system, and no trace entries are generated by them
in the selftests.

Re: [PATCH] tracing/events: Add module tracepoints

[Frederic Weisbecker]

On Mon, Jul 27, 2009 at 09:41:46AM +0800, Li Zefan wrote:
> Frederic Weisbecker wrote:
> > On Tue, Jul 21, 2009 at 04:56:33PM +0800, Li Zefan wrote:
> >> 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>
> > 
> > 
> > Nice.
> > 
> > Just two worries about it.
> > 
> > The ring buffer are flushed on module unloading right?
> > That won't make it easy to perform module event tracing.
> > 
> 
> Yes, but only when the module has "_ftrace_events" section.
> They are ext4 and gfs2 for the current kernel.


Ah, good point.

 
> > Also the events selftests do a lot of random things to trigger
> > each kind of events, I guess some new others will be needed to
> > tests these, unless they will seem to fail on every selftests.
> > Although I can't imagine a module loading/unloading for
> > every ftrace event selftest... I guess these will require
> > a specific treatement and also will need to be selftested once
> > the filesystem is set to be able to load modules.
> > 
> 
> It's nice to have more selftests but I don't think it is a
> necessity.
> 
> Actually the events selftests just confirm the events won't
> crash the system, and no trace entries are generated by them
> in the selftests.


Indeed, forget about these worries :)

Thanks.