Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace

From: Chunyu Hu
Date: Tue Jun 28 2016 - 04:03:28 EST


Hello,

----- Original Message -----
> From: "Namhyung Kim" <namhyung@xxxxxxxxx>
> To: "Chunyu Hu" <chuhu@xxxxxxxxxx>
> Cc: "Steven Rostedt" <rostedt@xxxxxxxxxxx>, "LKML" <linux-kernel@xxxxxxxxxxxxxxx>
> Sent: Tuesday, June 28, 2016 1:20:02 PM
> Subject: Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace
>
> Hello,
>
> On Fri, Jun 24, 2016 at 7:55 PM, Chunyu Hu <chuhu@xxxxxxxxxx> wrote:
> > latency tracers(wakeup, wakeup_rt, wakeup_dl, irqsoff) can use the
> > function_graph trace when display_graph trace option is set by user
> > via tracefs. And currently the set_graph_notrace filter is not fully
> > supported in latency tracers, only the graph_ret event can be filtered,
> > the graph_ent events will always be submitted to the trace ring buffer
> > without respecting to the filter.
> >
> > The issue is that the submitted graph_entry event that matches the
> > filter can be assigned with a negative depth(minuts FTRACE_NOTRACE_DEPTH)
> > which will be used as the array index of fgraph_cpu_data when printing
> > trace entries, as a result, an oops can be hit when accessing the array.
> >
> > Fully supporting the set_graph_notrace filter in latency tracers can
> > avoid this oops and provide a small enhancement for these tracers at
> > the same time.
> >
> > To reproduce the oops:
> > echo 1 > options/display_graph
> > echo schedule > set_graph_notrace
> > echo wakeup > current_tracer
> > cat trace (several times)
>
> I'm unabled to reproduce the oops even after running 'cat trace' multiple
> times.

Thanks for attention. It needs about three trace entries after the graph_entry
of the filtered function, and the entries are all the sub call of the filtered
function. As tracing_max_latency will be set to the last
latency value, and only entries with larger latency can be submitted. So
looks like i missed the reset of the tracing_max_latency. After experiments,
I wrote a small script, hope it can show something on your machine.

set -x
debugfs=/sys/kernel/debug
tracing=/sys/kernel/debug/tracing/

grep debugfs /proc/mounts || mount -t debugfs d $debugfs

echo nop > $tracing/current_tracer
echo 1 > $tracing/options/display-graph
echo schedule > $tracing/set_graph_notrace
echo wakeup > $tracing/current_tracer

for i in $(seq 1 100); do
for i in $(seq 1 20); do
echo 1 > $tracing/tracing_max_latency
cat $tracing/trace > /dev/null
done
done


> Anyway, the patch looks good to me.
>
> Acked-by: Namhyung Kim <namhyung@xxxxxxxxxx>
>
> Thanks,
> Namhyung
>
>
> >
> > Signed-off-by: Chunyu Hu <chuhu@xxxxxxxxxx>
> > ---
> > kernel/trace/trace_irqsoff.c | 6 ++++++
> > kernel/trace/trace_sched_wakeup.c | 6 ++++++
> > 2 files changed, 12 insertions(+)
> >
> > diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> > index 03cdff8..a4ed46a 100644
> > --- a/kernel/trace/trace_irqsoff.c
> > +++ b/kernel/trace/trace_irqsoff.c
> > @@ -175,6 +175,12 @@ static int irqsoff_graph_entry(struct ftrace_graph_ent
> > *trace)
> > int ret;
> > int pc;
> >
> > + if (trace->depth < 0)
> > + return 0;
> > +
> > + if (ftrace_graph_notrace_addr(trace->func))
> > + return 1;
> > +
> > if (!func_prolog_dec(tr, &data, &flags))
> > return 0;
> >
> > diff --git a/kernel/trace/trace_sched_wakeup.c
> > b/kernel/trace/trace_sched_wakeup.c
> > index 9d4399b..e54fff7 100644
> > --- a/kernel/trace/trace_sched_wakeup.c
> > +++ b/kernel/trace/trace_sched_wakeup.c
> > @@ -239,6 +239,12 @@ static int wakeup_graph_entry(struct ftrace_graph_ent
> > *trace)
> > unsigned long flags;
> > int pc, ret = 0;
> >
> > + if (trace->depth < 0)
> > + return 0;
> > +
> > + if (ftrace_graph_notrace_addr(trace->func))
> > + return 1;
> > +
> > if (!func_prolog_preempt_disable(tr, &data, &pc))
> > return 0;
> >
> > --
> > 1.8.3.1
> >
>

--
Regards,
Chunyu Hu