Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1344580 > unrolled thread

[PATCH 4/5] perf report: Fix dynamic entry display in hierarchy

Started byNamhyung Kim <namhyung@kernel.org>
First post2016-02-26 20:00 +0100
Last post2016-02-27 10:50 +0100
Articles 13 — 6 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Namhyung Kim <namhyung@kernel.org> - 2016-02-26 20:00 +0100
    Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Arnaldo Carvalho de Melo <acme@kernel.org> - 2016-02-26 22:50 +0100
      Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Arnaldo Carvalho de Melo <acme@kernel.org> - 2016-02-26 22:50 +0100
        Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Arnaldo Carvalho de Melo <acme@kernel.org> - 2016-02-26 23:10 +0100
          Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Arnaldo Carvalho de Melo <acme@kernel.org> - 2016-02-26 23:30 +0100
          Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Steven Rostedt <rostedt@goodmis.org> - 2016-02-26 23:30 +0100
            Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Arnaldo Carvalho de Melo <acme@kernel.org> - 2016-02-26 23:40 +0100
              Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Jiri Olsa <jolsa@redhat.com> - 2016-02-27 00:20 +0100
                Re: [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy Jiri Olsa <jolsa@redhat.com> - 2016-02-27 00:20 +0100
          [PATCH] tools lib traceevent: Add '~' operation within  arg_num_eval() Steven Rostedt <rostedt@goodmis.org> - 2016-02-27 00:20 +0100
            Re: [PATCH] tools lib traceevent: Add '~' operation within  arg_num_eval() Arnaldo Carvalho de Melo <acme@kernel.org> - 2016-02-27 00:40 +0100
            Re: [PATCH] tools lib traceevent: Add '~' operation within  arg_num_eval() David Ahern <dsahern@gmail.com> - 2016-02-27 00:50 +0100
    [tip:perf/core] perf hists: Fix dynamic entry display in hierarchy tip-bot for Namhyung Kim <tipbot@zytor.com> - 2016-02-27 10:50 +0100

#1344580 — [PATCH 4/5] perf report: Fix dynamic entry display in hierarchy

FromNamhyung Kim <namhyung@kernel.org>
Date2016-02-26 20:00 +0100
Subject[PATCH 4/5] perf report: Fix dynamic entry display in hierarchy
Message-ID<r6vMm-7w1-5@gated-at.bofh.it>
When dynamic sort key is used it might not show pretty printed output.
This is because the trace output was not set only for the first dynamic
sort key.  During hierarchy_insert_entry() it missed to pass the
trace_output to dynamic entries.  Also even if it did, only first entry
will have it.  Subsequent entries might set it during collapsing stage
but it's not guaranteed.

Before:

  $ perf report --hierarchy --stdio -s ptr,bytes_req,gfp_flags -g none
  #
  #       Overhead  ptr / bytes_req / gfp_flags
  # ..............  ..........................................
  #
      37.50%        0xffff8803f7669400
         37.50%        448
            37.50%        66080
      10.42%        0xffff8803f766be00
          8.33%        96
             8.33%        66080
          2.08%        512
             2.08%        67280

After:

  #
  #       Overhead  ptr / bytes_req / gfp_flags
  # ..............  ..........................................
  #
      37.50%        0xffff8803f7669400
         37.50%        448
            37.50%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
      10.42%        0xffff8803f766be00
          8.33%        96
             8.33%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
          2.08%        512
             2.08%        GFP_KERNEL|GFP_NOWARN|GFP_REPEAT|GFP

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/util/hist.c | 2 +-
 tools/perf/util/sort.c | 3 +++
 2 files changed, 4 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index cc849d326211..9b3f582867d6 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -1125,7 +1125,7 @@ static struct hist_entry *hierarchy_insert_entry(struct hists *hists,
 	new->fmt = fmt;
 
 	/* some fields are now passed to 'new' */
-	if (perf_hpp__is_trace_entry(fmt))
+	if (perf_hpp__is_trace_entry(fmt) || perf_hpp__is_dynamic_entry(fmt))
 		he->trace_output = NULL;
 	else
 		new->trace_output = NULL;
diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index e948fcac0939..3b1b4018f111 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -1767,6 +1767,9 @@ static int __sort__hde_entry(struct perf_hpp_fmt *fmt, struct perf_hpp *hpp,
 	if (hde->raw_trace)
 		goto raw_field;
 
+	if (!he->trace_output)
+		he->trace_output = get_trace_output(he);
+
 	field = hde->field;
 	namelen = strlen(field->name);
 	str = he->trace_output;
-- 
2.7.1

[toc] | [next] | [standalone]

#1344725

FromArnaldo Carvalho de Melo <acme@kernel.org>
Date2016-02-26 22:50 +0100
Message-ID<r6yqT-W4-29@gated-at.bofh.it>
In reply to#1344580
Em Sat, Feb 27, 2016 at 03:52:46AM +0900, Namhyung Kim escreveu:
> When dynamic sort key is used it might not show pretty printed output.
> This is because the trace output was not set only for the first dynamic
> sort key.  During hierarchy_insert_entry() it missed to pass the
> trace_output to dynamic entries.  Also even if it did, only first entry
> will have it.  Subsequent entries might set it during collapsing stage
> but it's not guaranteed.
> 
> Before:
> 
>   $ perf report --hierarchy --stdio -s ptr,bytes_req,gfp_flags -g none
>   #
>   #       Overhead  ptr / bytes_req / gfp_flags
>   # ..............  ..........................................
>   #
>       37.50%        0xffff8803f7669400
>          37.50%        448
>             37.50%        66080
>       10.42%        0xffff8803f766be00
>           8.33%        96
>              8.33%        66080
>           2.08%        512
>              2.08%        67280
> 
> After:
> 
>   #
>   #       Overhead  ptr / bytes_req / gfp_flags
>   # ..............  ..........................................
>   #
>       37.50%        0xffff8803f7669400
>          37.50%        448
>             37.50%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC

So, I'm not getting this translation, it looks just like before. So I
tried the non-hierarchy mode and got this [FAILED TO PARSE] on each
line:

Samples: 107  of event 'kmem:kmalloc', Event count (approx.): 107
Overhead  Trace output 
  33.64%  [FAILED TO PARSE] call_site=0xffffffff811a0747 ptr=0xffff880109c54000 bytes_req=4096 bytes_alloc=4096 gfp_flags=37748928                           ▒

Investigating...


>       10.42%        0xffff8803f766be00
>           8.33%        96
>              8.33%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
>           2.08%        512
>              2.08%        GFP_KERNEL|GFP_NOWARN|GFP_REPEAT|GFP
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/util/hist.c | 2 +-
>  tools/perf/util/sort.c | 3 +++
>  2 files changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> index cc849d326211..9b3f582867d6 100644
> --- a/tools/perf/util/hist.c
> +++ b/tools/perf/util/hist.c
> @@ -1125,7 +1125,7 @@ static struct hist_entry *hierarchy_insert_entry(struct hists *hists,
>  	new->fmt = fmt;
>  
>  	/* some fields are now passed to 'new' */
> -	if (perf_hpp__is_trace_entry(fmt))
> +	if (perf_hpp__is_trace_entry(fmt) || perf_hpp__is_dynamic_entry(fmt))
>  		he->trace_output = NULL;
>  	else
>  		new->trace_output = NULL;
> diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
> index e948fcac0939..3b1b4018f111 100644
> --- a/tools/perf/util/sort.c
> +++ b/tools/perf/util/sort.c
> @@ -1767,6 +1767,9 @@ static int __sort__hde_entry(struct perf_hpp_fmt *fmt, struct perf_hpp *hpp,
>  	if (hde->raw_trace)
>  		goto raw_field;
>  
> +	if (!he->trace_output)
> +		he->trace_output = get_trace_output(he);
> +
>  	field = hde->field;
>  	namelen = strlen(field->name);
>  	str = he->trace_output;
> -- 
> 2.7.1

[toc] | [prev] | [next] | [standalone]

#1344729

FromArnaldo Carvalho de Melo <acme@kernel.org>
Date2016-02-26 22:50 +0100
Message-ID<r6yqU-W4-39@gated-at.bofh.it>
In reply to#1344725
Em Fri, Feb 26, 2016 at 06:43:07PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Sat, Feb 27, 2016 at 03:52:46AM +0900, Namhyung Kim escreveu:
> >       37.50%        0xffff8803f7669400
> >          37.50%        448
> >             37.50%        66080
> >       10.42%        0xffff8803f766be00
> >           8.33%        96
> >              8.33%        66080
> >           2.08%        512
> >              2.08%        67280
> > 
> > After:
> > 
> >   #       Overhead  ptr / bytes_req / gfp_flags
> >   # ..............  ..........................................
> >       37.50%        0xffff8803f7669400
> >          37.50%        448
> >             37.50%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
> 
> So, I'm not getting this translation, it looks just like before. So I
> tried the non-hierarchy mode and got this [FAILED TO PARSE] on each
> line:
> 
> Samples: 107  of event 'kmem:kmalloc', Event count (approx.): 107
> Overhead  Trace output 
>   33.64%  [FAILED TO PARSE] call_site=0xffffffff811a0747 ptr=0xffff880109c54000 bytes_req=4096 bytes_alloc=4096 gfp_flags=37748928                           ▒
> 
> Investigating...

Further (lots of!) info:

[root@jouet ~]# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format 
name: kmalloc
ID: 424
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:8;	signed:0;
	field:const void * ptr;	offset:16;	size:8;	signed:0;
	field:size_t bytes_req;	offset:24;	size:8;	signed:0;
	field:size_t bytes_alloc;	offset:32;	size:8;	signed:0;
	field:gfp_t gfp_flags;	offset:40;	size:4;	signed:0;

print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)((((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) | (( gfp_t)0x1000u) | (( gfp_t)0x200u)) & ~(( gfp_t)0x2000000u)), "GFP_TRANSHUGE"}, {(unsigned long)((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)(((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)), "GFP_USER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x10u)), "GFP_TEMPORARY"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u)), "GFP_NOFS"}, {(unsigned long)((( gfp_t)0x20u)|(( gfp_t)0x80000u)|(( gfp_t)0x2000000u)), "GFP_ATOMIC"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u))), "GFP_NOIO"}, {(unsigned long)(( gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)(( gfp_t)0x80000u), "GFP_ATOMIC"}, {(unsigned long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)(( gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned long)(( gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"}, {(unsigned long)(( gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x2000u), "GFP_MEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u), "GFP_HARDWALL"}, {(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)(( gfp_t)0x10u), "GFP_RECLAIMABLE"}, {(unsigned long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0x200000u), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_DIRECT_RECLAIM"}, {(unsigned long)(( gfp_t)0x2000000u), "GFP_KSWAPD_RECLAIM"}, {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT"
[root@jouet ~]# uname -a
Linux jouet 4.5.0-rc4 #1 SMP Mon Feb 22 15:53:36 BRT 2016 x86_64 x86_64 x86_64 GNU/Linux
[root@jouet ~]#

[toc] | [prev] | [next] | [standalone]

#1344734

FromArnaldo Carvalho de Melo <acme@kernel.org>
Date2016-02-26 23:10 +0100
Message-ID<r6yKe-1lH-3@gated-at.bofh.it>
In reply to#1344729
Em Fri, Feb 26, 2016 at 06:45:06PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Fri, Feb 26, 2016 at 06:43:07PM -0300, Arnaldo Carvalho de Melo escreveu:
> > Em Sat, Feb 27, 2016 at 03:52:46AM +0900, Namhyung Kim escreveu:
> > >       37.50%        0xffff8803f7669400
> > >          37.50%        448
> > >             37.50%        66080
> > >       10.42%        0xffff8803f766be00
> > >           8.33%        96
> > >              8.33%        66080
> > >           2.08%        512
> > >              2.08%        67280
> > > 
> > > After:
> > > 
> > >   #       Overhead  ptr / bytes_req / gfp_flags
> > >   # ..............  ..........................................
> > >       37.50%        0xffff8803f7669400
> > >          37.50%        448
> > >             37.50%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
> > 
> > So, I'm not getting this translation, it looks just like before. So I
> > tried the non-hierarchy mode and got this [FAILED TO PARSE] on each
> > line:
> > 
> > Samples: 107  of event 'kmem:kmalloc', Event count (approx.): 107
> > Overhead  Trace output 
> >   33.64%  [FAILED TO PARSE] call_site=0xffffffff811a0747 ptr=0xffff880109c54000 bytes_req=4096 bytes_alloc=4096 gfp_flags=37748928                           ▒
> > 
> > Investigating...
> 
> Further (lots of!) info:
> 
> [root@jouet ~]# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format 
> name: kmalloc
> ID: 424
> 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:8;	signed:0;
> 	field:const void * ptr;	offset:16;	size:8;	signed:0;
> 	field:size_t bytes_req;	offset:24;	size:8;	signed:0;
> 	field:size_t bytes_alloc;	offset:32;	size:8;	signed:0;
> 	field:gfp_t gfp_flags;	offset:40;	size:4;	signed:0;
> 
> print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)((((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) | (( gfp_t)0x1000u) | (( gfp_t)0x200u)) & ~(( gfp_t)0x2000000u)), "GFP_TRANSHUGE"}, {(unsigned long)((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)(((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)), "GFP_USER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x10u)), "GFP_TEMPORARY"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u)), "GFP_NOFS"}, {(unsigned long)((( gfp_t)0x20u)|(( gfp_t)0x80000u)|(( gfp_t)0x2000000u)), "GFP_ATOMIC"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u))), "GFP_NOIO"}, {(unsigned long)(( gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)(( gfp_t)0x80000u), "GFP_ATOMIC"}, {(unsigned long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)(( gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned long)(( gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"}, {(unsigned long)(( gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x2000u), "GFP_MEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u), "GFP_HARDWALL"}, {(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)(( gfp_t)0x10u), "GFP_RECLAIMABLE"}, {(unsigned long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0x200000u), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_DIRECT_RECLAIM"}, {(unsigned long)(( gfp_t)0x2000000u), "GFP_KSWAPD_RECLAIM"}, {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT"
> [root@jouet ~]# uname -a
> Linux jouet 4.5.0-rc4 #1 SMP Mon Feb 22 15:53:36 BRT 2016 x86_64 x86_64 x86_64 GNU/Linux
> [root@jouet ~]#

It is exploding at this depth, not liking how gfp_flags is described, problem
seems to be in this function, this __print_flags() long thing.

Steven, does this look familiar?

(gdb) bt
#0  process_fields (event=0x19b95e0, list=0x19bb0d0, tok=0x7fffffffa0e8) at event-parse.c:2527
#1  0x000000000058410d in process_flags (event=0x19b95e0, arg=0x19bb0b0, tok=0x7fffffffa178) at event-parse.c:2567
#2  0x0000000000584eba in process_function (event=0x19b95e0, arg=0x19bb0b0, token=0x19bb130 "gfp_flags", tok=0x7fffffffa178) at event-parse.c:2989
#3  0x0000000000585231 in process_arg_token (event=0x19b95e0, arg=0x19bb0b0, tok=0x7fffffffa218, type=EVENT_DELIM) at event-parse.c:3060
#4  0x0000000000581f2c in process_arg (event=0x19b95e0, arg=0x19bb0b0, tok=0x7fffffffa218) at event-parse.c:1698
#5  0x000000000058208a in process_cond (event=0x19b95e0, top=0x19bafd0, tok=0x7fffffffa308) at event-parse.c:1746
#6  0x0000000000582772 in process_op (event=0x19b95e0, arg=0x19bafd0, tok=0x7fffffffa308) at event-parse.c:1941
#7  0x0000000000585573 in event_read_print_args (event=0x19b95e0, list=0x19baf70) at event-parse.c:3153
#8  0x0000000000585778 in event_read_print (event=0x19b95e0) at event-parse.c:3225
#9  0x000000000058b402 in __pevent_parse_format (eventp=0x7fffffffa458, pevent=0x19b94c0, 
    buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at event-parse.c:5916
#10 0x000000000058b5bb in __pevent_parse_event (pevent=0x19b94c0, eventp=0x7fffffffa458, 
    buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at event-parse.c:5970
#11 0x000000000058b68f in pevent_parse_event (pevent=0x19b94c0, 
    buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at event-parse.c:6033
#12 0x00000000004f2c3c in parse_event_file (pevent=0x19b94c0, 
    buf=0x19b96e0 "name: kmem_cache_alloc\nID: 423\nformat:\n\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n\tfield:unsigned char common_preempt"..., size=2983, sys=0x19b96c0 "kmem") at util/trace-event-parse.c:171
#13 0x0000000000502e16 in read_event_file (pevent=0x19b94c0, sys=0x19b96c0 "kmem", size=2983) at util/trace-event-read.c:293
#14 0x0000000000502f51 in read_event_files (pevent=0x19b94c0) at util/trace-event-read.c:336
#15 0x00000000005032e2 in trace_report (fd=3, tevent=0x19b5a80, __repipe=false) at util/trace-event-read.c:417
#16 0x00000000004d6303 in process_tracing_data (section=0x19b93b0, ph=0x19b57c0, fd=3, data=0x19b5a80) at util/header.c:1595
#17 0x00000000004d8f84 in perf_file_section__process (section=0x19b93b0, ph=0x19b57c0, feat=1, fd=3, data=0x19b5a80) at util/header.c:2704
#18 0x00000000004d8878 in perf_header__process_sections (header=0x19b57c0, fd=3, data=0x19b5a80, process=0x4d8e7e <perf_file_section__process>)
    at util/header.c:2487
#19 0x00000000004d9860 in perf_session__read_header (session=0x19b57c0) at util/header.c:2922
#20 0x00000000004e8c59 in perf_session__open (session=0x19b57c0) at util/session.c:32
#21 0x00000000004e915c in perf_session__new (file=0x7fffffffc8a0, repipe=false, tool=0x7fffffffc990) at util/session.c:139
#22 0x0000000000436dfb in cmd_report (argc=0, argv=0x7fffffffe330, prefix=0x0) at builtin-report.c:878
#23 0x000000000049dbb3 in run_builtin (p=0x90d560 <commands+192>, argc=1, argv=0x7fffffffe330) at perf.c:390
#24 0x000000000049de1b in handle_internal_command (argc=1, argv=0x7fffffffe330) at perf.c:451
#25 0x000000000049df60 in run_argv (argcp=0x7fffffffe18c, argv=0x7fffffffe180) at perf.c:497
#26 0x000000000049e2f7 in main (argc=1, argv=0x7fffffffe330) at perf.c:622
(gdb)

[toc] | [prev] | [next] | [standalone]

#1344754

FromArnaldo Carvalho de Melo <acme@kernel.org>
Date2016-02-26 23:30 +0100
Message-ID<r6z3A-1uq-19@gated-at.bofh.it>
In reply to#1344734
Em Fri, Feb 26, 2016 at 07:08:19PM -0300, Arnaldo Carvalho de Melo escreveu:
> > 
> > print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)((((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) | (( gfp_t)0x1000u) | (( gfp_t)0x200u)) & ~(( gfp_t)0x2000000u)), "GFP_TRANSHUGE"}, {(unsigned long)((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) | (( gfp_t)0x08u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)(((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)), "GFP_USER"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x10u)), "GFP_TEMPORARY"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) | (( gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u)), "GFP_NOFS"}, {(unsigned long)((( gfp_t)0x20u)|(( gfp_t)0x80000u)|(( gfp_t)0x2000000u)), "GFP_ATOMIC"}, {(unsigned long)((( gfp_t)(0x400000u|0x2000000u))), "GFP_NOIO"}, {(unsigned long)(( gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)(( gfp_t)0x80000u), "GFP_ATOMIC"}, {(unsigned long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)(( gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned long)(( gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"}, {(unsigned long)(( gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x2000u), "GFP_MEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u), "GFP_HARDWALL"}, {(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)(( gfp_t)0x10u), "GFP_RECLAIMABLE"}, {(unsigned long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0x200000u), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_DIRECT_RECLAIM"}, {(unsigned long)(( gfp_t)0x2000000u), "GFP_KSWAPD_RECLAIM"}, {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT"
> > [root@jouet ~]# uname -a
> > Linux jouet 4.5.0-rc4 #1 SMP Mon Feb 22 15:53:36 BRT 2016 x86_64 x86_64 x86_64 GNU/Linux
> > [root@jouet ~]#
> 
> It is exploding at this depth, not liking how gfp_flags is described, problem
> seems to be in this function, this __print_flags() long thing.
> 
> Steven, does this look familiar?

Steven, the same tool works when running on an earlier kernel, i.e.
libtraceevent manages to parse that gfp_flags function, while on 4.5-rc it doesn't, ideas?




[root@felicio ~]# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format
name: kmalloc
ID: 411
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:8;	signed:0;
	field:const void * ptr;	offset:16;	size:8;	signed:0;
	field:size_t bytes_req;	offset:24;	size:8;	signed:0;
	field:size_t bytes_alloc;	offset:32;	size:8;	signed:0;
	field:gfp_t gfp_flags;	offset:40;	size:4;	signed:0;

print fmt: "call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s", REC->call_site, REC->ptr, REC->bytes_req, REC->bytes_alloc, (REC->gfp_flags) ? __print_flags(REC->gfp_flags, "|", {(unsigned long)(((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u) | (( gfp_t)0x02u) | (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) | (( gfp_t)0x1000u) | (( gfp_t)0x200u) | (( gfp_t)0x400000u)), "GFP_TRANSHUGE"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u) | (( gfp_t)0x02u) | (( gfp_t)0x08u)), "GFP_HIGHUSER_MOVABLE"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u) | (( gfp_t)0x02u)), "GFP_HIGHUSER"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x20000u)), "GFP_USER"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u) | (( gfp_t)0x80000u)), "GFP_TEMPORARY"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u) | (( gfp_t)0x80u)), "GFP_KERNEL"}, {(unsigned long)((( gfp_t)0x10u) | (( gfp_t)0x40u)), "GFP_NOFS"}, {(unsigned long)((( gfp_t)0x20u)), "GFP_ATOMIC"}, {(unsigned long)((( gfp_t)0x10u)), "GFP_NOIO"}, {(unsigned long)(( gfp_t)0x20u), "GFP_HIGH"}, {(unsigned long)(( gfp_t)0x10u), "GFP_WAIT"}, {(unsigned long)(( gfp_t)0x40u), "GFP_IO"}, {(unsigned long)(( gfp_t)0x100u), "GFP_COLD"}, {(unsigned long)(( gfp_t)0x200u), "GFP_NOWARN"}, {(unsigned long)(( gfp_t)0x400u), "GFP_REPEAT"}, {(unsigned long)(( gfp_t)0x800u), "GFP_NOFAIL"}, {(unsigned long)(( gfp_t)0x1000u), "GFP_NORETRY"}, {(unsigned long)(( gfp_t)0x4000u), "GFP_COMP"}, {(unsigned long)(( gfp_t)0x8000u), "GFP_ZERO"}, {(unsigned long)(( gfp_t)0x10000u), "GFP_NOMEMALLOC"}, {(unsigned long)(( gfp_t)0x2000u), "GFP_MEMALLOC"}, {(unsigned long)(( gfp_t)0x20000u), "GFP_HARDWALL"}, {(unsigned long)(( gfp_t)0x40000u), "GFP_THISNODE"}, {(unsigned long)(( gfp_t)0x80000u), "GFP_RECLAIMABLE"}, {(unsigned long)(( gfp_t)0x100000u), "GFP_KMEMCG"}, {(unsigned long)(( gfp_t)0x08u), "GFP_MOVABLE"}, {(unsigned long)(( gfp_t)0x200000u), "GFP_NOTRACK"}, {(unsigned long)(( gfp_t)0x400000u), "GFP_NO_KSWAPD"}, {(unsigned long)(( gfp_t)0x800000u), "GFP_OTHER_NODE"} ) : "GFP_NOWAIT"
[root@felicio ~]# uname -r
3.10.0-350.el7perf_sync_4_4_v1.x86_64
[root@felicio ~]# perf report | head -15
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 128  of event 'kmem:kmalloc'
# Event count (approx.): 128
#
# Overhead  Trace output                                                                                   
# ........  ......................................................................................................................
#
    34.38%  call_site=ffffffff811655cd ptr=0xffff880233c0f000 bytes_req=4096 bytes_alloc=4096 gfp_flags=GFP_KERNEL
    14.84%  call_site=ffffffffa02e25de ptr=0xffff880231f12800 bytes_req=1025 bytes_alloc=2048 gfp_flags=GFP_KERNEL
     4.69%  call_site=ffffffff811ed957 ptr=0xffff880231765700 bytes_req=256 bytes_alloc=256 gfp_flags=GFP_KERNEL|GFP_ZERO
     4.69%  call_site=ffffffff8129461c ptr=0xffff880231563d60 bytes_req=16 bytes_alloc=16 gfp_flags=GFP_KERNEL|GFP_ZERO
[root@felicio ~]#

[toc] | [prev] | [next] | [standalone]

#1344783

FromSteven Rostedt <rostedt@goodmis.org>
Date2016-02-26 23:30 +0100
Message-ID<r6z3C-1uq-77@gated-at.bofh.it>
In reply to#1344734
On Fri, 26 Feb 2016 19:08:19 -0300
Arnaldo Carvalho de Melo <acme@kernel.org> wrote:


> It is exploding at this depth, not liking how gfp_flags is described, problem
> seems to be in this function, this __print_flags() long thing.
> 
> Steven, does this look familiar?
> 
>

Hmm, trace-cmd has the same issue. I just having noticed.

I'll see if I can fix it.

-- Steve

[toc] | [prev] | [next] | [standalone]

#1344793

FromArnaldo Carvalho de Melo <acme@kernel.org>
Date2016-02-26 23:40 +0100
Message-ID<r6zdg-1zD-9@gated-at.bofh.it>
In reply to#1344783
Em Fri, Feb 26, 2016 at 05:26:02PM -0500, Steven Rostedt escreveu:
> On Fri, 26 Feb 2016 19:08:19 -0300
> Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> 
> 
> > It is exploding at this depth, not liking how gfp_flags is described, problem
> > seems to be in this function, this __print_flags() long thing.
> > 
> > Steven, does this look familiar?
> > 
> >
> 
> Hmm, trace-cmd has the same issue. I just having noticed.
> 
> I'll see if I can fix it.

Ok, this works well with an RHEL kernel being tested with tons of perf
backports by Jiri, its just with 4.5-rc kernels that this is exploding.

- Arnaldo

[toc] | [prev] | [next] | [standalone]

#1344814

FromJiri Olsa <jolsa@redhat.com>
Date2016-02-27 00:20 +0100
Message-ID<r6zPY-26L-9@gated-at.bofh.it>
In reply to#1344793
On Fri, Feb 26, 2016 at 07:37:05PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Fri, Feb 26, 2016 at 05:26:02PM -0500, Steven Rostedt escreveu:
> > On Fri, 26 Feb 2016 19:08:19 -0300
> > Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> > 
> > 
> > > It is exploding at this depth, not liking how gfp_flags is described, problem
> > > seems to be in this function, this __print_flags() long thing.
> > > 
> > > Steven, does this look familiar?
> > > 
> > >
> > 
> > Hmm, trace-cmd has the same issue. I just having noticed.
> > 
> > I'll see if I can fix it.
> 
> Ok, this works well with an RHEL kernel being tested with tons of perf
> backports by Jiri, its just with 4.5-rc kernels that this is exploding.

thanks, I isolated this down to the:
  156174999dd1 perf/intel/x86: Enlarge the PEBS buffer

it's related to the FREERUNNING PEBS patchset that allows
store more than 1 event in PEBS buffer

seems like Core CPU doesn't like the default setup and
delays in msr access, which makes the watchdog scream

jirka

[toc] | [prev] | [next] | [standalone]

#1344825

FromJiri Olsa <jolsa@redhat.com>
Date2016-02-27 00:20 +0100
Message-ID<r6zPZ-26L-29@gated-at.bofh.it>
In reply to#1344814
On Sat, Feb 27, 2016 at 12:12:08AM +0100, Jiri Olsa wrote:
> On Fri, Feb 26, 2016 at 07:37:05PM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Fri, Feb 26, 2016 at 05:26:02PM -0500, Steven Rostedt escreveu:
> > > On Fri, 26 Feb 2016 19:08:19 -0300
> > > Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> > > 
> > > 
> > > > It is exploding at this depth, not liking how gfp_flags is described, problem
> > > > seems to be in this function, this __print_flags() long thing.
> > > > 
> > > > Steven, does this look familiar?
> > > > 
> > > >
> > > 
> > > Hmm, trace-cmd has the same issue. I just having noticed.
> > > 
> > > I'll see if I can fix it.
> > 
> > Ok, this works well with an RHEL kernel being tested with tons of perf
> > backports by Jiri, its just with 4.5-rc kernels that this is exploding.
> 
> thanks, I isolated this down to the:
>   156174999dd1 perf/intel/x86: Enlarge the PEBS buffer
> 
> it's related to the FREERUNNING PEBS patchset that allows
> store more than 1 event in PEBS buffer
> 
> seems like Core CPU doesn't like the default setup and
> delays in msr access, which makes the watchdog scream

heh, wrong thread.. sry ;-)

jirka

[toc] | [prev] | [next] | [standalone]

#1344816 — [PATCH] tools lib traceevent: Add '~' operation within arg_num_eval()

FromSteven Rostedt <rostedt@goodmis.org>
Date2016-02-27 00:20 +0100
Subject[PATCH] tools lib traceevent: Add '~' operation within arg_num_eval()
Message-ID<r6zPY-26L-13@gated-at.bofh.it>
In reply to#1344734
When evaluating values for print flags, if the value included a '~'
operator, the parsing would fail. This broke kmalloc's parsing of:

__print_flags(REC->gfp_flags, "|", {(unsigned
long)((((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) |
(( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) |
(( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) |
(( gfp_t)0x1000u) | (( gfp_t)0x200u)) & ~(( gfp_t)0x2000000u))
                                        ^
                                        |
                                      here

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index c3bd294a63d1..557d8edf07f3 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -2397,6 +2397,12 @@ static int arg_num_eval(struct print_arg *arg, long long *val)
 				break;
 			*val = left + right;
 			break;
+		case '~':
+			ret = arg_num_eval(arg->op.right, &right);
+			if (!ret)
+				break;
+			*val = ~right;
+			break;
 		default:
 			do_warning("unknown op '%s'", arg->op.op);
 			ret = 0;

[toc] | [prev] | [next] | [standalone]

#1344847 — Re: [PATCH] tools lib traceevent: Add '~' operation within arg_num_eval()

FromArnaldo Carvalho de Melo <acme@kernel.org>
Date2016-02-27 00:40 +0100
SubjectRe: [PATCH] tools lib traceevent: Add '~' operation within arg_num_eval()
Message-ID<r6A9j-2hX-11@gated-at.bofh.it>
In reply to#1344816
Em Fri, Feb 26, 2016 at 06:13:28PM -0500, Steven Rostedt escreveu:
> When evaluating values for print flags, if the value included a '~'
> operator, the parsing would fail. This broke kmalloc's parsing of:
> 
> __print_flags(REC->gfp_flags, "|", {(unsigned
> long)((((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) |
> (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) |
> (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) |
> (( gfp_t)0x1000u) | (( gfp_t)0x200u)) & ~(( gfp_t)0x2000000u))
>                                         ^
>                                         |
>                                       here

Thanks, I'll test this later.

- Arnaldo
> 
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
> diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
> index c3bd294a63d1..557d8edf07f3 100644
> --- a/tools/lib/traceevent/event-parse.c
> +++ b/tools/lib/traceevent/event-parse.c
> @@ -2397,6 +2397,12 @@ static int arg_num_eval(struct print_arg *arg, long long *val)
>  				break;
>  			*val = left + right;
>  			break;
> +		case '~':
> +			ret = arg_num_eval(arg->op.right, &right);
> +			if (!ret)
> +				break;
> +			*val = ~right;
> +			break;
>  		default:
>  			do_warning("unknown op '%s'", arg->op.op);
>  			ret = 0;

[toc] | [prev] | [next] | [standalone]

#1344848 — Re: [PATCH] tools lib traceevent: Add '~' operation within arg_num_eval()

FromDavid Ahern <dsahern@gmail.com>
Date2016-02-27 00:50 +0100
SubjectRe: [PATCH] tools lib traceevent: Add '~' operation within arg_num_eval()
Message-ID<r6AiZ-2oo-1@gated-at.bofh.it>
In reply to#1344816
On 2/26/16 4:13 PM, Steven Rostedt wrote:
> When evaluating values for print flags, if the value included a '~'
> operator, the parsing would fail. This broke kmalloc's parsing of:
>
> __print_flags(REC->gfp_flags, "|", {(unsigned
> long)((((((( gfp_t)(0x400000u|0x2000000u)) | (( gfp_t)0x40u) |
> (( gfp_t)0x80u) | (( gfp_t)0x20000u)) | (( gfp_t)0x02u)) |
> (( gfp_t)0x08u)) | (( gfp_t)0x4000u) | (( gfp_t)0x10000u) |
> (( gfp_t)0x1000u) | (( gfp_t)0x200u)) & ~(( gfp_t)0x2000000u))
>                                          ^
>                                          |
>                                        here
>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---

I've been meaning to chase this down for a few weeks. Worked for me.

Tested-by: David Ahern <dsahern@gmail.com>

[toc] | [prev] | [next] | [standalone]

#1344961 — [tip:perf/core] perf hists: Fix dynamic entry display in hierarchy

Fromtip-bot for Namhyung Kim <tipbot@zytor.com>
Date2016-02-27 10:50 +0100
Subject[tip:perf/core] perf hists: Fix dynamic entry display in hierarchy
Message-ID<r6JFE-XE-11@gated-at.bofh.it>
In reply to#1344580
Commit-ID:  e049d4a3fa194c8aa0d3ca29a9b11b32387ca6e3
Gitweb:     http://git.kernel.org/tip/e049d4a3fa194c8aa0d3ca29a9b11b32387ca6e3
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Sat, 27 Feb 2016 03:52:46 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 26 Feb 2016 19:37:38 -0300

perf hists: Fix dynamic entry display in hierarchy

When dynamic sort key is used it might not show pretty printed output.
This is because the trace output was not set only for the first dynamic
sort key.  During hierarchy_insert_entry() it missed to pass the
trace_output to dynamic entries.  Also even if it did, only first entry
will have it.  Subsequent entries might set it during collapsing stage
but it's not guaranteed.

Before:

  $ perf report --hierarchy --stdio -s ptr,bytes_req,gfp_flags -g none
  #
  #       Overhead  ptr / bytes_req / gfp_flags
  # ..............  ..........................................
  #
      37.50%        0xffff8803f7669400
         37.50%        448
            37.50%        66080
      10.42%        0xffff8803f766be00
          8.33%        96
             8.33%        66080
          2.08%        512
             2.08%        67280

After:

  #
  #       Overhead  ptr / bytes_req / gfp_flags
  # ..............  ..........................................
  #
      37.50%        0xffff8803f7669400
         37.50%        448
            37.50%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
      10.42%        0xffff8803f766be00
          8.33%        96
             8.33%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
          2.08%        512
             2.08%        GFP_KERNEL|GFP_NOWARN|GFP_REPEAT|GFP

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Wang Nan <wangnan0@huawei.com>
Link: http://lkml.kernel.org/r/1456512767-1164-4-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/hist.c | 2 +-
 tools/perf/util/sort.c | 3 +++
 2 files changed, 4 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index cc849d3..9b3f582 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -1125,7 +1125,7 @@ static struct hist_entry *hierarchy_insert_entry(struct hists *hists,
 	new->fmt = fmt;
 
 	/* some fields are now passed to 'new' */
-	if (perf_hpp__is_trace_entry(fmt))
+	if (perf_hpp__is_trace_entry(fmt) || perf_hpp__is_dynamic_entry(fmt))
 		he->trace_output = NULL;
 	else
 		new->trace_output = NULL;
diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index 2beb7a6..d26c6b9 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -1764,6 +1764,9 @@ static int __sort__hde_entry(struct perf_hpp_fmt *fmt, struct perf_hpp *hpp,
 	if (hde->raw_trace)
 		goto raw_field;
 
+	if (!he->trace_output)
+		he->trace_output = get_trace_output(he);
+
 	field = hde->field;
 	namelen = strlen(field->name);
 	str = he->trace_output;

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web