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

[Chunyu Hu]

----- Original Message -----
> From: "Steven Rostedt" <rostedt@xxxxxxxxxxx>
> To: "Chunyu Hu" <chuhu@xxxxxxxxxx>
> Cc: "Namhyung Kim" <namhyung@xxxxxxxxx>, "LKML" <linux-kernel@xxxxxxxxxxxxxxx>
> 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@xxxxxxxxxx> 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@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