On 2015/05/22 0:26, Tom Zanussi wrote:
> 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.
Hmm, can we reuse ftrace's options? We already have options/sym-offset and
options/sym-addr under debugfs/tracing/. E.g.
# options/sym-offset=0 options/sym-addr=0
caller: seq_buf_alloc
# options/sym-offset=0 options/sym-addr=1
caller: [ffffffff812621bb] seq_buf_alloc
# options/sym-offset=1 options/sym-addr=0
caller: seq_buf_alloc+0x1b
# options/sym-offset=1 options/sym-addr=1
caller: [ffffffff812621bb] seq_buf_alloc+0x1b
>
>> 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...
Yeah, that looks good to me :)
>> - 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...
Thank you!
--
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu...@hitachi.com
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
