Re: [GIT PULL] tracing: Fix traceon trigger condition to actually turn tracing on

Re: [GIT PULL] tracing: Fix traceon trigger condition to actually turn tracing on

[Steven Rostedt]

Bah, I forgot to Cc LKML on my pull request. Doing this from a
conference with very poor internet access from a laptop that I don't
usually develop on, means I might make mistakes.

On Wed, 2014-03-26 at 13:19 -0500, Tom Zanussi wrote:
> On Wed, 2014-03-26 at 09:17 -0400, Steven Rostedt wrote:
> > Linus,
> > 
> > While on my flight to Linux Collaboration Summit, I was working on
> > my slides for the event trigger tutorial. I booted a 3.14-rc7 kernel
> > to perform what I wanted to teach and cut and paste it into my slides.
> > When I tried the traceon event trigger with a condition attached to it
> > (turns tracing on only if a field of the trigger event matches a condition
> > set by the user), nothing happened. Tracing would not turn on. I stopped
> > working on my presentation in order to find what was wrong.
> > 
> 
> Hi Steve,
> 
> Sorry you had to stop working on your presentation to dig into this -
> thanks for doing that though - it looks correct and fixes the problem
> here for me, so you can add my Tested-by:
> 
> Tested-by: Tom Zanussi <tom.zanussi@linux.intel.com>

Linus already pulled it. But Olof came to me at lunch to tell me my
patch broke his PA Semi PPC box.

Olof, as you well know, I also own one of those beasts, and I just
booted the kernel with that patch and all works fine. Perhaps its a
config issue? Can you send me your config.

Thanks,

-- Steve

> 
> And I'll make sure I add the 'traceon with filter' case to my
> 'test-suite' (I covered the 'traceoff with filter' case, obviously
> there's an important difference, though).
> 
> Also, if you'd be interested in adding something for your Collab Summit
> event triggers talk, I've been working on a new trigger type called a
> 'hash' trigger and have been using it for my own work here.  If so, I
> can do a quick cleanup and push it somewhere...
> 
> Tom
> 
> 
> > It ended up being the way trace event triggers work when they have
> > conditions. Instead of copying the fields, the condition code just
> > looks at the fields that were copied into the ring buffer. This works
> > great, unless tracing is off. That's because when the event is reserved
> > on the ring buffer, the ring buffer returns a NULL pointer, this tells
> > the tracing code that the ring buffer is disabled. This ends up being
> > a problem for the traceon trigger if it is using this information to
> > check its condition.
> > 
> > Luckily the code that checks if tracing is on returns the ring buffer
> > to use (because the ring buffer is determined by the event file
> > also passed to that field). I was able to easily solve this bug by
> > checking in that helper function if the returned ring buffer entry
> > is NULL, and if so, also check the file flag if it has a trace event
> > trigger condition, and if so, to pass back a temp ring buffer to use.
> > This will allow the trace event trigger condition to still test the
> > event fields, but nothing will be recorded.
> > 
> > I understand that this is very late, but as this feature was added in
> > 3.14, and fixes a bug that breaks a feature that I'm showing people
> > how to use in my tutorial, it would be great if it's not broken in
> > the v3.14 release.
> > 
> > Please pull the latest trace-fixes-v3.14-rc7-v2 tree, which can be found at:
> > 
> > 
> >   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> > trace-fixes-v3.14-rc7-v2
> > 
> > Tag SHA1: fb89a9d8782b1b25cd78a7c06e1110efa5339911
> > Head SHA1: 2c4a33aba5f9ea3a28f2e40351f078d95f00786b
> > 
> > 
> > Steven Rostedt (Red Hat) (1):
> >       tracing: Fix traceon trigger condition to actually turn tracing on
> > 
> > ----
> >  kernel/trace/trace.c | 27 +++++++++++++++++++++++++--
> >  1 file changed, 25 insertions(+), 2 deletions(-)
> > ---------------------------
> > commit 2c4a33aba5f9ea3a28f2e40351f078d95f00786b
> > Author: Steven Rostedt (Red Hat) <rostedt@goodmis.org>
> > Date:   Tue Mar 25 23:39:41 2014 -0400
> > 
> >     tracing: Fix traceon trigger condition to actually turn tracing on
> >     
> >     While working on my tutorial for 2014 Linux Collaboration Summit
> >     I found that the traceon trigger did not work when conditions were
> >     used. The other triggers worked fine though. Looking into it, it
> >     is because of the way the triggers use the ring buffer to store
> >     the fields it will use for the condition. But if tracing is off, nothing
> >     is stored in the buffer, and the tracepoint exits before calling the
> >     trigger to test the condition. This is fine for all the triggers that
> >     only work when tracing is on, but for traceon trigger that is to
> >     work when tracing is off, nothing happens.
> >     
> >     The fix is simple, just use a temp ring buffer to record the event
> >     if tracing is off and the event has a trace event conditional trigger
> >     enabled. The rest of the tracepoint code will work just fine, but
> >     the tracepoint wont be recorded in the other buffers.
> >     
> >     Cc: Tom Zanussi <tom.zanussi@linux.intel.com>
> >     Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> > 
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index 815c878..24c1f23 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -1600,15 +1600,31 @@ void trace_buffer_unlock_commit(struct ring_buffer *buffer,
> >  }
> >  EXPORT_SYMBOL_GPL(trace_buffer_unlock_commit);
> >  
> > +static struct ring_buffer *temp_buffer;
> > +
> >  struct ring_buffer_event *
> >  trace_event_buffer_lock_reserve(struct ring_buffer **current_rb,
> >  			  struct ftrace_event_file *ftrace_file,
> >  			  int type, unsigned long len,
> >  			  unsigned long flags, int pc)
> >  {
> > +	struct ring_buffer_event *entry;
> > +
> >  	*current_rb = ftrace_file->tr->trace_buffer.buffer;
> > -	return trace_buffer_lock_reserve(*current_rb,
> > +	entry = trace_buffer_lock_reserve(*current_rb,
> >  					 type, len, flags, pc);
> > +	/*
> > +	 * If tracing is off, but we have triggers enabled
> > +	 * we still need to look at the event data. Use the temp_buffer
> > +	 * to store the trace event for the tigger to use. It's recusive
> > +	 * safe and will not be recorded anywhere.
> > +	 */
> > +	if (!entry && ftrace_file->flags & FTRACE_EVENT_FL_TRIGGER_COND) {
> > +		*current_rb = temp_buffer;
> > +		entry = trace_buffer_lock_reserve(*current_rb,
> > +						  type, len, flags, pc);
> > +	}
> > +	return entry;
> >  }
> >  EXPORT_SYMBOL_GPL(trace_event_buffer_lock_reserve);
> >  
> > @@ -6494,11 +6510,16 @@ __init static int tracer_alloc_buffers(void)
> >  
> >  	raw_spin_lock_init(&global_trace.start_lock);
> >  
> > +	/* Used for event triggers */
> > +	temp_buffer = ring_buffer_alloc(PAGE_SIZE, RB_FL_OVERWRITE);
> > +	if (!temp_buffer)
> > +		goto out_free_cpumask;
> > +
> >  	/* TODO: make the number of buffers hot pluggable with CPUS */
> >  	if (allocate_trace_buffers(&global_trace, ring_buf_size) < 0) {
> >  		printk(KERN_ERR "tracer: failed to allocate ring buffer!\n");
> >  		WARN_ON(1);
> > -		goto out_free_cpumask;
> > +		goto out_free_temp_buffer;
> >  	}
> >  
> >  	if (global_trace.buffer_disabled)
> > @@ -6540,6 +6561,8 @@ __init static int tracer_alloc_buffers(void)
> >  
> >  	return 0;
> >  
> > +out_free_temp_buffer:
> > +	ring_buffer_free(temp_buffer);
> >  out_free_cpumask:
> >  	free_percpu(global_trace.trace_buffer.data);
> >  #ifdef CONFIG_TRACER_MAX_TRACE
> > 
> > 
> 

Re: [GIT PULL] tracing: Fix traceon trigger condition to actually turn tracing on

[Olof Johansson]

On Wed, Mar 26, 2014 at 2:21 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> Bah, I forgot to Cc LKML on my pull request. Doing this from a
> conference with very poor internet access from a laptop that I don't
> usually develop on, means I might make mistakes.
>
> On Wed, 2014-03-26 at 13:19 -0500, Tom Zanussi wrote:
>> On Wed, 2014-03-26 at 09:17 -0400, Steven Rostedt wrote:
>> > Linus,
>> >
>> > While on my flight to Linux Collaboration Summit, I was working on
>> > my slides for the event trigger tutorial. I booted a 3.14-rc7 kernel
>> > to perform what I wanted to teach and cut and paste it into my slides.
>> > When I tried the traceon event trigger with a condition attached to it
>> > (turns tracing on only if a field of the trigger event matches a condition
>> > set by the user), nothing happened. Tracing would not turn on. I stopped
>> > working on my presentation in order to find what was wrong.
>> >
>>
>> Hi Steve,
>>
>> Sorry you had to stop working on your presentation to dig into this -
>> thanks for doing that though - it looks correct and fixes the problem
>> here for me, so you can add my Tested-by:
>>
>> Tested-by: Tom Zanussi <tom.zanussi@linux.intel.com>
>
> Linus already pulled it. But Olof came to me at lunch to tell me my
> patch broke his PA Semi PPC box.
>
> Olof, as you well know, I also own one of those beasts, and I just
> booted the kernel with that patch and all works fine. Perhaps its a
> config issue? Can you send me your config.


I think it's a side effect, and something else is going on. If I build
an boot a ppc64_defconfig on the box (I mistakenly told you that it
was pasemi_defconfig), it hangs early during boot during PCI init,
halfway through printing a line of stack usage warning.

However, it seems fickle. If I disable the hung task detector it seems
to go away, for example. So, I think something else is going on and it
just happened to align the stars for it to happen.

I'll keep trying to change variables enough to see what's going on. I
really wish I still had JTAG access on this box, but all those tools
are since long gone and forgotten. The conference wifi makes it harder
to work on this too, as I'm sure you've noticed...

Don't let this hold up anything at this time, unless someone else complains.


-Olof

Re: [GIT PULL] tracing: Fix traceon trigger condition to actually turn tracing on

[Tom Zanussi]

Adding lkml to the Cc: for completeness - this is the 'other thread' I
mentioned in my hash triggers post, which accidentally didn't get Cc:'ed
to the list...

On Wed, 2014-03-26 at 19:17 -0400, Steven Rostedt wrote:
> On Wed, 2014-03-26 at 13:19 -0500, Tom Zanussi wrote:
> 
> > Also, if you'd be interested in adding something for your Collab Summit
> > event triggers talk, I've been working on a new trigger type called a
> > 'hash' trigger and have been using it for my own work here.  If so, I
> > can do a quick cleanup and push it somewhere...
> 
> Thanks, but I'm currently at 82 slides with what I got (for a 2 hour
> tutorial). I'm not sure I can add that. Although, I have two slides near
> the end that say "Coming in 3.15" and "Coming in 3.16". I can add this
> to the 3.16 slide. Unless you have it well tested, it may be too close

Hi Steve,

Here's the commit log for the current hash trigger command, which kind
of explains what it does, in case you need some kind of description for
it for a 'coming in 3.xx' slide.  Feel free to use whatever you want
from this...

commit 2466f73ec49fb4df65dcfd7cd85469df1a99c07d
Author: Tom Zanussi <tom.zanussi@linux.intel.com>
Date:   Sat Mar 1 12:07:27 2014 -0600

    tracing: Add 'hash' event trigger command
    
    Hash triggers allow users to continually hash events which can then be
    dumped later by simply reading the trigger file.  This is done
    strictly via one-liners and without any kind of programming language.
    
    The syntax follows the existing trigger syntax:
    
      # echo 'hash:key(s):value(s)[:sort_keys()][ if filter] > event/trigger
    
    The values used as keys and values are just the fields that define the
    trace event and available in the event's 'format' file.  For example,
    the kmalloc event:
    
    root@ie:/sys/kernel/debug/tracing/events/kmem/kmalloc# cat format
    name: kmalloc
    ID: 370
    format:
            field:unsigned short common_type;       offset:0;       size:2; signed:0;
            field:unsigned char common_flags;       offset:2;       size:1; signed:0;
            field:unsigned char common_preempt_count;       offset:3;       size:1;signed:0;
            field:int common_pid;   offset:4;       size:4; signed:1;
    
            field:unsigned long call_site;  offset:8;       size:4; signed:0;
            field:const void * ptr; offset:12;      size:4; signed:0;
            field:size_t bytes_req; offset:16;      size:4; signed:0;
            field:size_t bytes_alloc;       offset:20;      size:4; signed:0;
            field:gfp_t gfp_flags;  offset:24;      size:4; signed:0;
    
    The key can be made up of one or more of these fields and any number of
    values can specified - these are automatically tallied in the hash entry
    any time the event is hit.  Stacktraces can also be used as keys.
    
    For example, the following uses the stacktrace leading up to a kmalloc
    as the key for hashing kmalloc events.  For each hash entry a tally of
    the bytes_alloc field is kept.  Dumping out the trigger shows the sum
    of bytes allocated for each execution path that led to a kmalloc:
    
      # echo 'hash:call_site:bytes_alloc' > /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
      # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    key: stacktrace:
             kmem_cache_alloc_trace+0xeb/0x140
             intel_ring_begin+0xd8/0x1a0 [i915]
             gen6_ring_sync+0x3c/0x140 [i915]
             i915_gem_object_sync+0xd1/0x130 [i915]
             i915_gem_do_execbuffer.isra.21+0x632/0x10d0 [i915]
             i915_gem_execbuffer2+0xac/0x280 [i915]
             drm_ioctl+0x4e9/0x610 [drm]
             do_vfs_ioctl+0x83/0x510
             SyS_ioctl+0x91/0xb0
             system_call_fastpath+0x16/0x1b
         vals: count:1595 bytes_alloc:153120
    key: stacktrace:
             __kmalloc+0x10b/0x180
             i915_gem_do_execbuffer.isra.21+0x67a/0x10d0 [i915]
             i915_gem_execbuffer2+0xac/0x280 [i915]
             drm_ioctl+0x4e9/0x610 [drm]
             do_vfs_ioctl+0x83/0x510
             SyS_ioctl+0x91/0xb0
             system_call_fastpath+0x16/0x1b
         vals: count:2850 bytes_alloc:888736
    key: stacktrace:
             __kmalloc+0x10b/0x180
             i915_gem_execbuffer2+0x60/0x280 [i915]
             drm_ioctl+0x4e9/0x610 [drm]
             do_vfs_ioctl+0x83/0x510
             SyS_ioctl+0x91/0xb0
             system_call_fastpath+0x16/0x1b
         vals: count:2850 bytes_alloc:2560384
    key: stacktrace:
             __kmalloc+0x10b/0x180
             hid_report_raw_event+0x15b/0x450 [hid]
             hid_input_report+0x119/0x1a0 [hid]
             hid_irq_in+0x20b/0x250 [usbhid]
             __usb_hcd_giveback_urb+0x7c/0x130
             usb_giveback_urb_bh+0x96/0xe0
             tasklet_hi_action+0xd7/0xe0
             __do_softirq+0x125/0x2e0
             irq_exit+0xb5/0xc0
             do_IRQ+0x67/0x110
             ret_from_intr+0x0/0x13
             cpuidle_idle_call+0xbb/0x1f0
             arch_cpu_idle+0xe/0x30
             cpu_startup_entry+0x9f/0x240
             rest_init+0x77/0x80
             start_kernel+0x3db/0x3e8
         vals: count:5968 bytes_alloc:131296
    Totals:
        Hits: 22648
        Entries: 119
        Dropped: 0
    
    This turns the hash trigger off:
    
      # echo '!hash:stacktrace:bytes_alloc' > /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    Stack traces, of course, are very useful but a bit of overkill for
    many uses.  For instance, suppose we just want a line per caller.
    Here, we keep a tally of bytes_alloc per caller.  Note that you don't
    need to explicitly keep a 'count' tally - counts are automatically
    tallied and displayed (and are in fact the default sort key).
    
    Also note that the raw call_site printed here isn't very useful (we'll
    remedy that later).
    
      # echo 'hash:call_site:bytes_alloc' > /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
      # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    hash:unlimited
    key: call_site:18446744071579450186 vals: count:1 bytes_alloc:64
    key: call_site:18446744071579439780 vals: count:1 bytes_alloc:64
    key: call_site:18446744071579400894 vals: count:1 bytes_alloc:1024
    key: call_site:18446744072104627352 vals: count:1 bytes_alloc:512
    key: call_site:18446744071580027351 vals: count:1 bytes_alloc:512
    key: call_site:18446744071580991590 vals: count:1 bytes_alloc:16
    key: call_site:18446744071579463899 vals: count:1 bytes_alloc:64
    key: call_site:18446744072102260685 vals: count:1 bytes_alloc:512
    key: call_site:18446744071579439821 vals: count:1 bytes_alloc:64
    key: call_site:18446744071579532598 vals: count:1 bytes_alloc:1024
    key: call_site:18446744071584838347 vals: count:1 bytes_alloc:64
    key: call_site:18446744071579450148 vals: count:1 bytes_alloc:64
    key: call_site:18446744071580886173 vals: count:2 bytes_alloc:256
    key: call_site:18446744071580886422 vals: count:2 bytes_alloc:1024
    key: call_site:18446744071580987082 vals: count:2 bytes_alloc:8192
    key: call_site:18446744071580652885 vals: count:2 bytes_alloc:128
    key: call_site:18446744071580565960 vals: count:2 bytes_alloc:512
    key: call_site:18446744071580680412 vals: count:2 bytes_alloc:64
    key: call_site:18446744071580891052 vals: count:2 bytes_alloc:1024
    key: call_site:18446744071580886777 vals: count:2 bytes_alloc:64
    key: call_site:18446744071580572594 vals: count:3 bytes_alloc:3072
    key: call_site:18446744071580592783 vals: count:3 bytes_alloc:48
    key: call_site:18446744071580679805 vals: count:3 bytes_alloc:12288
    key: call_site:18446744071582021108 vals: count:3 bytes_alloc:768
    key: call_site:18446744071580572564 vals: count:3 bytes_alloc:576
    key: call_site:18446744071581165381 vals: count:4 bytes_alloc:256
    key: call_site:18446744071580953553 vals: count:4 bytes_alloc:256
    key: call_site:18446744072102160648 vals: count:4 bytes_alloc:1024
    key: call_site:18446744071580652708 vals: count:4 bytes_alloc:4224
    key: call_site:18446744071580680238 vals: count:5 bytes_alloc:640
    key: call_site:18446744071581375333 vals: count:6 bytes_alloc:384
    key: call_site:18446744072102162313 vals: count:16 bytes_alloc:7616
    key: call_site:18446744071581165832 vals: count:24 bytes_alloc:1600
    key: call_site:18446744071582016247 vals: count:26 bytes_alloc:832
    key: call_site:18446744071580843814 vals: count:35 bytes_alloc:2240
    key: call_site:18446744071581367368 vals: count:39 bytes_alloc:3744
    key: call_site:18446744072101806931 vals: count:39 bytes_alloc:1248
    key: call_site:18446744072103721852 vals: count:89 bytes_alloc:8544
    key: call_site:18446744072101850501 vals: count:89 bytes_alloc:8544
    key: call_site:18446744072103729728 vals: count:89 bytes_alloc:17088
    key: call_site:18446744071583128580 vals: count:154 bytes_alloc:157696
    key: call_site:18446744072103573325 vals: count:643 bytes_alloc:10288
    key: call_site:18446744071582381017 vals: count:643 bytes_alloc:159008
    key: call_site:18446744072103563942 vals: count:645 bytes_alloc:123840
    key: call_site:18446744071582043239 vals: count:765 bytes_alloc:6120
    key: call_site:18446744072101884462 vals: count:776 bytes_alloc:49664
    key: call_site:18446744072103903864 vals: count:1026 bytes_alloc:98496
    key: call_site:18446744072103596026 vals: count:1026 bytes_alloc:287040
    key: call_site:18446744072103599888 vals: count:1026 bytes_alloc:724736
    key: call_site:18446744071580813202 vals: count:2433 bytes_alloc:155712
    key: call_site:18446744072099520315 vals: count:2948 bytes_alloc:64856
    Totals:
        Hits: 12601
        Entries: 51
        Dropped: 0
    
    A little more useful, but not much, would be to display the call_sites
    as hex addresses.  To do this we add a '.hex' modifier to the
    call_site key :
    
    root@trz-ThinkPad-T420:~# echo 'hash:call_site.hex:bytes_alloc' > /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    root@trz-ThinkPad-T420:~# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    hash:unlimited
    key: call_site:ffffffff811e7f26     vals: count:1 bytes_alloc:64
    key: call_site:ffffffff811a5bb2     vals: count:1 bytes_alloc:1024
    key: call_site:ffffffff811a41c8     vals: count:1 bytes_alloc:256
    key: call_site:ffffffff811c002e     vals: count:1 bytes_alloc:128
    key: call_site:ffffffff811209d7     vals: count:1 bytes_alloc:256
    key: call_site:ffffffff811f26f9     vals: count:1 bytes_alloc:32
    key: call_site:ffffffff811f2596     vals: count:1 bytes_alloc:512
    key: call_site:ffffffff811f249d     vals: count:1 bytes_alloc:128
    key: call_site:ffffffff811f37ac     vals: count:1 bytes_alloc:512
    key: call_site:ffffffff811bfe7d     vals: count:1 bytes_alloc:4096
    key: call_site:ffffffff811a5b94     vals: count:1 bytes_alloc:192
    key: call_site:ffffffff813075f4     vals: count:1 bytes_alloc:256
    key: call_site:ffffffff811b9555     vals: count:1 bytes_alloc:64
    key: call_site:ffffffff811b94a4     vals: count:2 bytes_alloc:2112
    key: call_site:ffffffff81236745     vals: count:2 bytes_alloc:128
    key: call_site:ffffffff813062f7     vals: count:5 bytes_alloc:160
    key: call_site:ffffffff811e0792     vals: count:8 bytes_alloc:512
    key: call_site:ffffffff81236908     vals: count:12 bytes_alloc:800
    key: call_site:ffffffffa0491a40     vals: count:12 bytes_alloc:2304
    key: call_site:ffffffffa02c6d85     vals: count:12 bytes_alloc:1152
    key: call_site:ffffffffa048fb7c     vals: count:12 bytes_alloc:1152
    key: call_site:ffffffffa0470ffa     vals: count:144 bytes_alloc:40192
    key: call_site:ffffffffa0471f10     vals: count:144 bytes_alloc:96192
    key: call_site:ffffffffa04bc278     vals: count:144 bytes_alloc:13824
    key: call_site:ffffffffa04692a6     vals: count:218 bytes_alloc:41856
    key: call_site:ffffffffa046b74d     vals: count:218 bytes_alloc:3488
    key: call_site:ffffffff8135f3d9     vals: count:218 bytes_alloc:53344
    key: call_site:ffffffffa02cf22e     vals: count:230 bytes_alloc:14720
    key: call_site:ffffffff8130cc67     vals: count:1229 bytes_alloc:9832
    Totals:
        Hits: 2623
        Entries: 29
        Dropped: 0
    
    Even more useful would be to display the call_sites as symbolic names.
    To do that we can add a '.sym' modifier to the call_site key:
    
    root@trz-ThinkPad-T420:~# echo 'hash:call_site.sym:bytes_alloc' > /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    root@trz-ThinkPad-T420:~# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    hash:unlimited
    key: call_site:[ffffffff8120aeca] stat_open vals: count:1 bytes_alloc:4096
    key: call_site:[ffffffff811a5bb2] alloc_pipe_info     vals: count:1 bytes_alloc:1024
    key: call_site:[ffffffff811f2596] load_elf_binary     vals: count:1 bytes_alloc:512
    key: call_site:[ffffffff811209d7] event_hash_trigger_print  vals: count:1 bytes_alloc:256
    key: call_site:[ffffffff811f26f9] load_elf_binary       vals: count:1 bytes_alloc:32
    key: call_site:[ffffffff811b9555] alloc_fdtable                 vals: count:1 bytes_alloc:64
    key: call_site:[ffffffff811f37ac] load_elf_binary       vals: count:1 bytes_alloc:512
    key: call_site:[ffffffff811a41c8] do_execve_common.isra.28  vals: count:1 bytes_alloc:256
    key: call_site:[ffffffff811c00dc] single_open                   vals: count:1 bytes_alloc:32
    key: call_site:[ffffffff811f249d] load_elf_binary       vals: count:1 bytes_alloc:128
    key: call_site:[ffffffff811a5b94] alloc_pipe_info       vals: count:1 bytes_alloc:192
    key: call_site:[ffffffff813075f4] aa_path_name                  vals: count:1 bytes_alloc:256
    key: call_site:[ffffffff811dd155] mounts_open_common            vals: count:2 bytes_alloc:384
    key: call_site:[ffffffff811b94a4] alloc_fdmem                   vals: count:2 bytes_alloc:2112
    key: call_site:[ffffffff81202bd1] proc_reg_open                 vals: count:2 bytes_alloc:128
    key: call_site:[ffffffff8120c066] proc_self_follow_link         vals: count:2 bytes_alloc:32
    key: call_site:[ffffffff811c002e] seq_open              vals: count:3 bytes_alloc:384
    key: call_site:[ffffffff811bfe7d] seq_read              vals: count:4 bytes_alloc:16384
    key: call_site:[ffffffff811e0792] inotify_handle_event          vals: count:4 bytes_alloc:256
    key: call_site:[ffffffff813062f7] aa_alloc_task_context         vals: count:5 bytes_alloc:160
    key: call_site:[ffffffffa0491a40] intel_framebuffer_create  vals: count:8 bytes_alloc:1536
    key: call_site:[ffffffffa02c6d85] drm_mode_page_flip_ioctl  vals: count:8 bytes_alloc:768
    key: call_site:[ffffffffa048fb7c] intel_crtc_page_flip          vals: count:8 bytes_alloc:768
    key: call_site:[ffffffffa04692a6] i915_gem_obj_lookup_or_create_vma   vals: count:112 bytes_alloc:21504
    key: call_site:[ffffffffa046b74d] i915_gem_object_get_pages_gtt               vals: count:112 bytes_alloc:1792
    key: call_site:[ffffffff8135f3d9] sg_kmalloc                                  vals: count:112 bytes_alloc:33088
    key: call_site:[ffffffffa02cf22e] drm_vma_node_allow                          vals: count:120 bytes_alloc:7680
    key: call_site:[ffffffffa0470ffa] i915_gem_do_execbuffer.isra.21      vals: count:122 bytes_alloc:34432
    key: call_site:[ffffffffa0471f10] i915_gem_execbuffer2                        vals: count:122 bytes_alloc:80960
    key: call_site:[ffffffffa04bc278] intel_ring_begin                    vals: count:122 bytes_alloc:11712
    key: call_site:[ffffffff8130cc67] apparmor_file_alloc_security                vals: count:126 bytes_alloc:1008
    Totals:
        Hits: 1008
        Entries: 31
        Dropped: 0
    
    Most useful of all would be to not only display the call_sites
    symbolically, but also display tallies of the total number of bytes
    requested by each caller, the number allocated, and sort by the
    difference betwen the two, which essentially gives you a listing of
    the callers that waste the most bytes due to the lack of allocation
    granularity.
    
    This is a good demonstration of hashing multiple values, tallying the
    difference between values (- is the only 'operator' supported), and
    specifying a non-default sort order.
    
      # echo 'hash:call_site.sym:bytes_req,bytes_alloc,bytes_alloc-bytes_req:sort=bytes_alloc-bytes_req' > /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
      # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
    
    key: call_site:[ffffffff813062f7] aa_alloc_task_context                                                vals: count:30 bytes_req:960,  bytes_alloc:960,  bytes_alloc-bytes_req:0
    key: call_site:[ffffffff813075f4] aa_path_name                                                         vals: count:4 bytes_req:1024,  bytes_alloc:1024,  bytes_alloc-bytes_req:0
    key: call_site:[ffffffff811c002e] seq_open                                                     vals: count:18 bytes_req:2304,  bytes_alloc:2304,  bytes_alloc-bytes_req:0
    key: call_site:[ffffffff811bfd3a] seq_read                                                     vals: count:3 bytes_req:24576,  bytes_alloc:24576,  bytes_alloc-bytes_req:0
    key: call_site:[ffffffff810912cd] alloc_fair_sched_group                                       vals: count:1 bytes_req:64,  bytes_alloc:64,  bytes_alloc-bytes_req:0
    key: call_site:[ffffffff810970db] sched_autogroup_create_attach                                        vals: count:1 bytes_req:64,  bytes_alloc:64,  bytes_alloc-bytes_req:0
    key: call_site:[ffffffff811aaa8f] vfs_rename                                                           vals: count:2 bytes_req:22,  bytes_alloc:32,  bytes_alloc-bytes_req:10
    key: call_site:[ffffffff8120c066] proc_self_follow_link                                                vals: count:3 bytes_req:36,  bytes_alloc:48,  bytes_alloc-bytes_req:12
    key: call_site:[ffffffff811f26f9] load_elf_binary                                              vals: count:4 bytes_req:112,  bytes_alloc:128,  bytes_alloc-bytes_req:16
    key: call_site:[ffffffff811f2596] load_elf_binary                                              vals: count:4 bytes_req:2016,  bytes_alloc:2048,  bytes_alloc-bytes_req:32
    key: call_site:[ffffffff81269b65] ext4_ext_remove_space                                                vals: count:3 bytes_req:144,  bytes_alloc:192,  bytes_alloc-bytes_req:48
    key: call_site:[ffffffff811dd155] mounts_open_common                                                   vals: count:2 bytes_req:320,  bytes_alloc:384,  bytes_alloc-bytes_req:64
    key: call_site:[ffffffff811b9555] alloc_fdtable                                                        vals: count:4 bytes_req:192,  bytes_alloc:256,  bytes_alloc-bytes_req:64
    key: call_site:[ffffffff81236745] ext4_readdir                                                         vals: count:13 bytes_req:624,  bytes_alloc:832,  bytes_alloc-bytes_req:208
    key: call_site:[ffffffff811a5b94] alloc_pipe_info                                              vals: count:5 bytes_req:680,  bytes_alloc:960,  bytes_alloc-bytes_req:280
    key: call_site:[ffffffff81202bd1] proc_reg_open                                                        vals: count:14 bytes_req:560,  bytes_alloc:896,  bytes_alloc-bytes_req:336
    key: call_site:[ffffffff81087abe] sched_create_group                                                   vals: count:1 bytes_req:664,  bytes_alloc:1024,  bytes_alloc-bytes_req:360
    key: call_site:[ffffffffa0312f89] cfg80211_inform_bss_width_frame                              vals: count:2 bytes_req:546,  bytes_alloc:1024,  bytes_alloc-bytes_req:478
    key: call_site:[ffffffff811f37ac] load_elf_binary                                              vals: count:4 bytes_req:1568,  bytes_alloc:2048,  bytes_alloc-bytes_req:480
    key: call_site:[ffffffff811209d7] event_hash_trigger_print                                     vals: count:7 bytes_req:2520,  bytes_alloc:3328,  bytes_alloc-bytes_req:808
    key: call_site:[ffffffff811e7f26] eventfd_file_create                                                  vals: count:71 bytes_req:3408,  bytes_alloc:4544,  bytes_alloc-bytes_req:1136
    key: call_site:[ffffffff81236908] ext4_htree_store_dirent                                      vals: count:100 bytes_req:6246,  bytes_alloc:7456,  bytes_alloc-bytes_req:1210
    key: call_site:[ffffffff811a5bb2] alloc_pipe_info                                              vals: count:5 bytes_req:3200,  bytes_alloc:5120,  bytes_alloc-bytes_req:1920
    key: call_site:[ffffffffa02c6d85] drm_mode_page_flip_ioctl                                     vals: count:370 bytes_req:32560,  bytes_alloc:35520,  bytes_alloc-bytes_req:2960
    key: call_site:[ffffffff8120aeca] stat_open                                                    vals: count:7 bytes_req:24752,  bytes_alloc:28672,  bytes_alloc-bytes_req:3920
    key: call_site:[ffffffff811e0792] inotify_handle_event                                                 vals: count:644 bytes_req:37470,  bytes_alloc:41792,  bytes_alloc-bytes_req:4322
    key: call_site:[ffffffffa048fb7c] intel_crtc_page_flip                                                 vals: count:370 bytes_req:26640,  bytes_alloc:35520,  bytes_alloc-bytes_req:8880
    key: call_site:[ffffffffa008df3b] hid_report_raw_event                                                 vals: count:7048 bytes_req:140960,  bytes_alloc:155056,  bytes_alloc-bytes_req:14096
    key: call_site:[ffffffffa0491a40] intel_framebuffer_create                                     vals: count:370 bytes_req:53280,  bytes_alloc:71040,  bytes_alloc-bytes_req:17760
    key: call_site:[ffffffff8130cc67] apparmor_file_alloc_security                                         vals: count:3058 bytes_req:6116,  bytes_alloc:24464,  bytes_alloc-bytes_req:18348
    key: call_site:[ffffffffa04bc278] intel_ring_begin                                             vals: count:2754 bytes_req:242352,  bytes_alloc:264384,  bytes_alloc-bytes_req:22032
    key: call_site:[ffffffffa04692a6] i915_gem_obj_lookup_or_create_vma                            vals: count:1835 bytes_req:308280,  bytes_alloc:352320,  bytes_alloc-bytes_req:44040
    key: call_site:[ffffffffa02cf22e] drm_vma_node_allow                                                   vals: count:2291 bytes_req:91640,  bytes_alloc:146624,  bytes_alloc-bytes_req:54984
    key: call_site:[ffffffff8135f3d9] sg_kmalloc                                                           vals: count:1827 bytes_req:432512,  bytes_alloc:491808,  bytes_alloc-bytes_req:59296
    key: call_site:[ffffffffa0470ffa] i915_gem_do_execbuffer.isra.21                               vals: count:2754 bytes_req:534960,  bytes_alloc:922624,  bytes_alloc-bytes_req:387664
    key: call_site:[ffffffffa0471f10] i915_gem_execbuffer2                                                 vals: count:2754 bytes_req:2030840,  bytes_alloc:2729792,  bytes_alloc-bytes_req:698952
    Totals:
        Hits: 28354
        Entries: 48
        Dropped: 0
    
    Here's an example of using a compound key.  The below tallies syscall
    hits for every unique combination of pid/syscall id ('hitcount' is
    essentially a placeholder - as mentioned before, counts are always
    kept - using 'hitcount' essentially references that 'fake' event field
    in the hash trigger specification).  Both the syscall id and the pid
    are displayed symbolically via the .syscall and .execname modifiers.
    
      # echo 'hash:common_pid.execname,id.syscall:hitcount:sort=common_pid,hitcount' > /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
    
      # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
    
    key: common_pid:bash[3112], id:sys_write                                   vals: count:69
    key: common_pid:bash[3112], id:sys_rt_sigprocmask                          vals: count:218
    key: common_pid:update-notifier[3164], id:sys_poll                         vals: count:37
    key: common_pid:update-notifier[3164], id:sys_recvfrom                             vals: count:118
    key: common_pid:deja-dup-monito[3194], id:sys_sendto                               vals: count:1
    key: common_pid:deja-dup-monito[3194], id:sys_read                         vals: count:4
    key: common_pid:deja-dup-monito[3194], id:sys_poll                         vals: count:8
    key: common_pid:deja-dup-monito[3194], id:sys_recvmsg                              vals: count:8
    key: common_pid:deja-dup-monito[3194], id:sys_geteuid                              vals: count:8
    key: common_pid:deja-dup-monito[3194], id:sys_write                        vals: count:8
    key: common_pid:deja-dup-monito[3194], id:sys_getegid                              vals: count:8
    key: common_pid:emacs[3275], id:sys_fsync                                  vals: count:1
    key: common_pid:emacs[3275], id:sys_open                                   vals: count:1
    key: common_pid:emacs[3275], id:sys_unlink                                 vals: count:1
    key: common_pid:emacs[3275], id:sys_close                                  vals: count:1
    key: common_pid:emacs[3275], id:sys_symlink                                vals: count:2
    key: common_pid:emacs[3275], id:sys_readlink                                       vals: count:2
    key: common_pid:emacs[3275], id:sys_access                                 vals: count:2
    key: common_pid:emacs[3275], id:sys_geteuid                                vals: count:2
    key: common_pid:emacs[3275], id:sys_getgid                                 vals: count:2
    key: common_pid:emacs[3275], id:sys_getuid                                 vals: count:2
    key: common_pid:emacs[3275], id:sys_getegid                                vals: count:3
    key: common_pid:emacs[3275], id:sys_newlstat                                       vals: count:4
    key: common_pid:emacs[3275], id:sys_setitimer                                      vals: count:7
    key: common_pid:emacs[3275], id:sys_newstat                                vals: count:8
    key: common_pid:emacs[3275], id:sys_read                                   vals: count:9
    key: common_pid:emacs[3275], id:sys_write                                  vals: count:14
    key: common_pid:emacs[3275], id:sys_kill                                   vals: count:14
    key: common_pid:emacs[3275], id:sys_poll                                   vals: count:23
    key: common_pid:emacs[3275], id:sys_select                                 vals: count:23
    key: common_pid:emacs[3275], id:unknown_syscall                                    vals: count:34
    key: common_pid:emacs[3275], id:sys_ioctl                                  vals: count:60
    key: common_pid:emacs[3275], id:sys_rt_sigprocmask                         vals: count:116
    key: common_pid:cat[3323], id:sys_munmap                                   vals: count:1
    key: common_pid:cat[3323], id:sys_fadvise64                                vals: count:1
    
    Finally, the below uses a string as a hash key, and simply tallies and
    displays the default count ('hitcount').
    
      # echo 'hash:child_comm:hitcount' > /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
    
      # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
    
    hash:unlimited
    
    key: child_comm:pool        vals: count:1
    key: child_comm:unity-panel-ser     vals: count:1
    key: child_comm:pool                vals: count:1
    key: child_comm:hud-service vals: count:1
    key: child_comm:Cache I/O   vals: count:1
    key: child_comm:postgres    vals: count:1
    key: child_comm:gdbus               vals: count:1
    key: child_comm:bash                vals: count:1
    key: child_comm:ubuntu-webapps-     vals: count:2
    key: child_comm:dbus-daemon vals: count:2
    key: child_comm:compiz              vals: count:3
    key: child_comm:apt-cache   vals: count:3
    key: child_comm:unity-webapps-s     vals: count:4
    key: child_comm:java                vals: count:6
    key: child_comm:firefox             vals: count:52
    Totals:
        Hits: 80
        Entries: 15
        Dropped: 0
    
    Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>