Messages in this thread | | | Date | Fri, 4 Dec 2009 11:46:16 +0100 | From | Jiri Olsa <> | Subject | Re: [PATCH] tracing - fix function graph trace to properly display failed entries |
| |
On Wed, Nov 25, 2009 at 09:45:25AM +0100, Jiri Olsa wrote: > On Tue, Nov 24, 2009 at 10:14:36PM +0100, Frederic Weisbecker wrote: > > 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. > > sure, but it is not the trace_seq structure that overflows, it is the bare > seq_file underneath. The s_show calls "trace_print_seq": > > void trace_print_seq(struct seq_file *m, struct trace_seq *s) > { > int len = s->len >= PAGE_SIZE ? PAGE_SIZE - 1 : s->len; > > seq_write(m, s->buffer, len); > > trace_seq_init(s); > } > > it flushes the trace_seq to the seq_file and reinits the trace_seq. > But the seq_file will get filled in the end, ending up with > not displayed output in that case I described in the first email. >
hi, any feedback on this?
thanks, jirka
> > > > > > > > > > > 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. > > that should be in the trace_output.c part of the patch, > each display function set the 'failed' flag appropriatelly > > > > > > > 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. > > I can see other solution, which would need to move the look ahead > skip of the record in the 'get_return_for_leaf' function. > > jirka > > > > > > 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. > >
| |