[PATCH] tracing - fix function graph trace to properly skip records

[PATCH] tracing - fix function graph trace to properly skip records

[Jiri Olsa]

Hi,

there's a case where the graph tracer might get confused and displays
"{}" brackets in a wrong way.

Sorry for long description, but I found no better way to 
describe the issue.. ;)


As the function_graph tracer goes through the trace entries (using "trace" file)
it keeps pointer to the current record and the next one:

current ->  func1 ENTRY
   next ->  func2 ENTRY
            func2 RETURN
            func1 RETURN

If it spots adjacent ENTRY and RETURN trace entries of the same function
and pid, it displays the "func2();" trace

            func1 ENTRY
current ->  func2 ENTRY 
   next ->  func2 RETURN
            func1 RETURN

and moves the next trace entry pointer behind the RETURN entry

            func1 ENTRY
current ->  func2 ENTRY 
            func2 RETURN
   next ->  func1 RETURN

so the next record peek will skip the RETURN entry and continue with
whatever is next.

It works ok but for one case. 

If the "func2()" trace does not make it to the seq_file read buffer, it needs
to be processed again in the next read.  And here comes the issue: 
the next read will see following pointers setup for func2 processing:

            func1 ENTRY
current ->  func2 ENTRY 
            func2 RETURN
   next ->  func1 RETURN

which will turn to displaying the func2 entry like: "func2() {", since the
next entry is not RETURN of the same type.  Generaly it is whatever entry 
that follows, but definitelly not the RETURN entry of the same function.

Following patch fixes the issue by skipping the entry in the last moment,
bypassing the issue to happen during the sequential reads.

wbr,
jirka


NOTE:

AFAIK patch does not affect "trace_pipe" handling, since the change is
on the ring_buffer_iter level. However the "trace_pipe" suffers from
the same issue -> when the read buffer is filled up, the current trace
entry is not copied to it. Following read will continue with next entry.
It might be harder to fix this, since "trace_pipe" in order to see next
record has to eat the current one... 

I'll look at possible solution, but any ideas are welcome.. :)



Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 include/linux/ftrace_event.h         |    1 +
 kernel/trace/trace.c                 |   29 +++++++++++++++++++++++++++++
 kernel/trace/trace_functions_graph.c |    2 +-
 3 files changed, 31 insertions(+), 1 deletions(-)

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index d117704..7b07ad2 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -53,6 +53,7 @@ struct trace_iterator {
 	struct mutex		mutex;
 	struct ring_buffer_iter	*buffer_iter[NR_CPUS];
 	unsigned long		iter_flags;
+	bool			skip_entry;
 
 	/* The below is zeroed out in pipe_read */
 	struct trace_seq	seq;
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 026e715..b8032b4 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1490,9 +1490,35 @@ struct trace_entry *trace_find_next_entry(struct trace_iterator *iter,
 	return __find_next_entry(iter, ent_cpu, ent_ts);
 }
 
+/*
+ * Move the head pointer one trace entry forward.
+ *
+ * Used currently by the function graph trace. It needs to move across
+ * the trace "RET record" in case of adjacent ENTRY and RET records,
+ * in order to display correctly the "();" or "{}" brackets.
+ */
+static void skip_entry(struct trace_iterator *iter)
+{
+	struct ring_buffer_iter *ring_iter;
+
+	/* Don't allow ftrace to trace into the ring buffers */
+	ftrace_disable_cpu();
+
+	ring_iter = iter->buffer_iter[iter->cpu];
+	if (ring_iter)
+		ring_buffer_read(ring_iter, NULL);
+
+	iter->skip_entry = false;
+
+	ftrace_enable_cpu();
+}
+
 /* Find the next real entry, and increment the iterator to the next entry */
 static void *find_next_entry_inc(struct trace_iterator *iter)
 {
+	if (iter->skip_entry)
+		skip_entry(iter);
+
 	iter->ent = __find_next_entry(iter, &iter->cpu, &iter->ts);
 
 	if (iter->ent)
@@ -1594,6 +1620,9 @@ static void *s_start(struct seq_file *m, loff_t *pos)
 
 	atomic_inc(&trace_record_cmdline_disabled);
 
+	/* Starting new read, no record skipping is desirable. */
+	iter->skip_entry = false;
+
 	if (*pos != iter->pos) {
 		iter->ent = NULL;
 		iter->cpu = 0;
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 45e6c01..1cf80f2 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -465,7 +465,7 @@ get_return_for_leaf(struct trace_iterator *iter,
 
 	/* this is a leaf, now advance the iterator */
 	if (ring_iter)
-		ring_buffer_read(ring_iter, NULL);
+		iter->skip_entry = true;
 
 	return next;
 }

Re: [PATCH] tracing - fix function graph trace to properly skip records

[Frederic Weisbecker]

On Tue, Oct 20, 2009 at 06:00:39PM +0200, Jiri Olsa wrote:
> Hi,
> 
> there's a case where the graph tracer might get confused and displays
> "{}" brackets in a wrong way.
> 
> Sorry for long description, but I found no better way to 
> describe the issue.. ;)
> 


I rather consider this changelog as nicely decribing the issue.

 
> It works ok but for one case. 
> 
> If the "func2()" trace does not make it to the seq_file read buffer, it needs
> to be processed again in the next read.  And here comes the issue: 
> the next read will see following pointers setup for func2 processing:
> 
>             func1 ENTRY
> current ->  func2 ENTRY 
>             func2 RETURN
>    next ->  func1 RETURN
> 
> which will turn to displaying the func2 entry like: "func2() {", since the
> next entry is not RETURN of the same type.  Generaly it is whatever entry 
> that follows, but definitelly not the RETURN entry of the same function.



I see... So that happens when the previous seq write failed, we already have
consume func2 RETURN and because we returned TRACE_PARTIAL_LINE, we reprocess
func2 ENTRY, but the next entry pointer have moved ahead already...

Nice catch!

 
> Following patch fixes the issue by skipping the entry in the last moment,
> bypassing the issue to happen during the sequential reads.
>
> wbr,
> jirka
> 
> 
> NOTE:
> 
> AFAIK patch does not affect "trace_pipe" handling, since the change is
> on the ring_buffer_iter level. However the "trace_pipe" suffers from
> the same issue -> when the read buffer is filled up, the current trace
> entry is not copied to it. Following read will continue with next entry.
> It might be harder to fix this, since "trace_pipe" in order to see next
> record has to eat the current one... 
> 
> I'll look at possible solution, but any ideas are welcome.. :)
> 
> 
> 
> Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> ---
>  include/linux/ftrace_event.h         |    1 +
>  kernel/trace/trace.c                 |   29 +++++++++++++++++++++++++++++
>  kernel/trace/trace_functions_graph.c |    2 +-
>  3 files changed, 31 insertions(+), 1 deletions(-)
> 
> diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
> index d117704..7b07ad2 100644
> --- a/include/linux/ftrace_event.h
> +++ b/include/linux/ftrace_event.h
> @@ -53,6 +53,7 @@ struct trace_iterator {
>  	struct mutex		mutex;
>  	struct ring_buffer_iter	*buffer_iter[NR_CPUS];
>  	unsigned long		iter_flags;
> +	bool			skip_entry;


Instead of adding this new field to struct trace_iterator,
why not creating a new return value like TRACE_TYPE_HANDLED
but that would consume two entries instead of one?

May be TRACE_TYPE_HANDLED_2? (sorry I suck in naming).

TRACE_TYPE_HANDLED_PAIR?
TRACE_TYPE_HANDLED_COUPLE?

Re: [PATCH] tracing - fix function graph trace to properly skip records

[Frederic Weisbecker]

On Tue, Oct 20, 2009 at 07:11:54PM +0200, Frederic Weisbecker wrote:
> > NOTE:
> > 
> > AFAIK patch does not affect "trace_pipe" handling, since the change is
> > on the ring_buffer_iter level. However the "trace_pipe" suffers from
> > the same issue -> when the read buffer is filled up, the current trace
> > entry is not copied to it. Following read will continue with next entry.
> > It might be harder to fix this, since "trace_pipe" in order to see next
> > record has to eat the current one... 
> > 
> > I'll look at possible solution, but any ideas are welcome.. :)
> > 


Yeah, dealing with the ring buffer consuming mode is more tricky.
Actually I would feel more comfortable with a generic solution that
solves consuming and iter modes.

We have a private field in struct trace_iterator so I guess
we can store useful things inside.

Say we have that in the ring buffer:

f1 entry
f1 return
f2 entry

If we know we are a leaf call, we need to store a copy of the
f1 entry/f1 return couple in struct trace_iterator::private
So that we can check that on the next processing and call
print_graph_entry_leaf() directly.

What remains is the need to check the status of the last
processing. Was it TRACE_TYPE_HANLED,TRACE_TYPE_PARTIAL_LINE..?

We probably need this info in trace_iterator...

Re: [PATCH] tracing - fix function graph trace to properly skip records

[Jiri Olsa]

On Tue, Oct 20, 2009 at 07:11:54PM +0200, Frederic Weisbecker wrote:
> On Tue, Oct 20, 2009 at 06:00:39PM +0200, Jiri Olsa wrote:
> > Hi,
> > 
> > there's a case where the graph tracer might get confused and displays
> > "{}" brackets in a wrong way.
> > 
> > Sorry for long description, but I found no better way to 
> > describe the issue.. ;)
> > 
> 
> 
> I rather consider this changelog as nicely decribing the issue.
> 
>  
> > It works ok but for one case. 
> > 
> > If the "func2()" trace does not make it to the seq_file read buffer, it needs
> > to be processed again in the next read.  And here comes the issue: 
> > the next read will see following pointers setup for func2 processing:
> > 
> >             func1 ENTRY
> > current ->  func2 ENTRY 
> >             func2 RETURN
> >    next ->  func1 RETURN
> > 
> > which will turn to displaying the func2 entry like: "func2() {", since the
> > next entry is not RETURN of the same type.  Generaly it is whatever entry 
> > that follows, but definitelly not the RETURN entry of the same function.
> 
> 
> 
> I see... So that happens when the previous seq write failed, we already have
> consume func2 RETURN and because we returned TRACE_PARTIAL_LINE, we reprocess
> func2 ENTRY, but the next entry pointer have moved ahead already...
> 
> Nice catch!
> 
>  
> > Following patch fixes the issue by skipping the entry in the last moment,
> > bypassing the issue to happen during the sequential reads.
> >
> > wbr,
> > jirka
> > 
> > 
> > NOTE:
> > 
> > AFAIK patch does not affect "trace_pipe" handling, since the change is
> > on the ring_buffer_iter level. However the "trace_pipe" suffers from
> > the same issue -> when the read buffer is filled up, the current trace
> > entry is not copied to it. Following read will continue with next entry.
> > It might be harder to fix this, since "trace_pipe" in order to see next
> > record has to eat the current one... 
> > 
> > I'll look at possible solution, but any ideas are welcome.. :)
> > 
> > 
> > 
> > Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> > ---
> >  include/linux/ftrace_event.h         |    1 +
> >  kernel/trace/trace.c                 |   29 +++++++++++++++++++++++++++++
> >  kernel/trace/trace_functions_graph.c |    2 +-
> >  3 files changed, 31 insertions(+), 1 deletions(-)
> > 
> > diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
> > index d117704..7b07ad2 100644
> > --- a/include/linux/ftrace_event.h
> > +++ b/include/linux/ftrace_event.h
> > @@ -53,6 +53,7 @@ struct trace_iterator {
> >  	struct mutex		mutex;
> >  	struct ring_buffer_iter	*buffer_iter[NR_CPUS];
> >  	unsigned long		iter_flags;
> > +	bool			skip_entry;
> 
> 
> Instead of adding this new field to struct trace_iterator,
> why not creating a new return value like TRACE_TYPE_HANDLED
> but that would consume two entries instead of one?
> 
> May be TRACE_TYPE_HANDLED_2? (sorry I suck in naming).
> 
> TRACE_TYPE_HANDLED_PAIR?
> TRACE_TYPE_HANDLED_COUPLE?
> 

I think we need to hold the state of crossing 2 entries, since the
issue happens when the seq_write fails, so there will be next read
operation, which needs to know what to do.

jirka

Re: [PATCH] tracing - fix function graph trace to properly skip records

[Jiri Olsa]

On Tue, Oct 20, 2009 at 07:33:40PM +0200, Frederic Weisbecker wrote:
> On Tue, Oct 20, 2009 at 07:11:54PM +0200, Frederic Weisbecker wrote:
> > > NOTE:
> > > 
> > > AFAIK patch does not affect "trace_pipe" handling, since the change is
> > > on the ring_buffer_iter level. However the "trace_pipe" suffers from
> > > the same issue -> when the read buffer is filled up, the current trace
> > > entry is not copied to it. Following read will continue with next entry.
> > > It might be harder to fix this, since "trace_pipe" in order to see next
> > > record has to eat the current one... 
> > > 
> > > I'll look at possible solution, but any ideas are welcome.. :)
> > > 
> 
> 
> Yeah, dealing with the ring buffer consuming mode is more tricky.
> Actually I would feel more comfortable with a generic solution that
> solves consuming and iter modes.
> 
> We have a private field in struct trace_iterator so I guess
> we can store useful things inside.
> 
> Say we have that in the ring buffer:
> 
> f1 entry
> f1 return
> f2 entry
> 
> If we know we are a leaf call, we need to store a copy of the
> f1 entry/f1 return couple in struct trace_iterator::private
> So that we can check that on the next processing and call
> print_graph_entry_leaf() directly.
> 
> What remains is the need to check the status of the last
> processing. Was it TRACE_TYPE_HANLED,TRACE_TYPE_PARTIAL_LINE..?
> 
> We probably need this info in trace_iterator...

I like this one, I think it could be done for both iterator and
consuming mode hence ending up with one way of handling this.

I'll repost soon hopefully... :)

thanks,
jirka