perf report: Fix comparing of dynamic entries

When hist_entry__cmp() and hist_entry__collapse() are called, it should check the dynamic entry is comparing matching hists only. Otherwise it might access different hists resulting in incorrect output.

---
 tools/perf/util/hist.c | 8 ++++++++
 1 file changed, 8 insertions(+)

index 75dc41d2dca9..cc849d326211 100644
@@ -1002,6 +1002,10 @@ hist_entry__cmp(struct hist_entry *left, struct hist_entry *right)
 	int64_t cmp = 0;
 
 	hists__for_each_sort_list(hists, fmt) {
+		if (perf_hpp__is_dynamic_entry(fmt) &&
+		    !perf_hpp__defined_dynamic_entry(fmt, hists))
+			continue;
+
 		cmp = fmt->cmp(fmt, left, right);
 		if (cmp)
 			break;

@@ -1018,6 +1022,10 @@ hist_entry__collapse(struct hist_entry *left, struct hist_entry *right)
 	int64_t cmp = 0;
 
 	hists__for_each_sort_list(hists, fmt) {
+		if (perf_hpp__is_dynamic_entry(fmt) &&
+		    !perf_hpp__defined_dynamic_entry(fmt, hists))
+			continue;
+
 		cmp = fmt->collapse(fmt, left, right);
 		if (cmp)
 			break;

2.7.1

When dynamic entries are used in the hierarchy mode with multiple events, the output might not be aligned properly. In the hierarchy mode, the each sort column is indented using total number of sort keys. So it keeps track of number of sort keys when adding them. However a dynamic sort key can be added more than once when multiple events have same field names. This results in unnecessarily long indentation in the output.

For example perf kmem records following events:

  $ perf evlist --trace-fields -i perf.data.kmem
  kmem:kmalloc: trace_fields: call_site,ptr,bytes_req,bytes_alloc,gfp_flags
  kmem:kmalloc_node: trace_fields: call_site,ptr,bytes_req,bytes_alloc,gfp_flags,node
  kmem:kfree: trace_fields: call_site,ptr
  kmem:kmem_cache_alloc: trace_fields: call_site,ptr,bytes_req,bytes_alloc,gfp_flags
  kmem:kmem_cache_alloc_node: trace_fields: call_site,ptr,bytes_req,bytes_alloc,gfp_flags,node
  kmem:kmem_cache_free: trace_fields: call_site,ptr
  kmem:mm_page_alloc: trace_fields: page,order,gfp_flags,migratetype
  kmem:mm_page_free: trace_fields: page,order

As you can see, many field names shared between kmem events. So adding 'ptr' dynamic sort key alone will set nr_sort_keys to 6. And this adds many unnecessary spaces between columns.

Before:

  $ perf report -i perf.data.kmem --hierarchy -s ptr -g none --stdio
  ...
  #                Overhead                 ptr
  # .......................  ...................................
  #
      99.89%                 0xffff8803ffb79720
       0.06%                 0xffff8803d228a000
       0.03%                 0xffff8803f7678f00
       0.00%                 0xffff880401dc5280
       0.00%                 0xffff880406172380
       0.00%                 0xffff8803ffac3a00
       0.00%                 0xffff8803ffac1600

After:

# Overhead ptr

  # ........  ....................
  #
      99.89%  0xffff8803ffb79720
       0.06%  0xffff8803d228a000
       0.03%  0xffff8803f7678f00
       0.00%  0xffff880401dc5280
       0.00%  0xffff880406172380
       0.00%  0xffff8803ffac3a00
       0.00%  0xffff8803ffac1600

---
 tools/perf/ui/browsers/hists.c |  6 +++---
 tools/perf/ui/stdio/hist.c     |  6 +++---
 tools/perf/util/hist.h         |  1 +
 tools/perf/util/sort.c         | 19 +++++++++++++++++++
 4 files changed, 26 insertions(+), 6 deletions(-)

index 71c6d510390f..5f74c6723c53 100644
@@ -1547,7 +1547,7 @@ static int hists_browser__scnprintf_hierarchy_headers(struct hist_browser *brows
 	struct perf_hpp_fmt *fmt;
 	size_t ret = 0;
 	int column = 0;
-	int nr_sort_keys = hists->hpp_list->nr_sort_keys;
+	int nr_sort_keys = hists->nr_sort_keys;
 	bool first = true;
 
 	ret = scnprintf(buf, size, " ");

@@ -1632,7 +1632,7 @@ static unsigned int hist_browser__refresh(struct ui_browser *browser)
 	u16 header_offset = 0;
 	struct rb_node *nd;
 	struct hist_browser *hb = container_of(browser, struct hist_browser, b);
-	int nr_sort = hb->hists->hpp_list->nr_sort_keys;
+	int nr_sort = hb->hists->nr_sort_keys;
 
 	if (hb->show_headers) {
 		hist_browser__show_headers(hb);

@@ -1969,7 +1969,7 @@ static int hist_browser__fprintf(struct hist_browser *browser, FILE *fp)
 	struct rb_node *nd = hists__filter_entries(rb_first(browser->b.entries),
 						   browser->min_pcnt);
 	int printed = 0;
-	int nr_sort = browser->hists->hpp_list->nr_sort_keys;
+	int nr_sort = browser->hists->nr_sort_keys;
 
 	while (nd) {
 		struct hist_entry *h = rb_entry(nd, struct hist_entry, rb_node);

index b3bdfcb245f9..5733d6c196be 100644
@@ -495,7 +495,7 @@ static int hist_entry__fprintf(struct hist_entry *he, size_t size,
 		size = hpp.size = bfsz;
 
 	if (symbol_conf.report_hierarchy) {
-		int nr_sort = hists->hpp_list->nr_sort_keys;
+		int nr_sort = hists->nr_sort_keys;
 
 		return hist_entry__hierarchy_fprintf(he, &hpp, nr_sort,
 						     hists, fp);

@@ -529,7 +529,7 @@ static int print_hierarchy_header(struct hists *hists, struct perf_hpp *hpp,
 	unsigned header_width = 0;
 	struct perf_hpp_fmt *fmt;
 
-	nr_sort = hists->hpp_list->nr_sort_keys;
+	nr_sort = hists->nr_sort_keys;
 
 	/* preserve max indent depth for column headers */
 	print_hierarchy_indent(sep, nr_sort, spaces, fp);

@@ -728,7 +728,7 @@ print_entries:
 		 * display "no entry >= x.xx%" message.
 		 */
 		if (!h->leaf && !hist_entry__has_hierarchy_children(h, min_pcnt)) {
-			int nr_sort = hists->hpp_list->nr_sort_keys;
+			int nr_sort = hists->nr_sort_keys;
 
 			print_hierarchy_indent(sep, nr_sort + h->depth + 1, spaces, fp);
 			fprintf(fp, "%*sno entry >= %.2f%%\n", indent, "", min_pcnt);

index 283a3e11358c..f4ef513527ba 100644
@@ -78,6 +78,7 @@ struct hists {
 	u16			col_len[HISTC_NR_COLS];
 	int			socket_filter;
 	struct perf_hpp_list	*hpp_list;
+	int			nr_sort_keys;
 };
 
 struct hist_entry_iter;

index 83b218c57fe2..e948fcac0939 100644
@@ -2641,6 +2641,9 @@ out:
 int setup_sorting(struct perf_evlist *evlist)
 {
 	int err;
+	struct hists *hists;
+	struct perf_evsel *evsel;
+	struct perf_hpp_fmt *fmt;
 
 	err = __setup_sorting(evlist);
 	if (err < 0)

@@ -2652,6 +2655,22 @@ int setup_sorting(struct perf_evlist *evlist)
 			return err;
 	}
 
+	evlist__for_each(evlist, evsel) {
+		hists = evsel__hists(evsel);
+		hists->nr_sort_keys = perf_hpp_list.nr_sort_keys;
+
+		/*
+		 * If dynamic entries were used, it might add multiple
+		 * entries to each evsel for a single field name.  Set
+		 * actual number of sort keys for each hists.
+		 */
+		perf_hpp_list__for_each_sort_list(&perf_hpp_list, fmt) {
+			if (perf_hpp__is_dynamic_entry(fmt) &&
+			    !perf_hpp__defined_dynamic_entry(fmt, hists))
+				hists->nr_sort_keys--;
+		}
+	}
+
 	reset_dimensions();
 
 	/*

2.7.1

The dynamic entries are right-aligned unlike other entries since it usually has numeric value. But for the hierarchy mode, left alignment is more appropriate IMHO. Also trim spaces on the left so that we can easily identify the hierarchy.

Before:

  $ perf report --hierarchy -i perf.data.kmem -s gfp_flags,ptr,bytes_req --stdio -g none
  ...
  #
  #       Overhead                                        gfp_flags /                ptr /          bytes_req
  # ..............  .................................................................................................
  #
      91.67%                   GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
         37.50%        0xffff8803f7669400
            37.50%                       448
          8.33%        0xffff8803f766be00
             8.33%                        96
          4.17%        0xffff8800d156dc00
             4.17%                       704

After:

# Overhead gfp_flags / ptr / bytes_req

  # ..............  ....................................
  #
      91.67%        GFP_ATOMIC|GFP_NOWARN|GFP_NOMEMALLOC
         37.50%        0xffff8803f7669400
            37.50%        448
          8.33%        0xffff8803f766be00
             8.33%        96
          4.17%        0xffff8800d156dc00
             4.17%        704

---
 tools/perf/ui/browsers/hists.c | 16 ++++++++++++++--
 tools/perf/ui/stdio/hist.c     | 28 +++++++++++++++++++---------
 2 files changed, 33 insertions(+), 11 deletions(-)

index 5f74c6723c53..5ffffcb1e3c5 100644
@@ -1400,8 +1400,13 @@ static int hist_browser__show_hierarchy_entry(struct hist_browser *browser,
 		if (fmt->color) {
 			width -= fmt->color(fmt, &hpp, entry);
 		} else {
+			int i = 0;
+
 			width -= fmt->entry(fmt, &hpp, entry);
-			ui_browser__printf(&browser->b, "%s", s);
+			ui_browser__printf(&browser->b, "%s", ltrim(s));
+
+			while (isspace(s[i++]))
+				width++;
 		}
 	}
 

@@ -1576,6 +1581,8 @@ static int hists_browser__scnprintf_hierarchy_headers(struct hist_browser *brows
 		return ret;
 
 	hists__for_each_format(hists, fmt) {
+		char *start;
+
 		if (!perf_hpp__is_sort_entry(fmt) && !perf_hpp__is_dynamic_entry(fmt))
 			continue;
 		if (perf_hpp__should_skip(fmt, hists))

@@ -1593,7 +1600,12 @@ static int hists_browser__scnprintf_hierarchy_headers(struct hist_browser *brows
 		dummy_hpp.buf[ret] = '\0';
 		rtrim(dummy_hpp.buf);
 
-		ret = strlen(dummy_hpp.buf);
+		start = ltrim(dummy_hpp.buf);
+		ret = strlen(start);
+
+		if (start != dummy_hpp.buf)
+			memmove(dummy_hpp.buf, start, ret + 1);
+
 		if (advance_hpp_check(&dummy_hpp, ret))
 			break;
 	}

index 5733d6c196be..6d06fbb365b6 100644
@@ -418,6 +418,7 @@ static int hist_entry__hierarchy_fprintf(struct hist_entry *he,
 	const char *sep = symbol_conf.field_sep;
 	struct perf_hpp_fmt *fmt;
 	char *buf = hpp->buf;
+	size_t size = hpp->size;
 	int ret, printed = 0;
 	bool first = true;
 

@@ -457,6 +458,11 @@ static int hist_entry__hierarchy_fprintf(struct hist_entry *he,
 				(nr_sort_key - 1) * HIERARCHY_INDENT + 2, "");
 	advance_hpp(hpp, ret);
 
+	printed += fprintf(fp, "%s", buf);
+
+	hpp->buf  = buf;
+	hpp->size = size;
+
 	/*
 	 * No need to call hist_entry__snprintf_alignment() since this
 	 * fmt is always the last column in the hierarchy mode.

@@ -467,7 +473,11 @@ static int hist_entry__hierarchy_fprintf(struct hist_entry *he,
 	else
 		fmt->entry(fmt, hpp, he);
 
-	printed += fprintf(fp, "%s\n", buf);
+	/*
+	 * dynamic entries are right-aligned but we want left-aligned
+	 * in the hierarchy mode
+	 */
+	printed += fprintf(fp, "%s\n", ltrim(buf));
 
 	if (symbol_conf.use_callchain && he->leaf) {
 		u64 total = hists__total_period(hists);

@@ -525,6 +535,7 @@ static int print_hierarchy_header(struct hists *hists, struct perf_hpp *hpp,
 {
 	bool first = true;
 	int nr_sort;
+	int depth;
 	unsigned width = 0;
 	unsigned header_width = 0;
 	struct perf_hpp_fmt *fmt;

@@ -558,19 +569,16 @@ static int print_hierarchy_header(struct hists *hists, struct perf_hpp *hpp,
 		if (!first)
 			header_width += fprintf(fp, " / ");
 		else {
-			header_width += fprintf(fp, "%s", sep ?: "  ");
+			fprintf(fp, "%s", sep ?: "  ");
 			first = false;
 		}
 
 		fmt->header(fmt, hpp, hists_to_evsel(hists));
 		rtrim(hpp->buf);
 
-		header_width += fprintf(fp, "%s", hpp->buf);
+		header_width += fprintf(fp, "%s", ltrim(hpp->buf));
 	}
 
-	/* preserve max indent depth for combined sort headers */
-	print_hierarchy_indent(sep, nr_sort, spaces, fp);
-
 	fprintf(fp, "\n# ");
 
 	/* preserve max indent depth for initial dots */

@@ -590,6 +598,7 @@ static int print_hierarchy_header(struct hists *hists, struct perf_hpp *hpp,
 		fprintf(fp, "%.*s", width, dots);
 	}
 
+	depth = 0;
 	hists__for_each_format(hists, fmt) {
 		if (!perf_hpp__is_sort_entry(fmt) && !perf_hpp__is_dynamic_entry(fmt))
 			continue;

@@ -597,15 +606,16 @@ static int print_hierarchy_header(struct hists *hists, struct perf_hpp *hpp,
 			continue;
 
 		width = fmt->width(fmt, hpp, hists_to_evsel(hists));
+		width += depth * HIERARCHY_INDENT;
+
 		if (width > header_width)
 			header_width = width;
+
+		depth++;
 	}
 
 	fprintf(fp, "%s%-.*s", sep ?: "  ", header_width, dots);
 
-	/* preserve max indent depth for dots under sort headers */
-	print_hierarchy_indent(sep, nr_sort, dots, fp);
-
 	fprintf(fp, "\n#\n");
 
 	return 2;

2.7.1

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

---
 tools/perf/util/hist.c | 2 +-
 tools/perf/util/sort.c | 3 +++
 2 files changed, 4 insertions(+), 1 deletion(-)

index cc849d326211..9b3f582867d6 100644
@@ -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;

index e948fcac0939..3b1b4018f111 100644
@@ -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

Em Sat, Feb 27, 2016 at 03:52:46AM +0900, Namhyung Kim escreveu:

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...

Em Fri, Feb 26, 2016 at 06:43:07PM -0300, Arnaldo Carvalho de Melo escreveu:

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 ~]#

Em Fri, Feb 26, 2016 at 06:45:06PM -0300, Arnaldo Carvalho de Melo escreveu:

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)

Em Fri, Feb 26, 2016 at 07:08:19PM -0300, Arnaldo Carvalho de Melo escreveu:

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 ~]#

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

I'll see if I can fix it.

-- Steve

Em Fri, Feb 26, 2016 at 05:26:02PM -0500, Steven Rostedt escreveu:

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

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

heh, wrong thread.. sry ;-)

jirka

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

---

index c3bd294a63d1..557d8edf07f3 100644
@@ -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;

Em Fri, Feb 26, 2016 at 06:13:28PM -0500, Steven Rostedt escreveu:

Thanks, I'll test this later.

- Arnaldo

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

Arnaldo: have not seen this one hit your tree. Did it fall through the cracks?

Em Thu, Mar 10, 2016 at 09:16:41AM -0700, David Ahern escreveu:

Yeap, thanks for the reminder, applied.

- Arnaldo

The column width of dynamic entries is updated when comparing hist entries. However some unique entries can miss the chance to update. So move the update to output resort stage to make sure every entry will get called before display.

To do that, abuse ->sort callback to update the width when the third argument is NULL. When resorting entries in normal path, it never be NULL so it should be fine IMHO.

Before:

# 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   <-- here

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_NOMEMALLOC

---
 tools/perf/util/hist.c | 11 +++++++++++
 tools/perf/util/sort.c |  8 +++++---
 2 files changed, 16 insertions(+), 3 deletions(-)

index 9b3f582867d6..4b8b67bc0cd8 100644
@@ -1371,6 +1371,10 @@ static void hierarchy_insert_output_entry(struct rb_root *root,
 
 	rb_link_node(&he->rb_node, parent, p);
 	rb_insert_color(&he->rb_node, root);
+
+	/* update column width of dynamic entry */
+	if (perf_hpp__is_dynamic_entry(he->fmt))
+		he->fmt->sort(he->fmt, he, NULL);
 }
 
 static void hists__hierarchy_output_resort(struct hists *hists,

@@ -1440,6 +1444,7 @@ static void __hists__insert_output_entry(struct rb_root *entries,
 	struct rb_node **p = &entries->rb_node;
 	struct rb_node *parent = NULL;
 	struct hist_entry *iter;
+	struct perf_hpp_fmt *fmt;
 
 	if (use_callchain) {
 		if (callchain_param.mode == CHAIN_GRAPH_REL) {

@@ -1466,6 +1471,12 @@ static void __hists__insert_output_entry(struct rb_root *entries,
 
 	rb_link_node(&he->rb_node, parent, p);
 	rb_insert_color(&he->rb_node, entries);
+
+	perf_hpp_list__for_each_sort_list(&perf_hpp_list, fmt) {
+		if (perf_hpp__is_dynamic_entry(fmt) &&
+		    perf_hpp__defined_dynamic_entry(fmt, he->hists))
+			fmt->sort(fmt, he, NULL);  /* update column width */
+	}
 }
 
 static void output_resort(struct hists *hists, struct ui_progress *prog,

index 3b1b4018f111..1457c9d975a0 100644
@@ -1819,6 +1819,11 @@ static int64_t __sort__hde_cmp(struct perf_hpp_fmt *fmt,
 
 	hde = container_of(fmt, struct hpp_dynamic_entry, hpp);
 
+	if (b == NULL) {
+		update_dynamic_len(hde, a);
+		return 0;
+	}
+
 	field = hde->field;
 	if (field->flags & FIELD_IS_DYNAMIC) {
 		unsigned long long dyn;

@@ -1833,9 +1838,6 @@ static int64_t __sort__hde_cmp(struct perf_hpp_fmt *fmt,
 	} else {
 		offset = field->offset;
 		size = field->size;
-
-		update_dynamic_len(hde, a);
-		update_dynamic_len(hde, b);
 	}
 
 	return memcmp(a->raw_data + offset, b->raw_data + offset, size);

2.7.1

Em Sat, Feb 27, 2016 at 03:52:47AM +0900, Namhyung Kim escreveu:

So, I tested this with:

perf report ... > /tmp/before

apply the patch, and then do > /tmp/after, do the diff, reproduced what you described, slightly different output:

[root@felicio ~]# diff -u /tmp/before /tmp/after | grep ^[+-]
--- /tmp/before 2016-02-26 19:38:31.321497576 -0300
+++ /tmp/after 2016-02-26 19:39:24.043614934 -0300
-# .............. .................................... +# .............. ........................................

-           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMA
+           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMALLOC
-           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMA
+           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMALLOC
-           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMA
+           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMALLOC
-           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMA
+           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMALLOC
-           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMA
+           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMALLOC
-           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMA
+           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMALLOC
-           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMA
+           0.35%        GFP_ATOMIC|GFP_ZERO|GFP_NOMEMALLOC

[root@felicio ~]# diff -u /tmp/before /tmp/after | grep ^[+-]

This is something else to add to the regression tests, output diff for as many command line combos outputs as we can...

Anyway, good work, all applied with Jiri's acks.

- Arnaldo

the whole patchset looks good to me:

thanks,
jirka