Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756884AbbEUVu0 (ORCPT ); Thu, 21 May 2015 17:50:26 -0400 Received: from mail4.hitachi.co.jp ([133.145.228.5]:39306 "EHLO mail4.hitachi.co.jp" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756789AbbEUVuR (ORCPT ); Thu, 21 May 2015 17:50:17 -0400 Message-ID: <555E5311.9000309@hitachi.com> Date: Fri, 22 May 2015 06:50:09 +0900 From: Masami Hiramatsu Organization: Hitachi, Ltd., Japan User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Thunderbird/31.6.0 MIME-Version: 1.0 To: Tom Zanussi CC: rostedt@goodmis.org, daniel.wagner@bmw-carit.de, namhyung@kernel.org, josh@joshtriplett.org, andi@firstfloor.org, linux-kernel@vger.kernel.org Subject: Re: [PATCH v5 00/10] tracing: 'hist' triggers References: <555D928E.5040004@hitachi.com> <1432221989.27713.38.camel@picadillo> In-Reply-To: <1432221989.27713.38.camel@picadillo> Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 9985 Lines: 221 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] [] dump_stack+0x45/0x57 >> [ 8431.319765] [] warn_slowpath_common+0x8a/0xc0 >> [ 8431.319769] [] ? function_hist_open+0x20/0x20 >> [ 8431.319772] [] warn_slowpath_null+0x1a/0x20 >> [ 8431.319776] [] ftrace_init_array_ops+0x6e/0x90 >> [ 8431.319779] [] function_hist_init+0x28/0x160 >> [ 8431.319783] [] tracing_set_tracer+0x10e/0x1b0 >> [ 8431.319787] [] ? xfs_file_buffered_aio_write+0xaf/0x240 >> [ 8431.319791] [] tracing_set_trace_write+0x90/0xd0 >> [ 8431.319796] [] __vfs_write+0x37/0x110 >> [ 8431.319799] [] ? __sb_start_write+0x58/0x100 >> [ 8431.319804] [] ? security_file_permission+0x23/0xa0 >> [ 8431.319808] [] vfs_write+0xa9/0x1b0 >> [ 8431.319812] [] ? do_audit_syscall_entry+0x6c/0x70 >> [ 8431.319816] [] SyS_write+0x55/0xd0 >> [ 8431.319821] [] 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.pt@hitachi.com -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/