Messages in this thread | | | Date | Mon, 21 Mar 2011 13:10:08 +0100 | From | Jiri Olsa <> | Subject | Re: [PATCHv2] tracing - avoid soft lockup in trace_pipe |
| |
On Mon, Mar 14, 2011 at 07:06:21PM +0100, Jiri Olsa wrote: > On Mon, Mar 14, 2011 at 11:20:57AM -0400, Steven Rostedt wrote: > > On Mon, 2011-03-14 at 16:07 +0100, Jiri Olsa wrote: > > > So we get back the the while loop with no data added and with > > > TRACE_TYPE_HANDLED return code, which will keep us in the loop. > > > > > > Not sure this is bug or feature :) > > > > > > > > Most bugs are features ;) > > > > honestly, I'd love to rip out all the "bin", "hex" etc formats as they > > are pretty much deprecated. > > > > But as you pointed out that this can keep us in the inner loop, we need > > to fix that. I prefer to fix it within the nop print function. Perhaps > > we need to fill in something. "type: %d", iter->ent->type ? > > sounds ok :) attaching v2 patch hi, any feedback?
thanks, jirka
> > thanks, > jirka > > > --- > running following commands: > > # enable the binary option > echo 1 > ./options/bin > # disable context info option > echo 0 > ./options/context-info > # tracing only events > echo 1 > ./events/enable > cat trace_pipe > > is causing lockup (in NON preemptive kernels) inside > tracing_read_pipe function. > > The reason are: > - bin/hex/raw output functions for events are set to > trace_nop_print function, which prints nothing and > returns TRACE_TYPE_HANDLED value > - LOST EVENT trace do not handle trace_seq overflow > > These reasons force the while loop in tracing_read_pipe > function never to break. > > The attached patch fixies handling of lost event trace, and > changes trace_nop_print to print minimal info, which is needed > for the correct tracing_read_pipe processing. > > v2 changes: > - omit the cond_resched changes by trace_nop_print changes > - WARN changed to WARN_ONCE and added info to be able > to find out the culprit > > wbr, > jirka > > > Signed-off-by: Jiri Olsa <jolsa@redhat.com> > --- > kernel/trace/trace.c | 15 ++++++++++++--- > kernel/trace/trace_output.c | 3 +++ > 2 files changed, 15 insertions(+), 3 deletions(-) > > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 9541c27..5af42f4 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -2013,9 +2013,10 @@ enum print_line_t print_trace_line(struct trace_iterator *iter) > { > enum print_line_t ret; > > - if (iter->lost_events) > - trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n", > - iter->cpu, iter->lost_events); > + if (iter->lost_events && > + !trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n", > + iter->cpu, iter->lost_events)) > + return TRACE_TYPE_PARTIAL_LINE; > > if (iter->trace && iter->trace->print_line) { > ret = iter->trace->print_line(iter); > @@ -3229,6 +3230,14 @@ waitagain: > > if (iter->seq.len >= cnt) > break; > + > + /* > + * Setting the full flag means we reached the trace_seq buffer > + * size and we should leave by partial output condition above. > + * One of the trace_seq_* functions is not used properly. > + */ > + WARN_ONCE(iter->seq.full, "full flag set for trace type %d", > + iter->ent->type); > } > trace_access_unlock(iter->cpu_file); > trace_event_read_unlock(); > diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c > index 456be90..cf535cc 100644 > --- a/kernel/trace/trace_output.c > +++ b/kernel/trace/trace_output.c > @@ -830,6 +830,9 @@ EXPORT_SYMBOL_GPL(unregister_ftrace_event); > enum print_line_t trace_nop_print(struct trace_iterator *iter, int flags, > struct trace_event *event) > { > + if (!trace_seq_printf(&iter->seq, "type: %d\n", iter->ent->type)) > + return TRACE_TYPE_PARTIAL_LINE; > + > return TRACE_TYPE_HANDLED; > } > > -- > 1.7.1 >
| |