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

2016-06-28 Thread Chunyu Hu 


- Original Message -
> From: "Steven Rostedt" <rost...@goodmis.org>
> To: "Chunyu Hu" <ch...@redhat.com>
> Cc: "Namhyung Kim" <namhy...@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 <ch...@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 e8b83aa0 
[ 2098.420429] IP: [] 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: 88084eeb ti: 880851194000 task.ti: 
880851194000 
[ 2098.518971] RIP: 0010:[]  [] 
print_graph_entry+0x3c4/0x3e0 
[ 2098.527599] RSP: 0018:880851197c68  EFLAGS: 00010286 
[ 2098.532908] RAX: e8c03a80 RBX: 88082eb34000 RCX: 
810ef390 
[ 2098.540037] RDX: 0002 RSI: 0282 RDI: 
81c81de0 
[ 2098.547166] RBP: 880851197ca8 R08: 0003 R09: 
884befca3180 
[ 2098.554298] R10: 0001 R11: 000b R12: 
880851197ce0 
[ 2098.561427] R13: 88082eb35098 R14: 884befca3180 R15: 
0038 
[ 2098.568559] FS:  7f174c16f740() GS:88085fd8() 
knlGS: 
[ 2098.576643] CS:  0010 DS:  ES:  CR0: 80050033 
[ 2098.582387] CR2: e8b83aa0 CR3: 00082e9f5000 CR4: 
06e0 
[ 2098.589516] Stack: 
[ 2098.591531]  8827ee598c00 884befca3180 000c51197cc8 
88082eb34000 
[ 2098.599011]  88082eb35098 000c 0038 
884bf2cd90d0 
[ 2098.606487]  880851197d28 81161329 01ec 
00d8 
[ 2098.613962] Call Trace: 
[ 2098.616416]  [] print_graph_function_flags+0xb9/0x500 
[ 2098.623029]  [] ? rcu_sched_qs+0x60/0x60 
[ 2098.628512]  [] wakeup_print_line+0x20/0x30 
[ 2098.634258]  [] print_trace_line+0x54/0x510 
[ 2098.640002]  [] s_show+0x29/0x150 
[ 2098.644883]  [] seq_read+0x22e/0x370 
[ 2098.650025]  [] __vfs_read+0x37/0x150 
[ 2098.655249]  [] ? __vfs_read+0x5/0x150 
[ 2098.660564]  [] ? security_file_permission+0xa3/0xc0 
[ 2098.667088]  [] ? __vfs_read+0x5/0x150 
[ 2098.672401]  [] vfs_read+0x8e/0x140 
[ 2098.677454]  [] SyS_read+0x55/0xc0 
[ 2098.682425]  [] do_syscall_64+0x62/0x110 
[

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

2016-06-28 Thread Chunyu Hu 


- Original Message -
> From: "Steven Rostedt" 
> To: "Chunyu Hu" 
> Cc: "Namhyung Kim" , "LKML" 
> 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  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 e8b83aa0 
[ 2098.420429] IP: [] 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: 88084eeb ti: 880851194000 task.ti: 
880851194000 
[ 2098.518971] RIP: 0010:[]  [] 
print_graph_entry+0x3c4/0x3e0 
[ 2098.527599] RSP: 0018:880851197c68  EFLAGS: 00010286 
[ 2098.532908] RAX: e8c03a80 RBX: 88082eb34000 RCX: 
810ef390 
[ 2098.540037] RDX: 0002 RSI: 0282 RDI: 
81c81de0 
[ 2098.547166] RBP: 880851197ca8 R08: 0003 R09: 
884befca3180 
[ 2098.554298] R10: 0001 R11: 000b R12: 
880851197ce0 
[ 2098.561427] R13: 88082eb35098 R14: 884befca3180 R15: 
0038 
[ 2098.568559] FS:  7f174c16f740() GS:88085fd8() 
knlGS: 
[ 2098.576643] CS:  0010 DS:  ES:  CR0: 80050033 
[ 2098.582387] CR2: e8b83aa0 CR3: 00082e9f5000 CR4: 
06e0 
[ 2098.589516] Stack: 
[ 2098.591531]  8827ee598c00 884befca3180 000c51197cc8 
88082eb34000 
[ 2098.599011]  88082eb35098 000c 0038 
884bf2cd90d0 
[ 2098.606487]  880851197d28 81161329 01ec 
00d8 
[ 2098.613962] Call Trace: 
[ 2098.616416]  [] print_graph_function_flags+0xb9/0x500 
[ 2098.623029]  [] ? rcu_sched_qs+0x60/0x60 
[ 2098.628512]  [] wakeup_print_line+0x20/0x30 
[ 2098.634258]  [] print_trace_line+0x54/0x510 
[ 2098.640002]  [] s_show+0x29/0x150 
[ 2098.644883]  [] seq_read+0x22e/0x370 
[ 2098.650025]  [] __vfs_read+0x37/0x150 
[ 2098.655249]  [] ? __vfs_read+0x5/0x150 
[ 2098.660564]  [] ? security_file_permission+0xa3/0xc0 
[ 2098.667088]  [] ? __vfs_read+0x5/0x150 
[ 2098.672401]  [] vfs_read+0x8e/0x140 
[ 2098.677454]  [] SyS_read+0x55/0xc0 
[ 2098.682425]  [] do_syscall_64+0x62/0x110 
[ 2098.687949]  [] 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

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

2016-06-28 Thread Steven Rostedt 
On Tue, 28 Jun 2016 04:03:12 -0400 (EDT)
Chunyu Hu  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 
> > 
> > Thanks,
> > Namhyung
> > 
> >   
> > >
> > > Signed-off-by: Chunyu Hu 
> > > ---
> > >  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, , ))
> > > 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, , ))
> > > return 0;
> > >
> > > --
> > > 1.8.3.1
> > >  
> >   
>

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

2016-06-28 Thread Steven Rostedt 
On Tue, 28 Jun 2016 04:03:12 -0400 (EDT)
Chunyu Hu  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 
> > 
> > Thanks,
> > Namhyung
> > 
> >   
> > >
> > > Signed-off-by: Chunyu Hu 
> > > ---
> > >  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, , ))
> > > 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, , ))
> > > return 0;
> > >
> > > --
> > > 1.8.3.1
> > >  
> >   
>

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

2016-06-28 Thread Chunyu Hu 
Hello,

- Original Message -
> From: "Namhyung Kim" <namhy...@gmail.com>
> To: "Chunyu Hu" <ch...@redhat.com>
> Cc: "Steven Rostedt" <rost...@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 <ch...@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 <namhy...@kernel.org>
> 
> Thanks,
> Namhyung
> 
> 
> >
> > Signed-off-by: Chunyu Hu <ch...@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, , ))
> > 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, , ))
> > return 0;
> >
> > --
> > 1.8.3.1
> >
> 

-- 
Regards,
Chunyu Hu

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

2016-06-28 Thread Chunyu Hu 
Hello,

- Original Message -
> From: "Namhyung Kim" 
> To: "Chunyu Hu" 
> Cc: "Steven Rostedt" , "LKML" 
> 
> 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  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 
> 
> Thanks,
> Namhyung
> 
> 
> >
> > Signed-off-by: Chunyu Hu 
> > ---
> >  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, , ))
> > 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, , ))
> > return 0;
> >
> > --
> > 1.8.3.1
> >
> 

-- 
Regards,
Chunyu Hu

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

2016-06-27 Thread Namhyung Kim 
Hello,

On Fri, Jun 24, 2016 at 7:55 PM, Chunyu Hu  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 

Thanks,
Namhyung


>
> Signed-off-by: Chunyu Hu 
> ---
>  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, , ))
> 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, , ))
> return 0;
>
> --
> 1.8.3.1
>

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

2016-06-27 Thread Namhyung Kim 
Hello,

On Fri, Jun 24, 2016 at 7:55 PM, Chunyu Hu  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 

Thanks,
Namhyung


>
> Signed-off-by: Chunyu Hu 
> ---
>  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, , ))
> 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, , ))
> return 0;
>
> --
> 1.8.3.1
>

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

2016-06-24 Thread Chunyu Hu 
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 
---
 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, , ))
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, , ))
return 0;
 
-- 
1.8.3.1

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

2016-06-24 Thread Chunyu Hu 
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 
---
 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, , ))
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, , ))
return 0;
 
-- 
1.8.3.1