[PATCH 00/11] [GIT PULL][for 2.6.32] new event print tag language

[PATCH 00/11] [GIT PULL][for 2.6.32] new event print tag language

[Steven Rostedt]

[
  Note, this work is aimed at 2.6.32 and not this merge window,
    except for maybe the first patch.
]

Ingo,

I rebased against tip/tracing/core and folded a lot of the fix ups into
their corresponding patches. I still kept some of the tags out of
the main patch since they explain those changes nicely and also
demonstrates how to add new tags.

The first patch "tracing: add entry size to iterator" is something that
was lacking in the trace output, and I would recommend for this
merge window. Just because it is low impact and it would be a nice thing
to have for those that are working on enhancing ftrace.

The rest, could you make a separate branch for, so we can experiment
with. I'll keep the event-print-format* branches around too.

Please pull the latest tip/tracing/event-print-format-1 tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/tracing/event-print-format-1


Steven Rostedt (11):
      tracing: add entry size to iterator
      tracing/events: nicer print format for parsing
      tracing: add nsec2sec print formats
      tracing: add major and minor tags for print format
      tracing: add func and symfunc to tag format
      tracing: update sample code with new tag format
      tracing/events: modify irq print to new format
      tracing/events: modify sched print to new format
      tracing/events: modify kmem print to new format
      tracing/events: modify lockdep print to new format
      tracing: convert the block trace points to use the new tag format

----
 include/linux/ftrace_event.h               |   13 +
 include/trace/events/block.h               |  101 +--
 include/trace/events/irq.h                 |   40 +-
 include/trace/events/kmem.h                |  100 ++--
 include/trace/events/lockdep.h             |   18 +-
 include/trace/events/sched.h               |   49 +-
 include/trace/ftrace.h                     |   22 +-
 kernel/trace/Makefile                      |    1 +
 kernel/trace/trace.c                       |   39 +-
 kernel/trace/trace_events.c                |    1 +
 kernel/trace/trace_output.c                |    2 +-
 kernel/trace/trace_output.h                |    4 +
 kernel/trace/trace_read_binary.c           |  973 ++++++++++++++++++++++++++++
 samples/trace_events/trace-events-sample.c |   21 +-
 samples/trace_events/trace-events-sample.h |   66 ++
 15 files changed, 1247 insertions(+), 203 deletions(-)
-- 

[PATCH 01/11] tracing: add entry size to iterator

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-add-entry-size-to-iterator.patch --]
[-- Type: text/plain, Size: 3751 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

In order to test against corruption of records, the size of the entry
needs to be passed to callbacks. This patch places the entry size
into a new field of the iterator "ent_size", that print call backs
can access.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/ftrace_event.h |    1 +
 kernel/trace/trace.c         |   39 ++++++++++++++++++++++++---------------
 2 files changed, 25 insertions(+), 15 deletions(-)

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index 5c093ff..c03befb 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -56,6 +56,7 @@ struct trace_iterator {
 	/* The below is zeroed out in pipe_read */
 	struct trace_seq	seq;
 	struct trace_entry	*ent;
+	unsigned int		ent_size;
 	int			cpu;
 	u64			ts;
 
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index cae34c6..d83036d 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1398,7 +1398,7 @@ static void trace_iterator_increment(struct trace_iterator *iter)
 	ftrace_enable_cpu();
 }
 
-static struct trace_entry *
+static struct ring_buffer_event *
 peek_next_entry(struct trace_iterator *iter, int cpu, u64 *ts)
 {
 	struct ring_buffer_event *event;
@@ -1414,15 +1414,17 @@ peek_next_entry(struct trace_iterator *iter, int cpu, u64 *ts)
 
 	ftrace_enable_cpu();
 
-	return event ? ring_buffer_event_data(event) : NULL;
+	return event;
 }
 
 static struct trace_entry *
-__find_next_entry(struct trace_iterator *iter, int *ent_cpu, u64 *ent_ts)
+__find_next_entry(struct trace_iterator *iter, int *ent_cpu, u64 *ent_ts,
+		  unsigned int *ent_size)
 {
 	struct ring_buffer *buffer = iter->tr->buffer;
-	struct trace_entry *ent, *next = NULL;
+	struct ring_buffer_event *event, *next = NULL;
 	int cpu_file = iter->cpu_file;
+	struct trace_entry *ent;
 	u64 next_ts = 0, ts;
 	int next_cpu = -1;
 	int cpu;
@@ -1434,11 +1436,9 @@ __find_next_entry(struct trace_iterator *iter, int *ent_cpu, u64 *ent_ts)
 	if (cpu_file > TRACE_PIPE_ALL_CPU) {
 		if (ring_buffer_empty_cpu(buffer, cpu_file))
 			return NULL;
-		ent = peek_next_entry(iter, cpu_file, ent_ts);
-		if (ent_cpu)
-			*ent_cpu = cpu_file;
-
-		return ent;
+		next_cpu = cpu_file;
+		next = peek_next_entry(iter, cpu_file, &next_ts);
+		goto out;
 	}
 
 	for_each_tracing_cpu(cpu) {
@@ -1446,38 +1446,47 @@ __find_next_entry(struct trace_iterator *iter, int *ent_cpu, u64 *ent_ts)
 		if (ring_buffer_empty_cpu(buffer, cpu))
 			continue;
 
-		ent = peek_next_entry(iter, cpu, &ts);
+		event = peek_next_entry(iter, cpu, &ts);
 
 		/*
 		 * Pick the entry with the smallest timestamp:
 		 */
-		if (ent && (!next || ts < next_ts)) {
-			next = ent;
+		if (event && (!next || ts < next_ts)) {
+			next = event;
 			next_cpu = cpu;
 			next_ts = ts;
 		}
 	}
 
+ out:
 	if (ent_cpu)
 		*ent_cpu = next_cpu;
 
 	if (ent_ts)
 		*ent_ts = next_ts;
 
-	return next;
+	if (!next)
+		return NULL;
+
+	ent = ring_buffer_event_data(next);
+	if (ent_size)
+		*ent_size = ring_buffer_event_length(next);
+
+	return ent;
 }
 
 /* Find the next real entry, without updating the iterator itself */
 struct trace_entry *trace_find_next_entry(struct trace_iterator *iter,
 					  int *ent_cpu, u64 *ent_ts)
 {
-	return __find_next_entry(iter, ent_cpu, ent_ts);
+	return __find_next_entry(iter, ent_cpu, ent_ts, NULL);
 }
 
 /* Find the next real entry, and increment the iterator to the next entry */
 static void *find_next_entry_inc(struct trace_iterator *iter)
 {
-	iter->ent = __find_next_entry(iter, &iter->cpu, &iter->ts);
+	iter->ent = __find_next_entry(iter, &iter->cpu, &iter->ts,
+				      &iter->ent_size);
 
 	if (iter->ent)
 		trace_iterator_increment(iter);
-- 
1.6.3.1

-- 

[PATCH 02/11] tracing/events: nicer print format for parsing

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-events-nicer-print-format-for-parsing.patch --]
[-- Type: text/plain, Size: 27763 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The current print format that is exported to userspace is simply a
copy of the printk format used to output the data. It would take a
full C parser to parse it. But as more tools are made to read the
binary data from ftrace, the larger the need for a nice parsing
format to facilitate tools in reading the binary buffer.

For example we currently have:

irq_handler_entry:
 print fmt: "irq=%d handler=%s", REC->irq, (char *)((void *)REC + REC->__data_loc
_name)

softirq_entry:
 print fmt: "softirq=%d action=%s", REC->vec, ({ static const struct trace_print_
flags symbols[] = { { HI_SOFTIRQ, "HI" }, { TIMER_SOFTIRQ, "TIMER" }, { NET_TX_S
OFTIRQ, "NET_TX" }, { NET_RX_SOFTIRQ, "NET_RX" }, { BLOCK_SOFTIRQ, "BLOCK" }, {
TASKLET_SOFTIRQ, "TASKLET" }, { SCHED_SOFTIRQ, "SCHED" }, { HRTIMER_SOFTIRQ, "HR
TIMER" }, { RCU_SOFTIRQ, "RCU" }, { -1, ((void *)0) }}; ftrace_print_symbols_seq
(p, REC->vec, symbols); })

kmalloc:
 print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", RE
C->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, (REC->gfp_flags) ? ({
static const struct trace_print_flags flags[] = { {(unsigned long)(((gfp_t)0x10u
) | ((gfp_t)0x40u) | ((gfp_t)0x80u) | ((gfp_t)0x20000u) | ((gfp_t)0x02u) | ((gfp
_t)0x100000u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)(((gfp_t)0x10u) | ((gfp
_t)0x40u) | ((gfp_t)0x80u) | ((gfp_t)0x20000u) | ((gfp_t)0x02u)), "GFP_HIGHUSER"
}, {(unsigned long)(((gfp_t)0x10u) | ((gfp_t)0x40u) | ((gfp_t)0x80u) | ((gfp_t)0
x20000u)), "GFP_USER"}, {(unsigned long)(((gfp_t)0x10u) | ((gfp_t)0x40u) | ((gfp
_t)0x80u) | ((gfp_t)0x80000u)), "GFP_TEMPORARY"}, {(unsigned long)(((gfp_t)0x10u
) | ((gfp_t)0x40u) | ((gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)(((gfp_t)0x
10u) | ((gfp_t)0x40u)), "GFP_NOFS"}, {(unsigned long)(((gfp_t)0x20u)), "GFP_ATOM
IC"}, {(unsigned long)(((gfp_t)0x10u)), "GFP_NOIO"}, {(unsigned long)((gfp_t)0x2
0u), "GFP_HIGH"}, {(unsigned long)((gfp_t)0x10u), "GFP_WAIT"}, {(unsigned long)(
(gfp_t)0x40u), "GFP_IO"}, {(unsigned long)((gfp_t)0x100u), "GFP_COLD"}, {(unsign
ed long)((gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)((gfp_t)0x400u), "GFP_RE
PEAT"}, {(unsigned long)((gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)((gfp_t)
0x1000u), "GFP_NORETRY"}, {(unsigned long)((gfp_t)0x4000u), "GFP_COMP"}, {(unsig
ned long)((gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)((gfp_t)0x10000u), "GFP_
NOMEMALLOC"}, {(unsigned long)((gfp_t)0x20000u), "GFP_HARDWALL"}, {(unsigned lon
g)((gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)((gfp_t)0x80000u), "GFP_RE
CLAIMABLE"}, {(unsigned long)((gfp_t)0x100000u), "GFP_MOVABLE"}, { -1, ((void *)
0) }}; ftrace_print_flags_seq(p, "|", REC->gfp_flags, flags); }) : "GFP_NOWAIT"

The language that is added by this patch is of the following:

 * FMT :=  constant string FMT | COMMAND FMT | empty
 * COMMAND := <TYPE:FIELD> | <mask:FIELD:DELIM:MASKS> | <sym:FIELD:SYMBOLS> |
 *               <if:FIELD:TRUE:FALSE> | <ifmask:FIELD:MASK:TRUE:FALSE>
 * TYPE := int | uint | hex | ptr | string | strarray
 * FIELD := defined by the event structure
 * MASKS := MASK=NAME,MASKS | MASK=NAME
 * MASK := the bit mask to match
 * DELIM := delimiter to separate the fields. None and ':' are both allowed
 * SYMBOLS := SYM=NAME,SYMBOLS | SYM=NAME
 * SYM := the symbol value to test against
 * TRUE := print when field is non zero
 * FALSE := print when field is zero or NULL
 * NAME := the name to write when a match is found
 *
 * A '\<' would print '<'

The above examples would then look like:

irq_handler_entry:
 format: irq=<int:irq> handler=<string:name>

softirq_entry:
 format: softirq=<int:vec> action=<sym:vec:0=HI,1=TIMER,2=NET_TX,3=NET_RX,4=BLOCK,5=TASKLET,6=SCHED,7=HRTIMER,8=RCU

kmalloc:
 format: call_site=<hex:call_site> ptr=<ptr:ptr> bytes_req=<int:bytes_req> bytes_alloc=<int:bytes_alloc> gfp_flags=<mask:gfp_flags:|:0=GFP_NOWAIT,0x1200d2=GFP_HIGHUSER_MOVABLE,0x200d2=GFP_HIGHUSER,0x200d0=GFP_USER,0x800d0=GFP_TEMPORARY,0xd0=GFP_KERNEL,0x50=GFP_NOFS,0x20=GFP_ATOMIC,0x10=GFP_NOIO,0x20=GFP_HIGH,0x10=GFP_WAIT,0x40=GFP_IO,0x100=GFP_COLD,0x200=GFP_NOWARN,0x400=GFP_REPEAT,0x800=GFP_NOFAIL,0x1000=GFP_NORETRY,0x4000=GFP_COMP,0x8000=GFP_ZERO,0x10000=GFP_NOMEMALLOC,0x20000=GFP_HARDWALL,0x40000=GFP_THISNODE,0x80000=GFP_RECLAIMABLE,0x100000=GFP_MOVABLE

The above "mask" command takes '0' as a special mask that should be done only in the beginning. It will write that symbol out when the mask is zero.

Another nice thing about this change set is that it can live together with
the current print format. The old version will show "print fmt:" in
the output file, where as the new version will use "format:" as shown
in the above examples.

Both may be used, but it would be preferable to use the new language.
If the new language is not adequate for a new trace point we can always
add new types. Userspace tools should just ignore types it does not
understand.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/ftrace_event.h     |   12 +
 include/trace/ftrace.h           |   22 +-
 kernel/trace/Makefile            |    1 +
 kernel/trace/trace_events.c      |    1 +
 kernel/trace/trace_read_binary.c |  831 ++++++++++++++++++++++++++++++++++++++
 5 files changed, 865 insertions(+), 2 deletions(-)
 create mode 100644 kernel/trace/trace_read_binary.c

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index c03befb..26fed99 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -120,6 +120,9 @@ struct ftrace_event_call {
 	void			*filter;
 	void			*mod;
 
+	struct list_head	print_info;
+	const char		*print_text;
+
 #ifdef CONFIG_EVENT_PROFILE
 	atomic_t	profile_count;
 	int		(*profile_enable)(struct ftrace_event_call *);
@@ -137,6 +140,15 @@ extern int filter_current_check_discard(struct ftrace_event_call *call,
 					void *rec,
 					struct ring_buffer_event *event);
 
+extern char *ftrace_read_binary(struct trace_seq *p,
+				struct ftrace_event_call *event,
+				struct trace_entry *entry,
+				int entry_size);
+extern int ftrace_initialize_print(struct ftrace_event_call *event,
+				   const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+extern void ftrace_destroy_print(struct ftrace_event_call *event);
+
 extern int trace_define_field(struct ftrace_event_call *call, char *type,
 			      char *name, int offset, int size, int is_signed);
 
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 40ede4d..d250cb9 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -124,6 +124,10 @@
 #undef TP_printk
 #define TP_printk(fmt, args...) fmt "\n", args
 
+#undef TP_FORMAT
+#define TP_FORMAT(fmt, args...) \
+	"%s\n", ftrace_read_binary(p, event_call, entry, iter->ent_size)
+
 #undef __get_dynamic_array
 #define __get_dynamic_array(field)	\
 		((void *)__entry + __entry->__data_loc_##field)
@@ -152,6 +156,7 @@
 enum print_line_t							\
 ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 {									\
+	struct ftrace_event_call *event_call __maybe_unused = &event_##call; \
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##call *field;				\
 	struct trace_entry *entry;					\
@@ -234,7 +239,10 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 #define __entry REC
 
 #undef TP_printk
-#define TP_printk(fmt, args...) "%s, %s\n", #fmt, __stringify(args)
+#define TP_printk(fmt, args...) "print fmt: %s, %s\n", #fmt, __stringify(args)
+
+#undef TP_FORMAT
+#define TP_FORMAT(fmt, args...) "format: " fmt "\n",  ##args
 
 #undef TP_fast_assign
 #define TP_fast_assign(args...) args
@@ -249,7 +257,7 @@ ftrace_format_##call(struct trace_seq *s)				\
 									\
 	tstruct;							\
 									\
-	trace_seq_printf(s, "\nprint fmt: " print);			\
+	trace_seq_printf(s, "\n" print);				\
 									\
 	return ret;							\
 }
@@ -279,6 +287,13 @@ ftrace_format_##call(struct trace_seq *s)				\
 				offsetof(typeof(field), __data_loc_##item),    \
 				 sizeof(field.__data_loc_##item), 0);
 
+#undef TP_printk
+#define TP_printk(fmt, args...)
+
+#undef TP_FORMAT
+#define TP_FORMAT(fmt, args...) \
+	ftrace_initialize_print(event_call, fmt, ##args)
+
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
 
@@ -299,6 +314,8 @@ ftrace_define_fields_##call(void)					\
 									\
 	tstruct;							\
 									\
+	print;								\
+									\
 	return ret;							\
 }
 
@@ -563,6 +580,7 @@ static int ftrace_raw_init_event_##call(void)				\
 	event_##call.id = id;						\
 	INIT_LIST_HEAD(&event_##call.fields);				\
 	init_preds(&event_##call);					\
+	INIT_LIST_HEAD(&event_##call.print_info);			\
 	return 0;							\
 }									\
 									\
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 844164d..9b112e2 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -54,5 +54,6 @@ obj-$(CONFIG_EVENT_TRACING) += trace_export.o
 obj-$(CONFIG_FTRACE_SYSCALLS) += trace_syscalls.o
 obj-$(CONFIG_EVENT_PROFILE) += trace_event_profile.o
 obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
+obj-$(CONFIG_EVENT_TRACING) += trace_read_binary.o
 
 libftrace-y := ftrace.o
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index aa08be6..eb917b8 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1061,6 +1061,7 @@ static void trace_module_remove_events(struct module *mod)
 			list_del(&call->list);
 			trace_destroy_fields(call);
 			destroy_preds(call);
+			ftrace_destroy_print(call);
 		}
 	}
 
diff --git a/kernel/trace/trace_read_binary.c b/kernel/trace/trace_read_binary.c
new file mode 100644
index 0000000..0ed7a1f
--- /dev/null
+++ b/kernel/trace/trace_read_binary.c
@@ -0,0 +1,831 @@
+/*
+ * trace_read_binary.c
+ *
+ * Copyright (C) 2009 Red Hat Inc, Steven Rostedt <srostedt@redhat.com>
+ *
+ */
+
+#include <linux/ftrace_event.h>
+#include <linux/hardirq.h>
+#include <linux/module.h>
+#include <linux/ctype.h>
+
+#include "trace_output.h"
+
+static DEFINE_MUTEX(buffer_lock);
+static struct trace_seq buffer;
+
+/*
+ * Binary string parser. The print format uses a special language to explain
+ * the format to print the entry out. The language is as follows:
+ *
+ * FMT :=  constant string FMT | COMMAND FMT | empty
+ * COMMAND := <TYPE:FIELD> | <mask:FIELD:DELIM:MASKS> | <sym:FIELD:SYMBOLS> |
+ *               <if:FIELD:TRUE:FALSE> | <ifmask:FIELD:MASK:TRUE:FALSE>
+ * TYPE := int | uint | hex | ptr | string | strarray
+ * FIELD := defined by the event structure
+ * MASKS := MASK=NAME,MASKS | MASK=NAME
+ * MASK := the bit mask to match
+ * DELIM := delimiter to separate the fields. None and ':' are both allowed
+ * SYMBOLS := SYM=NAME,SYMBOLS | SYM=NAME
+ * SYM := the symbol value to test against
+ * TRUE := print when field is non zero
+ * FALSE := print when field is zero or NULL
+ * NAME := the name to write when a match is found
+ *
+ * A '<<' would print '<'
+ *
+ * Commands:
+ *  int       : Print the field out as an signed integer. The size of the field
+ *              determines if it is a char, short, long, or long long.
+ *  uint      : Same as int, but for unsigned.
+ *  hex       : Print the field as a hex (ie. 0x4ab)
+ *  ptr       : Print the field as a hex but without the '0x'.
+ *  string    : Used with dynamic sized strings (__string)
+ *  strarray  : Used with static sized arrays (__array ( char , item, len)).
+ *  if        : If the field is non zero, print the TRUE text,
+ *              otherwise print FALSE text.
+ *  ifmask    : If the bit in MASK in the field is set,
+ *              then print the TRUE text, otherwise print FALSE text.
+ *  mask      : Print out the values of a bit mask. Each matching mask will
+ *              print its name. The order does matter. Mask of '0' is special
+ *              for it will print only if the value matches zero. The given
+ *              DELIM will separate the different masks.
+ *  sym       : Print out the name of a matching value. This is similar to
+ *              mask, but only one value may print.
+ */
+
+#define TOK_SIZE 32
+
+enum field_types {
+	FIELD_IS_TEXT,
+	FIELD_IS_INT,
+	FIELD_IS_UINT,
+	FIELD_IS_PTR,
+	FIELD_IS_LT,
+	FIELD_IS_IF,
+	FIELD_IS_IFMASK,
+	FIELD_IS_STRING,
+	FIELD_IS_STRARRAY,
+	FIELD_IS_HEX,
+	FIELD_IS_MASK,
+	FIELD_IS_SYMBOL,
+};
+
+struct sym_mask {
+	struct list_head			list;
+	unsigned long long			val;
+	unsigned short				start;
+	unsigned short				len;
+};
+
+struct print_info {
+	struct list_head				list;
+	enum field_types				type;
+	union {
+		struct {
+			unsigned short			start;
+			unsigned short			len;
+		} text;
+		struct {
+			struct ftrace_event_field	*field;
+		} data;
+		struct {
+			struct ftrace_event_field	*field;
+			unsigned long long		mask;
+			unsigned short			true_text;
+			unsigned short			true_len;
+			unsigned short			false_text;
+			unsigned short			false_len;
+		} cond;
+		struct {
+			struct ftrace_event_field	*field;
+			struct list_head		masks;
+			unsigned short			delim;
+			unsigned short			len;
+		} sym_mask;
+	};
+};
+
+static void free_sym_masks(struct list_head *list)
+{
+	struct sym_mask *sm, *n;
+
+	list_for_each_entry_safe(sm, n, list, list) {
+		list_del(&sm->list);
+		kfree(sm);
+	}
+}
+
+void ftrace_destroy_print(struct ftrace_event_call *event)
+{
+	struct print_info *info, *n;
+
+	if (!event->print_text)
+		return;
+
+	kfree(event->print_text);
+	event->print_text = NULL;
+
+	list_for_each_entry_safe(info, n, &event->print_info, list) {
+		switch (info->type) {
+		case FIELD_IS_SYMBOL:
+		case FIELD_IS_MASK:
+			free_sym_masks(&info->sym_mask.masks);
+			break;
+		default:
+			/* nothing special for the rest */
+			break;
+		}
+		list_del(&info->list);
+		kfree(info);
+	}
+}
+
+static struct print_info *
+alloc_print_info(struct ftrace_event_call *call, enum field_types type)
+{
+	struct print_info *info;
+
+	info = kmalloc(sizeof(*info), GFP_KERNEL);
+	if (WARN_ON(!info))
+		return NULL;
+
+	info->type = type;
+
+	list_add_tail(&info->list, &call->print_info);
+
+	return info;
+}
+
+static int
+add_text(struct ftrace_event_call *call, const char *start, const char *end)
+{
+	struct print_info *info;
+
+	info = alloc_print_info(call, FIELD_IS_TEXT);
+	if (!info)
+		return -ENOMEM;
+
+	info->text.start = start - call->print_text;
+	if (!end)
+		end = call->print_text + strlen(call->print_text);
+	info->text.len = end - start;
+
+	return 0;
+}
+
+static int
+add_less_than(struct ftrace_event_call *call,
+	      const char *start, const char *end)
+{
+	struct print_info *info;
+
+	info = alloc_print_info(call, FIELD_IS_LT);
+	if (!info)
+		return -ENOMEM;
+
+	info->text.start = start - call->print_text;
+	info->text.len = end - start;
+
+	return 0;
+}
+
+static int
+add_data(struct ftrace_event_call *call, enum field_types type,
+	 struct ftrace_event_field *field)
+{
+	struct print_info *info;
+
+	info = alloc_print_info(call, type);
+	if (!info)
+		return -ENOMEM;
+
+	info->data.field = field;
+
+	return 0;
+}
+
+static int
+add_if(struct ftrace_event_call *call, enum field_types type,
+       struct ftrace_event_field *field, unsigned long long mask,
+       const char *fmt, const char *end)
+{
+	struct print_info *info;
+	const char *tok;
+
+	info = alloc_print_info(call, type);
+	if (!info)
+		return -ENOMEM;
+
+	info->cond.field = field;
+	info->cond.mask = mask;
+
+	tok = strchr(fmt, ':');
+	if (WARN(!tok || tok > end, "error in format: %s\n", fmt))
+		return -EINVAL;
+
+	info->cond.true_text = fmt - call->print_text;
+	info->cond.true_len = tok - fmt;
+
+	fmt = tok + 1;
+
+	info->cond.false_text = fmt - call->print_text;
+	info->cond.false_len = end - fmt;
+
+	return 0;
+}
+
+static int add_sym_mask(struct ftrace_event_call *call, struct list_head *list,
+			unsigned long long val,
+			const char *start, const char *end)
+{
+	struct sym_mask *sm;
+
+	sm = kmalloc(sizeof(*sm), GFP_KERNEL);
+	if (WARN_ON(!sm))
+		return -ENOMEM;
+
+	list_add_tail(&sm->list, list);
+	sm->val = val;
+	sm->start = start - call->print_text;
+	sm->len = end - start;
+
+	return 0;
+}
+
+static const char *
+add_mask(struct ftrace_event_call *call, struct ftrace_event_field *field,
+	 const char *delim, unsigned int delim_len,
+	 const char *fmt, const char *end)
+{
+	struct print_info *info;
+	unsigned long long mask;
+	const char *tok;
+	int ret;
+
+	info = alloc_print_info(call, FIELD_IS_MASK);
+	if (!info)
+		return NULL;
+
+	info->sym_mask.field = field;
+
+	INIT_LIST_HEAD(&info->sym_mask.masks);
+	info->sym_mask.len = delim_len;
+	if (delim_len)
+		info->sym_mask.delim = delim - call->print_text;
+
+	do {
+		while (isspace(*fmt))
+			fmt++;
+
+		tok = strchr(fmt, '=');
+		if (WARN(!tok || tok > end, "error in format '%s'\n", fmt))
+			return NULL;
+
+		mask = simple_strtoull(fmt, NULL, 0);
+		fmt = tok + 1;
+
+		tok = strchr(fmt, ',');
+		if (!tok || tok > end)
+			tok = end;
+
+		ret = add_sym_mask(call, &info->sym_mask.masks, mask, fmt, tok);
+		if (ret)
+			return NULL;
+
+		fmt = tok + 1;
+	} while (fmt < end);
+
+	return end;
+}
+
+static const char *
+add_symbol(struct ftrace_event_call *call, struct ftrace_event_field *field,
+	   const char *fmt, const char *end)
+{
+	struct print_info *info;
+	unsigned long long sym;
+	const char *tok;
+	int ret;
+
+	info = alloc_print_info(call, FIELD_IS_SYMBOL);
+	if (!info)
+		return NULL;
+
+	info->sym_mask.field = field;
+
+	INIT_LIST_HEAD(&info->sym_mask.masks);
+
+	do {
+		while (isspace(*fmt))
+			fmt++;
+
+		tok = strchr(fmt, '=');
+		if (WARN(!tok || tok > end, "error in format '%s'\n", fmt))
+			return NULL;
+
+		sym = simple_strtoull(fmt, NULL, 0);
+		fmt = tok + 1;
+
+		tok = strchr(fmt, ',');
+		if (!tok || tok > end)
+			tok = end;
+
+		ret = add_sym_mask(call, &info->sym_mask.masks, sym, fmt, tok);
+		if (ret)
+			return NULL;
+
+		fmt = tok + 1;
+	} while (fmt < end);
+
+	return end;
+}
+
+static struct ftrace_event_field *
+find_field(struct ftrace_event_call *call, const char *name, int len)
+{
+	struct ftrace_event_field *field;
+
+	list_for_each_entry(field, &call->fields, link) {
+		if (!strncmp(field->name, name, len) &&
+		    !field->name[len])
+			return field;
+	}
+
+	return NULL;
+}
+
+static const char *
+handle_field(struct ftrace_event_call *event,
+	     const char *fmt, enum field_types field_type)
+{
+	struct ftrace_event_field *field;
+	const char *end, *tok, *delim;
+	unsigned long long mask;
+	unsigned int delim_len;
+	int ret;
+
+	end = strchr(fmt, '>');
+	if (!end)
+		goto out_err;
+
+	switch (field_type) {
+	case FIELD_IS_INT:
+	case FIELD_IS_UINT:
+	case FIELD_IS_PTR:
+	case FIELD_IS_HEX:
+	case FIELD_IS_STRING:
+	case FIELD_IS_STRARRAY:
+		field = find_field(event, fmt, end - fmt);
+		if (!field)
+			goto out_err;
+
+		ret = add_data(event, field_type, field);
+		if (ret)
+			return NULL;
+		break;
+
+	case FIELD_IS_IF:
+	case FIELD_IS_IFMASK:
+		tok = strchr(fmt, ':');
+		if (!tok || tok > end)
+			goto out_err;
+
+		field = find_field(event, fmt, tok - fmt);
+		if (!field)
+			goto out_err;
+
+		fmt = tok + 1;
+
+		if (field_type == FIELD_IS_IFMASK) {
+			tok = strchr(fmt, ':');
+			if (!tok || tok > end)
+				goto out_err;
+			mask = simple_strtoull(fmt, NULL, 0);
+			fmt = tok + 1;
+		} else
+			mask = 0;
+
+		ret = add_if(event, field_type, field, mask, fmt, end);
+		if (ret)
+			return NULL;
+		break;
+
+	case FIELD_IS_MASK:
+	case FIELD_IS_SYMBOL:
+		tok = strchr(fmt, ':');
+		if (!tok || tok > end)
+			goto out_err;
+
+		field = find_field(event, fmt, tok - fmt);
+		if (!field)
+			goto out_err;
+
+		fmt = tok + 1;
+
+		if (field_type == FIELD_IS_MASK) {
+			tok = strchr(fmt, ':');
+			if (!tok || tok > end)
+				goto out_err;
+
+			delim = fmt;
+			delim_len = tok - fmt;
+
+			/* we allow ':' as a delimiter */
+			if (!delim_len && tok[1] == ':') {
+				tok++;
+				delim_len++;
+			}
+
+			fmt = tok+1;
+
+			end = add_mask(event, field, delim, delim_len,
+				       fmt, end);
+		} else
+			end = add_symbol(event, field, fmt, end);
+
+		if (!end)
+			return NULL;
+		break;
+	default:
+		WARN(1, "unknown field: %s\n", fmt);
+	}
+
+	end++;
+	return end;
+
+ out_err:
+	WARN(1, "error in format field: '%s'\n", fmt);
+	return NULL;
+}
+
+int
+ftrace_initialize_print(struct ftrace_event_call *event, const char *fmt, ...)
+{
+	const char *tok;
+	va_list ap;
+	int ret;
+
+	mutex_lock(&buffer_lock);
+	trace_seq_init(&buffer);
+
+	va_start(ap, fmt);
+	ret = trace_seq_vprintf(&buffer, fmt, ap);
+	va_end(ap);
+	if (!ret)
+		goto err_unlock;
+
+	ret = trace_seq_putc(&buffer, 0);
+	if (!ret)
+		goto err_unlock;
+
+	event->print_text = kstrdup(buffer.buffer, GFP_KERNEL);
+	if (!event->print_text)
+		goto err_unlock;
+
+	mutex_unlock(&buffer_lock);
+
+	fmt = event->print_text;
+
+	do {
+		enum field_types field_type;
+
+		tok = strchr(fmt, '<');
+		if (!tok) {
+			ret = add_text(event, fmt, tok);
+			if (ret)
+				goto err_free;
+			break;
+		}
+		if (*(tok + 1) == '<') {
+			ret = add_less_than(event, fmt, tok);
+			if (ret)
+				goto err_free;
+			fmt = tok + 2;
+			continue;
+		}
+
+		ret = add_text(event, fmt, tok);
+		if (ret)
+			goto err_free;
+
+		fmt = tok + 1;
+
+		tok = strchr(fmt, ':');
+		if (!tok)
+			goto err_format;
+
+		if (strncmp(fmt, "int:", 4) == 0)
+			field_type = FIELD_IS_INT;
+
+		else if (strncmp(fmt, "uint:", 5) == 0)
+			field_type = FIELD_IS_UINT;
+
+		else if (strncmp(fmt, "ptr:", 4) == 0)
+			field_type = FIELD_IS_PTR;
+
+		else if (strncmp(fmt, "string:", 7) == 0)
+			field_type = FIELD_IS_STRING;
+
+		else if (strncmp(fmt, "hex:", 4) == 0)
+			field_type = FIELD_IS_HEX;
+
+		else if (strncmp(fmt, "if:", 3) == 0)
+			field_type = FIELD_IS_IF;
+
+		else if (strncmp(fmt, "ifmask:", 7) == 0)
+			field_type = FIELD_IS_IFMASK;
+
+		else if (strncmp(fmt, "mask:", 5) == 0)
+			field_type = FIELD_IS_MASK;
+
+		else if (strncmp(fmt, "sym:", 4) == 0)
+			field_type = FIELD_IS_SYMBOL;
+
+		else if (strncmp(fmt, "strarray:", 9) == 0)
+			field_type = FIELD_IS_STRARRAY;
+
+		else
+			goto err_format;
+
+		tok++;
+		fmt = handle_field(event, tok, field_type);
+		if (!fmt)
+			goto err_free;
+
+	} while (fmt);
+
+	return 0;
+
+ err_unlock:
+	WARN(1, "Can not allocate event print format data\n");
+	mutex_unlock(&buffer_lock);
+	return -1;
+
+ err_format:
+	WARN(1, "error in format type: '%s'\n", fmt);
+ err_free:
+	ftrace_destroy_print(event);
+	return -1;
+}
+EXPORT_SYMBOL_GPL(ftrace_initialize_print);
+
+
+static void
+trace_read_mask(struct trace_seq *s, unsigned long long val,
+		struct print_info *info, struct ftrace_event_call *event)
+{
+	unsigned long long mask;
+	struct sym_mask *sm;
+	int first = 1;
+
+	list_for_each_entry(sm, &info->sym_mask.masks, list) {
+		mask = sm->val;
+
+		if (first && !mask && !val) {
+			trace_seq_putmem(s, event->print_text + sm->start,
+					 sm->len);
+			return;
+		}
+
+		if (mask && (mask & val) == mask) {
+			if (first)
+				first = 0;
+			else if (info->sym_mask.len)
+				trace_seq_putmem(s, event->print_text +
+						 info->sym_mask.delim,
+						 info->sym_mask.len);
+			val &= ~mask;
+
+			trace_seq_putmem(s, event->print_text + sm->start,
+					 sm->len);
+		}
+	}
+
+	if (val)
+		trace_seq_printf(s, "(%llx)", val);
+
+	return;
+}
+
+static void
+trace_read_symbol(struct trace_seq *s, unsigned long long val,
+		  struct print_info *info, struct ftrace_event_call *event)
+{
+	unsigned long long sym;
+	struct sym_mask *sm;
+	int found = 0;
+
+	list_for_each_entry(sm, &info->sym_mask.masks, list) {
+		sym = sm->val;
+
+		if (sym == val) {
+			found = 1;
+			trace_seq_putmem(s, event->print_text + sm->start,
+					 sm->len);
+			break;
+		}
+	}
+
+	if (!found)
+		trace_seq_printf(s, "(%llx)", val);
+
+}
+
+#define BAD_SIZE	0xdeadbeaf
+
+static unsigned long long
+get_val(void *p, int size, unsigned long long *mask)
+{
+	unsigned long long val;
+
+	switch (size) {
+	case 1:
+		val = *(char *)p;
+		*mask =  0xffULL;
+		break;
+	case 2:
+		val = *(short *)p;
+		*mask =  0xffffULL;
+		break;
+	case 4:
+		val = *(int *)p;
+		*mask =  0xffffffffULL;
+		break;
+	case 8:
+		val = *(long long *)p;
+		*mask = 0;
+		break;
+	default:
+		/* pass back a bad mask on error */
+		*mask = BAD_SIZE;
+		return 0;
+	}
+
+	return val;
+}
+
+/* make sure string pointer has an end */
+static int test_string(const char *str, int size)
+{
+	int i;
+
+	for (i = 0; i < size; i++) {
+		if (!str[i])
+			return 0;
+	}
+
+	return -1;
+}
+
+char *
+ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
+		   struct trace_entry *entry, int entry_size)
+{
+	unsigned long long val, mask;
+	struct print_info *info;
+	char *start = s->buffer + s->len;
+	struct ftrace_event_field *field;
+	void *p;
+	int len;
+
+	if (!event->print_text) {
+		trace_seq_puts(s, "UNDEFINED EVENT\n");
+		return start;
+	}
+
+	list_for_each_entry(info, &event->print_info, list) {
+
+		p = entry;
+
+		switch (info->type) {
+		case FIELD_IS_LT:
+		case FIELD_IS_TEXT:
+			trace_seq_putmem(s, event->print_text +
+					 info->text.start,
+					 info->text.len);
+			if (info->type == FIELD_IS_LT)
+				trace_seq_putc(s, '<');
+			break;
+		case FIELD_IS_INT:
+		case FIELD_IS_UINT:
+		case FIELD_IS_HEX:
+		case FIELD_IS_PTR:
+			field = info->data.field;
+			goto skip_if;
+
+		case FIELD_IS_IF:
+		case FIELD_IS_IFMASK:
+			field = info->cond.field;
+ skip_if:
+			p += field->offset;
+
+			val = get_val(p, field->size, &mask);
+
+			if (mask == BAD_SIZE) {
+				trace_seq_printf(s,
+					"<error: bad field size %d?>\n",
+					field->size);
+				return start;
+			}
+
+			switch (info->type) {
+			case FIELD_IS_IF:
+			case FIELD_IS_IFMASK:
+
+				if (info->type == FIELD_IS_IFMASK)
+					val &= info->cond.mask;
+
+				if (val)
+					trace_seq_putmem(s, event->print_text +
+							 info->cond.true_text,
+							 info->cond.true_len);
+				else
+					trace_seq_putmem(s, event->print_text +
+							 info->cond.false_text,
+							 info->cond.false_len);
+				break;
+
+			case FIELD_IS_INT:
+				trace_seq_printf(s, "%lld", val);
+				break;
+
+			case FIELD_IS_UINT:
+				trace_seq_printf(s, "%llu", val);
+			default:
+				/* hex should only print the size specified */
+				if (mask)
+					val &= mask;
+
+				trace_seq_printf(s, "%llx", val);
+			}
+
+			break;
+
+		case FIELD_IS_STRING:
+			field = info->data.field;
+			p += field->offset;
+			/* indexes are expected to be unsigned short */
+			if (field->size != 2) {
+				trace_seq_printf(s, "BAD FIELD SIZE %d\n",
+						 field->size);
+				return start;
+			}
+			if (*(unsigned short *)p > entry_size) {
+				trace_seq_puts(s, "BAD STRING POINTER\n");
+				return start;
+			}
+			len = entry_size - *(unsigned short *)p;
+			p = (void *)entry + *(unsigned short *)p;
+
+			/* make sure that the string has an end */
+			if (test_string(p, len)) {
+				trace_seq_puts(s, "BAD STRING CONTENT\n");
+				return start;
+			}
+
+			trace_seq_puts(s, p);
+			break;
+
+		case FIELD_IS_STRARRAY:
+			field = info->data.field;
+			p += field->offset;
+			if (test_string(p, field->size)) {
+				trace_seq_puts(s, "BAD STRING CONTENT\n");
+				return start;
+			}
+			trace_seq_puts(s, p);
+			break;
+
+		case FIELD_IS_MASK:
+		case FIELD_IS_SYMBOL:
+			field = info->sym_mask.field;
+			p += field->offset;
+
+			val = get_val(p, field->size, &mask);
+
+			if (mask == BAD_SIZE) {
+				trace_seq_printf(s,
+					 "<error: bad field size %d?>\n",
+					 field->size);
+				return start;
+			}
+
+			val &= mask;
+
+			if (info->type == FIELD_IS_MASK)
+				trace_read_mask(s, val, info, event);
+			else
+				trace_read_symbol(s, val, info, event);
+			break;
+		default:
+			trace_seq_printf(s, "UNKNOWN TYPE %d\n", info->type);
+		}
+	}
+
+	trace_seq_putc(s, 0);
+
+	return start;
+}
+EXPORT_SYMBOL_GPL(ftrace_read_binary);
-- 
1.6.3.1

-- 

[PATCH 03/11] tracing: add nsec2sec print formats

[Steven Rostedt]

[-- Attachment #1: 0003-tracing-add-nsec2sec-print-formats.patch --]
[-- Type: text/plain, Size: 5718 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

This patch adds the tags nsec2sec, nsec2usec and nsec2msec tags that
will do the conversion of a nsec unsigned long long value into a
printf("%lu.%0*lu", precision, nsec) format.

The tags are:

  <nsec2sec:precision:field>
  <nsec2msec:precision:field>
  <nsec2usec:precision:field>

For example, having the field ns that holds an unsigned long long
nanosecond value, we can do:

  <nsec2sec:6:ns>

That will produce something like:

 23.123456  as a value, if ns was 23123456789.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_read_binary.c |   95 +++++++++++++++++++++++++++++++++++++-
 1 files changed, 94 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_read_binary.c b/kernel/trace/trace_read_binary.c
index 0ed7a1f..4ac31f5 100644
--- a/kernel/trace/trace_read_binary.c
+++ b/kernel/trace/trace_read_binary.c
@@ -21,7 +21,9 @@ static struct trace_seq buffer;
  *
  * FMT :=  constant string FMT | COMMAND FMT | empty
  * COMMAND := <TYPE:FIELD> | <mask:FIELD:DELIM:MASKS> | <sym:FIELD:SYMBOLS> |
- *               <if:FIELD:TRUE:FALSE> | <ifmask:FIELD:MASK:TRUE:FALSE>
+ *            <if:FIELD:TRUE:FALSE> | <ifmask:FIELD:MASK:TRUE:FALSE> |
+ *            <nsec2sec:PRECISION:FIELD> | <nsec2usec:PRECISION:FIELD> |
+ *            <nsec2msec:PRECISION:FIELD>
  * TYPE := int | uint | hex | ptr | string | strarray
  * FIELD := defined by the event structure
  * MASKS := MASK=NAME,MASKS | MASK=NAME
@@ -47,6 +49,10 @@ static struct trace_seq buffer;
  *              otherwise print FALSE text.
  *  ifmask    : If the bit in MASK in the field is set,
  *              then print the TRUE text, otherwise print FALSE text.
+ *  nsec2sec  : Convert a nsec field into secs in the format:
+ *              printf("%lu.%0Plu", field), where PRECISION defines what 'P' is.
+ *  nsec2usec : Same as nsec2sec but will convert to usec.
+ *  nsec2usec : Same as nsec2sec but will convert to msec.
  *  mask      : Print out the values of a bit mask. Each matching mask will
  *              print its name. The order does matter. Mask of '0' is special
  *              for it will print only if the value matches zero. The given
@@ -68,6 +74,9 @@ enum field_types {
 	FIELD_IS_STRING,
 	FIELD_IS_STRARRAY,
 	FIELD_IS_HEX,
+	FIELD_IS_NSEC2SEC,
+	FIELD_IS_NSEC2USEC,
+	FIELD_IS_NSEC2MSEC,
 	FIELD_IS_MASK,
 	FIELD_IS_SYMBOL,
 };
@@ -100,6 +109,10 @@ struct print_info {
 		} cond;
 		struct {
 			struct ftrace_event_field	*field;
+			unsigned int			precision;
+		} time;
+		struct {
+			struct ftrace_event_field	*field;
 			struct list_head		masks;
 			unsigned short			delim;
 			unsigned short			len;
@@ -236,6 +249,22 @@ add_if(struct ftrace_event_call *call, enum field_types type,
 	return 0;
 }
 
+static int
+add_time(struct ftrace_event_call *call, enum field_types type,
+	 struct ftrace_event_field *field, unsigned int precision)
+{
+	struct print_info *info;
+
+	info = alloc_print_info(call, type);
+	if (!info)
+		return -ENOMEM;
+
+	info->time.field = field;
+	info->time.precision = precision;
+
+	return 0;
+}
+
 static int add_sym_mask(struct ftrace_event_call *call, struct list_head *list,
 			unsigned long long val,
 			const char *start, const char *end)
@@ -364,6 +393,7 @@ handle_field(struct ftrace_event_call *event,
 	const char *end, *tok, *delim;
 	unsigned long long mask;
 	unsigned int delim_len;
+	unsigned long precision;
 	int ret;
 
 	end = strchr(fmt, '>');
@@ -412,6 +442,26 @@ handle_field(struct ftrace_event_call *event,
 			return NULL;
 		break;
 
+	case FIELD_IS_NSEC2SEC:
+	case FIELD_IS_NSEC2USEC:
+	case FIELD_IS_NSEC2MSEC:
+		tok = strchr(fmt, ':');
+		if (!tok || tok > end)
+			goto out_err;
+
+		precision = simple_strtoul(fmt, NULL, 0);
+
+		fmt = tok + 1;
+
+		field = find_field(event, fmt, end - fmt);
+		if (!field)
+			goto out_err;
+
+		ret = add_time(event, field_type, field, precision);
+		if (ret)
+			return NULL;
+		break;
+
 	case FIELD_IS_MASK:
 	case FIELD_IS_SYMBOL:
 		tok = strchr(fmt, ':');
@@ -537,6 +587,15 @@ ftrace_initialize_print(struct ftrace_event_call *event, const char *fmt, ...)
 		else if (strncmp(fmt, "ifmask:", 7) == 0)
 			field_type = FIELD_IS_IFMASK;
 
+		else if (strncmp(fmt, "nsec2sec:", 9) == 0)
+			field_type = FIELD_IS_NSEC2SEC;
+
+		else if (strncmp(fmt, "nsec2usec:", 10) == 0)
+			field_type = FIELD_IS_NSEC2USEC;
+
+		else if (strncmp(fmt, "nsec2msec:", 10) == 0)
+			field_type = FIELD_IS_NSEC2MSEC;
+
 		else if (strncmp(fmt, "mask:", 5) == 0)
 			field_type = FIELD_IS_MASK;
 
@@ -687,6 +746,7 @@ ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
 	struct print_info *info;
 	char *start = s->buffer + s->len;
 	struct ftrace_event_field *field;
+	unsigned long divisor, rem;
 	void *p;
 	int len;
 
@@ -798,6 +858,39 @@ ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
 			trace_seq_puts(s, p);
 			break;
 
+		case FIELD_IS_NSEC2USEC:
+			divisor = NSEC_PER_USEC;
+			goto do_time;
+		case FIELD_IS_NSEC2MSEC:
+			divisor = NSEC_PER_MSEC;
+			goto do_time;
+		case FIELD_IS_NSEC2SEC:
+			divisor = NSEC_PER_SEC;
+
+ do_time:
+			field = info->time.field;
+
+			p += field->offset;
+
+			val = get_val(p, field->size, &mask);
+
+			if (mask == BAD_SIZE) {
+				trace_seq_printf(s,
+					"<error: bad field size %d?>\n",
+					field->size);
+				return start;
+			}
+
+			rem = do_div(val, divisor);
+			if (info->time.precision)
+				trace_seq_printf(s, "%llu.%0*lu",
+						 val, info->time.precision,
+						 rem);
+			else
+				trace_seq_printf(s, "%llu", val);
+
+			break;
+
 		case FIELD_IS_MASK:
 		case FIELD_IS_SYMBOL:
 			field = info->sym_mask.field;
-- 
1.6.3.1

-- 

[PATCH 04/11] tracing: add major and minor tags for print format

[Steven Rostedt]

[-- Attachment #1: 0004-tracing-add-major-and-minor-tags-for-print-format.patch --]
[-- Type: text/plain, Size: 3139 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Create the tags <major:field> and <minor:field> for trace format prints.

Given a field (should be of type dev_t) these tags will extract the
major or minor number from the field.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_read_binary.c |   28 +++++++++++++++++++++++++++-
 1 files changed, 27 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_read_binary.c b/kernel/trace/trace_read_binary.c
index 4ac31f5..4378350 100644
--- a/kernel/trace/trace_read_binary.c
+++ b/kernel/trace/trace_read_binary.c
@@ -23,7 +23,7 @@ static struct trace_seq buffer;
  * COMMAND := <TYPE:FIELD> | <mask:FIELD:DELIM:MASKS> | <sym:FIELD:SYMBOLS> |
  *            <if:FIELD:TRUE:FALSE> | <ifmask:FIELD:MASK:TRUE:FALSE> |
  *            <nsec2sec:PRECISION:FIELD> | <nsec2usec:PRECISION:FIELD> |
- *            <nsec2msec:PRECISION:FIELD>
+ *            <nsec2msec:PRECISION:FIELD> | <major:FIELD> | <minor:FIELD>
  * TYPE := int | uint | hex | ptr | string | strarray
  * FIELD := defined by the event structure
  * MASKS := MASK=NAME,MASKS | MASK=NAME
@@ -59,6 +59,10 @@ static struct trace_seq buffer;
  *              DELIM will separate the different masks.
  *  sym       : Print out the name of a matching value. This is similar to
  *              mask, but only one value may print.
+ *  major     : Given a 'device number' value, this will convert it to its
+ *              major number.
+ *  minor     : Given a 'device number' value, this will convert it to its
+ *              minor number.
  */
 
 #define TOK_SIZE 32
@@ -74,6 +78,8 @@ enum field_types {
 	FIELD_IS_STRING,
 	FIELD_IS_STRARRAY,
 	FIELD_IS_HEX,
+	FIELD_IS_MINOR,
+	FIELD_IS_MAJOR,
 	FIELD_IS_NSEC2SEC,
 	FIELD_IS_NSEC2USEC,
 	FIELD_IS_NSEC2MSEC,
@@ -405,6 +411,8 @@ handle_field(struct ftrace_event_call *event,
 	case FIELD_IS_UINT:
 	case FIELD_IS_PTR:
 	case FIELD_IS_HEX:
+	case FIELD_IS_MINOR:
+	case FIELD_IS_MAJOR:
 	case FIELD_IS_STRING:
 	case FIELD_IS_STRARRAY:
 		field = find_field(event, fmt, end - fmt);
@@ -605,6 +613,12 @@ ftrace_initialize_print(struct ftrace_event_call *event, const char *fmt, ...)
 		else if (strncmp(fmt, "strarray:", 9) == 0)
 			field_type = FIELD_IS_STRARRAY;
 
+		else if (strncmp(fmt, "major:", 6) == 0)
+			field_type = FIELD_IS_MAJOR;
+
+		else if (strncmp(fmt, "minor:", 6) == 0)
+			field_type = FIELD_IS_MINOR;
+
 		else
 			goto err_format;
 
@@ -772,6 +786,8 @@ ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
 		case FIELD_IS_UINT:
 		case FIELD_IS_HEX:
 		case FIELD_IS_PTR:
+		case FIELD_IS_MAJOR:
+		case FIELD_IS_MINOR:
 			field = info->data.field;
 			goto skip_if;
 
@@ -813,6 +829,16 @@ ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
 
 			case FIELD_IS_UINT:
 				trace_seq_printf(s, "%llu", val);
+				break;
+
+			case FIELD_IS_MAJOR:
+				trace_seq_printf(s, "%u", MAJOR(val));
+				break;
+
+			case FIELD_IS_MINOR:
+				trace_seq_printf(s, "%u", MINOR(val));
+				break;
+
 			default:
 				/* hex should only print the size specified */
 				if (mask)
-- 
1.6.3.1

-- 

[PATCH 05/11] tracing: add func and symfunc to tag format

[Steven Rostedt]

[-- Attachment #1: 0005-tracing-add-func-and-symfunc-to-tag-format.patch --]
[-- Type: text/plain, Size: 4552 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

This adds a way to print out a function name from a pointer the same way
that the Linux printf "%pF" does. Well the symfunc tag does.

If we change kmalloc and kfree formats to:

  TP_FORMAT("call_site=<symfunc:call_site> ptr=<ptr:ptr> bytes_req=<int:bytes_req> "

and

  TP_FORMAT("call_site=<func:call_site> ptr=<ptr:ptr>")

respectively, we would get something like:

   kmalloc: call_site=__alloc_skb+0x70/0x160 ptr=ffff88003d830800 bytes_req=680
   kfree: call_site=skb_release_data ptr=ffff88003d830800

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_output.c      |    2 +-
 kernel/trace/trace_output.h      |    4 ++++
 kernel/trace/trace_read_binary.c |   25 ++++++++++++++++++++++++-
 3 files changed, 29 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 7938f3a..39d5eeb 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -326,7 +326,7 @@ static inline const char *kretprobed(const char *name)
 }
 #endif /* CONFIG_KRETPROBES */
 
-static int
+int
 seq_print_sym_short(struct trace_seq *s, const char *fmt, unsigned long address)
 {
 #ifdef CONFIG_KALLSYMS
diff --git a/kernel/trace/trace_output.h b/kernel/trace/trace_output.h
index d38bec4..412eee8 100644
--- a/kernel/trace/trace_output.h
+++ b/kernel/trace/trace_output.h
@@ -47,5 +47,9 @@ do {							\
 		return TRACE_TYPE_PARTIAL_LINE;		\
 } while (0)
 
+/* until we have a way with sprintf to do this */
+int seq_print_sym_short(struct trace_seq *s, const char *fmt,
+			unsigned long address);
+
 #endif
 
diff --git a/kernel/trace/trace_read_binary.c b/kernel/trace/trace_read_binary.c
index 4378350..bfa8fc3 100644
--- a/kernel/trace/trace_read_binary.c
+++ b/kernel/trace/trace_read_binary.c
@@ -23,7 +23,8 @@ static struct trace_seq buffer;
  * COMMAND := <TYPE:FIELD> | <mask:FIELD:DELIM:MASKS> | <sym:FIELD:SYMBOLS> |
  *            <if:FIELD:TRUE:FALSE> | <ifmask:FIELD:MASK:TRUE:FALSE> |
  *            <nsec2sec:PRECISION:FIELD> | <nsec2usec:PRECISION:FIELD> |
- *            <nsec2msec:PRECISION:FIELD> | <major:FIELD> | <minor:FIELD>
+ *            <nsec2msec:PRECISION:FIELD> | <major:FIELD> | <minor:FIELD> |
+ *            <func:FIELD> | <symfunc:FIELD>
  * TYPE := int | uint | hex | ptr | string | strarray
  * FIELD := defined by the event structure
  * MASKS := MASK=NAME,MASKS | MASK=NAME
@@ -43,6 +44,8 @@ static struct trace_seq buffer;
  *  uint      : Same as int, but for unsigned.
  *  hex       : Print the field as a hex (ie. 0x4ab)
  *  ptr       : Print the field as a hex but without the '0x'.
+ *  symfunc   : Print a ptr like the "%pF" does.
+ *  func      : Like symfunc but without the address.
  *  string    : Used with dynamic sized strings (__string)
  *  strarray  : Used with static sized arrays (__array ( char , item, len)).
  *  if        : If the field is non zero, print the TRUE text,
@@ -80,6 +83,8 @@ enum field_types {
 	FIELD_IS_HEX,
 	FIELD_IS_MINOR,
 	FIELD_IS_MAJOR,
+	FIELD_IS_FUNC,
+	FIELD_IS_SYMFUNC,
 	FIELD_IS_NSEC2SEC,
 	FIELD_IS_NSEC2USEC,
 	FIELD_IS_NSEC2MSEC,
@@ -413,6 +418,8 @@ handle_field(struct ftrace_event_call *event,
 	case FIELD_IS_HEX:
 	case FIELD_IS_MINOR:
 	case FIELD_IS_MAJOR:
+	case FIELD_IS_FUNC:
+	case FIELD_IS_SYMFUNC:
 	case FIELD_IS_STRING:
 	case FIELD_IS_STRARRAY:
 		field = find_field(event, fmt, end - fmt);
@@ -595,6 +602,12 @@ ftrace_initialize_print(struct ftrace_event_call *event, const char *fmt, ...)
 		else if (strncmp(fmt, "ifmask:", 7) == 0)
 			field_type = FIELD_IS_IFMASK;
 
+		else if (strncmp(fmt, "func:", 5) == 0)
+			field_type = FIELD_IS_FUNC;
+
+		else if (strncmp(fmt, "symfunc:", 8) == 0)
+			field_type = FIELD_IS_SYMFUNC;
+
 		else if (strncmp(fmt, "nsec2sec:", 9) == 0)
 			field_type = FIELD_IS_NSEC2SEC;
 
@@ -786,6 +799,8 @@ ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
 		case FIELD_IS_UINT:
 		case FIELD_IS_HEX:
 		case FIELD_IS_PTR:
+		case FIELD_IS_FUNC:
+		case FIELD_IS_SYMFUNC:
 		case FIELD_IS_MAJOR:
 		case FIELD_IS_MINOR:
 			field = info->data.field;
@@ -839,6 +854,14 @@ ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
 				trace_seq_printf(s, "%u", MINOR(val));
 				break;
 
+			case FIELD_IS_SYMFUNC:
+				trace_seq_printf(s, "%pF", (void *)val);
+				break;
+
+			case FIELD_IS_FUNC:
+				seq_print_sym_short(s, "%s", val);
+				break;
+
 			default:
 				/* hex should only print the size specified */
 				if (mask)
-- 
1.6.3.1

-- 

[PATCH 06/11] tracing: update sample code with new tag format

[Steven Rostedt]

[-- Attachment #1: 0006-tracing-update-sample-code-with-new-tag-format.patch --]
[-- Type: text/plain, Size: 4225 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

This patch adds examples of all the new tags in the
samples/trace_events/ example code.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 samples/trace_events/trace-events-sample.c |   21 ++++++++-
 samples/trace_events/trace-events-sample.h |   66 ++++++++++++++++++++++++++++
 2 files changed, 85 insertions(+), 2 deletions(-)

diff --git a/samples/trace_events/trace-events-sample.c b/samples/trace_events/trace-events-sample.c
index aabc4e9..dea8eb3 100644
--- a/samples/trace_events/trace-events-sample.c
+++ b/samples/trace_events/trace-events-sample.c
@@ -10,12 +10,31 @@
 #define CREATE_TRACE_POINTS
 #include "trace-events-sample.h"
 
+static struct task_struct *simple_tsk;
 
 static void simple_thread_func(int cnt)
 {
+	static int mask;
+	static int myif;
+
 	set_current_state(TASK_INTERRUPTIBLE);
 	schedule_timeout(HZ);
 	trace_foo_bar("hello", cnt);
+	trace_format_examples(jiffies,
+			      jiffies * 2,
+			      "a string here",
+			      &simple_tsk,
+			      mask, mask, simple_thread_func,
+			      myif, myif, cpu_clock(raw_smp_processor_id()),
+			      123456);
+	if (!myif)
+		myif = 3;
+
+	if (!mask)
+		mask = 5;
+
+	mask <<= mask;
+	myif <<= myif;
 }
 
 static int simple_thread(void *arg)
@@ -28,8 +47,6 @@ static int simple_thread(void *arg)
 	return 0;
 }
 
-static struct task_struct *simple_tsk;
-
 static int __init trace_event_init(void)
 {
 	simple_tsk = kthread_run(simple_thread, NULL, "event-sample");
diff --git a/samples/trace_events/trace-events-sample.h b/samples/trace_events/trace-events-sample.h
index 128a897..08b4768 100644
--- a/samples/trace_events/trace-events-sample.h
+++ b/samples/trace_events/trace-events-sample.h
@@ -65,6 +65,11 @@
  * Note, that for both the assign and the printk, __entry is the handler
  * to the data structure in the ring buffer, and is defined by the
  * TP_STRUCT__entry.
+ *
+ * Note it is better to now use the tag format. Examples are in the event
+ * below, and the explanation of the tag format language is in:
+ *
+ *  kernel/trace/trace_read_binary.h
  */
 TRACE_EVENT(foo_bar,
 
@@ -84,6 +89,67 @@ TRACE_EVENT(foo_bar,
 
 	TP_printk("foo %s %d", __entry->foo, __entry->bar)
 );
+
+/*
+ * These are a few examples of the tag format to do the output.
+ */
+TRACE_EVENT(format_examples,
+
+	TP_PROTO(int myint, long mylong, char *mystr, void *myptr,
+		 unsigned long mask, unsigned sym, void *func,
+		 int myif, int myifmask, unsigned long long nsec,
+		 int dev),
+
+	TP_ARGS(myint, mylong, mystr, myptr, mask, sym, func,
+		myif, myifmask, nsec, dev),
+
+	TP_STRUCT__entry(
+		__field(	int,		myint		)
+		__field(	long,		mylong		)
+		__string(str, mystr)
+		__array(	char,		str_arr,	20	)
+		__field(	void *,		func		)
+		__field(	int,		myif		)
+		__field(	unsigned long,	mask		)
+		__field(	unsigned long,	sym		)
+		__field(	int,		myifmask	)
+		__field(	int,		dev		)
+		__field(	unsigned long long, nsec	)
+	),
+
+	TP_fast_assign(
+		__entry->myint = myint;
+		__entry->mylong = mylong;
+		__assign_str(str, mystr);
+		strncpy(__entry->str_arr, mystr, 19);
+		__entry->str_arr[19] = 0;
+		__entry->mask	= mask;
+		__entry->sym	= sym;
+		__entry->func	= func;
+		__entry->myif	= myif;
+		__entry->myifmask = myifmask;
+		__entry->dev	= dev;
+		__entry->nsec	= nsec;
+	),
+
+	TP_FORMAT("to see a normal int <int:myint> \n"
+		  "or perhaps make it unsigned <uint:myint>\n"
+		  "no difference for the size <int:mylong>\n"
+		  "lets make it into a hex <hex:myint>\n"
+		  "dynamic strings are simple <string:str>\n"
+		  "and so are static ones <strarray:str_arr>\n"
+		  "see a func and offset <symfunc:func>\n"
+		  "or just the func name <func:func>\n"
+		  "should we print <if:myif:this:that>\n"
+		  "or base it on a bit mask <ifmask:myif:0xc:foo:bar>\n"
+		  "we want to see that device <major:dev>,<minor:dev>\n"
+		  "we can see masks <mask:mask:,:0=nothing,0xa=a,1=one,2=two>\n"
+		  "or values of symbols <sym:sym:1=this,2=that,3=nevermind>\n"
+		  "and know what time it is in seconds <nsec2sec:6:nsec> \n"
+		  "millisecs <nsec2msec:6:nsec>\n"
+		  "or microsecs <nsec2usec:3:nsec>")
+);
+
 #endif
 
 /***** NOTICE! The #if protection ends here. *****/
-- 
1.6.3.1

-- 

[PATCH 07/11] tracing/events: modify irq print to new format

[Steven Rostedt]

[-- Attachment #1: 0007-tracing-events-modify-irq-print-to-new-format.patch --]
[-- Type: text/plain, Size: 2526 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Use new format for better parsing of irq events.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/irq.h |   40 +++++++++++++++++++++-------------------
 1 files changed, 21 insertions(+), 19 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index b0c7ede..4294a6d 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -7,18 +7,19 @@
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM irq
 
-#define softirq_name(sirq) { sirq##_SOFTIRQ, #sirq }
-#define show_softirq_name(val)			\
-	__print_symbolic(val,			\
-			 softirq_name(HI),	\
-			 softirq_name(TIMER),	\
-			 softirq_name(NET_TX),	\
-			 softirq_name(NET_RX),	\
-			 softirq_name(BLOCK),	\
-			 softirq_name(TASKLET),	\
-			 softirq_name(SCHED),	\
-			 softirq_name(HRTIMER),	\
-			 softirq_name(RCU))
+#define softirq_name(sirq) sirq##_SOFTIRQ, #sirq
+#define show_softirq_name_format(val)					\
+	"%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s"
+#define show_softirq_name_args()					\
+		softirq_name(HI),					\
+		softirq_name(TIMER),					\
+		softirq_name(NET_TX),					\
+		softirq_name(NET_RX),					\
+		softirq_name(BLOCK),					\
+		softirq_name(TASKLET),					\
+		softirq_name(SCHED),					\
+		softirq_name(HRTIMER),					\
+		softirq_name(RCU)
 
 /**
  * irq_handler_entry - called immediately before the irq action handler
@@ -47,7 +48,7 @@ TRACE_EVENT(irq_handler_entry,
 		__assign_str(name, action->name);
 	),
 
-	TP_printk("irq=%d handler=%s", __entry->irq, __get_str(name))
+	TP_FORMAT("irq=<int:irq> handler=<string:name>")
 );
 
 /**
@@ -77,8 +78,7 @@ TRACE_EVENT(irq_handler_exit,
 		__entry->ret	= ret;
 	),
 
-	TP_printk("irq=%d return=%s",
-		  __entry->irq, __entry->ret ? "handled" : "unhandled")
+	TP_FORMAT("irq=<int:irq> return=<if:ret:handled:unhandled>")
 );
 
 /**
@@ -106,8 +106,9 @@ TRACE_EVENT(softirq_entry,
 		__entry->vec = (int)(h - vec);
 	),
 
-	TP_printk("softirq=%d action=%s", __entry->vec,
-		  show_softirq_name(__entry->vec))
+	TP_FORMAT("softirq=<int:vec> action=<sym:vec:"
+		  show_softirq_name_format() ">",
+		  show_softirq_name_args())
 );
 
 /**
@@ -135,8 +136,9 @@ TRACE_EVENT(softirq_exit,
 		__entry->vec = (int)(h - vec);
 	),
 
-	TP_printk("softirq=%d action=%s", __entry->vec,
-		  show_softirq_name(__entry->vec))
+	TP_FORMAT("softirq=<int:vec> action=<sym:vec:"
+		  show_softirq_name_format() ">",
+		  show_softirq_name_args())
 );
 
 #endif /*  _TRACE_IRQ_H */
-- 
1.6.3.1

-- 

[PATCH 08/11] tracing/events: modify sched print to new format

[Steven Rostedt]

[-- Attachment #1: 0008-tracing-events-modify-sched-print-to-new-format.patch --]
[-- Type: text/plain, Size: 4012 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Use new format for better parsing of sched events.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/sched.h |   49 ++++++++++++++---------------------------
 1 files changed, 17 insertions(+), 32 deletions(-)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index 24ab5bc..beb1584 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -26,7 +26,7 @@ TRACE_EVENT(sched_kthread_stop,
 		__entry->pid	= t->pid;
 	),
 
-	TP_printk("task %s:%d", __entry->comm, __entry->pid)
+	TP_FORMAT("task <strarray:comm>:<int:pid>")
 );
 
 /*
@@ -46,7 +46,7 @@ TRACE_EVENT(sched_kthread_stop_ret,
 		__entry->ret	= ret;
 	),
 
-	TP_printk("ret %d", __entry->ret)
+	TP_FORMAT("ret <int:ret>")
 );
 
 /*
@@ -73,8 +73,7 @@ TRACE_EVENT(sched_wait_task,
 		__entry->prio	= p->prio;
 	),
 
-	TP_printk("task %s:%d [%d]",
-		  __entry->comm, __entry->pid, __entry->prio)
+	TP_FORMAT("task <strarray:comm>:<int:pid> [<int:prio>]")
 );
 
 /*
@@ -103,9 +102,7 @@ TRACE_EVENT(sched_wakeup,
 		__entry->success	= success;
 	),
 
-	TP_printk("task %s:%d [%d] success=%d",
-		  __entry->comm, __entry->pid, __entry->prio,
-		  __entry->success)
+	TP_FORMAT("task <strarray:comm>:<int:pid> [<int:prio>] success=<int:success>")
 );
 
 /*
@@ -134,9 +131,7 @@ TRACE_EVENT(sched_wakeup_new,
 		__entry->success	= success;
 	),
 
-	TP_printk("task %s:%d [%d] success=%d",
-		  __entry->comm, __entry->pid, __entry->prio,
-		  __entry->success)
+	TP_FORMAT("task <strarray:comm>:<int:pid> [<int:prio>] success=<int:success>")
 );
 
 /*
@@ -172,14 +167,10 @@ TRACE_EVENT(sched_switch,
 		__entry->next_prio	= next->prio;
 	),
 
-	TP_printk("task %s:%d [%d] (%s) ==> %s:%d [%d]",
-		__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
-		__entry->prev_state ?
-		  __print_flags(__entry->prev_state, "|",
-				{ 1, "S"} , { 2, "D" }, { 4, "T" }, { 8, "t" },
-				{ 16, "Z" }, { 32, "X" }, { 64, "x" },
-				{ 128, "W" }) : "R",
-		__entry->next_comm, __entry->next_pid, __entry->next_prio)
+	TP_FORMAT("task <strarray:prev_comm>:<int:prev_pid> [<int:prev_prio>] "
+		  "(<mask:prev_state:|:0=R,1=S,2=D,4=T,8=t,16=Z,32=X,64=x,128=W>)"
+		  " ==> "
+		  "task <strarray:next_comm>:<int:next_pid> [<int:next_prio>]")
 );
 
 /*
@@ -207,9 +198,8 @@ TRACE_EVENT(sched_migrate_task,
 		__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)
+	TP_FORMAT("task <strarray:comm>:<int:pid> [<int:prio>] "
+		  "from: <int:orig_cpu>  to: <int:dest_cpu>")
 );
 
 /*
@@ -233,8 +223,7 @@ TRACE_EVENT(sched_process_free,
 		__entry->prio		= p->prio;
 	),
 
-	TP_printk("task %s:%d [%d]",
-		  __entry->comm, __entry->pid, __entry->prio)
+	TP_FORMAT("task <strarray:comm>:<int:pid> [<int:prio>]")
 );
 
 /*
@@ -258,8 +247,7 @@ TRACE_EVENT(sched_process_exit,
 		__entry->prio		= p->prio;
 	),
 
-	TP_printk("task %s:%d [%d]",
-		  __entry->comm, __entry->pid, __entry->prio)
+	TP_FORMAT("task <strarray:comm>:<int:pid> [<int:prio>]")
 );
 
 /*
@@ -283,8 +271,7 @@ TRACE_EVENT(sched_process_wait,
 		__entry->prio		= current->prio;
 	),
 
-	TP_printk("task %s:%d [%d]",
-		  __entry->comm, __entry->pid, __entry->prio)
+	TP_FORMAT("task <strarray:comm>:<int:pid> [<int:prio>]")
 );
 
 /*
@@ -310,9 +297,8 @@ TRACE_EVENT(sched_process_fork,
 		__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)
+	TP_FORMAT("parent <strarray:parent_comm>:<int:parent_pid>"
+		  "  child <strarray:child_comm>:<int:child_pid>")
 );
 
 /*
@@ -336,8 +322,7 @@ TRACE_EVENT(sched_signal_send,
 		__entry->sig	= sig;
 	),
 
-	TP_printk("sig: %d  task %s:%d",
-		  __entry->sig, __entry->comm, __entry->pid)
+	TP_FORMAT("sig: <int:sig>  task <strarray:comm>:<int:pid>")
 );
 
 #endif /* _TRACE_SCHED_H */
-- 
1.6.3.1

-- 

[PATCH 09/11] tracing/events: modify kmem print to new format

[Steven Rostedt]

[-- Attachment #1: 0009-tracing-events-modify-kmem-print-to-new-format.patch --]
[-- Type: text/plain, Size: 5968 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Use new format for better parsing of kmem events.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/kmem.h |  100 ++++++++++++++++++++-----------------------
 1 files changed, 46 insertions(+), 54 deletions(-)

diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
index 9baba50..32c93da 100644
--- a/include/trace/events/kmem.h
+++ b/include/trace/events/kmem.h
@@ -17,32 +17,36 @@
  *
  * Thus most bits set go first.
  */
-#define show_gfp_flags(flags)						\
-	(flags) ? __print_flags(flags, "|",				\
-	{(unsigned long)GFP_HIGHUSER_MOVABLE,	"GFP_HIGHUSER_MOVABLE"}, \
-	{(unsigned long)GFP_HIGHUSER,		"GFP_HIGHUSER"},	\
-	{(unsigned long)GFP_USER,		"GFP_USER"},		\
-	{(unsigned long)GFP_TEMPORARY,		"GFP_TEMPORARY"},	\
-	{(unsigned long)GFP_KERNEL,		"GFP_KERNEL"},		\
-	{(unsigned long)GFP_NOFS,		"GFP_NOFS"},		\
-	{(unsigned long)GFP_ATOMIC,		"GFP_ATOMIC"},		\
-	{(unsigned long)GFP_NOIO,		"GFP_NOIO"},		\
-	{(unsigned long)__GFP_HIGH,		"GFP_HIGH"},		\
-	{(unsigned long)__GFP_WAIT,		"GFP_WAIT"},		\
-	{(unsigned long)__GFP_IO,		"GFP_IO"},		\
-	{(unsigned long)__GFP_COLD,		"GFP_COLD"},		\
-	{(unsigned long)__GFP_NOWARN,		"GFP_NOWARN"},		\
-	{(unsigned long)__GFP_REPEAT,		"GFP_REPEAT"},		\
-	{(unsigned long)__GFP_NOFAIL,		"GFP_NOFAIL"},		\
-	{(unsigned long)__GFP_NORETRY,		"GFP_NORETRY"},		\
-	{(unsigned long)__GFP_COMP,		"GFP_COMP"},		\
-	{(unsigned long)__GFP_ZERO,		"GFP_ZERO"},		\
-	{(unsigned long)__GFP_NOMEMALLOC,	"GFP_NOMEMALLOC"},	\
-	{(unsigned long)__GFP_HARDWALL,		"GFP_HARDWALL"},	\
-	{(unsigned long)__GFP_THISNODE,		"GFP_THISNODE"},	\
-	{(unsigned long)__GFP_RECLAIMABLE,	"GFP_RECLAIMABLE"},	\
-	{(unsigned long)__GFP_MOVABLE,		"GFP_MOVABLE"}		\
-	) : "GFP_NOWAIT"
+#define show_gfp_flags_format()						\
+	"0=GFP_NOWAIT,"							\
+	"0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s," \
+	"0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s," \
+	"0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s,0x%lx=%s," \
+	"0x%lx=%s,0x%lx=%s"
+#define show_gfp_flags_args()						\
+	(unsigned long)GFP_HIGHUSER_MOVABLE,	"GFP_HIGHUSER_MOVABLE", \
+	(unsigned long)GFP_HIGHUSER,		"GFP_HIGHUSER",		\
+	(unsigned long)GFP_USER,		"GFP_USER",		\
+	(unsigned long)GFP_TEMPORARY,		"GFP_TEMPORARY",	\
+	(unsigned long)GFP_KERNEL,		"GFP_KERNEL",		\
+	(unsigned long)GFP_NOFS,		"GFP_NOFS",		\
+	(unsigned long)GFP_ATOMIC,		"GFP_ATOMIC",		\
+	(unsigned long)GFP_NOIO,		"GFP_NOIO",		\
+	(unsigned long)__GFP_HIGH,		"GFP_HIGH",		\
+	(unsigned long)__GFP_WAIT,		"GFP_WAIT",		\
+	(unsigned long)__GFP_IO,		"GFP_IO",		\
+	(unsigned long)__GFP_COLD,		"GFP_COLD",		\
+	(unsigned long)__GFP_NOWARN,		"GFP_NOWARN",		\
+	(unsigned long)__GFP_REPEAT,		"GFP_REPEAT",		\
+	(unsigned long)__GFP_NOFAIL,		"GFP_NOFAIL",		\
+	(unsigned long)__GFP_NORETRY,		"GFP_NORETRY",		\
+	(unsigned long)__GFP_COMP,		"GFP_COMP",		\
+	(unsigned long)__GFP_ZERO,		"GFP_ZERO",		\
+	(unsigned long)__GFP_NOMEMALLOC,	"GFP_NOMEMALLOC",	\
+	(unsigned long)__GFP_HARDWALL,		"GFP_HARDWALL",		\
+	(unsigned long)__GFP_THISNODE,		"GFP_THISNODE",		\
+	(unsigned long)__GFP_RECLAIMABLE,	"GFP_RECLAIMABLE",	\
+	(unsigned long)__GFP_MOVABLE,		"GFP_MOVABLE"
 
 TRACE_EVENT(kmalloc,
 
@@ -70,12 +74,9 @@ TRACE_EVENT(kmalloc,
 		__entry->gfp_flags	= gfp_flags;
 	),
 
-	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
-		__entry->call_site,
-		__entry->ptr,
-		__entry->bytes_req,
-		__entry->bytes_alloc,
-		show_gfp_flags(__entry->gfp_flags))
+	TP_FORMAT("call_site=<hex:call_site> ptr=<ptr:ptr> bytes_req=<int:bytes_req> "
+		  "bytes_alloc=<int:bytes_alloc> gfp_flags=<mask:gfp_flags:|:"
+		  show_gfp_flags_format() ">", show_gfp_flags_args())
 );
 
 TRACE_EVENT(kmem_cache_alloc,
@@ -104,12 +105,9 @@ TRACE_EVENT(kmem_cache_alloc,
 		__entry->gfp_flags	= gfp_flags;
 	),
 
-	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
-		__entry->call_site,
-		__entry->ptr,
-		__entry->bytes_req,
-		__entry->bytes_alloc,
-		show_gfp_flags(__entry->gfp_flags))
+	TP_FORMAT("call_site=<hex:call_site> ptr=<ptr:ptr> bytes_req=<int:bytes_req> "
+		  "bytes_alloc=<int:bytes_alloc> gfp_flags=<mask:gfp_flags:|:"
+		  show_gfp_flags_format() ">", show_gfp_flags_args())
 );
 
 TRACE_EVENT(kmalloc_node,
@@ -141,13 +139,10 @@ TRACE_EVENT(kmalloc_node,
 		__entry->node		= node;
 	),
 
-	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s node=%d",
-		__entry->call_site,
-		__entry->ptr,
-		__entry->bytes_req,
-		__entry->bytes_alloc,
-		show_gfp_flags(__entry->gfp_flags),
-		__entry->node)
+	TP_FORMAT("call_site=<hex:call_site> ptr=<ptr:ptr> bytes_req=<int:bytes_req> "
+		  "bytes_alloc=<int:bytes_alloc> gfp_flags=<mask:gfp_flags:|:"
+		  show_gfp_flags_format() "> node=<int:node>",
+		  show_gfp_flags_args())
 );
 
 TRACE_EVENT(kmem_cache_alloc_node,
@@ -179,13 +174,10 @@ TRACE_EVENT(kmem_cache_alloc_node,
 		__entry->node		= node;
 	),
 
-	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s node=%d",
-		__entry->call_site,
-		__entry->ptr,
-		__entry->bytes_req,
-		__entry->bytes_alloc,
-		show_gfp_flags(__entry->gfp_flags),
-		__entry->node)
+	TP_FORMAT("call_site=<hex:call_site> ptr=<ptr:ptr> bytes_req=<int:bytes_req> "
+		  "bytes_alloc=<int:bytes_alloc> gfp_flags=<mask:gfp_flags:|:"
+		  show_gfp_flags_format() "> node=<int:node>",
+		  show_gfp_flags_args())
 );
 
 TRACE_EVENT(kfree,
@@ -204,7 +196,7 @@ TRACE_EVENT(kfree,
 		__entry->ptr		= ptr;
 	),
 
-	TP_printk("call_site=%lx ptr=%p", __entry->call_site, __entry->ptr)
+	TP_FORMAT("call_site=<hex:call_site> ptr=<ptr:ptr>")
 );
 
 TRACE_EVENT(kmem_cache_free,
@@ -223,7 +215,7 @@ TRACE_EVENT(kmem_cache_free,
 		__entry->ptr		= ptr;
 	),
 
-	TP_printk("call_site=%lx ptr=%p", __entry->call_site, __entry->ptr)
+	TP_FORMAT("call_site=<hex:call_site> ptr=<ptr:ptr>")
 );
 #endif /* _TRACE_KMEM_H */
 
-- 
1.6.3.1

-- 

[PATCH 10/11] tracing/events: modify lockdep print to new format

[Steven Rostedt]

[-- Attachment #1: 0010-tracing-events-modify-lockdep-print-to-new-format.patch --]
[-- Type: text/plain, Size: 2065 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Use new format for better parsing of lockdep events.

The current conversion of the nsec value in the lockstat lock event
is performed in the fast path. Now that there is a tag to do the conversion
we can move this into the slow path and increase performance while tracing.

[ Impact: increase performance in lockstat tracing ]

Cc: Peter Zijlstra <peterz@infradead.org>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/lockdep.h |   18 +++++++-----------
 1 files changed, 7 insertions(+), 11 deletions(-)

diff --git a/include/trace/events/lockdep.h b/include/trace/events/lockdep.h
index 0e956c9..4251f17 100644
--- a/include/trace/events/lockdep.h
+++ b/include/trace/events/lockdep.h
@@ -27,9 +27,8 @@ TRACE_EVENT(lock_acquire,
 		__assign_str(name, lock->name);
 	),
 
-	TP_printk("%s%s%s", (__entry->flags & 1) ? "try " : "",
-		  (__entry->flags & 2) ? "read " : "",
-		  __get_str(name))
+	TP_FORMAT("<ifmask:flags:1:try :><ifmask:flags:2:read :>"
+		  "<string:name>")
 );
 
 TRACE_EVENT(lock_release,
@@ -46,7 +45,7 @@ TRACE_EVENT(lock_release,
 		__assign_str(name, lock->name);
 	),
 
-	TP_printk("%s", __get_str(name))
+	TP_FORMAT("<string:name>")
 );
 
 #ifdef CONFIG_LOCK_STAT
@@ -65,7 +64,7 @@ TRACE_EVENT(lock_contended,
 		__assign_str(name, lock->name);
 	),
 
-	TP_printk("%s", __get_str(name))
+	TP_FORMAT("<string:name>")
 );
 
 TRACE_EVENT(lock_acquired,
@@ -75,16 +74,13 @@ TRACE_EVENT(lock_acquired,
 
 	TP_STRUCT__entry(
 		__string(name, lock->name)
-		__field(unsigned long, wait_usec)
-		__field(unsigned long, wait_nsec_rem)
+		__field(long long, wait_nsec)
 	),
 	TP_fast_assign(
 		__assign_str(name, lock->name);
-		__entry->wait_nsec_rem = do_div(waittime, NSEC_PER_USEC);
-		__entry->wait_usec = (unsigned long) waittime;
+		__entry->wait_nsec = waittime;
 	),
-	TP_printk("%s (%lu.%03lu us)", __get_str(name), __entry->wait_usec,
-				       __entry->wait_nsec_rem)
+	TP_FORMAT("<string:name> (<nsec2usec:3:wait_nsec> us)")
 );
 
 #endif
-- 
1.6.3.1

-- 

[PATCH 11/11] tracing: convert the block trace points to use the new tag format

[Steven Rostedt]

[-- Attachment #1: 0011-tracing-convert-the-block-trace-points-to-use-the-ne.patch --]
[-- Type: text/plain, Size: 7872 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Convert the block trace points to use the new tag format for easier parsing
by userspace tools.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/block.h |  101 ++++++++++++++----------------------------
 1 files changed, 34 insertions(+), 67 deletions(-)

diff --git a/include/trace/events/block.h b/include/trace/events/block.h
index 53effd4..f12cee3 100644
--- a/include/trace/events/block.h
+++ b/include/trace/events/block.h
@@ -34,11 +34,8 @@ TRACE_EVENT(block_rq_abort,
 		blk_dump_cmd(__get_str(cmd), rq);
 	),
 
-	TP_printk("%d,%d %s (%s) %llu + %u [%d]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev),
-		  __entry->rwbs, __get_str(cmd),
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->errors)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> (<string:cmd>) "
+		  "<uint:sector> + <uint:nr_sector> [<int:errors>]")
 );
 
 TRACE_EVENT(block_rq_insert,
@@ -69,11 +66,9 @@ TRACE_EVENT(block_rq_insert,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %u (%s) %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev),
-		  __entry->rwbs, __entry->bytes, __get_str(cmd),
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> <uint:bytes>"
+		  " (<string:cmd>) <uint:sector> + <uint:nr_sector>"
+		  " [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_rq_issue,
@@ -104,11 +99,9 @@ TRACE_EVENT(block_rq_issue,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %u (%s) %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev),
-		  __entry->rwbs, __entry->bytes, __get_str(cmd),
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> <uint:bytes>"
+		  " (<string:cmd>) <uint:sector> + <uint:nr_sector>"
+		  " [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_rq_requeue,
@@ -137,11 +130,8 @@ TRACE_EVENT(block_rq_requeue,
 		blk_dump_cmd(__get_str(cmd), rq);
 	),
 
-	TP_printk("%d,%d %s (%s) %llu + %u [%d]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev),
-		  __entry->rwbs, __get_str(cmd),
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->errors)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> (<string:cmd>)"
+		  " <uint:sector> + <uint:nr_sector> [<int:errors>]")
 );
 
 TRACE_EVENT(block_rq_complete,
@@ -170,11 +160,8 @@ TRACE_EVENT(block_rq_complete,
 		blk_dump_cmd(__get_str(cmd), rq);
 	),
 
-	TP_printk("%d,%d %s (%s) %llu + %u [%d]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev),
-		  __entry->rwbs, __get_str(cmd),
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->errors)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> (<string:cmd>) "
+		  "<uint:sector> + <uint:nr_sector> [<int:errors>]")
 );
 TRACE_EVENT(block_bio_bounce,
 
@@ -198,10 +185,8 @@ TRACE_EVENT(block_bio_bounce,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> "
+		  "<uint:sector> + <uint:nr_sector> [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_bio_complete,
@@ -225,10 +210,8 @@ TRACE_EVENT(block_bio_complete,
 		blk_fill_rwbs(__entry->rwbs, bio->bi_rw, bio->bi_size);
 	),
 
-	TP_printk("%d,%d %s %llu + %u [%d]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->error)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> <uint:sector>"
+		  " + <uint:nr_sector> [<int:error>]")
 );
 
 TRACE_EVENT(block_bio_backmerge,
@@ -253,10 +236,8 @@ TRACE_EVENT(block_bio_backmerge,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> "
+		  "<uint:sector> + <uint:nr_sector> [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_bio_frontmerge,
@@ -281,10 +262,8 @@ TRACE_EVENT(block_bio_frontmerge,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> "
+		  "<uint:sector> + <uint:nr_sector> [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_bio_queue,
@@ -309,10 +288,8 @@ TRACE_EVENT(block_bio_queue,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> "
+		  "<uint:sector> + <uint:nr_sector> [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_getrq,
@@ -338,10 +315,8 @@ TRACE_EVENT(block_getrq,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
         ),
 
-	TP_printk("%d,%d %s %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> "
+		  "<uint:sector> + <uint:nr_sector> [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_sleeprq,
@@ -367,10 +342,8 @@ TRACE_EVENT(block_sleeprq,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %llu + %u [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector, __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> "
+		  "<uint:sector> + <uint:nr_sector> [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_plug,
@@ -387,7 +360,7 @@ TRACE_EVENT(block_plug,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("[%s]", __entry->comm)
+	TP_FORMAT("[<strarray:comm>]")
 );
 
 TRACE_EVENT(block_unplug_timer,
@@ -406,7 +379,7 @@ TRACE_EVENT(block_unplug_timer,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("[%s] %d", __entry->comm, __entry->nr_rq)
+	TP_FORMAT("[<strarray:comm>] <int:nr_rq>")
 );
 
 TRACE_EVENT(block_unplug_io,
@@ -425,7 +398,7 @@ TRACE_EVENT(block_unplug_io,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("[%s] %d", __entry->comm, __entry->nr_rq)
+	TP_FORMAT("[<strarray:comm>] <int:nr_rq>")
 );
 
 TRACE_EVENT(block_split,
@@ -451,11 +424,8 @@ TRACE_EVENT(block_split,
 		memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
 	),
 
-	TP_printk("%d,%d %s %llu / %llu [%s]",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  (unsigned long long)__entry->new_sector,
-		  __entry->comm)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> <uint:sector> / "
+		  "<uint:new_sector> [<strarray:comm>]")
 );
 
 TRACE_EVENT(block_remap,
@@ -483,12 +453,9 @@ TRACE_EVENT(block_remap,
 		blk_fill_rwbs(__entry->rwbs, bio->bi_rw, bio->bi_size);
 	),
 
-	TP_printk("%d,%d %s %llu + %u <- (%d,%d) %llu",
-		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->rwbs,
-		  (unsigned long long)__entry->sector,
-		  __entry->nr_sector,
-		  MAJOR(__entry->old_dev), MINOR(__entry->old_dev),
-		  (unsigned long long)__entry->old_sector)
+	TP_FORMAT("<major:dev>,<minor:dev> <strarray:rwbs> <uint:sector> + "
+		  "<uint:nr_sector> <<- (<major:old_dev>,<minor:old_dev>) "
+		  "<uint:old_sector>")
 );
 
 #endif /* _TRACE_BLOCK_H */
-- 
1.6.3.1

--