[PATCH 0/3] tracing/events: enumerating flags

[PATCH 0/3] tracing/events: enumerating flags

[Steven Rostedt]

Ingo,

I'm not really publishing this as a pull request. I would like one last
comment from people since the last patch modifies the kmem trace to
print out the actual names of the flags instead of a flags value. If
this is unwanted, then I can strip it out in my next series.

-- Steve


The following patches are in:

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

    branch: tip/tracing/ftrace-1


Steven Rostedt (3):
      tracing: add __print_flags for events
      tracing: add previous task state info to sched switch event
      tracing: add flag output for kmem events

----
 include/linux/ftrace_event.h |    6 ++++-
 include/trace/events/kmem.h  |   43 ++++++++++++++++++++++++++++++++++-------
 include/trace/events/sched.h |    8 ++++++-
 include/trace/ftrace.h       |   10 +++++++++
 kernel/trace/trace_output.c  |   38 +++++++++++++++++++++++++++++++++++++
 5 files changed, 95 insertions(+), 10 deletions(-)

-- 

[PATCH 1/3] tracing: add __print_flags for events

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-add-__print_flags-for-events.patch --]
[-- Type: text/plain, Size: 4626 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Developers have been asking for the ability in the ftrace event tracer
to display names of bits in a flags variable.

Instead of printing out c2, it would be easier to read FOO|BAR|GOO,
assuming that FOO is bit 1, BAR is bit 6 and GOO is bit 7.

Some examples where this would be useful are the state flags in a context
switch, kmalloc flags, and even permision flags in accessing files.

I included Frederic Weisbecker's idea of using a mask instead of bits,
thus we can output GFP_KERNEL instead of GPF_WAIT|GFP_IO|GFP_FS.

I also included Li Zefan's idea of allowing the caller of __print_flags
to add their own delimiter (or no delimiter) where we can get for
file permissions rwx instead of r|w|x.

[ Impact: better displaying of flags in trace output ]

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/ftrace_event.h |    6 +++++-
 include/trace/ftrace.h       |   10 ++++++++++
 kernel/trace/trace_output.c  |   38 ++++++++++++++++++++++++++++++++++++++
 3 files changed, 53 insertions(+), 1 deletions(-)

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index bae51dd..253c3d0 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -3,12 +3,16 @@
 
 #include <linux/trace_seq.h>
 #include <linux/ring_buffer.h>
-
+#include <linux/percpu.h>
 
 struct trace_array;
 struct tracer;
 struct dentry;
 
+DECLARE_PER_CPU(struct trace_seq, ftrace_event_seq);
+const char *ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
+				   unsigned long flags, ...);
+
 /*
  * The trace entry - the most basic unit of tracing. This is what
  * is printed in the end as a single line in the trace output, such as:
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index edb02bc..9b79c7c 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -87,6 +87,7 @@
  *	struct trace_seq *s = &iter->seq;
  *	struct ftrace_raw_<call> *field; <-- defined in stage 1
  *	struct trace_entry *entry;
+ *	struct trace_seq *p;
  *	int ret;
  *
  *	entry = iter->ent;
@@ -98,7 +99,9 @@
  *
  *	field = (typeof(field))entry;
  *
+ *	p = get_cpu_var(ftrace_event_seq);
  *	ret = trace_seq_printf(s, <TP_printk> "\n");
+ *	put_cpu();
  *	if (!ret)
  *		return TRACE_TYPE_PARTIAL_LINE;
  *
@@ -119,6 +122,10 @@
 #undef __get_str
 #define __get_str(field)	((char *)__entry + __entry->__str_loc_##field)
 
+#undef __print_flags
+#define __print_flags(flag, delim, x...) \
+	ftrace_print_flags_seq(p, delim, flag, x , 0)
+
 #undef TRACE_EVENT
 #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
 enum print_line_t							\
@@ -127,6 +134,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 	struct trace_seq *s = &iter->seq;				\
 	struct ftrace_raw_##call *field;				\
 	struct trace_entry *entry;					\
+	struct trace_seq *p;						\
 	int ret;							\
 									\
 	entry = iter->ent;						\
@@ -138,7 +146,9 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 									\
 	field = (typeof(field))entry;					\
 									\
+	p = &get_cpu_var(ftrace_event_seq);				\
 	ret = trace_seq_printf(s, #call ": " print);			\
+	put_cpu();							\
 	if (!ret)							\
 		return TRACE_TYPE_PARTIAL_LINE;				\
 									\
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 489c0e8..f730de5 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -14,6 +14,8 @@
 /* must be a power of 2 */
 #define EVENT_HASHSIZE	128
 
+DEFINE_PER_CPU(struct trace_seq, ftrace_event_seq);
+
 static DEFINE_MUTEX(trace_event_mutex);
 static struct hlist_head event_hash[EVENT_HASHSIZE] __read_mostly;
 
@@ -212,6 +214,42 @@ int trace_seq_path(struct trace_seq *s, struct path *path)
 	return 0;
 }
 
+const char *
+ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
+		       unsigned long flags, ...)
+{
+	const char *str;
+	va_list args;
+	unsigned long mask;
+
+	trace_seq_init(p);
+	va_start(args, flags);
+	for (mask = va_arg(args, unsigned long); mask && flags;
+	     mask = va_arg(args, unsigned long)) {
+		str = va_arg(args, const char *);
+
+		if ((flags & mask) != mask)
+			continue;
+
+		flags &= ~mask;
+		if (p->len && delim)
+			trace_seq_puts(p, delim);
+		trace_seq_puts(p, str);
+	}
+	va_end(args);
+
+	/* check for left over flags */
+	if (flags) {
+		if (p->len && delim)
+			trace_seq_puts(p, delim);
+		trace_seq_printf(p, "0x%lx", flags);
+	}
+
+	trace_seq_putc(p, 0);
+
+	return p->buffer;
+}
+
 #ifdef CONFIG_KRETPROBES
 static inline const char *kretprobed(const char *name)
 {
-- 
1.6.2.4

-- 

Re: [PATCH 1/3] tracing: add __print_flags for events

[Christoph Hellwig]

On Fri, May 15, 2009 at 05:03:43PM -0400, Steven Rostedt wrote:
> From: Steven Rostedt <srostedt@redhat.com>
> 
> Developers have been asking for the ability in the ftrace event tracer
> to display names of bits in a flags variable.
> 
> Instead of printing out c2, it would be easier to read FOO|BAR|GOO,
> assuming that FOO is bit 1, BAR is bit 6 and GOO is bit 7.
> 
> Some examples where this would be useful are the state flags in a context
> switch, kmalloc flags, and even permision flags in accessing files.
> 
> I included Frederic Weisbecker's idea of using a mask instead of bits,
> thus we can output GFP_KERNEL instead of GPF_WAIT|GFP_IO|GFP_FS.
> 
> I also included Li Zefan's idea of allowing the caller of __print_flags
> to add their own delimiter (or no delimiter) where we can get for
> file permissions rwx instead of r|w|x.

Looks good to me.

Some small comments:

 - __print_flags might be a little to generic.  What about trace_print_flags?
 - some documentation would help.  I can submit a patch to the
   trave_events sample module to make use of it once this patch is
   merged.
 - Maybe passing an array instead of a list of flag/value pairs would be
   a tad cleaner?  That would get rid of all the varargs mess and allow
   to declare that array next to the flags so get less easily out of
   sync.

Re: [PATCH 1/3] tracing: add __print_flags for events

[Steven Rostedt]

On Mon, 18 May 2009, Christoph Hellwig wrote:
> Some small comments:
> 
>  - __print_flags might be a little to generic.  What about trace_print_flags?

The __print_flags is not a macro nor a function. It is similar to 
__field() and __array() and __string(). It is a place holder that will be 
overriden by the ftrace.h magic.

I'll keep it as __print_flags since it follows format with the other tags.

>  - some documentation would help.  I can submit a patch to the
>    trave_events sample module to make use of it once this patch is
>    merged.
>  - Maybe passing an array instead of a list of flag/value pairs would be
>    a tad cleaner?  That would get rid of all the varargs mess and allow
>    to declare that array next to the flags so get less easily out of
>    sync.

OK, this may even save space. By passing by parameters we must load all 
the parameters before calling the function. Even though this is on the 
print side, it is still bloated. I'll convert it to an array.

Thanks,

-- Steve

Re: [PATCH 1/3] tracing: add __print_flags for events

[Christoph Hellwig]

On Wed, May 20, 2009 at 06:13:37PM -0400, Steven Rostedt wrote:
> OK, this may even save space. By passing by parameters we must load all 
> the parameters before calling the function. Even though this is on the 
> print side, it is still bloated. I'll convert it to an array.

Nice, thanks.

Btw, it would be nice to add a __print_symbolic cousin that looks for
an exact match in an array.  That way we can also print translations to
names in a way that can be read from the format file and duplicated
by userspace apps using the binary trace buffer.

Re: [PATCH 1/3] tracing: add __print_flags for events

[Steven Rostedt]

On Wed, 20 May 2009, Christoph Hellwig wrote:

> On Wed, May 20, 2009 at 06:13:37PM -0400, Steven Rostedt wrote:
> > OK, this may even save space. By passing by parameters we must load all 
> > the parameters before calling the function. Even though this is on the 
> > print side, it is still bloated. I'll convert it to an array.
> 
> Nice, thanks.
> 
> Btw, it would be nice to add a __print_symbolic cousin that looks for
> an exact match in an array.  That way we can also print translations to
> names in a way that can be read from the format file and duplicated
> by userspace apps using the binary trace buffer.

You mean more like a "__print_enumerated"? A backward translation of 
enumerated types to their names.

Perhaps __print_symbolic is a bit nicer name.

-- Steve

Re: [PATCH 1/3] tracing: add __print_flags for events

[Christoph Hellwig]

On Wed, May 20, 2009 at 07:02:56PM -0400, Steven Rostedt wrote:
> You mean more like a "__print_enumerated"? A backward translation of 
> enumerated types to their names.

Yeah.

> Perhaps __print_symbolic is a bit nicer name.

Sounds good.

Re: [PATCH 1/3] tracing: add __print_flags for events

[KOSAKI Motohiro]

Hi Steven,

> From: Steven Rostedt <srostedt@redhat.com>
> 
> Developers have been asking for the ability in the ftrace event tracer
> to display names of bits in a flags variable.
> 
> Instead of printing out c2, it would be easier to read FOO|BAR|GOO,
> assuming that FOO is bit 1, BAR is bit 6 and GOO is bit 7.
> 
> Some examples where this would be useful are the state flags in a context
> switch, kmalloc flags, and even permision flags in accessing files.
> 
> I included Frederic Weisbecker's idea of using a mask instead of bits,
> thus we can output GFP_KERNEL instead of GPF_WAIT|GFP_IO|GFP_FS.
> 
> I also included Li Zefan's idea of allowing the caller of __print_flags
> to add their own delimiter (or no delimiter) where we can get for
> file permissions rwx instead of r|w|x.
> 
> [ Impact: better displaying of flags in trace output ]

very good feature :)

I'd like to discuss a bit offtopic. struct page->flags have
some overlapped meaning.

example, Wu proposed kpageflags enhancement about two week ago.
his patch have following hunk.

+	/*
+	 * pseudo flags for the well known (anonymous) memory mapped pages
+	 *
+	 * Note that page->_mapcount is overloaded in SLOB/SLUB/SLQB, so the
+	 * simple test in page_mapped() is not enough.
+	 */
+	if (!PageSlab(page) && page_mapped(page))
+		u |= 1 << KPF_MMAP;


How do we handle such complex condition?

[PATCH 2/3] tracing: add previous task state info to sched switch event

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-add-previous-task-state-info-to-sched-switc.patch --]
[-- Type: text/plain, Size: 1635 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

It is useful to see the state of a task that is being switched out.
This patch adds the output of the state of the previous task in
the context switch event.

[ Impact: see state of switched out task in context switch ]

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

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index dd4033c..f887462 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -156,6 +156,7 @@ TRACE_EVENT(sched_switch,
 		__array(	char,	prev_comm,	TASK_COMM_LEN	)
 		__field(	pid_t,	prev_pid			)
 		__field(	int,	prev_prio			)
+		__field(	long,	prev_state			)
 		__array(	char,	next_comm,	TASK_COMM_LEN	)
 		__field(	pid_t,	next_pid			)
 		__field(	int,	next_prio			)
@@ -165,13 +166,18 @@ TRACE_EVENT(sched_switch,
 		memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
 		__entry->prev_pid	= prev->pid;
 		__entry->prev_prio	= prev->prio;
+		__entry->prev_state	= prev->state;
 		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
 		__entry->next_pid	= next->pid;
 		__entry->next_prio	= next->prio;
 	),
 
-	TP_printk("task %s:%d [%d] ==> %s:%d [%d]",
+	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)
 );
 
-- 
1.6.2.4

-- 

[PATCH 3/3] tracing: add flag output for kmem events

[Steven Rostedt]

[-- Attachment #1: 0003-tracing-add-flag-output-for-kmem-events.patch --]
[-- Type: text/plain, Size: 3773 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

This patch changes the output for gfp_flags from being a simple hex value
to the actual names.

  gfp_flags=GFP_ATOMIC  instead of gfp_flags=00000020

And even

  gfp_flags=GFP_KERNEL instead of gfp_flags=000000d0

[ Impact: more human readable output from tracer ]

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

diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
index c22c42f..9b3886b 100644
--- a/include/trace/events/kmem.h
+++ b/include/trace/events/kmem.h
@@ -7,6 +7,33 @@
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM kmem
 
+#define show_gfp_flags(flags)						\
+	(flags) ? __print_flags(flags, "|",				\
+	(unsigned long)GFP_KERNEL,		"GFP_KERNEL",		\
+	(unsigned long)GFP_NOFS,		"GFP_NOFS",		\
+	(unsigned long)GFP_TEMPORARY,		"GFP_TEMPORARY",	\
+	(unsigned long)GFP_USER,		"GFP_USER",		\
+	(unsigned long)GFP_HIGHUSER,		"GFP_HIGHUSER",		\
+	(unsigned long)GFP_HIGHUSER_MOVABLE,	"GFP_HIGHUSER_MOVABLE",	\
+	(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"
+
 TRACE_EVENT(kmalloc,
 
 	TP_PROTO(unsigned long call_site,
@@ -33,12 +60,12 @@ TRACE_EVENT(kmalloc,
 		__entry->gfp_flags	= gfp_flags;
 	),
 
-	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%08x",
+	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,
-		__entry->gfp_flags)
+		show_gfp_flags(__entry->gfp_flags))
 );
 
 TRACE_EVENT(kmem_cache_alloc,
@@ -67,12 +94,12 @@ 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=%08x",
+	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,
-		__entry->gfp_flags)
+		show_gfp_flags(__entry->gfp_flags))
 );
 
 TRACE_EVENT(kmalloc_node,
@@ -104,12 +131,12 @@ TRACE_EVENT(kmalloc_node,
 		__entry->node		= node;
 	),
 
-	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%08x node=%d",
+	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,
-		__entry->gfp_flags,
+		show_gfp_flags(__entry->gfp_flags),
 		__entry->node)
 );
 
@@ -142,12 +169,12 @@ TRACE_EVENT(kmem_cache_alloc_node,
 		__entry->node		= node;
 	),
 
-	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%08x node=%d",
+	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,
-		__entry->gfp_flags,
+		show_gfp_flags(__entry->gfp_flags),
 		__entry->node)
 );
 
-- 
1.6.2.4

-- 

Re: [PATCH 3/3] tracing: add flag output for kmem events

[Frederic Weisbecker]

On Fri, May 15, 2009 at 05:03:45PM -0400, Steven Rostedt wrote:
> From: Steven Rostedt <srostedt@redhat.com>
> 
> This patch changes the output for gfp_flags from being a simple hex value
> to the actual names.
> 
>   gfp_flags=GFP_ATOMIC  instead of gfp_flags=00000020
> 
> And even
> 
>   gfp_flags=GFP_KERNEL instead of gfp_flags=000000d0
> 
> [ Impact: more human readable output from tracer ]
> 
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>


Nice!


> ---
>  include/trace/events/kmem.h |   43 +++++++++++++++++++++++++++++++++++--------
>  1 files changed, 35 insertions(+), 8 deletions(-)
> 
> diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
> index c22c42f..9b3886b 100644
> --- a/include/trace/events/kmem.h
> +++ b/include/trace/events/kmem.h
> @@ -7,6 +7,33 @@
>  #undef TRACE_SYSTEM
>  #define TRACE_SYSTEM kmem
>  
> +#define show_gfp_flags(flags)						\
> +	(flags) ? __print_flags(flags, "|",				\
> +	(unsigned long)GFP_KERNEL,		"GFP_KERNEL",		\
> +	(unsigned long)GFP_NOFS,		"GFP_NOFS",		\
> +	(unsigned long)GFP_TEMPORARY,		"GFP_TEMPORARY",	\
> +	(unsigned long)GFP_USER,		"GFP_USER",		\


Because you clear the mask value after finding out a matching mask
string, you should sort the masks from the highest number of bits
to the lowest.

GFP_USER should be placed before GFP_KERNEL otherwise it will always be
eaten.
Instead of GFP_USER, you will get:

GFP_KERNEL | __GFP_HARDWALL


> +	(unsigned long)GFP_HIGHUSER,		"GFP_HIGHUSER",		\


Ditto, it should be placed before GFP_USER otherwise you will get:

GFP_USER | __GFP_HIGHMEM


> +	(unsigned long)GFP_HIGHUSER_MOVABLE,	"GFP_HIGHUSER_MOVABLE",	\

And this one before HIGH_USER otherwise:

GFP_HIGHUSER__GFP_MOVABLE


:-)


Frederic.

> +	(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"
> +
>  TRACE_EVENT(kmalloc,
>  
>  	TP_PROTO(unsigned long call_site,
> @@ -33,12 +60,12 @@ TRACE_EVENT(kmalloc,
>  		__entry->gfp_flags	= gfp_flags;
>  	),
>  
> -	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%08x",
> +	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,
> -		__entry->gfp_flags)
> +		show_gfp_flags(__entry->gfp_flags))
>  );
>  
>  TRACE_EVENT(kmem_cache_alloc,
> @@ -67,12 +94,12 @@ 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=%08x",
> +	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,
> -		__entry->gfp_flags)
> +		show_gfp_flags(__entry->gfp_flags))
>  );
>  
>  TRACE_EVENT(kmalloc_node,
> @@ -104,12 +131,12 @@ TRACE_EVENT(kmalloc_node,
>  		__entry->node		= node;
>  	),
>  
> -	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%08x node=%d",
> +	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,
> -		__entry->gfp_flags,
> +		show_gfp_flags(__entry->gfp_flags),
>  		__entry->node)
>  );
>  
> @@ -142,12 +169,12 @@ TRACE_EVENT(kmem_cache_alloc_node,
>  		__entry->node		= node;
>  	),
>  
> -	TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%08x node=%d",
> +	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,
> -		__entry->gfp_flags,
> +		show_gfp_flags(__entry->gfp_flags),
>  		__entry->node)
>  );
>  
> -- 
> 1.6.2.4
> 
> -- 

Re: [PATCH 3/3] tracing: add flag output for kmem events

[Steven Rostedt]

On Fri, 15 May 2009, Frederic Weisbecker wrote:

> On Fri, May 15, 2009 at 05:03:45PM -0400, Steven Rostedt wrote:
> > From: Steven Rostedt <srostedt@redhat.com>
> > 
> > This patch changes the output for gfp_flags from being a simple hex value
> > to the actual names.
> > 
> >   gfp_flags=GFP_ATOMIC  instead of gfp_flags=00000020
> > 
> > And even
> > 
> >   gfp_flags=GFP_KERNEL instead of gfp_flags=000000d0
> > 
> > [ Impact: more human readable output from tracer ]
> > 
> > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> 
> 
> Nice!
> 
> 
> > ---
> >  include/trace/events/kmem.h |   43 +++++++++++++++++++++++++++++++++++--------
> >  1 files changed, 35 insertions(+), 8 deletions(-)
> > 
> > diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
> > index c22c42f..9b3886b 100644
> > --- a/include/trace/events/kmem.h
> > +++ b/include/trace/events/kmem.h
> > @@ -7,6 +7,33 @@
> >  #undef TRACE_SYSTEM
> >  #define TRACE_SYSTEM kmem
> >  
> > +#define show_gfp_flags(flags)						\
> > +	(flags) ? __print_flags(flags, "|",				\
> > +	(unsigned long)GFP_KERNEL,		"GFP_KERNEL",		\
> > +	(unsigned long)GFP_NOFS,		"GFP_NOFS",		\
> > +	(unsigned long)GFP_TEMPORARY,		"GFP_TEMPORARY",	\
> > +	(unsigned long)GFP_USER,		"GFP_USER",		\
> 
> 
> Because you clear the mask value after finding out a matching mask
> string, you should sort the masks from the highest number of bits
> to the lowest.
> 
> GFP_USER should be placed before GFP_KERNEL otherwise it will always be
> eaten.
> Instead of GFP_USER, you will get:
> 
> GFP_KERNEL | __GFP_HARDWALL

Ug, I was thinking the code only printed the mask if the mask matched 
fully.

> 
> 
> > +	(unsigned long)GFP_HIGHUSER,		"GFP_HIGHUSER",		\
> 
> 
> Ditto, it should be placed before GFP_USER otherwise you will get:
> 
> GFP_USER | __GFP_HIGHMEM
> 
> 
> > +	(unsigned long)GFP_HIGHUSER_MOVABLE,	"GFP_HIGHUSER_MOVABLE",	\
> 
> And this one before HIGH_USER otherwise:
> 
> GFP_HIGHUSER__GFP_MOVABLE

Anyway, I thought I did sort it out, but I did not realize that some masks 
have masks within. I need more sleep.

Will fix in take two. Still waiting for comments from the MM folks.

-- Steve

Re: [PATCH 3/3] tracing: add flag output for kmem events

[Eduard - Gabriel Munteanu]

On Fri, May 15, 2009 at 05:03:45PM -0400, Steven Rostedt wrote:
> From: Steven Rostedt <srostedt@redhat.com>
> 
> This patch changes the output for gfp_flags from being a simple hex value
> to the actual names.
> 
>   gfp_flags=GFP_ATOMIC  instead of gfp_flags=00000020
> 
> And even
> 
>   gfp_flags=GFP_KERNEL instead of gfp_flags=000000d0
> 
> [ Impact: more human readable output from tracer ]
> 
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  include/trace/events/kmem.h |   43 +++++++++++++++++++++++++++++++++++--------
>  1 files changed, 35 insertions(+), 8 deletions(-)

As long as it doesn't touch (and I see it doesn't) the raw kmemtrace
output for kmemtrace-user, I'm okay with this sort of changes.

Acked-by: Eduard - Gabriel Munteanu <eduard.munteanu@linux360.ro>

Re: [PATCH 3/3] tracing: add flag output for kmem events

[Steven Rostedt]

On Sat, 16 May 2009, Eduard - Gabriel Munteanu wrote:

> On Fri, May 15, 2009 at 05:03:45PM -0400, Steven Rostedt wrote:
> > From: Steven Rostedt <srostedt@redhat.com>
> > 
> > This patch changes the output for gfp_flags from being a simple hex value
> > to the actual names.
> > 
> >   gfp_flags=GFP_ATOMIC  instead of gfp_flags=00000020
> > 
> > And even
> > 
> >   gfp_flags=GFP_KERNEL instead of gfp_flags=000000d0
> > 
> > [ Impact: more human readable output from tracer ]
> > 
> > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> > ---
> >  include/trace/events/kmem.h |   43 +++++++++++++++++++++++++++++++++++--------
> >  1 files changed, 35 insertions(+), 8 deletions(-)
> 
> As long as it doesn't touch (and I see it doesn't) the raw kmemtrace
> output for kmemtrace-user, I'm okay with this sort of changes.
> 
> Acked-by: Eduard - Gabriel Munteanu <eduard.munteanu@linux360.ro>

Thanks!

I'll add you Ack to my next spin.

-- Steve