Re: [PATCH] tracing - fix function graph trace to properly display failed entries

[Frederic Weisbecker <fweisbec@gmail.com>]

On Tue, Nov 24, 2009 at 12:14:05PM -0500, Steven Rostedt wrote:
> On Tue, 2009-11-24 at 13:57 +0100, Jiri Olsa wrote:
> > Hi,
> > 
> > there's a case where the graph tracer might get confused and omits
> > display of a single record.  This applies for both destructive
> > (trace_pipe) and nondestructive (trace) cases.
> > 
> > 
> > <issue description>
> > 
> > The issue description for nondestructive case (trace) follows:
> > 
> > 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
> 
> In the trace_pipe it may be possible to fill the trace_seq buffer if the
> buffer passed into userspace is larger than the trace_seq buffer. But
> the trace_seq buffer should never overflow on the "trace" case. If it
> is, then there's probably another bug.



Hmm, yeah in trace_pipe case we repeat until we have no space
left in trace_seq (TRACE_TYPE_PARTIAL_LINE), or until we
the user buffer is filled.

But indeed in case of trace file, we are using a seq file
so the buffer gets flushed after each entries.

Assuming the trace_seq is 4096 bytes long this is probably
enough for every function graph entries (even with headers and
interrupts), this is not something we are supposed to see in trace_seq.

I did not realized that when Jiri sent the first version of this patch.

 
> 
> > 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.
> > 
> > The destructive case (trace_pipe) suffers from the similar issue,
> > although it keeps only the current pointer.
> > 
> > </issue description>
> > 
> > 
> > The following patch propose generic solution for both cases.
> > It keeps the last read entry/return in the tracer private
> > iterator storage and keeps track of the failed output.
> > Whenever the output fails, next read will output previous
> > 'not displayed' entry before processing next entry.
> 
> Have you added tests to make sure that the trace_seq buffer is indeed
> filling up?  In the trace_pipe, this could happen when the user buffer
> gets full.
> 
> What I think you are seeing, is a buffer overflow during a run. If the
> trace buffer overflows, it will leave gaps in the trace. Those abandoned
> leaf functions are probably a result of a trace buffer wrap.
> 
> I don't thing this is the proper solution to the problem.


But I guess it doesn't happen because the function graph tracer
has too large entries, or it would do an endless loop while
reading the trace file.

It's more likely a bug somewhere in the trace_seq_* functions.

I'm going to have a look.

Thanks.