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>

4 files changed, 152 insertions, 3 deletions

diff --git a/include/linux/module.h b/include/linux/module.h
index 098bdb7bfacf..f8f92d015efe 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)
 
@@ -462,7 +464,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();
         }
 }
@@ -473,8 +478,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 000000000000..84160fb18478
--- /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 385c31a1bdbf..a92280870e30 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 fd1411403558..b1821438694e 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);
@@ -1491,6 +1498,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);
@@ -2358,6 +2367,8 @@ static noinline struct module *load_module(void __user *umod,
         /* Get rid of temporary copy */
         vfree(hdr);
 
+        trace_module_load(mod);
+
         /* Done! */
         return mod;