trace: fix multiple use of __print_flags and __print_symbolic

trace: fix multiple use of __print_flags and __print_symbolic

[Steven Whitehouse]

When using multiple calls to __print_symbolic and __print_flags in
the same tracer, I noticed that the output was incorrect. I think
the following patch is the correct fix (it works for me) but please
check it carefully since I'm not that familiar with this code,
and I may well have made a mistake somewhere.

The patch is vs. the latest -tip tree which doesn't yet seem to
contain the EXPORT_SYMBOL() fix that I sent earlier.

Signed-off-by: Steven Whitehouse <swhiteho@redhat.com>


diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index c12d95d..ac6ced1 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -222,10 +222,9 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 {
 	unsigned long mask;
 	const char *str;
+	const char *ret = p->buffer + p->len;
 	int i;
 
-	trace_seq_init(p);
-
 	for (i = 0;  flag_array[i].name && flags; i++) {
 
 		mask = flag_array[i].mask;
@@ -248,7 +247,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 
 	trace_seq_putc(p, 0);
 
-	return p->buffer;
+	return ret;
 }
 
 const char *
@@ -256,8 +255,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 			 const struct trace_print_flags *symbol_array)
 {
 	int i;
-
-	trace_seq_init(p);
+	const char *ret = p->buffer + p->len;
 
 	for (i = 0;  symbol_array[i].name; i++) {
 
@@ -273,7 +271,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 		
 	trace_seq_putc(p, 0);
 
-	return p->buffer;
+	return ret;
 }
 
 #ifdef CONFIG_KRETPROBES

Re: trace: fix multiple use of __print_flags and __print_symbolic

[Li Zefan]

Steven Whitehouse wrote:
> When using multiple calls to __print_symbolic and __print_flags in
> the same tracer, I noticed that the output was incorrect. I think
> the following patch is the correct fix (it works for me) but please
> check it carefully since I'm not that familiar with this code,
> and I may well have made a mistake somewhere.
> 

I don't see there's bug in __print_symbolic() or __print_flags():

enum print_line_t
ftrace_raw_output_##call(struct trace_iterator *iter, int flags)
{
	...
	p = &get_cpu_var(ftrace_event_seq);
	/* here we call ftrace_print_flags_seq(p, ...) */
	ret = trace_seq_printf(s, #call ": " print);
	put_cpu();
	...
}

ftrace_event_seq is percpu data, and here is used with preempt-disabled,
so there shouldn't be problem of concurrent accessing.


> The patch is vs. the latest -tip tree which doesn't yet seem to
> contain the EXPORT_SYMBOL() fix that I sent earlier.
> 
> Signed-off-by: Steven Whitehouse <swhiteho@redhat.com>
> 
> 
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index c12d95d..ac6ced1 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -222,10 +222,9 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
>  {
>  	unsigned long mask;
>  	const char *str;
> +	const char *ret = p->buffer + p->len;
>  	int i;
>  
> -	trace_seq_init(p);
> -

This is wrong. Without reseting, the seq buffer will quickly be filled.

>  	for (i = 0;  flag_array[i].name && flags; i++) {
>  
>  		mask = flag_array[i].mask;
> @@ -248,7 +247,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
>  
>  	trace_seq_putc(p, 0);
>  
> -	return p->buffer;
> +	return ret;
>  }
>  
>  const char *
> @@ -256,8 +255,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
>  			 const struct trace_print_flags *symbol_array)
>  {
>  	int i;
> -
> -	trace_seq_init(p);
> +	const char *ret = p->buffer + p->len;
>  
>  	for (i = 0;  symbol_array[i].name; i++) {
>  
> @@ -273,7 +271,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
>  		
>  	trace_seq_putc(p, 0);
>  
> -	return p->buffer;
> +	return ret;
>  }
>  
>  #ifdef CONFIG_KRETPROBES
> 

Re: trace: fix multiple use of __print_flags and __print_symbolic

[Steven Whitehouse]

Hi,

On Wed, 2009-06-03 at 17:50 +0800, Li Zefan wrote:
> Steven Whitehouse wrote:
> > When using multiple calls to __print_symbolic and __print_flags in
> > the same tracer, I noticed that the output was incorrect. I think
> > the following patch is the correct fix (it works for me) but please
> > check it carefully since I'm not that familiar with this code,
> > and I may well have made a mistake somewhere.
> > 
> 
> I don't see there's bug in __print_symbolic() or __print_flags():
> 
> enum print_line_t
> ftrace_raw_output_##call(struct trace_iterator *iter, int flags)
> {
> 	...
> 	p = &get_cpu_var(ftrace_event_seq);
> 	/* here we call ftrace_print_flags_seq(p, ...) */
> 	ret = trace_seq_printf(s, #call ": " print);
> 	put_cpu();
> 	...
> }
> 
> ftrace_event_seq is percpu data, and here is used with preempt-disabled,
> so there shouldn't be problem of concurrent accessing.
> 
> 
Well without the "fix" every call to __print_symbolic and __print_flags
seems to result in printing the same string, so with:


        TP_printk("%u.%u glock %d:%lld state %s => %s tgt:%s dmt:%s flags:%s",
                  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->gltype,
                 (unsigned long long)__entry->glnum,
                  glock_trace_name(__entry->cur_state),
                  glock_trace_name(__entry->new_state),
                  glock_trace_name(__entry->tgt_state),
                  glock_trace_name(__entry->dmt_state),
                  show_glock_flags(__entry->flags))
and

#define dlm_state_name(nn) { DLM_LOCK_##nn, #nn }
#define glock_trace_name(x) __print_symbolic(x,         \
                            dlm_state_name(IV),         \
                            dlm_state_name(NL),         \
                            dlm_state_name(CR),         \
                            dlm_state_name(CW),         \
                            dlm_state_name(PR),         \
                            dlm_state_name(PW),         \
                            dlm_state_name(EX))

#define show_glock_flags(flags) __print_flags(flags, "",        \
        {(1UL << GLF_LOCK),                     "l" },          \
        {(1UL << GLF_DEMOTE),                   "D" },          \
        {(1UL << GLF_PENDING_DEMOTE),           "d" },          \
        {(1UL << GLF_DEMOTE_IN_PROGRESS),       "p" },          \
        {(1UL << GLF_DIRTY),                    "y" },          \
        {(1UL << GLF_LFLUSH),                   "f" },          \
        {(1UL << GLF_INVALIDATE_IN_PROGRESS),   "i" },          \
        {(1UL << GLF_REPLY_PENDING),            "r" },          \
        {(1UL << GLF_INITIAL),                  "I" },          \
        {(1UL << GLF_FROZEN),                   "F" })

every call to glock_trace_name and the call to glock_show_flags resulted in the
string "EX" when I was testing it. With the previous version of my patch where
I did the constant to string conversion with my own function, this didn't happen.
Applying the patch corrects the output, so there is a bug here I think, even if I've
not found the correct fix for it,

Steve.

Re: trace: fix multiple use of __print_flags and __print_symbolic

[Steven Whitehouse]

Hi

On Wed, 2009-06-03 at 17:50 +0800, Li Zefan wrote:
> Steven Whitehouse wrote:
> > When using multiple calls to __print_symbolic and __print_flags in
> > the same tracer, I noticed that the output was incorrect. I think
> > the following patch is the correct fix (it works for me) but please
> > check it carefully since I'm not that familiar with this code,
> > and I may well have made a mistake somewhere.
> > 
> 
> I don't see there's bug in __print_symbolic() or __print_flags():
> 
> enum print_line_t
> ftrace_raw_output_##call(struct trace_iterator *iter, int flags)
> {
> 	...
> 	p = &get_cpu_var(ftrace_event_seq);
> 	/* here we call ftrace_print_flags_seq(p, ...) */
> 	ret = trace_seq_printf(s, #call ": " print);
> 	put_cpu();
> 	...
> }
> 
> ftrace_event_seq is percpu data, and here is used with preempt-disabled,
> so there shouldn't be problem of concurrent accessing.
> 
I've double checked this now, and I'm seeing results like:


glock_workqueue-2482  [001]   809.956985: gfs2_glock_state_change: 8.7 glock 2:33119 state EX => EX tgt:EX dmt:EX flags:EX
glock_workqueue-2482  [001]   809.957155: gfs2_glock_state_change: 8.7 glock 2:33119 state NL => NL tgt:NL dmt:NL flags:NL
glock_workqueue-2482  [001]   809.959473: gfs2_glock_state_change: 8.7 glock 1:2 state NL => NL tgt:NL dmt:NL flags:NL
glock_workqueue-2482  [001]   809.959556: gfs2_glock_state_change: 8.7 glock 2:33119 state EX => EX tgt:EX dmt:EX flags:EX
glock_workqueue-2482  [001]   810.008773: gfs2_glock_state_change: 8.7 glock 1:0 state EX => EX tgt:EX dmt:EX flags:EX


without the patch, which is clearly wrong,

Steve.

Re: trace: fix multiple use of __print_flags and __print_symbolic

[Steven Rostedt]

On Wed, 3 Jun 2009, Steven Whitehouse wrote:

> Hi
> 
> On Wed, 2009-06-03 at 17:50 +0800, Li Zefan wrote:
> > Steven Whitehouse wrote:
> > > When using multiple calls to __print_symbolic and __print_flags in
> > > the same tracer, I noticed that the output was incorrect. I think
> > > the following patch is the correct fix (it works for me) but please
> > > check it carefully since I'm not that familiar with this code,
> > > and I may well have made a mistake somewhere.
> > > 
> > 
> > I don't see there's bug in __print_symbolic() or __print_flags():
> > 
> > enum print_line_t
> > ftrace_raw_output_##call(struct trace_iterator *iter, int flags)
> > {
> > 	...
> > 	p = &get_cpu_var(ftrace_event_seq);
> > 	/* here we call ftrace_print_flags_seq(p, ...) */
> > 	ret = trace_seq_printf(s, #call ": " print);
> > 	put_cpu();
> > 	...
> > }
> > 
> > ftrace_event_seq is percpu data, and here is used with preempt-disabled,
> > so there shouldn't be problem of concurrent accessing.
> > 
> I've double checked this now, and I'm seeing results like:
> 
> 
> glock_workqueue-2482  [001]   809.956985: gfs2_glock_state_change: 8.7 glock 2:33119 state EX => EX tgt:EX dmt:EX flags:EX
> glock_workqueue-2482  [001]   809.957155: gfs2_glock_state_change: 8.7 glock 2:33119 state NL => NL tgt:NL dmt:NL flags:NL
> glock_workqueue-2482  [001]   809.959473: gfs2_glock_state_change: 8.7 glock 1:2 state NL => NL tgt:NL dmt:NL flags:NL
> glock_workqueue-2482  [001]   809.959556: gfs2_glock_state_change: 8.7 glock 2:33119 state EX => EX tgt:EX dmt:EX flags:EX
> glock_workqueue-2482  [001]   810.008773: gfs2_glock_state_change: 8.7 glock 1:0 state EX => EX tgt:EX dmt:EX flags:EX
> 
> 
> without the patch, which is clearly wrong,

Ah, I did not account for having multiple instances of print_symbol of 
print_flags in a single print. Your patch is partialy correct. Add a:

	trace_seq_init(p);

after the "p = &get_cpu_var(ftrace_event_seq);".

-- Steve

trace: fix multiple use of __print_flags and __print_symbolic

[Steven Whitehouse]

Here is an updated patch to include the extra call to
trace_seq_init() as requested. This is vs. the latest
-tip tree and fixes the use of multiple __print_flags
and __print_symbolic in a single tracer. Also tested
to ensure its working now:

mount.gfs2-2534  [000]   235.850587: gfs2_glock_queue: 8.7 glock 1:2 dequeue PR
mount.gfs2-2534  [000]   235.850591: gfs2_demote_rq: 8.7 glock 1:0 demote EX to NL flags:DI
mount.gfs2-2534  [000]   235.850591: gfs2_glock_queue: 8.7 glock 1:0 dequeue EX
glock_workqueue-2529  [000]   235.850666: gfs2_glock_state_change: 8.7 glock 1:0 state EX => NL tgt:NL dmt:NL flags:lDpI
glock_workqueue-2529  [000]   235.850672: gfs2_glock_put: 8.7 glock 1:0 state NL => IV flags:I

Signed-off-by: Steven Whitehouse <swhiteho@redhat.com>

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index b4ec83a..1c58f05 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -100,6 +100,7 @@
  *	field = (typeof(field))entry;
  *
  *	p = get_cpu_var(ftrace_event_seq);
+ *	trace_seq_init(p);
  *	ret = trace_seq_printf(s, <TP_printk> "\n");
  *	put_cpu();
  *	if (!ret)
@@ -159,6 +160,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 	field = (typeof(field))entry;					\
 									\
 	p = &get_cpu_var(ftrace_event_seq);				\
+	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, #call ": " print);			\
 	put_cpu();							\
 	if (!ret)							\
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index c12d95d..ac6ced1 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -222,10 +222,9 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 {
 	unsigned long mask;
 	const char *str;
+	const char *ret = p->buffer + p->len;
 	int i;
 
-	trace_seq_init(p);
-
 	for (i = 0;  flag_array[i].name && flags; i++) {
 
 		mask = flag_array[i].mask;
@@ -248,7 +247,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 
 	trace_seq_putc(p, 0);
 
-	return p->buffer;
+	return ret;
 }
 
 const char *
@@ -256,8 +255,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 			 const struct trace_print_flags *symbol_array)
 {
 	int i;
-
-	trace_seq_init(p);
+	const char *ret = p->buffer + p->len;
 
 	for (i = 0;  symbol_array[i].name; i++) {
 
@@ -273,7 +271,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 		
 	trace_seq_putc(p, 0);
 
-	return p->buffer;
+	return ret;
 }
 
 #ifdef CONFIG_KRETPROBES

[tip:tracing/core] tracing: fix multiple use of __print_flags and __print_symbolic

[tip-bot for Steven Whitehouse]

Commit-ID:  56d8bd3f0b98972312cad683947ec90b21011199
Gitweb:     http://git.kernel.org/tip/56d8bd3f0b98972312cad683947ec90b21011199
Author:     Steven Whitehouse <swhiteho@redhat.com>
AuthorDate: Wed, 3 Jun 2009 14:52:03 +0100
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Wed, 3 Jun 2009 10:29:48 -0400

tracing: fix multiple use of __print_flags and __print_symbolic

Here is an updated patch to include the extra call to
trace_seq_init() as requested. This is vs. the latest
-tip tree and fixes the use of multiple __print_flags
and __print_symbolic in a single tracer. Also tested
to ensure its working now:

mount.gfs2-2534  [000]   235.850587: gfs2_glock_queue: 8.7 glock 1:2 dequeue PR
mount.gfs2-2534  [000]   235.850591: gfs2_demote_rq: 8.7 glock 1:0 demote EX to NL flags:DI
mount.gfs2-2534  [000]   235.850591: gfs2_glock_queue: 8.7 glock 1:0 dequeue EX
glock_workqueue-2529  [000]   235.850666: gfs2_glock_state_change: 8.7 glock 1:0 state EX => NL tgt:NL dmt:NL flags:lDpI
glock_workqueue-2529  [000]   235.850672: gfs2_glock_put: 8.7 glock 1:0 state NL => IV flags:I

Signed-off-by: Steven Whitehouse <swhiteho@redhat.com>
LKML-Reference: <1244037123.29604.603.camel@localhost.localdomain>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>


---
 include/trace/ftrace.h      |    2 ++
 kernel/trace/trace_output.c |   10 ++++------
 2 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index b5478da..40ede4d 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -104,6 +104,7 @@
  *	field = (typeof(field))entry;
  *
  *	p = get_cpu_var(ftrace_event_seq);
+ *	trace_seq_init(p);
  *	ret = trace_seq_printf(s, <TP_printk> "\n");
  *	put_cpu();
  *	if (!ret)
@@ -167,6 +168,7 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 	field = (typeof(field))entry;					\
 									\
 	p = &get_cpu_var(ftrace_event_seq);				\
+	trace_seq_init(p);						\
 	ret = trace_seq_printf(s, #call ": " print);			\
 	put_cpu();							\
 	if (!ret)							\
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 8dadbbb..8afeea4 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -223,10 +223,9 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 {
 	unsigned long mask;
 	const char *str;
+	const char *ret = p->buffer + p->len;
 	int i;
 
-	trace_seq_init(p);
-
 	for (i = 0;  flag_array[i].name && flags; i++) {
 
 		mask = flag_array[i].mask;
@@ -249,7 +248,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 
 	trace_seq_putc(p, 0);
 
-	return p->buffer;
+	return ret;
 }
 EXPORT_SYMBOL(ftrace_print_flags_seq);
 
@@ -258,8 +257,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 			 const struct trace_print_flags *symbol_array)
 {
 	int i;
-
-	trace_seq_init(p);
+	const char *ret = p->buffer + p->len;
 
 	for (i = 0;  symbol_array[i].name; i++) {
 
@@ -275,7 +273,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 		
 	trace_seq_putc(p, 0);
 
-	return p->buffer;
+	return ret;
 }
 EXPORT_SYMBOL(ftrace_print_symbols_seq);