Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Tom Zanussi <tom.zanussi@linux.intel.com>]

Hi Masami,

On Thu, 2015-05-21 at 17:08 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On 2015/05/21 6:19, Tom Zanussi wrote:
> > This is v5 of the 'hist triggers' patchset, following feedback from
> > v4.
> > 
> > Changes from v4:
> > 
> > This version addresses some problems and suggestions made by Daniel
> > Wagner - a lot of the code was reworked to get rid of the distinction
> > between keys and values, and as a result, both keys and values can be
> > used as sort keys.  As suggested, it also allows 'val=' to be absent
> > in a trigger command - if no 'val' is specified, hitcount is assumed
> > and automatically used as the only val.
> 
> Thank you for this amazing work! :)
> Here is an example how I've used it.

Nice example - thanks for sharing it!

> 
> ---------
> [root@localhost perf]# ./perf probe -a '__kmalloc caller=$stack0 size'
> Added new event:
>   probe:__kmalloc      (on __kmalloc with caller=$stack0 size)
> 
> You can now use it in all perf tools, such as:
> 
>         perf record -e probe:__kmalloc -aR sleep 1
> 
> [root@localhost perf]# cd /sys/kernel/debug/tracing
> [root@localhost tracing]# echo hist:keys=caller.sym > events/probe/__kmalloc/trigger
> [root@localhost tracing]# echo 1 > events/probe/__kmalloc/enable
> [root@localhost tracing]# cat events/probe/__kmalloc/hist
> # trigger info: hist:keys=caller.sym:vals=hitcount:sort=hitcount:size=2048 [active]
> 
> caller: [ffffffff811964d7] tracing_map_sort_entries            hitcount:          1
> caller: [ffffffff81296120] load_elf_binary                     hitcount:          1
> caller: [ffffffff813eb98c] context_struct_to_string            hitcount:          1
> caller: [ffffffff81264c8c] simple_xattr_alloc                  hitcount:          1
> caller: [ffffffff811e0a02] shmem_initxattrs                    hitcount:          1
> caller: [ffffffff81295eb6] load_elf_phdrs                      hitcount:          2
> caller: [ffffffff8169c49b] sk_prot_alloc                       hitcount:          2
> caller: [ffffffff81395567] kmem_alloc                          hitcount:          6
> caller: [ffffffff8125b844] alloc_fdmem                         hitcount:          6
> caller: [ffffffff81415918] bio_alloc_bioset                    hitcount:          8
> caller: [ffffffff813ecc44] security_context_to_sid_core        hitcount:         17
> caller: [ffffffff812621bb] seq_buf_alloc                       hitcount:         18
> 
> Totals:
>     Hits: 64
>     Entries: 12
>     Dropped: 0
> ----------
> Good! Just one more, I also want to see the offset of the symbols. :)
> 

Sure, I could add a new 'sym-offset' modifier e.g. caller.sym-offset, or
I can just have .sym always include the offset.

> And this can dig deeper to investigate the size histogram, with filtering by caller.
> ----------
> [root@localhost tracing]# echo \!hist:keys=caller.sym > events/probe/__kmalloc/trigger
> [root@localhost tracing]# echo hist:keys=size if caller==0xffffffff812621bb > events/probe/__kmalloc/trigger
> [root@localhost tracing]# cat events/probe/__kmalloc/hist
> # trigger info: hist:keys=size:vals=hitcount:sort=hitcount:size=2048 if caller==0xffffffff812621bb [active]
> 
> size:       3024 hitcount:          1
> size:       4096 hitcount:         12
> 
> Totals:
>     Hits: 13
>     Entries: 2
>     Dropped: 0
> [root@localhost tracing]#
> ---------
> Yes! This interactivity is what I want :)
> 
> Another enhancement ideas what I want are here:
> - Named hist instance, which can be shared among several events.
>   Since probing an inlined function can make a several probe-events,
>   those need to share a histogram among them.

Makes sense - any ideas on how this would work from an interface
perspective?

Would just allowing hist="myname": ... suffice?  i.e. creating a hist
trigger with hist="myname" would look for an existing trigger with that
name - if found would use that, otherwise create a new instance with
that name... 

> - Multiple hist instances for each event, which allows us to compare
>   several histograms which have different filters.
> 

Yeah, that would be a nice enhancement - will do that when I get a
chance.

> Anyway, without above, this look fine to me :)

Great.

> > 
> > The map code was also separated out into a separate file,
> > tracing_map.c, allowing it to be reused.  It also adds a second tracer
> > called function_hist that actually does reuse the code, as an RFC
> > patch.
> > 
> > Patch 01/10 [tracing: Update cond flag when enabling or disabling..]
> > is a fix for a problem noticed by Daniel and that fixes a problem in
> > existing trigger code and should be applied regardless of whether the
> > rest of the patchset is merged.
> 
> I've reviewed that.
> 

Thanks for doing that.

> > As mentioned, patch 10/10 is an RFC patch implementing a new tracer
> > based on the function tracer code.  It's a fun little tool and is
> > useful for a specific problem I'm working on (and is also a nice test
> > of the tracing_map code), but is an RFC because first, I'm not sure it
> > would really be of general interest and secondly, it's POC-level
> > quality and I'd need to spend more time fixing it up to make it
> > upstreamable, but I don't want to waste my time if not.
> 
> BTW, I've hit a warning while testing:
> 
> [ 8431.319668] ------------[ cut here ]------------
> [ 8431.319678] WARNING: CPU: 0 PID: 14413 at /home/mhiramat/ksrc/linux-3/kernel/trace/ftrace.c:5080 ftrace_init_array_ops+0x6e/0x90()
> [ 8431.319680] Modules linked in: xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT
> nf_reject_ipv4 iptable_filter ip_tables tun bridge stp llc coretemp crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel glue_helper lrw gf128mul ablk_helper cryptd iTCO_wdt
> iTCO_vendor_support ipmi_si lpc_ich ipmi_msghandler mfd_core pcspkr i2c_i801 i2c_ismt shpchp acpi_cpufreq uinput sr_mod sd_mod cdrom ast syscopyarea sysfillrect sysimgblt drm_kms_helper ttm drm ahci
> igb libahci libata ptp pps_core dca i2c_algo_bit i2c_core dm_mirror dm_region_hash dm_log dm_mod
> [ 8431.319736] CPU: 0 PID: 14413 Comm: ftracetest Not tainted 4.1.0-rc3+ #33
> [ 8431.319738] Hardware name: Supermicro A1SAi/A1SAi, BIOS 1.0b 11/06/2013
> [ 8431.319741]  0000000000000000 0000000037d828fa ffff880467eabc98 ffffffff817d5b48
> [ 8431.319745]  0000000000000000 0000000000000000 ffff880467eabcd8 ffffffff810c70ba
> [ 8431.319748]  ffff880467eabcb8 ffffffff820a2b80 ffffffff81197330 ffffffff820a2b80
> [ 8431.319752] Call Trace:
> [ 8431.319760]  [<ffffffff817d5b48>] dump_stack+0x45/0x57
> [ 8431.319765]  [<ffffffff810c70ba>] warn_slowpath_common+0x8a/0xc0
> [ 8431.319769]  [<ffffffff81197330>] ? function_hist_open+0x20/0x20
> [ 8431.319772]  [<ffffffff810c71ea>] warn_slowpath_null+0x1a/0x20
> [ 8431.319776]  [<ffffffff81183efe>] ftrace_init_array_ops+0x6e/0x90
> [ 8431.319779]  [<ffffffff811976d8>] function_hist_init+0x28/0x160
> [ 8431.319783]  [<ffffffff811918ee>] tracing_set_tracer+0x10e/0x1b0
> [ 8431.319787]  [<ffffffff8137cd8f>] ? xfs_file_buffered_aio_write+0xaf/0x240
> [ 8431.319791]  [<ffffffff81191bc0>] tracing_set_trace_write+0x90/0xd0
> [ 8431.319796]  [<ffffffff8123d2d7>] __vfs_write+0x37/0x110
> [ 8431.319799]  [<ffffffff81240198>] ? __sb_start_write+0x58/0x100
> [ 8431.319804]  [<ffffffff813d5393>] ? security_file_permission+0x23/0xa0
> [ 8431.319808]  [<ffffffff8123da09>] vfs_write+0xa9/0x1b0
> [ 8431.319812]  [<ffffffff810716fc>] ? do_audit_syscall_entry+0x6c/0x70
> [ 8431.319816]  [<ffffffff8123e8b5>] SyS_write+0x55/0xd0
> [ 8431.319821]  [<ffffffff817dd26e>] system_call_fastpath+0x12/0x71
> [ 8431.319823] ---[ end trace 7f402f6ea6c9516c ]---
> [ 8431.319826] ftrace ops had function_hist_call+0x0/0x150 for function
> 
> Here is the ftrace.c:5080
> -----
> void ftrace_init_array_ops(struct trace_array *tr, ftrace_func_t func)
> {
>         /* If we filter on pids, update to use the pid function */
>         if (tr->flags & TRACE_ARRAY_FL_GLOBAL) {
>                 if (WARN_ON(tr->ops->func != ftrace_stub))		<-- here
>                         printk("ftrace ops had %pS for function\n",
>                                tr->ops->func);
>                 /* Only the top level instance does pid tracing */
>                 if (!list_empty(&ftrace_pids)) {
>                         set_ftrace_pid_function(func);
>                         func = ftrace_pid_func;
>                 }
>         }
>         tr->ops->func = func;
>         tr->ops->private = tr;
> }
> -----
> 
> Since function_hist_call was introduced by 10/10, this warning was also
> occurred by it.
> 

Right, why it's an RFC ;-)  I need to look some more at the ftrace code
and figure out how to hook it up properly...

Thanks,

Tom

> Thank you,
> 
> 
>