Merge branch 'tip/tracing/ftrace' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace into tracing/ftrace

3 files changed, 159 insertions, 56 deletions

diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index 69b56988813d..d35a7ee7611f 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -157,7 +157,110 @@ static inline void tracepoint_synchronize_unregister(void)
 #define TRACE_FORMAT(name, proto, args, fmt)            \
         DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 
-#define TRACE_EVENT(name, proto, args, struct, print, assign)   \
+
+/*
+ * For use with the TRACE_EVENT macro:
+ *
+ * We define a tracepoint, its arguments, its printk format
+ * and its 'fast binay record' layout.
+ *
+ * Firstly, name your tracepoint via TRACE_EVENT(name : the
+ * 'subsystem_event' notation is fine.
+ *
+ * Think about this whole construct as the
+ * 'trace_sched_switch() function' from now on.
+ *
+ *
+ *  TRACE_EVENT(sched_switch,
+ *
+ *      *
+ *      * A function has a regular function arguments
+ *      * prototype, declare it via TP_PROTO():
+ *      *
+ *
+ *      TP_PROTO(struct rq *rq, struct task_struct *prev,
+ *               struct task_struct *next),
+ *
+ *      *
+ *      * Define the call signature of the 'function'.
+ *      * (Design sidenote: we use this instead of a
+ *      *  TP_PROTO1/TP_PROTO2/TP_PROTO3 ugliness.)
+ *      *
+ *
+ *      TP_ARGS(rq, prev, next),
+ *
+ *      *
+ *      * Fast binary tracing: define the trace record via
+ *      * TP_STRUCT__entry(). You can think about it like a
+ *      * regular C structure local variable definition.
+ *      *
+ *      * This is how the trace record is structured and will
+ *      * be saved into the ring buffer. These are the fields
+ *      * that will be exposed to user-space in
+ *      * /debug/tracing/events/<*>/format.
+ *      *
+ *      * The declared 'local variable' is called '__entry'
+ *      *
+ *      * __field(pid_t, prev_prid) is equivalent to a standard declariton:
+ *      *
+ *      *       pid_t   prev_pid;
+ *      *
+ *      * __array(char, prev_comm, TASK_COMM_LEN) is equivalent to:
+ *      *
+ *      *       char    prev_comm[TASK_COMM_LEN];
+ *      *
+ *
+ *      TP_STRUCT__entry(
+ *              __array(        char,   prev_comm,      TASK_COMM_LEN   )
+ *              __field(        pid_t,  prev_pid                        )
+ *              __field(        int,    prev_prio                       )
+ *              __array(        char,   next_comm,      TASK_COMM_LEN   )
+ *              __field(        pid_t,  next_pid                        )
+ *              __field(        int,    next_prio                       )
+ *      ),
+ *
+ *      *
+ *      * Assign the entry into the trace record, by embedding
+ *      * a full C statement block into TP_fast_assign(). You
+ *      * can refer to the trace record as '__entry' -
+ *      * otherwise you can put arbitrary C code in here.
+ *      *
+ *      * Note: this C code will execute every time a trace event
+ *      * happens, on an active tracepoint.
+ *      *
+ *
+ *      TP_fast_assign(
+ *              memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
+ *              __entry->prev_pid       = prev->pid;
+ *              __entry->prev_prio      = prev->prio;
+ *              memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
+ *              __entry->next_pid       = next->pid;
+ *              __entry->next_prio      = next->prio;
+ *      )
+ *
+ *      *
+ *      * Formatted output of a trace record via TP_printk().
+ *      * This is how the tracepoint will appear under ftrace
+ *      * plugins that make use of this tracepoint.
+ *      *
+ *      * (raw-binary tracing wont actually perform this step.)
+ *      *
+ *
+ *      TP_printk("task %s:%d [%d] ==> %s:%d [%d]",
+ *              __entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
+ *              __entry->next_comm, __entry->next_pid, __entry->next_prio),
+ *
+ * );
+ *
+ * This macro construct is thus used for the regular printk format
+ * tracing setup, it is used to construct a function pointer based
+ * tracepoint callback (this is used by programmatic plugins and
+ * can also by used by generic instrumentation like SystemTap), and
+ * it is also used to expose a structured trace record in
+ * /debug/tracing/events/.
+ */
+
+#define TRACE_EVENT(name, proto, args, struct, assign, print)   \
         DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 
 #endif
diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
index 43bcb74dd49f..214bb928fe9e 100644
--- a/include/trace/irq_event_types.h
+++ b/include/trace/irq_event_types.h
@@ -31,13 +31,13 @@ TRACE_EVENT(irq_handler_exit,
                 __field(        int,    ret     )
         ),
 
-        TP_printk("irq=%d return=%s",
-                  __entry->irq, __entry->ret ? "handled" : "unhandled"),
-
         TP_fast_assign(
                 __entry->irq    = irq;
                 __entry->ret    = ret;
-        )
+        ),
+
+        TP_printk("irq=%d return=%s",
+                  __entry->irq, __entry->ret ? "handled" : "unhandled")
 );
 
 #undef TRACE_SYSTEM
diff --git a/include/trace/sched_event_types.h b/include/trace/sched_event_types.h
index fb37af672c88..63547dc1125f 100644
--- a/include/trace/sched_event_types.h
+++ b/include/trace/sched_event_types.h
@@ -22,12 +22,12 @@ TRACE_EVENT(sched_kthread_stop,
                 __field(        pid_t,  pid                     )
         ),
 
-        TP_printk("task %s:%d", __entry->comm, __entry->pid),
-
         TP_fast_assign(
                 memcpy(__entry->comm, t->comm, TASK_COMM_LEN);
                 __entry->pid    = t->pid;
-        )
+        ),
+
+        TP_printk("task %s:%d", __entry->comm, __entry->pid)
 );
 
 /*
@@ -43,11 +43,11 @@ TRACE_EVENT(sched_kthread_stop_ret,
                 __field(        int,    ret     )
         ),
 
-        TP_printk("ret %d", __entry->ret),
-
         TP_fast_assign(
                 __entry->ret    = ret;
-        )
+        ),
+
+        TP_printk("ret %d", __entry->ret)
 );
 
 /*
@@ -68,14 +68,14 @@ TRACE_EVENT(sched_wait_task,
                 __field(        int,    prio                    )
         ),
 
-        TP_printk("task %s:%d [%d]",
-                  __entry->comm, __entry->pid, __entry->prio),
-
         TP_fast_assign(
                 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                 __entry->pid    = p->pid;
                 __entry->prio   = p->prio;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d]",
+                  __entry->comm, __entry->pid, __entry->prio)
 );
 
 /*
@@ -97,16 +97,16 @@ TRACE_EVENT(sched_wakeup,
                 __field(        int,    success                 )
         ),
 
-        TP_printk("task %s:%d [%d] success=%d",
-                  __entry->comm, __entry->pid, __entry->prio,
-                  __entry->success),
-
         TP_fast_assign(
                 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                 __entry->pid            = p->pid;
                 __entry->prio           = p->prio;
                 __entry->success        = success;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d] success=%d",
+                  __entry->comm, __entry->pid, __entry->prio,
+                  __entry->success)
 );
 
 /*
@@ -128,16 +128,16 @@ TRACE_EVENT(sched_wakeup_new,
                 __field(        int,    success                 )
         ),
 
-        TP_printk("task %s:%d [%d] success=%d",
-                  __entry->comm, __entry->pid, __entry->prio,
-                  __entry->success),
-
         TP_fast_assign(
                 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                 __entry->pid            = p->pid;
                 __entry->prio           = p->prio;
                 __entry->success        = success;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d] success=%d",
+                  __entry->comm, __entry->pid, __entry->prio,
+                  __entry->success)
 );
 
 /*
@@ -162,10 +162,6 @@ TRACE_EVENT(sched_switch,
                 __field(        int,    next_prio                       )
         ),
 
-        TP_printk("task %s:%d [%d] ==> %s:%d [%d]",
-                __entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
-                __entry->next_comm, __entry->next_pid, __entry->next_prio),
-
         TP_fast_assign(
                 memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
                 __entry->prev_pid       = prev->pid;
@@ -173,7 +169,11 @@ TRACE_EVENT(sched_switch,
                 memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
                 __entry->next_pid       = next->pid;
                 __entry->next_prio      = next->prio;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d] ==> %s:%d [%d]",
+                __entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
+                __entry->next_comm, __entry->next_pid, __entry->next_prio)
 );
 
 /*
@@ -193,17 +193,17 @@ TRACE_EVENT(sched_migrate_task,
                 __field(        int,    dest_cpu                )
         ),
 
-        TP_printk("task %s:%d [%d] from: %d  to: %d",
-                  __entry->comm, __entry->pid, __entry->prio,
-                  __entry->orig_cpu, __entry->dest_cpu),
-
         TP_fast_assign(
                 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                 __entry->pid            = p->pid;
                 __entry->prio           = p->prio;
                 __entry->orig_cpu       = orig_cpu;
                 __entry->dest_cpu       = dest_cpu;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d] from: %d  to: %d",
+                  __entry->comm, __entry->pid, __entry->prio,
+                  __entry->orig_cpu, __entry->dest_cpu)
 );
 
 /*
@@ -221,14 +221,14 @@ TRACE_EVENT(sched_process_free,
                 __field(        int,    prio                    )
         ),
 
-        TP_printk("task %s:%d [%d]",
-                  __entry->comm, __entry->pid, __entry->prio),
-
         TP_fast_assign(
                 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                 __entry->pid            = p->pid;
                 __entry->prio           = p->prio;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d]",
+                  __entry->comm, __entry->pid, __entry->prio)
 );
 
 /*
@@ -246,14 +246,14 @@ TRACE_EVENT(sched_process_exit,
                 __field(        int,    prio                    )
         ),
 
-        TP_printk("task %s:%d [%d]",
-                  __entry->comm, __entry->pid, __entry->prio),
-
         TP_fast_assign(
                 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                 __entry->pid            = p->pid;
                 __entry->prio           = p->prio;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d]",
+                  __entry->comm, __entry->pid, __entry->prio)
 );
 
 /*
@@ -271,14 +271,14 @@ TRACE_EVENT(sched_process_wait,
                 __field(        int,    prio                    )
         ),
 
-        TP_printk("task %s:%d [%d]",
-                  __entry->comm, __entry->pid, __entry->prio),
-
         TP_fast_assign(
                 memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
                 __entry->pid            = pid_nr(pid);
                 __entry->prio           = current->prio;
-        )
+        ),
+
+        TP_printk("task %s:%d [%d]",
+                  __entry->comm, __entry->pid, __entry->prio)
 );
 
 /*
@@ -297,16 +297,16 @@ TRACE_EVENT(sched_process_fork,
                 __field(        pid_t,  child_pid                       )
         ),
 
-        TP_printk("parent %s:%d  child %s:%d",
-                __entry->parent_comm, __entry->parent_pid,
-                __entry->child_comm, __entry->child_pid),
-
         TP_fast_assign(
                 memcpy(__entry->parent_comm, parent->comm, TASK_COMM_LEN);
                 __entry->parent_pid     = parent->pid;
                 memcpy(__entry->child_comm, child->comm, TASK_COMM_LEN);
                 __entry->child_pid      = child->pid;
-        )
+        ),
+
+        TP_printk("parent %s:%d  child %s:%d",
+                __entry->parent_comm, __entry->parent_pid,
+                __entry->child_comm, __entry->child_pid)
 );
 
 /*
@@ -324,14 +324,14 @@ TRACE_EVENT(sched_signal_send,
                 __field(        pid_t,  pid                     )
         ),
 
-        TP_printk("sig: %d  task %s:%d",
-                  __entry->sig, __entry->comm, __entry->pid),
-
         TP_fast_assign(
                 memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                 __entry->pid    = p->pid;
                 __entry->sig    = sig;
-        )
+        ),
+
+        TP_printk("sig: %d  task %s:%d",
+                  __entry->sig, __entry->comm, __entry->pid)
 );
 
 #undef TRACE_SYSTEM