[PATCH 1/5] perf report: Fix comparing of dynamic entries

[PATCH 1/5] perf report: Fix comparing of dynamic entries

[Namhyung Kim]

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.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/util/hist.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 75dc41d2dca9..cc849d326211 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -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

[PATCH 2/5] perf report: Fix indentation of dynamic entries in hierarchy

[Namhyung Kim]

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

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 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(-)

diff --git a/tools/perf/ui/browsers/hists.c b/tools/perf/ui/browsers/hists.c
index 71c6d510390f..5f74c6723c53 100644
--- a/tools/perf/ui/browsers/hists.c
+++ b/tools/perf/ui/browsers/hists.c
@@ -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);
diff --git a/tools/perf/ui/stdio/hist.c b/tools/perf/ui/stdio/hist.c
index b3bdfcb245f9..5733d6c196be 100644
--- a/tools/perf/ui/stdio/hist.c
+++ b/tools/perf/ui/stdio/hist.c
@@ -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);
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index 283a3e11358c..f4ef513527ba 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -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;
diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index 83b218c57fe2..e948fcac0939 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -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

[tip:perf/core] perf report: Fix indentation of dynamic entries in hierarchy

[tip-bot for Namhyung Kim]

Commit-ID:  d3a72fd8187b7fa0014394c9dec95ba349b3301e
Gitweb:     http://git.kernel.org/tip/d3a72fd8187b7fa0014394c9dec95ba349b3301e
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Sat, 27 Feb 2016 03:52:44 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 26 Feb 2016 18:36:11 -0300

perf report: Fix indentation of dynamic entries in hierarchy

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

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-2-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 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(-)

diff --git a/tools/perf/ui/browsers/hists.c b/tools/perf/ui/browsers/hists.c
index 71c6d51..5f74c67 100644
--- a/tools/perf/ui/browsers/hists.c
+++ b/tools/perf/ui/browsers/hists.c
@@ -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);
diff --git a/tools/perf/ui/stdio/hist.c b/tools/perf/ui/stdio/hist.c
index b3bdfcb..5733d6c 100644
--- a/tools/perf/ui/stdio/hist.c
+++ b/tools/perf/ui/stdio/hist.c
@@ -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);
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index da3e7b6..da5e505 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -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;
diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index 6bee8bd..2beb7a6 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -2633,6 +2633,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)
@@ -2644,6 +2647,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();
 
 	/*

[PATCH 3/5] perf report: Left align dynamic entries in hierarchy

[Namhyung Kim]

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

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/ui/browsers/hists.c | 16 ++++++++++++++--
 tools/perf/ui/stdio/hist.c     | 28 +++++++++++++++++++---------
 2 files changed, 33 insertions(+), 11 deletions(-)

diff --git a/tools/perf/ui/browsers/hists.c b/tools/perf/ui/browsers/hists.c
index 5f74c6723c53..5ffffcb1e3c5 100644
--- a/tools/perf/ui/browsers/hists.c
+++ b/tools/perf/ui/browsers/hists.c
@@ -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;
 	}
diff --git a/tools/perf/ui/stdio/hist.c b/tools/perf/ui/stdio/hist.c
index 5733d6c196be..6d06fbb365b6 100644
--- a/tools/perf/ui/stdio/hist.c
+++ b/tools/perf/ui/stdio/hist.c
@@ -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

[tip:perf/core] perf report: Left align dynamic entries in hierarchy

[tip-bot for Namhyung Kim]

Commit-ID:  cb1fab917206f822d1f905cbc45971eefdef361d
Gitweb:     http://git.kernel.org/tip/cb1fab917206f822d1f905cbc45971eefdef361d
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Sat, 27 Feb 2016 03:52:45 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 26 Feb 2016 18:37:06 -0300

perf report: Left align dynamic entries in hierarchy

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

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-3-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/ui/browsers/hists.c | 16 ++++++++++++++--
 tools/perf/ui/stdio/hist.c     | 28 +++++++++++++++++++---------
 2 files changed, 33 insertions(+), 11 deletions(-)

diff --git a/tools/perf/ui/browsers/hists.c b/tools/perf/ui/browsers/hists.c
index 5f74c67..5ffffcb 100644
--- a/tools/perf/ui/browsers/hists.c
+++ b/tools/perf/ui/browsers/hists.c
@@ -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;
 	}
diff --git a/tools/perf/ui/stdio/hist.c b/tools/perf/ui/stdio/hist.c
index 5733d6c..6d06fbb 100644
--- a/tools/perf/ui/stdio/hist.c
+++ b/tools/perf/ui/stdio/hist.c
@@ -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;

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

[Namhyung Kim]

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

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

[Arnaldo Carvalho de Melo]

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

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

[Arnaldo Carvalho de Melo]

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

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

[Arnaldo Carvalho de Melo]

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)

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

[Arnaldo Carvalho de Melo]

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

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

[Steven Rostedt]

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

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

[Arnaldo Carvalho de Melo]

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

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

[Jiri Olsa]

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

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

[Jiri Olsa]

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

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

[Steven Rostedt]

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;

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

[Arnaldo Carvalho de Melo]

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;

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

[David Ahern]

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>

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

[David Ahern]

On 2/26/16 4:45 PM, David Ahern wrote:
> 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>

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

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

[Arnaldo Carvalho de Melo]

Em Thu, Mar 10, 2016 at 09:16:41AM -0700, David Ahern escreveu:
> >>(( 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>

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

Yeap, thanks for the reminder, applied.

- Arnaldo

[tip:perf/core] tools lib traceevent: Add '~' operation within arg_num_eval()

[tip-bot for Steven Rostedt]

Commit-ID:  9eb42dee2b11635174c74a7996934b6ca18f2179
Gitweb:     http://git.kernel.org/tip/9eb42dee2b11635174c74a7996934b6ca18f2179
Author:     Steven Rostedt <rostedt@goodmis.org>
AuthorDate: Fri, 26 Feb 2016 18:13:28 -0500
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 10 Mar 2016 16:27:41 -0300

tools lib traceevent: Add '~' operation within arg_num_eval()

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>
Reported-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Tested-by: David Ahern <dsahern@gmail.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Wang Nan <wangnan0@huawei.com>
Link: http://lkml.kernel.org/r/20160226181328.22f47129@gandalf.local.home
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/lib/traceevent/event-parse.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index 865dea5..190cc88 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -2398,6 +2398,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;

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

[tip-bot for Namhyung Kim]

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;

[PATCH 5/5] perf report: Update column width of dynamic entries

[Namhyung Kim]

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

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

diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 9b3f582867d6..4b8b67bc0cd8 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -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,
diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index 3b1b4018f111..1457c9d975a0 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -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

Re: [PATCH 5/5] perf report: Update column width of dynamic entries

[Arnaldo Carvalho de Melo]

Em Sat, Feb 27, 2016 at 03:52:47AM +0900, Namhyung Kim escreveu:
> 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

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

> 
> 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
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/util/hist.c | 11 +++++++++++
>  tools/perf/util/sort.c |  8 +++++---
>  2 files changed, 16 insertions(+), 3 deletions(-)
> 
> diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
> index 9b3f582867d6..4b8b67bc0cd8 100644
> --- a/tools/perf/util/hist.c
> +++ b/tools/perf/util/hist.c
> @@ -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,
> diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
> index 3b1b4018f111..1457c9d975a0 100644
> --- a/tools/perf/util/sort.c
> +++ b/tools/perf/util/sort.c
> @@ -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

[tip:perf/core] perf report: Update column width of dynamic entries

[tip-bot for Namhyung Kim]

Commit-ID:  abab5e7fcec16e526968f8a5448cd81c635705ce
Gitweb:     http://git.kernel.org/tip/abab5e7fcec16e526968f8a5448cd81c635705ce
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Sat, 27 Feb 2016 03:52:47 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 26 Feb 2016 19:38:48 -0300

perf report: Update column width of dynamic entries

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

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-5-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/hist.c | 11 +++++++++++
 tools/perf/util/sort.c |  8 +++++---
 2 files changed, 16 insertions(+), 3 deletions(-)

diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 9b3f582..4b8b67b 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -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,
diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index d26c6b9..5888bfe 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -1816,6 +1816,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;
@@ -1830,9 +1835,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);

Re: [PATCH 1/5] perf report: Fix comparing of dynamic entries

[Jiri Olsa]

On Sat, Feb 27, 2016 at 03:52:43AM +0900, Namhyung Kim wrote:
> 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.

the whole patchset looks good to me:

Acked-by: Jiri Olsa <jolsa@kernel.org>

thanks,
jirka

[tip:perf/core] perf hists: Fix comparing of dynamic entries

[tip-bot for Namhyung Kim]

Commit-ID:  84b6ee8ea36ff797afa13c297a86ed0144482bee
Gitweb:     http://git.kernel.org/tip/84b6ee8ea36ff797afa13c297a86ed0144482bee
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Sat, 27 Feb 2016 03:52:43 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 26 Feb 2016 18:35:57 -0300

perf hists: Fix comparing of dynamic entries

When hist_entry__cmp() and hist_entry__collapse() are called, they
should check if the dynamic entry is comparing matching hists only.

Otherwise it might access different hists resulting in incorrect output.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
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-1-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/hist.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 75dc41d..cc849d3 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -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;