[RFC PATCH 0/5] simplify the print fmt in the event format files

[RFC PATCH 0/5] simplify the print fmt in the event format files

[Steven Rostedt]

This is a request for comments on the new print format style to show
in the format file.

As more and more users of ftrace are retrieving their data through
the binary interface, it has become more important to be able to
parse the format of these binary records.

Since the output may also be used in dumps of the kernel, it is still
important that ftrace has a way within the kernel to display the
data records in a human readable format.

The current method is with TP_printk, in the TRACE_EVENT. This acts
just like a printk and lets the developer print out their format
anyway they would like to. But the problem with this is that the
readers of the binary data would either have to have a C parser to understand
the output, or would have to have a custom made parser to match the
contents, and hope that the contents would not change.

This patch series creates a new marco called TP_FORMAT that can be
used in place of the TP_printk inside the TRACE_EVENT macro.

This format has the current following language:

 * FMT :=  constant string FMT | COMMAND FMT | empty
 * COMMAND := <TYPE:FIELD> | <mask:FIELD:DELIM:MASKS> | <sym:FIELD:SYMBOLS> |
 *               <if:FIELD:TRUE:FALSE>
 * TYPE := int | 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 '<'

We can extend this langange when we need to. A user app could just
ignore a type it does not understand.

This is an RFC patch set. I basically just got it working but it lacks
some clean ups on errors. And I need to investigate the use of the
fields structures to make sure they are adquately protected. It uses
the fields that are pased by the filter code.

This makes the output of the format much cleaner.

We go from this:

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

to this:

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

and this:

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

To this:

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

And finally this:

print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->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)0x20000u)), "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)0x10u) | ((gfp_t)0x40u)), "GFP_NOFS"}, {(unsigned long)(((gfp_t)0x20u)), "GFP_ATOMIC"}, {(unsigned long)(((gfp_t)0x10u)), "GFP_NOIO"}, {(unsigned long)((gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)((gfp_t)0x10u), "GFP_WAIT"}, {(unsigned long)((gfp_t)0x40u), "GFP_IO"}, {(unsigned long)((gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)((gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)((gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned long)((gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)((gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)((gfp_t)0x4000u), "GFP_COMP"}, {(unsigned long)((gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)((gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)((gfp_t)0x20000u), "GFP_HARDWALL"}, {(unsigned long)((gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)((gfp_t)0x80000u), "GFP_RECLAIMABLE"}, {(unsigned long)((gfp_t)0x100000u), "GFP_MOVABLE"}, { -1, ((void *)0) }}; ftrace_print_flags_seq(p, "|", REC->gfp_flags, flags); }) : "GFP_NOWAIT"

to this:

 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

Note that the old format has "print fmt" where as the new has just "format", 
this will allow for userspace apps to differentiate between the two.

 The following patches are in:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git

    branch: tip/tracing/event-print-format


Steven Rostedt (5):
      tracing: add trace_seq_vprint interface
      tracing/events: nicer print format for parsing
      tracing/events: modify irq print to new format
      tracing/events: modify sched print to new format
      tracing/events: modify kmem print to new format

----
 include/linux/ftrace_event.h     |   10 +
 include/linux/trace_seq.h        |    2 +
 include/trace/events/irq.h       |   35 +-
 include/trace/events/kmem.h      |   97 +++---
 include/trace/events/sched.h     |   49 +--
 include/trace/ftrace.h           |   22 ++-
 kernel/trace/Makefile            |    1 +
 kernel/trace/trace_output.c      |   32 ++
 kernel/trace/trace_read_binary.c |  674 ++++++++++++++++++++++++++++++++++++++
 9 files changed, 815 insertions(+), 107 deletions(-)
-- 

[RFC PATCH 1/5] tracing: add trace_seq_vprint interface

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-add-trace_seq_vprint-interface.patch --]
[-- Type: text/plain, Size: 2270 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

The code to update the print formats for events requires a vprintf
format in the trace_seq. This patch adds that interface.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/trace_seq.h   |    2 ++
 kernel/trace/trace_output.c |   32 ++++++++++++++++++++++++++++++++
 2 files changed, 34 insertions(+), 0 deletions(-)

diff --git a/include/linux/trace_seq.h b/include/linux/trace_seq.h
index ba9627f..c68bccb 100644
--- a/include/linux/trace_seq.h
+++ b/include/linux/trace_seq.h
@@ -27,6 +27,8 @@ trace_seq_init(struct trace_seq *s)
 #ifdef CONFIG_TRACING
 extern int trace_seq_printf(struct trace_seq *s, const char *fmt, ...)
 	__attribute__ ((format (printf, 2, 3)));
+extern int trace_seq_vprintf(struct trace_seq *s, const char *fmt, va_list args)
+	__attribute__ ((format (printf, 2, 0)));
 extern int
 trace_seq_bprintf(struct trace_seq *s, const char *fmt, const u32 *binary);
 extern void trace_print_seq(struct seq_file *m, struct trace_seq *s);
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 425725c..c05aff4 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -100,6 +100,38 @@ trace_seq_printf(struct trace_seq *s, const char *fmt, ...)
 }
 EXPORT_SYMBOL_GPL(trace_seq_printf);
 
+/**
+ * trace_seq_vprintf - sequence printing of trace information
+ * @s: trace sequence descriptor
+ * @fmt: printf format string
+ *
+ * The tracer may use either sequence operations or its own
+ * copy to user routines. To simplify formating of a trace
+ * trace_seq_printf is used to store strings into a special
+ * buffer (@s). Then the output may be either used by
+ * the sequencer or pulled into another buffer.
+ */
+int
+trace_seq_vprintf(struct trace_seq *s, const char *fmt, va_list args)
+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (!len)
+		return 0;
+
+	ret = vsnprintf(s->buffer + s->len, len, fmt, args);
+
+	/* If we can't write it all, don't bother writing anything */
+	if (ret >= len)
+		return 0;
+
+	s->len += ret;
+
+	return len;
+}
+EXPORT_SYMBOL_GPL(trace_seq_vprintf);
+
 int trace_seq_bprintf(struct trace_seq *s, const char *fmt, const u32 *binary)
 {
 	int len = (PAGE_SIZE - 1) - s->len;
-- 
1.6.3.1

-- 

[RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-events-nicer-print-format-for-parsing.patch --]
[-- Type: text/plain, Size: 23176 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>
 * TYPE := int | 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     |   10 +
 include/trace/ftrace.h           |   22 ++-
 kernel/trace/Makefile            |    1 +
 kernel/trace/trace_read_binary.c |  674 ++++++++++++++++++++++++++++++++++++++
 4 files changed, 705 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 5c093ff..f1b59d3 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -119,6 +119,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 *);
@@ -136,6 +139,13 @@ 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);
+extern int ftrace_initialize_print(struct ftrace_event_call *event,
+				   const char *fmt, ...)
+	__attribute__ ((format (printf, 2, 3)));
+
 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..e3370c5 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)
+
 #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 06b8585..7c2ff68 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -51,5 +51,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_read_binary.c b/kernel/trace/trace_read_binary.c
new file mode 100644
index 0000000..100d5c0
--- /dev/null
+++ b/kernel/trace/trace_read_binary.c
@@ -0,0 +1,674 @@
+/*
+ * 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.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>
+ * TYPE := int | 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 '<'
+ */
+
+#define TOK_SIZE 32
+
+enum field_types {
+	FIELD_IS_TEXT,
+	FIELD_IS_INT,
+	FIELD_IS_PTR,
+	FIELD_IS_LT,
+	FIELD_IS_IF,
+	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 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 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 (!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, struct ftrace_event_field *field,
+       const char *fmt, const char *end)
+{
+	struct print_info *info;
+	const char *tok;
+
+	info = alloc_print_info(call, FIELD_IS_IF);
+	if (!info)
+		return -ENOMEM;
+
+	info->cond.field = field;
+
+	tok = strchr(fmt, ':');
+	if (!tok || tok > end)
+		return -1;
+
+	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 (!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;
+
+	info = alloc_print_info(call, FIELD_IS_MASK);
+	if (!info)
+		return end;
+
+	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 (!tok || tok > end)
+			goto out_err;
+
+		mask = simple_strtoull(fmt, NULL, 0);
+		fmt = tok + 1;
+
+		tok = strchr(fmt, ',');
+		if (!tok || tok > end)
+			tok = end;
+
+		add_sym_mask(call, &info->sym_mask.masks, mask, fmt, tok);
+
+		fmt = tok + 1;
+	} while (fmt < end);
+
+	return end;
+ out_err:
+	WARN_ON(1);
+	printk("error in format '%s'\n", fmt);
+	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;
+
+	info = alloc_print_info(call, FIELD_IS_SYMBOL);
+	if (!info)
+		return end;
+
+	info->sym_mask.field = field;
+
+	INIT_LIST_HEAD(&info->sym_mask.masks);
+
+	do {
+		while (isspace(*fmt))
+			fmt++;
+
+		tok = strchr(fmt, '=');
+		if (!tok || tok > end)
+			goto out_err;
+
+		sym = simple_strtoull(fmt, NULL, 0);
+		fmt = tok + 1;
+
+		tok = strchr(fmt, ',');
+		if (!tok || tok > end)
+			tok = end;
+
+		add_sym_mask(call, &info->sym_mask.masks, sym, fmt, tok);
+
+		fmt = tok + 1;
+	} while (fmt < end);
+
+	return end;
+ out_err:
+	WARN_ON(1);
+	printk("error in format '%s'\n", fmt);
+	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))
+			return field;
+	}
+
+	return NULL;
+}
+
+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 int delim_len;
+
+	end = strchr(fmt, '>');
+	if (!end)
+		goto out_err;
+
+	switch (field_type) {
+	case FIELD_IS_INT:
+	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;
+
+		add_data(event, field_type, field);
+		break;
+
+	case FIELD_IS_IF:
+		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;
+
+		add_if(event, field, fmt, end);
+		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);
+
+		break;
+	default:
+		WARN_ON(1);
+		printk("unknown field\n");
+	}
+
+	end++;
+	return end;
+
+ out_err:
+	WARN_ON(1);
+	printk("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) {
+			add_text(event, fmt, tok);
+			break;
+		}
+		if (*(tok - 1) == '\\') {
+			add_less_than(event, fmt, tok);
+			fmt = tok + 1;
+			continue;
+		}
+
+		add_text(event, fmt, tok);
+
+		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, "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, "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);
+
+	} while (fmt);
+
+	return 0;
+
+ err_unlock:
+	WARN_ON(1);
+	printk("Can not allocate event print format data\n");
+	mutex_unlock(&buffer_lock);
+	return -1;
+
+ err_format:
+	WARN_ON(1);
+	printk("error in format type: '%s'\n", fmt);
+	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);
+
+}
+
+char *
+ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
+		   struct trace_entry *entry)
+{
+	unsigned long long val, mask;
+	struct print_info *info;
+	char *start = s->buffer + s->len;
+	struct ftrace_event_field *field;
+	void *p;
+
+	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_HEX:
+		case FIELD_IS_PTR:
+			field = info->data.field;
+			goto skip_if;
+
+		case FIELD_IS_IF:
+			field = info->cond.field;
+ skip_if:
+			p += field->offset;
+
+			switch (field->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:
+				trace_seq_printf(s, "<error: bad field size %d?>\n",
+						 field->size);
+				return start;
+			}
+
+			if (info->type == FIELD_IS_IF) {
+				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);
+			} else if (info->type == FIELD_IS_INT)
+				trace_seq_printf(s, "%lld", val);
+			else {
+				/* hex should only print the size specified */
+				if (mask)
+					val &= mask;
+
+				trace_seq_printf(s, "%llx", val);
+			}
+
+			break;
+
+		case FIELD_IS_STRING:
+			p += info->data.field->offset;
+			/* indexes are expected to be unsigned short */
+			WARN_ON(info->data.field->size != 2);
+			p = (void *)entry + *(unsigned short *)p;
+			trace_seq_puts(s, p);
+			break;
+
+		case FIELD_IS_STRARRAY:
+			p += info->data.field->offset;
+			trace_seq_puts(s, p);
+			break;
+
+		case FIELD_IS_MASK:
+		case FIELD_IS_SYMBOL:
+
+			p += info->sym_mask.field->offset;
+
+			switch (info->sym_mask.field->size) {
+			case 1:
+				val = *(unsigned char *)p;
+				break;
+			case 2:
+				val = *(unsigned short *)p;
+				break;
+			case 4:
+				val = *(unsigned int *)p;
+				break;
+			case 8:
+				val = *(unsigned long long*)p;
+				break;
+
+			default:
+				trace_seq_printf(s, "<error: bad field size %d?>\n",
+						 info->sym_mask.field->size);
+				return start;
+			}
+
+			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

-- 

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Frederic Weisbecker]

On Mon, Jun 08, 2009 at 09:45:36PM -0400, Steven Rostedt wrote:
> 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"



I agree with the fact that it must be simplified.



 
> 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>
>  * TYPE := int | 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 '<'


But I wonder if the above new language is not breaking the charm
of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).

Everyone knows the printk formats. And I guess this new thing is easy and
quick to learn. But because it's a new unknown language, the TRACE_EVENT
will become less readable, less reachable for newcomers in TRACE_EVENT.

I don't know...

Frederic.

 
> 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     |   10 +
>  include/trace/ftrace.h           |   22 ++-
>  kernel/trace/Makefile            |    1 +
>  kernel/trace/trace_read_binary.c |  674 ++++++++++++++++++++++++++++++++++++++
>  4 files changed, 705 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 5c093ff..f1b59d3 100644
> --- a/include/linux/ftrace_event.h
> +++ b/include/linux/ftrace_event.h
> @@ -119,6 +119,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 *);
> @@ -136,6 +139,13 @@ 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);
> +extern int ftrace_initialize_print(struct ftrace_event_call *event,
> +				   const char *fmt, ...)
> +	__attribute__ ((format (printf, 2, 3)));
> +
>  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..e3370c5 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)
> +
>  #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 06b8585..7c2ff68 100644
> --- a/kernel/trace/Makefile
> +++ b/kernel/trace/Makefile
> @@ -51,5 +51,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_read_binary.c b/kernel/trace/trace_read_binary.c
> new file mode 100644
> index 0000000..100d5c0
> --- /dev/null
> +++ b/kernel/trace/trace_read_binary.c
> @@ -0,0 +1,674 @@
> +/*
> + * 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.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>
> + * TYPE := int | 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 '<'
> + */
> +
> +#define TOK_SIZE 32
> +
> +enum field_types {
> +	FIELD_IS_TEXT,
> +	FIELD_IS_INT,
> +	FIELD_IS_PTR,
> +	FIELD_IS_LT,
> +	FIELD_IS_IF,
> +	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 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 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 (!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, struct ftrace_event_field *field,
> +       const char *fmt, const char *end)
> +{
> +	struct print_info *info;
> +	const char *tok;
> +
> +	info = alloc_print_info(call, FIELD_IS_IF);
> +	if (!info)
> +		return -ENOMEM;
> +
> +	info->cond.field = field;
> +
> +	tok = strchr(fmt, ':');
> +	if (!tok || tok > end)
> +		return -1;
> +
> +	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 (!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;
> +
> +	info = alloc_print_info(call, FIELD_IS_MASK);
> +	if (!info)
> +		return end;
> +
> +	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 (!tok || tok > end)
> +			goto out_err;
> +
> +		mask = simple_strtoull(fmt, NULL, 0);
> +		fmt = tok + 1;
> +
> +		tok = strchr(fmt, ',');
> +		if (!tok || tok > end)
> +			tok = end;
> +
> +		add_sym_mask(call, &info->sym_mask.masks, mask, fmt, tok);
> +
> +		fmt = tok + 1;
> +	} while (fmt < end);
> +
> +	return end;
> + out_err:
> +	WARN_ON(1);
> +	printk("error in format '%s'\n", fmt);
> +	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;
> +
> +	info = alloc_print_info(call, FIELD_IS_SYMBOL);
> +	if (!info)
> +		return end;
> +
> +	info->sym_mask.field = field;
> +
> +	INIT_LIST_HEAD(&info->sym_mask.masks);
> +
> +	do {
> +		while (isspace(*fmt))
> +			fmt++;
> +
> +		tok = strchr(fmt, '=');
> +		if (!tok || tok > end)
> +			goto out_err;
> +
> +		sym = simple_strtoull(fmt, NULL, 0);
> +		fmt = tok + 1;
> +
> +		tok = strchr(fmt, ',');
> +		if (!tok || tok > end)
> +			tok = end;
> +
> +		add_sym_mask(call, &info->sym_mask.masks, sym, fmt, tok);
> +
> +		fmt = tok + 1;
> +	} while (fmt < end);
> +
> +	return end;
> + out_err:
> +	WARN_ON(1);
> +	printk("error in format '%s'\n", fmt);
> +	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))
> +			return field;
> +	}
> +
> +	return NULL;
> +}
> +
> +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 int delim_len;
> +
> +	end = strchr(fmt, '>');
> +	if (!end)
> +		goto out_err;
> +
> +	switch (field_type) {
> +	case FIELD_IS_INT:
> +	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;
> +
> +		add_data(event, field_type, field);
> +		break;
> +
> +	case FIELD_IS_IF:
> +		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;
> +
> +		add_if(event, field, fmt, end);
> +		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);
> +
> +		break;
> +	default:
> +		WARN_ON(1);
> +		printk("unknown field\n");
> +	}
> +
> +	end++;
> +	return end;
> +
> + out_err:
> +	WARN_ON(1);
> +	printk("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) {
> +			add_text(event, fmt, tok);
> +			break;
> +		}
> +		if (*(tok - 1) == '\\') {
> +			add_less_than(event, fmt, tok);
> +			fmt = tok + 1;
> +			continue;
> +		}
> +
> +		add_text(event, fmt, tok);
> +
> +		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, "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, "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);
> +
> +	} while (fmt);
> +
> +	return 0;
> +
> + err_unlock:
> +	WARN_ON(1);
> +	printk("Can not allocate event print format data\n");
> +	mutex_unlock(&buffer_lock);
> +	return -1;
> +
> + err_format:
> +	WARN_ON(1);
> +	printk("error in format type: '%s'\n", fmt);
> +	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);
> +
> +}
> +
> +char *
> +ftrace_read_binary(struct trace_seq *s, struct ftrace_event_call *event,
> +		   struct trace_entry *entry)
> +{
> +	unsigned long long val, mask;
> +	struct print_info *info;
> +	char *start = s->buffer + s->len;
> +	struct ftrace_event_field *field;
> +	void *p;
> +
> +	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_HEX:
> +		case FIELD_IS_PTR:
> +			field = info->data.field;
> +			goto skip_if;
> +
> +		case FIELD_IS_IF:
> +			field = info->cond.field;
> + skip_if:
> +			p += field->offset;
> +
> +			switch (field->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:
> +				trace_seq_printf(s, "<error: bad field size %d?>\n",
> +						 field->size);
> +				return start;
> +			}
> +
> +			if (info->type == FIELD_IS_IF) {
> +				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);
> +			} else if (info->type == FIELD_IS_INT)
> +				trace_seq_printf(s, "%lld", val);
> +			else {
> +				/* hex should only print the size specified */
> +				if (mask)
> +					val &= mask;
> +
> +				trace_seq_printf(s, "%llx", val);
> +			}
> +
> +			break;
> +
> +		case FIELD_IS_STRING:
> +			p += info->data.field->offset;
> +			/* indexes are expected to be unsigned short */
> +			WARN_ON(info->data.field->size != 2);
> +			p = (void *)entry + *(unsigned short *)p;
> +			trace_seq_puts(s, p);
> +			break;
> +
> +		case FIELD_IS_STRARRAY:
> +			p += info->data.field->offset;
> +			trace_seq_puts(s, p);
> +			break;
> +
> +		case FIELD_IS_MASK:
> +		case FIELD_IS_SYMBOL:
> +
> +			p += info->sym_mask.field->offset;
> +
> +			switch (info->sym_mask.field->size) {
> +			case 1:
> +				val = *(unsigned char *)p;
> +				break;
> +			case 2:
> +				val = *(unsigned short *)p;
> +				break;
> +			case 4:
> +				val = *(unsigned int *)p;
> +				break;
> +			case 8:
> +				val = *(unsigned long long*)p;
> +				break;
> +
> +			default:
> +				trace_seq_printf(s, "<error: bad field size %d?>\n",
> +						 info->sym_mask.field->size);
> +				return start;
> +			}
> +
> +			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
> 
> -- 

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Steven Rostedt]

On Tue, 9 Jun 2009, Frederic Weisbecker wrote:
> 
>  
> > 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>
> >  * TYPE := int | 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 '<'
> 
> 
> But I wonder if the above new language is not breaking the charm
> of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
> 
> Everyone knows the printk formats. And I guess this new thing is easy and
> quick to learn. But because it's a new unknown language, the TRACE_EVENT
> will become less readable, less reachable for newcomers in TRACE_EVENT.

I tried to avoid this too, but when I started writing a tool in C that 
would parse the format file, I found that the printf was horrible.

Note, I will still keep the TP_printk() macro, that will not change. The 
new macro is TP_FORMAT() that preforms the tags. Thus, if you really want 
it to print out, you can use TP_printk, but the user space tools that read 
the binary will not know how to read it unless the printk is simple.

I really want to keep this language simple. If anyone has any better 
ideas, I'm all for it.

I barfed when I saw this in irq_handler_entry:

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

That we probably can get to show something like:

  print fmt: "irq=%d handler=%s", REC->irq, __get_string(REC->name)

I plan on also adding some type tags. Perhaps adding a GFP that would do 
the flags for kmem, and have a way to export the values in another file.

But for now, I would like to add the tags "major" and "minor" that would 
get the major and minor from a device:

  <major:dev>  <minor:dev>

And also one that can handle time:

  <nsec2usec:nsec> that would convert a ns time to the "%lu.%03lu" format, 
or even a <nsec2sec:n:nsec> that would convert to "%lu.%0" n "lu" format.

Again, anyone have any better ideas?

-- Steve

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:

> Again, anyone have any better ideas?
> 
> -- Steve
> 

Hi Steven,

sorry I don't have much time to look into this. My ph.d. thesis is due
for july 5th..

I just wanted to let you now that I wrote a very simple XML parser in
the early days of LTTng. I dumped it in favor of the trace_mark() format
strings, but it really gave much more flexibility to describe events,
including nested structures, unions... etc.

It's written in C with almost no external dependency. The goal was to
make it so it could be acceptable in the kernel tree. I think you might
want to have a quick look at it. It generated the probe callbacks which
were, at the time, inlines. Since then I realised that inlining the
tracer code in the kernel call site pollutes the i-cache, so it's not
the way I would deal with code generation today, but those are minor
details.

It would need a cleanup. I did not write the original version of this
code, but rather kicked it until it worked as I wanted it. It worked
with the old LTTng versions:

http://www.lttng.org/files/packages/genevent-0.35.tar.gz

The package contains sample XML files.

Good luck,

Mathieu


-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Lai Jiangshan]

Steven Rostedt wrote:
> On Tue, 9 Jun 2009, Frederic Weisbecker wrote:
>>  
>>> 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>
>>>  * TYPE := int | 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 '<'
>>
>> But I wonder if the above new language is not breaking the charm
>> of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
>>
>> Everyone knows the printk formats. And I guess this new thing is easy and
>> quick to learn. But because it's a new unknown language, the TRACE_EVENT
>> will become less readable, less reachable for newcomers in TRACE_EVENT.
> 
> I tried to avoid this too, but when I started writing a tool in C that 
> would parse the format file, I found that the printf was horrible.
> 
> Note, I will still keep the TP_printk() macro, that will not change. The 
> new macro is TP_FORMAT() that preforms the tags. Thus, if you really want 
> it to print out, you can use TP_printk, but the user space tools that read 
> the binary will not know how to read it unless the printk is simple.
> 
> I really want to keep this language simple. If anyone has any better 
> ideas, I'm all for it.
> 
> I barfed when I saw this in irq_handler_entry:
> 
>   print fmt: "irq=%d handler=%s", REC->irq, (char *)((void *)REC + REC->__data_loc_name)
> 

I barfed too when I saw this. Introducing a new format is
very meaningful. And this print format looks well.
Good Work!

I'm trying to write user-space tools. Could you tell me your tools'
developing status? And the aim of these tools? Will it be public?

I'm wandering whether I should stop this trying.

Lai.

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Steven Rostedt]

On Wed, 10 Jun 2009, Lai Jiangshan wrote:
> 
> I'm trying to write user-space tools. Could you tell me your tools'
> developing status? And the aim of these tools? Will it be public?

I'm toying with a command line parser, and something to hook with Ingo's 
perf.

> 
> I'm wandering whether I should stop this trying.

Well, more ideas the better, anything that is done can probably be used 
;-)

-- Steve

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Christoph Hellwig]

On Tue, Jun 09, 2009 at 03:45:36PM -0400, Steven Rostedt wrote:
> Note, I will still keep the TP_printk() macro, that will not change. The 
> new macro is TP_FORMAT() that preforms the tags. Thus, if you really want 
> it to print out, you can use TP_printk, but the user space tools that read 
> the binary will not know how to read it unless the printk is simple.

Keeping the two in parallel for more than a short migration period
will be a nightmare.  We should have one way to express all our tracers,
and not keep on adding special cases that userland has to deal with.

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Christoph Hellwig]

On Tue, Jun 09, 2009 at 09:22:01PM +0200, Frederic Weisbecker wrote:
> But I wonder if the above new language is not breaking the charm
> of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
> 
> Everyone knows the printk formats. And I guess this new thing is easy and
> quick to learn. But because it's a new unknown language, the TRACE_EVENT
> will become less readable, less reachable for newcomers in TRACE_EVENT.

I must also say I don't particularly like it.  printk is nice and easy
an everybody knows it, but it's not quite flexible enough as we might
have to do all kinds of conversions on the reader side.  What might be
a better idea is to just have C function pointer for output conversions
that could be put into the a file in debugfs and used by the binary
trace buffer reader.  Or maybe not as we would pull in too many
depenencies.

I think we should go with the printk solution for 2.6.31 and use the
full development cycle for 2.6.32 to come up with something better.

As soon as a couple of large subsystems use the even tracer we also
have a broader base examples to see how new syntax works on them.

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Ingo Molnar]

* Christoph Hellwig <hch@infradead.org> wrote:

> On Tue, Jun 09, 2009 at 09:22:01PM +0200, Frederic Weisbecker wrote:
> > But I wonder if the above new language is not breaking the charm
> > of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
> > 
> > Everyone knows the printk formats. And I guess this new thing is 
> > easy and quick to learn. But because it's a new unknown 
> > language, the TRACE_EVENT will become less readable, less 
> > reachable for newcomers in TRACE_EVENT.
> 
> I must also say I don't particularly like it.  printk is nice and 
> easy an everybody knows it, but it's not quite flexible enough as 
> we might have to do all kinds of conversions on the reader side.  
> What might be a better idea is to just have C function pointer for 
> output conversions that could be put into the a file in debugfs 
> and used by the binary trace buffer reader.  Or maybe not as we 
> would pull in too many depenencies.

Another bigger problem with the new tag format, beyond introducing 
an arbitrary descriptor language (which is easy to mess up) is the 
loss of type checking.

With the tags the field printouts can go stray easily - while with 
TP_printk() we had printf type checking. (which, as imperfect as it 
may be to specify a format, does create a real connection between 
the record and the output format specification.)

> I think we should go with the printk solution for 2.6.31 and use 
> the full development cycle for 2.6.32 to come up with something 
> better.
>
> As soon as a couple of large subsystems use the even tracer we 
> also have a broader base examples to see how new syntax works on 
> them.

I think much of the tooling problem could be solved with a little 
trick: the format string can be injected into an artificial .c file 
(runtime), and the tool could compile that .c file (in user-space) 
and get access to the result.

For example, one of the more complex block tracepoints, 
/debug/tracing/events/block/block_bio_backmerge:

print fmt: "%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 
20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, 
(unsigned long long)REC->sector, REC->nr_sector, REC->comm

when pasted verbatim into the stub below, produces:

   0,6 a 7 + 8 [abc]

Note that i pasted the format string into the code below unchanged, 
and i used the format descriptor to create the record type. (this 
too is easy to automate).

If this is generated into the following function:

 format_block_bio_backmerge(struct record *rec);

and a small dynamic library is built out of it, tooling can use 
dlopen() to load those format printing stubs.

It's all pretty straightforward and can be used for arbitrarily 
complex formats.

And i kind of like the whole notion on a design level as weell: the 
kernel exporting C source code for tools :-)

	Ingo

------------------>

struct record {
	unsigned short common_type;
	unsigned char common_flags;
	unsigned char common_preempt;
	int common_pid;
	int common_tgid;
	int dev;
	unsigned long long sector;
	unsigned int nr_sector;
	char rwbs[6];
	char comm[16];
} this_record = { 1, 2, 3, 4, 5, 6, 7, 8, { 'a', }, "abc" };

void main(void)
{
	struct record *REC = &this_record;

	printf("%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, (unsigned long long)REC->sector, REC->nr_sector, REC->comm);
}

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Frédéric Weisbecker]

2009/6/10 Ingo Molnar <mingo@elte.hu>:
>
> * Christoph Hellwig <hch@infradead.org> wrote:
>
>> On Tue, Jun 09, 2009 at 09:22:01PM +0200, Frederic Weisbecker wrote:
>> > But I wonder if the above new language is not breaking the charm
>> > of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
>> >
>> > Everyone knows the printk formats. And I guess this new thing is
>> > easy and quick to learn. But because it's a new unknown
>> > language, the TRACE_EVENT will become less readable, less
>> > reachable for newcomers in TRACE_EVENT.
>>
>> I must also say I don't particularly like it.  printk is nice and
>> easy an everybody knows it, but it's not quite flexible enough as
>> we might have to do all kinds of conversions on the reader side.
>> What might be a better idea is to just have C function pointer for
>> output conversions that could be put into the a file in debugfs
>> and used by the binary trace buffer reader.  Or maybe not as we
>> would pull in too many depenencies.
>
> Another bigger problem with the new tag format, beyond introducing
> an arbitrary descriptor language (which is easy to mess up) is the
> loss of type checking.
>
> With the tags the field printouts can go stray easily - while with
> TP_printk() we had printf type checking. (which, as imperfect as it
> may be to specify a format, does create a real connection between
> the record and the output format specification.)
>
>> I think we should go with the printk solution for 2.6.31 and use
>> the full development cycle for 2.6.32 to come up with something
>> better.
>>
>> As soon as a couple of large subsystems use the even tracer we
>> also have a broader base examples to see how new syntax works on
>> them.
>
> I think much of the tooling problem could be solved with a little
> trick: the format string can be injected into an artificial .c file
> (runtime), and the tool could compile that .c file (in user-space)
> and get access to the result.
>
> For example, one of the more complex block tracepoints,
> /debug/tracing/events/block/block_bio_backmerge:
>
> print fmt: "%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >>
> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs,
> (unsigned long long)REC->sector, REC->nr_sector, REC->comm
>
> when pasted verbatim into the stub below, produces:
>
>   0,6 a 7 + 8 [abc]
>
> Note that i pasted the format string into the code below unchanged,
> and i used the format descriptor to create the record type. (this
> too is easy to automate).
>
> If this is generated into the following function:
>
>  format_block_bio_backmerge(struct record *rec);
>
> and a small dynamic library is built out of it, tooling can use
> dlopen() to load those format printing stubs.
>
> It's all pretty straightforward and can be used for arbitrarily
> complex formats.



Hmm



> And i kind of like the whole notion on a design level as weell: the
> kernel exporting C source code for tools :-)
>
>        Ingo
>
> ------------------>
>
> struct record {
>        unsigned short common_type;
>        unsigned char common_flags;
>        unsigned char common_preempt;
>        int common_pid;
>        int common_tgid;
>        int dev;
>        unsigned long long sector;
>        unsigned int nr_sector;
>        char rwbs[6];
>        char comm[16];
> } this_record = { 1, 2, 3, 4, 5, 6, 7, 8, { 'a', }, "abc" };
>
> void main(void)
> {
>        struct record *REC = &this_record;
>
>        printf("%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, (unsigned long long)REC->sector, REC->nr_sector, REC->comm);
> }


Yeah it's a quite nice idea.
But it's assuming everyone parses binary files using C programs.
Usually, such parsing
more likely involves the use of scripting languages.

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Frédéric Weisbecker]

Le 10 juin 2009 13:31, Frédéric Weisbecker<fweisbec@gmail.com> a écrit :
> 2009/6/10 Ingo Molnar <mingo@elte.hu>:
>>
>> * Christoph Hellwig <hch@infradead.org> wrote:
>>
>>> On Tue, Jun 09, 2009 at 09:22:01PM +0200, Frederic Weisbecker wrote:
>>> > But I wonder if the above new language is not breaking the charm
>>> > of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
>>> >
>>> > Everyone knows the printk formats. And I guess this new thing is
>>> > easy and quick to learn. But because it's a new unknown
>>> > language, the TRACE_EVENT will become less readable, less
>>> > reachable for newcomers in TRACE_EVENT.
>>>
>>> I must also say I don't particularly like it.  printk is nice and
>>> easy an everybody knows it, but it's not quite flexible enough as
>>> we might have to do all kinds of conversions on the reader side.
>>> What might be a better idea is to just have C function pointer for
>>> output conversions that could be put into the a file in debugfs
>>> and used by the binary trace buffer reader.  Or maybe not as we
>>> would pull in too many depenencies.
>>
>> Another bigger problem with the new tag format, beyond introducing
>> an arbitrary descriptor language (which is easy to mess up) is the
>> loss of type checking.
>>
>> With the tags the field printouts can go stray easily - while with
>> TP_printk() we had printf type checking. (which, as imperfect as it
>> may be to specify a format, does create a real connection between
>> the record and the output format specification.)
>>
>>> I think we should go with the printk solution for 2.6.31 and use
>>> the full development cycle for 2.6.32 to come up with something
>>> better.
>>>
>>> As soon as a couple of large subsystems use the even tracer we
>>> also have a broader base examples to see how new syntax works on
>>> them.
>>
>> I think much of the tooling problem could be solved with a little
>> trick: the format string can be injected into an artificial .c file
>> (runtime), and the tool could compile that .c file (in user-space)
>> and get access to the result.
>>
>> For example, one of the more complex block tracepoints,
>> /debug/tracing/events/block/block_bio_backmerge:
>>
>> print fmt: "%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >>
>> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs,
>> (unsigned long long)REC->sector, REC->nr_sector, REC->comm
>>
>> when pasted verbatim into the stub below, produces:
>>
>>   0,6 a 7 + 8 [abc]
>>
>> Note that i pasted the format string into the code below unchanged,
>> and i used the format descriptor to create the record type. (this
>> too is easy to automate).
>>
>> If this is generated into the following function:
>>
>>  format_block_bio_backmerge(struct record *rec);
>>
>> and a small dynamic library is built out of it, tooling can use
>> dlopen() to load those format printing stubs.
>>
>> It's all pretty straightforward and can be used for arbitrarily
>> complex formats.
>
>
>
> Hmm
>
>
>
>> And i kind of like the whole notion on a design level as weell: the
>> kernel exporting C source code for tools :-)
>>
>>        Ingo
>>
>> ------------------>
>>
>> struct record {
>>        unsigned short common_type;
>>        unsigned char common_flags;
>>        unsigned char common_preempt;
>>        int common_pid;
>>        int common_tgid;
>>        int dev;
>>        unsigned long long sector;
>>        unsigned int nr_sector;
>>        char rwbs[6];
>>        char comm[16];
>> } this_record = { 1, 2, 3, 4, 5, 6, 7, 8, { 'a', }, "abc" };
>>
>> void main(void)
>> {
>>        struct record *REC = &this_record;
>>
>>        printf("%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, (unsigned long long)REC->sector, REC->nr_sector, REC->comm);
>> }
>
>
> Yeah it's a quite nice idea.
> But it's assuming everyone parses binary files using C programs.
> Usually, such parsing
> more likely involves the use of scripting languages.
>

While thinking more about it your idea can produce a whole parser
automatically and dynamically written.
So actually, looks like a right direction :-)

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Steven Rostedt]

On Wed, 10 Jun 2009, Ingo Molnar wrote:
> 
> And i kind of like the whole notion on a design level as weell: the 
> kernel exporting C source code for tools :-)
> 
> 	Ingo
> 
> ------------------>
> 
> struct record {
> 	unsigned short common_type;
> 	unsigned char common_flags;
> 	unsigned char common_preempt;
> 	int common_pid;
> 	int common_tgid;
> 	int dev;
> 	unsigned long long sector;
> 	unsigned int nr_sector;
> 	char rwbs[6];
> 	char comm[16];
> } this_record = { 1, 2, 3, 4, 5, 6, 7, 8, { 'a', }, "abc" };
> 
> void main(void)
> {
> 	struct record *REC = &this_record;
> 
> 	printf("%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, (unsigned long long)REC->sector, REC->nr_sector, REC->comm);
> }

I actually tried this first. But it breaks once we start getting types 
into the code:

print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
          REC->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"}, [...]

Will break on gfp_t. We also have cases where the enum name slips in too:

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

Yes we can add special types for things like gfp_t, but as we get more and 
more users of TRACE_EVENT, the tools will never be able to keep up.

-- Steve

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Wed, 10 Jun 2009, Ingo Molnar wrote:
> > 
> > And i kind of like the whole notion on a design level as weell: the 
> > kernel exporting C source code for tools :-)
> > 
> > 	Ingo
> > 
> > ------------------>
> > 
> > struct record {
> > 	unsigned short common_type;
> > 	unsigned char common_flags;
> > 	unsigned char common_preempt;
> > 	int common_pid;
> > 	int common_tgid;
> > 	int dev;
> > 	unsigned long long sector;
> > 	unsigned int nr_sector;
> > 	char rwbs[6];
> > 	char comm[16];
> > } this_record = { 1, 2, 3, 4, 5, 6, 7, 8, { 'a', }, "abc" };
> > 
> > void main(void)
> > {
> > 	struct record *REC = &this_record;
> > 
> > 	printf("%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, (unsigned long long)REC->sector, REC->nr_sector, REC->comm);
> > }
> 
> I actually tried this first. But it breaks once we start getting types 
> into the code:
> 
> print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
>           REC->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"}, [...]
> 
> Will break on gfp_t. [...]

It wont break if we introduce a couple of common-sense types into 
the parsing/translation code. gfp_t is well-known.

Modules wont be able to generate new dynamic types - but that's OK i 
think, existing C types and common kernel types (and anything else 
we add) ought to be plenty enough.

> [...] We also have cases where the enum name slips in too:
> 
> print fmt: "softirq=%d action=%s", REC->vec, ({ static const struct trace_print_flags symbols[] =
>             { { HI_SOFTIRQ, "HI" }, { TIMER_SOFTIRQ, "TIMER" }, { NET_TX_SOFTIRQ, "NET_TX" },
>               { NET_RX_SOFTIRQ, "NET_RX" }, { BLOCK_SOFTIRQ, "BLOCK" },
>               { TASKLET_SOFTIRQ, "TASKLET" }, { SCHED_SOFTIRQ, "SCHED" },
>               { HRTIMER_SOFTIRQ, "HRTIMER" }, { RCU_SOFTIRQ, "RCU" },
>               { -1, ((void *)0) }}; ftrace_print_symbols_seq(p, REC->vec, symbols); })
> 
> Yes we can add special types for things like gfp_t, but as we get 
> more and more users of TRACE_EVENT, the tools will never be able 
> to keep up.

i still disagree. The tool will have to know about gfp_t in the tag 
language too. So there's always going to be a constant expansion of 
the type space.

The point is that the number of new types is an order of magnitude 
less than the number of new tracepoints.

Also, with tools like perf in the kernel repo under tools/perf/, 
we'll be able to keep up with mainline types very flexibly and very 
accurately.

	Ingo

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Steven Rostedt]

On Wed, 10 Jun 2009, Ingo Molnar wrote:
> > 
> > I actually tried this first. But it breaks once we start getting types 
> > into the code:
> > 
> > print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
> >           REC->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"}, [...]
> > 
> > Will break on gfp_t. [...]
> 
> It wont break if we introduce a couple of common-sense types into 
> the parsing/translation code. gfp_t is well-known.
> 
> Modules wont be able to generate new dynamic types - but that's OK i 
> think, existing C types and common kernel types (and anything else 
> we add) ought to be plenty enough.
> 
> > [...] We also have cases where the enum name slips in too:
> > 
> > print fmt: "softirq=%d action=%s", REC->vec, ({ static const struct trace_print_flags symbols[] =
> >             { { HI_SOFTIRQ, "HI" }, { TIMER_SOFTIRQ, "TIMER" }, { NET_TX_SOFTIRQ, "NET_TX" },
> >               { NET_RX_SOFTIRQ, "NET_RX" }, { BLOCK_SOFTIRQ, "BLOCK" },
> >               { TASKLET_SOFTIRQ, "TASKLET" }, { SCHED_SOFTIRQ, "SCHED" },
> >               { HRTIMER_SOFTIRQ, "HRTIMER" }, { RCU_SOFTIRQ, "RCU" },
> >               { -1, ((void *)0) }}; ftrace_print_symbols_seq(p, REC->vec, symbols); })
> > 
> > Yes we can add special types for things like gfp_t, but as we get 
> > more and more users of TRACE_EVENT, the tools will never be able 
> > to keep up.
> 
> i still disagree. The tool will have to know about gfp_t in the tag 
> language too. So there's always going to be a constant expansion of 
> the type space.
> 
> The point is that the number of new types is an order of magnitude 
> less than the number of new tracepoints.
> 
> Also, with tools like perf in the kernel repo under tools/perf/, 
> we'll be able to keep up with mainline types very flexibly and very 
> accurately.

I rather include a C parser than require dynamic compiling of the code to 
read the file. The want to be able to read the binary data from other 
systems. The output could include the format, and the binary data.

I'm working on ways to make the printk output in the format file not so 
ugly. There's tricks I can still do with __get_str and friends. But this 
still does not solve the issues with enums.

But my CPP skills are starting to incur another boost, lets see what else 
I can come up with ;-)

-- Steve

[PATCH][GIT PULL] tracing: do not translate event helper macros in print format

[Steven Rostedt]

Ingo,

This looks like it changed more than it really did, I only moved the one 
macro above another and added a few lines:

 +#undef __print_symbolic
 +#undef __get_dynamic_array
 +#undef __get_str
 +

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

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


Steven Rostedt (1):
      tracing: do not translate event helper macros in print format

----
 include/trace/ftrace.h |  158 ++++++++++++++++++++++++-----------------------
 1 files changed, 81 insertions(+), 77 deletions(-)
---------------------------
commit 6ff9a64d2aaa6eae396adc95e9c91c0cbfa6dbe4
Author: Steven Rostedt <srostedt@redhat.com>
Date:   Wed Jun 10 14:28:34 2009 -0400

    tracing: do not translate event helper macros in print format
    
    By moving the macro that creates the print format code above the
    defining of the event macro helpers (__get_str, __print_symbolic,
    and __get_dynamic_array), we get a little cleaner print format.
    
    Instead of:
    
      (char *)((void *)REC + REC->__data_loc_name)
    
    we get:
    
       __get_str(name)
    
    Instead of:
    
       ({ static const struct trace_print_flags symbols[] = { { HI_SOFTIRQ, "HI" }, {
    
    we get:
    
       __print_symbolic(REC->vec, { HI_SOFTIRQ, "HI" }, {
    
    Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 40ede4d..1867553 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -81,6 +81,87 @@
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
 
 /*
+ * Setup the showing format of trace point.
+ *
+ * int
+ * ftrace_format_##call(struct trace_seq *s)
+ * {
+ *	struct ftrace_raw_##call field;
+ *	int ret;
+ *
+ *	ret = trace_seq_printf(s, #type " " #item ";"
+ *			       " offset:%u; size:%u;\n",
+ *			       offsetof(struct ftrace_raw_##call, item),
+ *			       sizeof(field.type));
+ *
+ * }
+ */
+
+#undef TP_STRUCT__entry
+#define TP_STRUCT__entry(args...) args
+
+#undef __field
+#define __field(type, item)					\
+	ret = trace_seq_printf(s, "\tfield:" #type " " #item ";\t"	\
+			       "offset:%u;\tsize:%u;\n",		\
+			       (unsigned int)offsetof(typeof(field), item), \
+			       (unsigned int)sizeof(field.item));	\
+	if (!ret)							\
+		return 0;
+
+#undef __array
+#define __array(type, item, len)						\
+	ret = trace_seq_printf(s, "\tfield:" #type " " #item "[" #len "];\t"	\
+			       "offset:%u;\tsize:%u;\n",		\
+			       (unsigned int)offsetof(typeof(field), item), \
+			       (unsigned int)sizeof(field.item));	\
+	if (!ret)							\
+		return 0;
+
+#undef __dynamic_array
+#define __dynamic_array(type, item, len)				       \
+	ret = trace_seq_printf(s, "\tfield:__data_loc " #item ";\t"	       \
+			       "offset:%u;\tsize:%u;\n",		       \
+			       (unsigned int)offsetof(typeof(field),	       \
+					__data_loc_##item),		       \
+			       (unsigned int)sizeof(field.__data_loc_##item)); \
+	if (!ret)							       \
+		return 0;
+
+#undef __string
+#define __string(item, src) __dynamic_array(char, item, -1)
+
+#undef __entry
+#define __entry REC
+
+#undef __print_symbolic
+#undef __get_dynamic_array
+#undef __get_str
+
+#undef TP_printk
+#define TP_printk(fmt, args...) "%s, %s\n", #fmt, __stringify(args)
+
+#undef TP_fast_assign
+#define TP_fast_assign(args...) args
+
+#undef TRACE_EVENT
+#define TRACE_EVENT(call, proto, args, tstruct, func, print)		\
+static int								\
+ftrace_format_##call(struct trace_seq *s)				\
+{									\
+	struct ftrace_raw_##call field __attribute__((unused));		\
+	int ret = 0;							\
+									\
+	tstruct;							\
+									\
+	trace_seq_printf(s, "\nprint fmt: " print);			\
+									\
+	return ret;							\
+}
+
+#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
+
+/*
  * Stage 3 of the trace events.
  *
  * Override the macros in <trace/trace_events.h> to include the following:
@@ -179,83 +260,6 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 	
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
 
-/*
- * Setup the showing format of trace point.
- *
- * int
- * ftrace_format_##call(struct trace_seq *s)
- * {
- *	struct ftrace_raw_##call field;
- *	int ret;
- *
- *	ret = trace_seq_printf(s, #type " " #item ";"
- *			       " offset:%u; size:%u;\n",
- *			       offsetof(struct ftrace_raw_##call, item),
- *			       sizeof(field.type));
- *
- * }
- */
-
-#undef TP_STRUCT__entry
-#define TP_STRUCT__entry(args...) args
-
-#undef __field
-#define __field(type, item)					\
-	ret = trace_seq_printf(s, "\tfield:" #type " " #item ";\t"	\
-			       "offset:%u;\tsize:%u;\n",		\
-			       (unsigned int)offsetof(typeof(field), item), \
-			       (unsigned int)sizeof(field.item));	\
-	if (!ret)							\
-		return 0;
-
-#undef __array
-#define __array(type, item, len)						\
-	ret = trace_seq_printf(s, "\tfield:" #type " " #item "[" #len "];\t"	\
-			       "offset:%u;\tsize:%u;\n",		\
-			       (unsigned int)offsetof(typeof(field), item), \
-			       (unsigned int)sizeof(field.item));	\
-	if (!ret)							\
-		return 0;
-
-#undef __dynamic_array
-#define __dynamic_array(type, item, len)				       \
-	ret = trace_seq_printf(s, "\tfield:__data_loc " #item ";\t"	       \
-			       "offset:%u;\tsize:%u;\n",		       \
-			       (unsigned int)offsetof(typeof(field),	       \
-					__data_loc_##item),		       \
-			       (unsigned int)sizeof(field.__data_loc_##item)); \
-	if (!ret)							       \
-		return 0;
-
-#undef __string
-#define __string(item, src) __dynamic_array(char, item, -1)
-
-#undef __entry
-#define __entry REC
-
-#undef TP_printk
-#define TP_printk(fmt, args...) "%s, %s\n", #fmt, __stringify(args)
-
-#undef TP_fast_assign
-#define TP_fast_assign(args...) args
-
-#undef TRACE_EVENT
-#define TRACE_EVENT(call, proto, args, tstruct, func, print)		\
-static int								\
-ftrace_format_##call(struct trace_seq *s)				\
-{									\
-	struct ftrace_raw_##call field __attribute__((unused));		\
-	int ret = 0;							\
-									\
-	tstruct;							\
-									\
-	trace_seq_printf(s, "\nprint fmt: " print);			\
-									\
-	return ret;							\
-}
-
-#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
-
 #undef __field
 #define __field(type, item)						\
 	ret = trace_define_field(event_call, #type, #item,		\

Re: [PATCH][GIT PULL] tracing: do not translate event helper macros in print format

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> Ingo,
> 
> This looks like it changed more than it really did, I only moved 
> the one macro above another and added a few lines:
> 
>  +#undef __print_symbolic
>  +#undef __get_dynamic_array
>  +#undef __get_str
>  +
> 
> Please pull the latest tip/tracing/ftrace-1 tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/ftrace-1
> 
> 
> Steven Rostedt (1):
>       tracing: do not translate event helper macros in print format
> 
> ----
>  include/trace/ftrace.h |  158 ++++++++++++++++++++++++-----------------------
>  1 files changed, 81 insertions(+), 77 deletions(-)
> ---------------------------
> commit 6ff9a64d2aaa6eae396adc95e9c91c0cbfa6dbe4
> Author: Steven Rostedt <srostedt@redhat.com>
> Date:   Wed Jun 10 14:28:34 2009 -0400
> 
>     tracing: do not translate event helper macros in print format
>     
>     By moving the macro that creates the print format code above the
>     defining of the event macro helpers (__get_str, __print_symbolic,
>     and __get_dynamic_array), we get a little cleaner print format.
>     
>     Instead of:
>     
>       (char *)((void *)REC + REC->__data_loc_name)
>     
>     we get:
>     
>        __get_str(name)
>     
>     Instead of:
>     
>        ({ static const struct trace_print_flags symbols[] = { { HI_SOFTIRQ, "HI" }, {
>     
>     we get:
>     
>        __print_symbolic(REC->vec, { HI_SOFTIRQ, "HI" }, {

Yeah, that's really nice! Pulled, thanks Steve!

	Ingo

Re: [PATCH][GIT PULL] tracing: do not translate event helper macros in print format

[Christoph Hellwig]

On Wed, Jun 10, 2009 at 10:48:02PM +0200, Ingo Molnar wrote:
> > This looks like it changed more than it really did, I only moved 
> > the one macro above another and added a few lines:
> > 
> >  +#undef __print_symbolic
> >  +#undef __get_dynamic_array
> >  +#undef __get_str

> >     tracing: do not translate event helper macros in print format
> >     
> >     By moving the macro that creates the print format code above the
> >     defining of the event macro helpers (__get_str, __print_symbolic,
> >     and __get_dynamic_array), we get a little cleaner print format.

__print_flags should also be added, shouldn't it?

Maybe also le/be*_to_cpu/cpu_to_le/be*? and major/minor?

We should also document those helpers that need special treatment
somewhere?

Re: [PATCH][GIT PULL] tracing: do not translate event helper macros in print format

[Steven Rostedt]

On Thu, 11 Jun 2009, Christoph Hellwig wrote:

> On Wed, Jun 10, 2009 at 10:48:02PM +0200, Ingo Molnar wrote:
> > > This looks like it changed more than it really did, I only moved 
> > > the one macro above another and added a few lines:
> > > 
> > >  +#undef __print_symbolic
> > >  +#undef __get_dynamic_array
> > >  +#undef __get_str
> 
> > >     tracing: do not translate event helper macros in print format
> > >     
> > >     By moving the macro that creates the print format code above the
> > >     defining of the event macro helpers (__get_str, __print_symbolic,
> > >     and __get_dynamic_array), we get a little cleaner print format.
> 
> __print_flags should also be added, shouldn't it?

Darn, I knew I forgot one :-/

> 
> Maybe also le/be*_to_cpu/cpu_to_le/be*? and major/minor?

We can only include macros that we define later. Otherwise we undefine 
them for when we need them.

-- Steve

> 
> We should also document those helpers that need special treatment
> somewhere?
> 
> 

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Mathieu Desnoyers]

* Ingo Molnar (mingo@elte.hu) wrote:
> 
> * Christoph Hellwig <hch@infradead.org> wrote:
> 
> > On Tue, Jun 09, 2009 at 09:22:01PM +0200, Frederic Weisbecker wrote:
> > > But I wonder if the above new language is not breaking the charm
> > > of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
> > > 
> > > Everyone knows the printk formats. And I guess this new thing is 
> > > easy and quick to learn. But because it's a new unknown 
> > > language, the TRACE_EVENT will become less readable, less 
> > > reachable for newcomers in TRACE_EVENT.
> > 
> > I must also say I don't particularly like it.  printk is nice and 
> > easy an everybody knows it, but it's not quite flexible enough as 
> > we might have to do all kinds of conversions on the reader side.  
> > What might be a better idea is to just have C function pointer for 
> > output conversions that could be put into the a file in debugfs 
> > and used by the binary trace buffer reader.  Or maybe not as we 
> > would pull in too many depenencies.
> 
> Another bigger problem with the new tag format, beyond introducing 
> an arbitrary descriptor language (which is easy to mess up) is the 
> loss of type checking.
> 
> With the tags the field printouts can go stray easily - while with 
> TP_printk() we had printf type checking. (which, as imperfect as it 
> may be to specify a format, does create a real connection between 
> the record and the output format specification.)
> 
> > I think we should go with the printk solution for 2.6.31 and use 
> > the full development cycle for 2.6.32 to come up with something 
> > better.
> >
> > As soon as a couple of large subsystems use the even tracer we 
> > also have a broader base examples to see how new syntax works on 
> > them.
> 
> I think much of the tooling problem could be solved with a little 
> trick: the format string can be injected into an artificial .c file 
> (runtime), and the tool could compile that .c file (in user-space) 
> and get access to the result.
> 
> For example, one of the more complex block tracepoints, 
> /debug/tracing/events/block/block_bio_backmerge:
> 
> print fmt: "%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 
> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, 
> (unsigned long long)REC->sector, REC->nr_sector, REC->comm
> 
> when pasted verbatim into the stub below, produces:
> 
>    0,6 a 7 + 8 [abc]
> 
> Note that i pasted the format string into the code below unchanged, 
> and i used the format descriptor to create the record type. (this 
> too is easy to automate).
> 
> If this is generated into the following function:
> 
>  format_block_bio_backmerge(struct record *rec);
> 
> and a small dynamic library is built out of it, tooling can use 
> dlopen() to load those format printing stubs.
> 
> It's all pretty straightforward and can be used for arbitrarily 
> complex formats.
> 
> And i kind of like the whole notion on a design level as weell: the 
> kernel exporting C source code for tools :-)
> 

Hrm, it's problematic for users who run the userspace analysis tools on
different machine than their kernel. And also problematic for 64-bits
kernel/32-bits userland. A lot of embedded developers run on very
resource limited ARM boards and have to analyse the traces on a
different machine.

It would be much more flexible if we parse the event format description
from a userland tool than trying to use C as a direct way to export
trace metadata, which would cause us to build an ABI-specific,
non-portable, analyser tool.

Mathieu


> 	Ingo
> 
> ------------------>
> 
> struct record {
> 	unsigned short common_type;
> 	unsigned char common_flags;
> 	unsigned char common_preempt;
> 	int common_pid;
> 	int common_tgid;
> 	int dev;
> 	unsigned long long sector;
> 	unsigned int nr_sector;
> 	char rwbs[6];
> 	char comm[16];
> } this_record = { 1, 2, 3, 4, 5, 6, 7, 8, { 'a', }, "abc" };
> 
> void main(void)
> {
> 	struct record *REC = &this_record;
> 
> 	printf("%d,%d %s %llu + %u [%s]", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), REC->rwbs, (unsigned long long)REC->sector, REC->nr_sector, REC->comm);
> }
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [RFC PATCH 2/5] tracing/events: nicer print format for parsing

[Steven Rostedt]

On Wed, 10 Jun 2009, Christoph Hellwig wrote:

> On Tue, Jun 09, 2009 at 09:22:01PM +0200, Frederic Weisbecker wrote:
> > But I wonder if the above new language is not breaking the charm
> > of the TRACE_EVENT(), which charm is that it's easy to implement (hopefully).
> > 
> > Everyone knows the printk formats. And I guess this new thing is easy and
> > quick to learn. But because it's a new unknown language, the TRACE_EVENT
> > will become less readable, less reachable for newcomers in TRACE_EVENT.
> 
> I must also say I don't particularly like it.  printk is nice and easy
> an everybody knows it, but it's not quite flexible enough as we might
> have to do all kinds of conversions on the reader side.  What might be
> a better idea is to just have C function pointer for output conversions
> that could be put into the a file in debugfs and used by the binary
> trace buffer reader.  Or maybe not as we would pull in too many
> depenencies.

Yeah, having a printk function in debugfs that is controlled by the kernel
sounds wrong on so many levels ;-)

> 
> I think we should go with the printk solution for 2.6.31 and use the
> full development cycle for 2.6.32 to come up with something better.
> 
> As soon as a couple of large subsystems use the even tracer we also
> have a broader base examples to see how new syntax works on them.

Fair enough. I'm just worried that we'll start to get users that depend on 
the printk format. Perhaps the better idea is to remove the printk format 
from the debugfs format file, and force all tools to add their own for 
every event? At least until we can come up with a solution to dynamically do this?

-- Steve

[RFC PATCH 3/5] tracing/events: modify irq print to new format

[Steven Rostedt]

[-- Attachment #1: 0003-tracing-events-modify-irq-print-to-new-format.patch --]
[-- Type: text/plain, Size: 2409 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 |   35 ++++++++++++++++-------------------
 1 files changed, 16 insertions(+), 19 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index b0c7ede..e1350fc 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -7,18 +7,18 @@
 #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(val)						\
+	"%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s>",	\
+		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 +47,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 +77,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 +105,7 @@ 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(__entry->vec))
 );
 
 /**
@@ -135,8 +133,7 @@ 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(__entry->vec))
 );
 
 #endif /*  _TRACE_IRQ_H */
-- 
1.6.3.1

-- 

Re: [RFC PATCH 3/5] tracing/events: modify irq print to new format

[Christoph Hellwig]

On Mon, Jun 08, 2009 at 09:45:37PM -0400, Steven Rostedt wrote:
> -#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(val)						\
> +	"%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s>",	\
> +		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)

This is a massive readability and maintainabilit  regression over the
old code.  I now need to add a useless and counter-intuitive %d=%s,
boilerplate for every new flag I add instead ofa simple line-line
array entry.

Also why does show_softirq_name get a val argument passed that's never
used?  And no, I don't think
%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s is an intuitive
way to print an enum.

Re: [RFC PATCH 3/5] tracing/events: modify irq print to new format

[Steven Rostedt]

On Wed, 10 Jun 2009, Christoph Hellwig wrote:

> On Mon, Jun 08, 2009 at 09:45:37PM -0400, Steven Rostedt wrote:
> > -#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(val)						\
> > +	"%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s>",	\
> > +		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)
> 
> This is a massive readability and maintainabilit  regression over the
> old code.  I now need to add a useless and counter-intuitive %d=%s,
> boilerplate for every new flag I add instead ofa simple line-line
> array entry.
> 
> Also why does show_softirq_name get a val argument passed that's never
> used?  And no, I don't think

That was from the original, I forgot to remove it.

> %d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s,%d=%s is an intuitive
> way to print an enum.

This is a helper macro and has nothing to do with the new format. In fact, 
I'd do something similar with the old format because currently without 
that "%d=%s,..." helper we get in the print format:

	HRTIMER_SOFTIRQ = "HRTIMER"

How is a user tool going to know what value HRTIMER_SOFTIRQ is?

This was a trick I used to evaluate the HRTIMER_SOFTIRQ to an actual 
number that might actually be useful for userland readers.

-- Steve

[RFC PATCH 4/5] tracing/events: modify sched print to new format

[Steven Rostedt]

[-- Attachment #1: 0004-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

-- 

[RFC PATCH 5/5] tracing/events: modify kmem print to new format

[Steven Rostedt]

[-- Attachment #1: 0005-tracing-events-modify-kmem-print-to-new-format.patch --]
[-- Type: text/plain, Size: 5798 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 |   97 +++++++++++++++++++------------------------
 1 files changed, 43 insertions(+), 54 deletions(-)

diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
index 9baba50..2ffa8ae 100644
--- a/include/trace/events/kmem.h
+++ b/include/trace/events/kmem.h
@@ -17,32 +17,35 @@
  *
  * 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(end...)						\
+	"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>" end ,					\
+	(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 +73,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())
 );
 
 TRACE_EVENT(kmem_cache_alloc,
@@ -104,12 +104,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())
 );
 
 TRACE_EVENT(kmalloc_node,
@@ -141,13 +138,9 @@ 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(" node=<int:node>"))
 );
 
 TRACE_EVENT(kmem_cache_alloc_node,
@@ -179,13 +172,9 @@ 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(" node=<int:node>"))
 );
 
 TRACE_EVENT(kfree,
@@ -204,7 +193,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 +212,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

-- 

Re: [RFC PATCH 5/5] tracing/events: modify kmem print to new format

[Peter Zijlstra]

On Mon, 2009-06-08 at 21:45 -0400, Steven Rostedt wrote:

> +#define show_gfp_flags(end...)						\
> +	"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>" end ,					\
> +	(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"

Just curious, how unhappy does stuff become when we add a __GFP_ flag
and forget to extend this table?

Re: [RFC PATCH 5/5] tracing/events: modify kmem print to new format

[Mel Gorman]

On Tue, Jun 09, 2009 at 09:12:42AM +0200, Peter Zijlstra wrote:
> On Mon, 2009-06-08 at 21:45 -0400, Steven Rostedt wrote:
> 
> > +#define show_gfp_flags(end...)						\
> > +	"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>" end ,					\
> > +	(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"
> 
> Just curious, how unhappy does stuff become when we add a __GFP_ flag
> and forget to extend this table?
> 

If it's the same behaviour as what I was looking at yesterday, it prints
the remaining flags it doesn't recognise as the number.

GFP_KERNEL|__GFP_DMA got outputted as |GFP_KERNEL|0x1|

-- 
Mel Gorman
Part-time Phd Student                          Linux Technology Center
University of Limerick                         IBM Dublin Software Lab

Re: [RFC PATCH 5/5] tracing/events: modify kmem print to new format

[Steven Rostedt]

On Tue, 9 Jun 2009, Mel Gorman wrote:

> On Tue, Jun 09, 2009 at 09:12:42AM +0200, Peter Zijlstra wrote:
> > On Mon, 2009-06-08 at 21:45 -0400, Steven Rostedt wrote:
> > 
> > > +#define show_gfp_flags(end...)						\
> > > +	"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>" end ,					\
> > > +	(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"
> > 
> > Just curious, how unhappy does stuff become when we add a __GFP_ flag
> > and forget to extend this table?
> > 
> 
> If it's the same behaviour as what I was looking at yesterday, it prints
> the remaining flags it doesn't recognise as the number.
> 
> GFP_KERNEL|__GFP_DMA got outputted as |GFP_KERNEL|0x1|

Yep, that is what would happen here too.

Any comments on this approach? I'll go ahead and start fixing it up more 
(handling all the memory freeing on errors) and get it ready to push out.

-- Steve

Re: [RFC PATCH 0/5] simplify the print fmt in the event format files

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> This is a request for comments on the new print format style to show
> in the format file.
> 
> As more and more users of ftrace are retrieving their data through
> the binary interface, it has become more important to be able to
> parse the format of these binary records.
> 
> Since the output may also be used in dumps of the kernel, it is still
> important that ftrace has a way within the kernel to display the
> data records in a human readable format.
> 
> The current method is with TP_printk, in the TRACE_EVENT. This acts
> just like a printk and lets the developer print out their format
> anyway they would like to. But the problem with this is that the
> readers of the binary data would either have to have a C parser to understand
> the output, or would have to have a custom made parser to match the
> contents, and hope that the contents would not change.
> 
> This patch series creates a new marco called TP_FORMAT that can be
> used in place of the TP_printk inside the TRACE_EVENT macro.
> 
> This format has the current following language:
> 
>  * FMT :=  constant string FMT | COMMAND FMT | empty
>  * COMMAND := <TYPE:FIELD> | <mask:FIELD:DELIM:MASKS> | <sym:FIELD:SYMBOLS> |
>  *               <if:FIELD:TRUE:FALSE>
>  * TYPE := int | 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 '<'
> 
> We can extend this langange when we need to. A user app could just
> ignore a type it does not understand.
> 
> This is an RFC patch set. I basically just got it working but it lacks
> some clean ups on errors. And I need to investigate the use of the
> fields structures to make sure they are adquately protected. It uses
> the fields that are pased by the filter code.
> 
> This makes the output of the format much cleaner.

Agreed, it's clearly cleaner.

> 
> We go from this:
> 
>  print fmt: "irq=%d handler=%s", REC->irq, (char *)((void *)REC + REC->__data_loc_name)
> 
> to this:
> 
>  format: irq=<int:irq> handler=<string:name>
> 
> and this:
> 
>   print fmt: "softirq=%d action=%s", REC->vec, ({ static const struct trace_print_flags symbols[] = { { HI_SOFTIRQ, "HI" }, { TIMER_SOFTIRQ, "TIMER" }, { NET_TX_SOFTIRQ, "NET_TX" }, { NET_RX_SOFTIRQ, "NET_RX" }, { BLOCK_SOFTIRQ, "BLOCK" }, { TASKLET_SOFTIRQ, "TASKLET" }, { SCHED_SOFTIRQ, "SCHED" }, { HRTIMER_SOFTIRQ, "HRTIMER" }, { RCU_SOFTIRQ, "RCU" }, { -1, ((void *)0) }}; ftrace_print_symbols_seq (p, REC->vec, symbols); })
> 
> To this:
> 
> 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

Introducing new, elaborate description languages is always risky. 
Would there be a way to reuse something existing - ideally some nice 
sub-set of C structure definitions?

Also, would it be possible to put more newlines into the format, so 
that human inspection is more straightforward. It wont matter to the 
tools.

	Ingo

Re: [RFC PATCH 0/5] simplify the print fmt in the event format files

[Steven Rostedt]

On Tue, 9 Jun 2009, Ingo Molnar wrote:
> 
> > 
> > We go from this:
> > 
> >  print fmt: "irq=%d handler=%s", REC->irq, (char *)((void *)REC + REC->__data_loc_name)
> > 
> > to this:
> > 
> >  format: irq=<int:irq> handler=<string:name>
> > 
> > and this:
> > 
> >   print fmt: "softirq=%d action=%s", REC->vec, ({ static const struct trace_print_flags symbols[] = { { HI_SOFTIRQ, "HI" }, { TIMER_SOFTIRQ, "TIMER" }, { NET_TX_SOFTIRQ, "NET_TX" }, { NET_RX_SOFTIRQ, "NET_RX" }, { BLOCK_SOFTIRQ, "BLOCK" }, { TASKLET_SOFTIRQ, "TASKLET" }, { SCHED_SOFTIRQ, "SCHED" }, { HRTIMER_SOFTIRQ, "HRTIMER" }, { RCU_SOFTIRQ, "RCU" }, { -1, ((void *)0) }}; ftrace_print_symbols_seq (p, REC->vec, symbols); })
> > 
> > To this:
> > 
> > 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
> 
> Introducing new, elaborate description languages is always risky. 
> Would there be a way to reuse something existing - ideally some nice 
> sub-set of C structure definitions?

I'm open for suggestions. Yeah, I was trying to avoid the new markup, but 
C is more for code and not for printing. In fact C sucks for text markup 
:-(

But I would also like to avoid a full xml parser in the kernel ;-)

> 
> Also, would it be possible to put more newlines into the format, so 
> that human inspection is more straightforward. It wont matter to the 
> tools.

Actually, you can add newlines in the tags, and they will not affect the 
mark up. Well, at least before the numbers. You can have:

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

But actually, this would make it harder on the tools. Since currently my 
tool just reads one entire line. But I guess I can fix that too.

-- Steve