Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1430576 > unrolled thread
| Started by | Chunyu Hu <chuhu@redhat.com> |
|---|---|
| First post | 2016-06-24 13:00 +0200 |
| Last post | 2016-06-29 01:40 +0200 |
| Articles | 5 — 3 participants |
Back to article view | Back to linux.kernel
[PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace Chunyu Hu <chuhu@redhat.com> - 2016-06-24 13:00 +0200
Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace Namhyung Kim <namhyung@gmail.com> - 2016-06-28 07:30 +0200
Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace Chunyu Hu <chuhu@redhat.com> - 2016-06-28 10:10 +0200
Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace Steven Rostedt <rostedt@goodmis.org> - 2016-06-28 22:10 +0200
Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace Chunyu Hu <chuhu@redhat.com> - 2016-06-29 01:40 +0200
| From | Chunyu Hu <chuhu@redhat.com> |
|---|---|
| Date | 2016-06-24 13:00 +0200 |
| Subject | [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace |
| Message-ID | <rNx05-6Zi-9@gated-at.bofh.it> |
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) Signed-off-by: Chunyu Hu <chuhu@redhat.com> --- 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
[toc] | [next] | [standalone]
| From | Namhyung Kim <namhyung@gmail.com> |
|---|---|
| Date | 2016-06-28 07:30 +0200 |
| Message-ID | <rOTKV-2x9-7@gated-at.bofh.it> |
| In reply to | #1430576 |
Hello, On Fri, Jun 24, 2016 at 7:55 PM, Chunyu Hu <chuhu@redhat.com> 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. Anyway, the patch looks good to me. Acked-by: Namhyung Kim <namhyung@kernel.org> Thanks, Namhyung > > Signed-off-by: Chunyu Hu <chuhu@redhat.com> > --- > 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 >
[toc] | [prev] | [next] | [standalone]
| From | Chunyu Hu <chuhu@redhat.com> |
|---|---|
| Date | 2016-06-28 10:10 +0200 |
| Subject | Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace |
| Message-ID | <rOWfM-4gQ-13@gated-at.bofh.it> |
| In reply to | #1432486 |
Hello,
----- Original Message -----
> From: "Namhyung Kim" <namhyung@gmail.com>
> To: "Chunyu Hu" <chuhu@redhat.com>
> Cc: "Steven Rostedt" <rostedt@goodmis.org>, "LKML" <linux-kernel@vger.kernel.org>
> 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@redhat.com> 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@kernel.org>
>
> Thanks,
> Namhyung
>
>
> >
> > Signed-off-by: Chunyu Hu <chuhu@redhat.com>
> > ---
> > 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
[toc] | [prev] | [next] | [standalone]
| From | Steven Rostedt <rostedt@goodmis.org> |
|---|---|
| Date | 2016-06-28 22:10 +0200 |
| Subject | Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace |
| Message-ID | <rP7ux-39z-1@gated-at.bofh.it> |
| In reply to | #1432608 |
On Tue, 28 Jun 2016 04:03:12 -0400 (EDT) Chunyu Hu <chuhu@redhat.com> wrote: > Hello, > > > 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 > Can you post the actually oops you are seeing, because I'm still unable to trigger this. -- Steve > > > Anyway, the patch looks good to me. > > > > Acked-by: Namhyung Kim <namhyung@kernel.org> > > > > Thanks, > > Namhyung > > > > > > > > > > Signed-off-by: Chunyu Hu <chuhu@redhat.com> > > > --- > > > 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 > > > > > >
[toc] | [prev] | [next] | [standalone]
| From | Chunyu Hu <chuhu@redhat.com> |
|---|---|
| Date | 2016-06-29 01:40 +0200 |
| Subject | Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace |
| Message-ID | <rPaLM-516-11@gated-at.bofh.it> |
| In reply to | #1433262 |
----- Original Message ----- > From: "Steven Rostedt" <rostedt@goodmis.org> > To: "Chunyu Hu" <chuhu@redhat.com> > Cc: "Namhyung Kim" <namhyung@gmail.com>, "LKML" <linux-kernel@vger.kernel.org> > Sent: Wednesday, June 29, 2016 4:03:33 AM > Subject: Re: [PATCH V3] tracing: Make latency tracers fully support the set_graph_notrace > > On Tue, 28 Jun 2016 04:03:12 -0400 (EDT) > Chunyu Hu <chuhu@redhat.com> wrote: > > > Hello, > > > > > > 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 > > > > Can you post the actually oops you are seeing, because I'm still unable > to trigger this. I'm also confused, I think it's related the data layout by gcc. I was using gcc 4.8. (gcc version 4.8.3 20140911 (Red Hat 4.8.3-9). where the -6553x falls to is uncertain in bin by different gcc I guess? I tried to make a kdump, but i failed to make it work. [ 2098.413419] BUG: unable to handle kernel paging request at ffffe8ffffb83aa0 [ 2098.420429] IP: [<ffffffff81161254>] print_graph_entry+0x3c4/0x3e0 [ 2098.426635] PGD 27f0c49067 PUD 27f0c42067 PMD 0 [ 2098.431320] Oops: 0002 [#1] SMP [ 2098.434464] Modules linked in: rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache vfat fat intel_powerclamp coretemp kvm_intel kvm iTCO_wdt iTCO_vendor_support ipmi_devintf ipmi_ssif cdc_ether usbnet irqbypass mii ipmi_si i7core_edac pcspkr ioatdma ipmi_msghandler sg shpchp edac_core dca i2c_i801 lpc_ich mfd_core acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sd_mod sr_mod cdrom mgag200 ata_generic i2c_algo_bit pata_acpi drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm mptsas scsi_transport_sas ata_piix mptscsih libata crc32c_intel serio_raw i2c_core bnx2 mptbase dm_mirror dm_region_hash dm_log dm_mod [ 2098.493591] CPU: 18 PID: 12433 Comm: cat Tainted: G I 4.7.0-rc3 #1 [ 2098.500895] Hardware name: IBM System x3850 X5 -[7145I18]-/Node 1, Processor Card, BIOS -[G0E175BUS-1.75]- 06/06/2012 [ 2098.511493] task: ffff88084eeb0000 ti: ffff880851194000 task.ti: ffff880851194000 [ 2098.518971] RIP: 0010:[<ffffffff81161254>] [<ffffffff81161254>] print_graph_entry+0x3c4/0x3e0 [ 2098.527599] RSP: 0018:ffff880851197c68 EFLAGS: 00010286 [ 2098.532908] RAX: ffffe8ffffc03a80 RBX: ffff88082eb34000 RCX: ffffffff810ef390 [ 2098.540037] RDX: ffffffffffff0002 RSI: 0000000000000282 RDI: ffffffff81c81de0 [ 2098.547166] RBP: ffff880851197ca8 R08: 0000000000000003 R09: ffff884befca3180 [ 2098.554298] R10: 0000000000000001 R11: 000000000000000b R12: ffff880851197ce0 [ 2098.561427] R13: ffff88082eb35098 R14: ffff884befca3180 R15: 0000000000000038 [ 2098.568559] FS: 00007f174c16f740(0000) GS:ffff88085fd80000(0000) knlGS:0000000000000000 [ 2098.576643] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 2098.582387] CR2: ffffe8ffffb83aa0 CR3: 000000082e9f5000 CR4: 00000000000006e0 [ 2098.589516] Stack: [ 2098.591531] ffff8827ee598c00 ffff884befca3180 0000000c51197cc8 ffff88082eb34000 [ 2098.599011] ffff88082eb35098 000000000000000c 0000000000000038 ffff884bf2cd90d0 [ 2098.606487] ffff880851197d28 ffffffff81161329 00000000000001ec 00000000000000d8 [ 2098.613962] Call Trace: [ 2098.616416] [<ffffffff81161329>] print_graph_function_flags+0xb9/0x500 [ 2098.623029] [<ffffffff810ef390>] ? rcu_sched_qs+0x60/0x60 [ 2098.628512] [<ffffffff8115ea10>] wakeup_print_line+0x20/0x30 [ 2098.634258] [<ffffffff81158524>] print_trace_line+0x54/0x510 [ 2098.640002] [<ffffffff81159389>] s_show+0x29/0x150 [ 2098.644883] [<ffffffff8123ddbe>] seq_read+0x22e/0x370 [ 2098.650025] [<ffffffff81218b67>] __vfs_read+0x37/0x150 [ 2098.655249] [<ffffffff81218b35>] ? __vfs_read+0x5/0x150 [ 2098.660564] [<ffffffff812c9413>] ? security_file_permission+0xa3/0xc0 [ 2098.667088] [<ffffffff81218b35>] ? __vfs_read+0x5/0x150 [ 2098.672401] [<ffffffff8121912e>] vfs_read+0x8e/0x140 [ 2098.677454] [<ffffffff8121a625>] SyS_read+0x55/0xc0 [ 2098.682425] [<ffffffff81003b12>] do_syscall_64+0x62/0x110 [ 2098.687949] [<ffffffff816c65a1>] entry_SYSCALL64_slow_path+0x25/0x25 [ 2098.694388] Code: 42 18 49 89 41 38 48 8b 42 20 49 89 41 40 48 8b 42 28 49 89 41 48 4c 89 e0 e9 93 fd ff ff 89 50 08 e9 95 fc ff ff 49 8b 4c 24 08 <48> 89 4c d0 10 e9 2f ff ff ff 4c 89 e0 e9 74 fd ff ff 66 2e 0f [ 2098.714766] RIP [<ffffffff81161254>] print_graph_entry+0x3c4/0x3e0 [ 2098.721051] RSP <ffff880851197c68> [ 2098.724542] CR2: ffffe8ffffb83aa0 > -- Steve > > > > > > Anyway, the patch looks good to me. > > > > > > Acked-by: Namhyung Kim <namhyung@kernel.org> > > > > > > Thanks, > > > Namhyung > > > > > > > > > > > > > > Signed-off-by: Chunyu Hu <chuhu@redhat.com> > > > > --- > > > > 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
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web