1. 10 Mar, 2009 4 commits
    • Steven Rostedt's avatar
      tracing: update comments to match event code macros · 0e3d0f05
      Steven Rostedt authored
      
      
      Impact: clean up / comments
      
      The comments that described the ftrace macros to manipulate the
      TRACE_EVENT and TRACE_FORMAT macros no longer match the code.
      This patch updates them.
      Reported-by: default avatarKOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      0e3d0f05
    • Steven Rostedt's avatar
      tracing: flip the TP_printk and TP_fast_assign in the TRACE_EVENT macro · 30a8fecc
      Steven Rostedt authored
      
      
      Impact: clean up
      
      In trying to stay consistant with the C style format in the TRACE_EVENT
      macro, it makes more sense to do the printk after the assigning of
      the variables.
      Reported-by: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      30a8fecc
    • Steven Rostedt's avatar
      tracing: new format for specialized trace points · da4d0302
      Steven Rostedt authored
      
      
      Impact: clean up and enhancement
      
      The TRACE_EVENT_FORMAT macro looks quite ugly and is limited in its
      ability to save data as well as to print the record out. Working with
      Ingo Molnar, we came up with a new format that is much more pleasing to
      the eye of C developers. This new macro is more C style than the old
      macro, and is more obvious to what it does.
      
      Here's the example. The only updated macro in this patch is the
      sched_switch trace point.
      
      The old method looked like this:
      
       TRACE_EVENT_FORMAT(sched_switch,
              TP_PROTO(struct rq *rq, struct task_struct *prev,
                      struct task_struct *next),
              TP_ARGS(rq, prev, next),
              TP_FMT("task %s:%d ==> %s:%d",
                    prev->comm, prev->pid, next->comm, next->pid),
              TRACE_STRUCT(
                      TRACE_FIELD(pid_t, prev_pid, prev->pid)
                      TRACE_FIELD(int, prev_prio, prev->prio)
                      TRACE_FIELD_SPECIAL(char next_comm[TASK_COMM_LEN],
                                          next_comm,
                                          TP_CMD(memcpy(TRACE_ENTRY->next_comm,
                                                       next->comm,
                                                       TASK_COMM_LEN)))
                      TRACE_FIELD(pid_t, next_pid, next->pid)
                      TRACE_FIELD(int, next_prio, next->prio)
              ),
              TP_RAW_FMT("prev %d:%d ==> next %s:%d:%d")
              );
      
      The above method is hard to read and requires two format fields.
      
      The new method:
      
       /*
        * Tracepoint for task switches, performed by the scheduler:
        *
        * (NOTE: the 'rq' argument is not used by generic trace events,
        *        but used by the latency tracer plugin. )
        */
       TRACE_EVENT(sched_switch,
      
      	TP_PROTO(struct rq *rq, struct task_struct *prev,
      		 struct task_struct *next),
      
      	TP_ARGS(rq, prev, next),
      
      	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			)
      	),
      
      	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;
      		__entry->prev_prio	= prev->prio;
      		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
      		__entry->next_pid	= next->pid;
      		__entry->next_prio	= next->prio;
      	)
       );
      
      This macro is called TRACE_EVENT, it is broken up into 5 parts:
      
       TP_PROTO:        the proto type of the trace point
       TP_ARGS:         the arguments of the trace point
       TP_STRUCT_entry: the structure layout of the entry in the ring buffer
       TP_printk:       the printk format
       TP_fast_assign:  the method used to write the entry into the ring buffer
      
      The structure is the definition of how the event will be saved in the
      ring buffer. The printk is used by the internal tracing in case of
      an oops, and the kernel needs to print out the format of the record
      to the console. This the TP_printk gives a means to show the records
      in a human readable format. It is also used to print out the data
      from the trace file.
      
      The TP_fast_assign is executed directly. It is basically like a C function,
      where the __entry is the handle to the record.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      da4d0302
    • Steven Rostedt's avatar
      tracing: replace TP<var> with TP_<var> · 2939b046
      Steven Rostedt authored
      
      
      Impact: clean up
      
      The macros TPPROTO, TPARGS, TPFMT, TPRAWFMT, and TPCMD all look a bit
      ugly. This patch adds an underscore to their names.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      2939b046
  2. 06 Mar, 2009 1 commit
  3. 02 Mar, 2009 3 commits
    • Steven Rostedt's avatar
      tracing: add print format to event trace format files · 96ccd21c
      Steven Rostedt authored
      
      
      This patch adds the internal print format used to print the raw events
      to the event trace point format file.
      
       # cat /debug/tracing/events/sched/sched_switch/format
      name: sched_switch
      ID: 29
      format:
              field:unsigned char type;       offset:0;       size:1;
              field:unsigned char flags;      offset:1;       size:1;
              field:unsigned char preempt_count;      offset:2;       size:1;
              field:int pid;  offset:4;       size:4;
              field:int tgid; offset:8;       size:4;
      
              field:pid_t prev_pid;   offset:12;      size:4;
              field:int prev_prio;    offset:16;      size:4;
              field special:char next_comm[TASK_COMM_LEN];    offset:20;      size:16;
              field:pid_t next_pid;   offset:36;      size:4;
              field:int next_prio;    offset:40;      size:4;
      
      print fmt: "prev %d:%d ==> next %s:%d:%d"
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      96ccd21c
    • Steven Rostedt's avatar
      tracing: add format file to describe event struct fields · 981d081e
      Steven Rostedt authored
      
      
      This patch adds the "format" file to the trace point event directory.
      This is based off of work by Tom Zanussi, in which a file is exported
      to be tread from user land such that a user space app may read the
      binary record stored in the ring buffer.
      
       # cat /debug/tracing/events/sched/sched_switch/format
              field:pid_t prev_pid;   offset:12;      size:4;
              field:int prev_prio;    offset:16;      size:4;
              field special:char next_comm[TASK_COMM_LEN];    offset:20;      size:16;
              field:pid_t next_pid;   offset:36;      size:4;
              field:int next_prio;    offset:40;      size:4;
      
      Idea-from: Tom Zanussi <tzanussi@gmail.com>
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      981d081e
    • Steven Rostedt's avatar
      tracing: add TRACE_FIELD_SPECIAL to record complex entries · d20e3b03
      Steven Rostedt authored
      
      
      Tom Zanussi pointed out that the simple TRACE_FIELD was not enough to
      record trace data that required memcpy. This patch addresses this issue
      by adding a TRACE_FIELD_SPECIAL. The format is similar to TRACE_FIELD
      but looks like so:
      
        TRACE_FIELD_SPECIAL(type_item, item, cmd)
      
      What TRACE_FIELD gave was:
      
        TRACE_FIELD(type, item, assign)
      
      The TRACE_FIELD would be used in declaring a structure:
      
        struct {
      	type	item;
        };
      
      And later assign it via:
      
        entry->item = assign;
      
      What TRACE_FIELD_SPECIAL gives us is:
      
      In the declaration of the structure:
      
        struct {
      	type_item;
        };
      
      And the assignment:
      
        cmd;
      
      This change log will explain the one example used in the patch:
      
       TRACE_EVENT_FORMAT(sched_switch,
      	TPPROTO(struct rq *rq, struct task_struct *prev,
      		struct task_struct *next),
      	TPARGS(rq, prev, next),
      	TPFMT("task %s:%d ==> %s:%d",
      	      prev->comm, prev->pid, next->comm, next->pid),
      	TRACE_STRUCT(
      		TRACE_FIELD(pid_t, prev_pid, prev->pid)
      		TRACE_FIELD(int, prev_prio, prev->prio)
      		TRACE_FIELD_SPECIAL(char next_comm[TASK_COMM_LEN],
      				    next_comm,
      				    TPCMD(memcpy(TRACE_ENTRY->next_comm,
      						 next->comm,
      						 TASK_COMM_LEN)))
      		TRACE_FIELD(pid_t, next_pid, next->pid)
      		TRACE_FIELD(int, next_prio, next->prio)
      	),
      	TPRAWFMT("prev %d:%d ==> next %s:%d:%d")
      	);
      
       The struct will be create as:
      
        struct {
      	pid_t		prev_pid;
      	int		prev_prio;
      	char next_comm[TASK_COMM_LEN];
      	pid_t		next_pid;
      	int		next_prio;
        };
      
      Note the TRACE_ENTRY in the cmd part of TRACE_SPECIAL. TRACE_ENTRY will
      be set by the tracer to point to the structure inside the trace buffer.
      
        entry->prev_pid	= prev->pid;
        entry->prev_prio	= prev->prio;
        memcpy(entry->next_comm, next->comm, TASK_COMM_LEN);
        entry->next_pid	= next->pid;
        entry->next_prio	= next->prio
      Reported-by: default avatarTom Zanussi <tzanussi@gmail.com>
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      d20e3b03
  4. 28 Feb, 2009 1 commit
    • Steven Rostedt's avatar
      tracing: add raw trace point recording infrastructure · c32e827b
      Steven Rostedt authored
      
      
      Impact: lower overhead tracing
      
      The current event tracer can automatically pick up trace points
      that are registered with the TRACE_FORMAT macro. But it required
      a printf format string and parsing. Although, this adds the ability
      to get guaranteed information like task names and such, it took
      a hit in overhead processing. This processing can add about 500-1000
      nanoseconds overhead, but in some cases that too is considered
      too much and we want to shave off as much from this overhead as
      possible.
      
      Tom Zanussi recently posted tracing patches to lkml that are based
      on a nice idea about capturing the data via C structs using
      STRUCT_ENTER, STRUCT_EXIT type of macros.
      
      I liked that method very much, but did not like the implementation
      that required a developer to add data/code in several disjoint
      locations.
      
      This patch extends the event_tracer macros to do a similar "raw C"
      approach that Tom Zanussi did. But instead of having the developers
      needing to tweak a bunch of code all over the place, they can do it
      all in one macro - preferably placed near the code that it is
      tracing. That makes it much more likely that tracepoints will be
      maintained on an ongoing basis by the code they modify.
      
      The new macro TRACE_EVENT_FORMAT is created for this approach. (Note,
      a developer may still utilize the more low level DECLARE_TRACE macros
      if they don't care about getting their traces automatically in the event
      tracer.)
      
      They can also use the existing TRACE_FORMAT if they don't need to code
      the tracepoint in C, but just want to use the convenience of printf.
      
      So if the developer wants to "hardwire" a tracepoint in the fastest
      possible way, and wants to acquire their data via a user space utility
      in a raw binary format, or wants to see it in the trace output but not
      sacrifice any performance, then they can implement the faster but
      more complex TRACE_EVENT_FORMAT macro.
      
      Here's what usage looks like:
      
        TRACE_EVENT_FORMAT(name,
      	TPPROTO(proto),
      	TPARGS(args),
      	TPFMT(fmt, fmt_args),
      	TRACE_STUCT(
      		TRACE_FIELD(type1, item1, assign1)
      		TRACE_FIELD(type2, item2, assign2)
      			[...]
      	),
      	TPRAWFMT(raw_fmt)
      	);
      
      Note name, proto, args, and fmt, are all identical to what TRACE_FORMAT
      uses.
      
       name: is the unique identifier of the trace point
       proto: The proto type that the trace point uses
       args: the args in the proto type
       fmt: printf format to use with the event printf tracer
       fmt_args: the printf argments to match fmt
      
       TRACE_STRUCT starts the ability to create a structure.
       Each item in the structure is defined with a TRACE_FIELD
      
        TRACE_FIELD(type, item, assign)
      
       type: the C type of item.
       item: the name of the item in the stucture
       assign: what to assign the item in the trace point callback
      
       raw_fmt is a way to pretty print the struct. It must match
        the order of the items are added in TRACE_STUCT
      
       An example of this would be:
      
       TRACE_EVENT_FORMAT(sched_wakeup,
      	TPPROTO(struct rq *rq, struct task_struct *p, int success),
      	TPARGS(rq, p, success),
      	TPFMT("task %s:%d %s",
      	      p->comm, p->pid, success?"succeeded":"failed"),
      	TRACE_STRUCT(
      		TRACE_FIELD(pid_t, pid, p->pid)
      		TRACE_FIELD(int, success, success)
      	),
      	TPRAWFMT("task %d success=%d")
      	);
      
       This creates us a unique struct of:
      
       struct {
      	pid_t		pid;
      	int		success;
       };
      
       And the way the call back would assign these values would be:
      
      	entry->pid = p->pid;
      	entry->success = success;
      
      The nice part about this is that the creation of the assignent is done
      via macro magic in the event tracer.  Once the TRACE_EVENT_FORMAT is
      created, the developer will then have a faster method to record
      into the ring buffer. They do not need to worry about the tracer itself.
      
      The developer would only need to touch the files in include/trace/*.h
      
      Again, I would like to give special thanks to Tom Zanussi for this
      nice idea.
      
      Idea-from: Tom Zanussi <tzanussi@gmail.com>
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      c32e827b