perf tools: Fix assertion failure on dynamic entry

The dynamic entry is created for each tracepoint event. When it sets up the sort key, it checks with existing keys using ->equal() callback. But it missed to set the ->equal for dynamic entries. The following segfault was due to the missing ->equal() callback.

(gdb) bt

  #0  0x0000000000140003 in ?? ()
  #1  0x0000000000537769 in fmt_equal (b=0x2106980, a=0x21067a0) at ui/hist.c:548
  #2  perf_hpp__setup_output_field (list=0x8c6d80 <perf_hpp_list>) at ui/hist.c:560
  #3  0x00000000004e927e in setup_sorting (evlist=<optimized out>) at util/sort.c:2642
  #4  0x000000000043cf50 in cmd_report (argc=<optimized out>, argv=<optimized out>, prefix=<optimized out>)
      at builtin-report.c:932
  #5  0x00000000004865a1 in run_builtin (p=p@entry=0x8bbce0 <commands+192>, argc=argc@entry=7,
      argv=argv@entry=0x7ffd24d56ce0) at perf.c:390
  #6  0x000000000042dc1f in handle_internal_command (argv=0x7ffd24d56ce0, argc=7) at perf.c:451
  #7  run_argv (argv=0x7ffd24d56a70, argcp=0x7ffd24d56a7c) at perf.c:495
  #8  main (argc=7, argv=0x7ffd24d56ce0) at perf.c:620

Signed-off-by Namhyung Kim <[email protected]>

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

tools/perf/util/sort.c +15 -0

index de715756f281..7daea71691df 100644
@@ -1835,6 +1835,20 @@ bool perf_hpp__is_dynamic_entry(struct perf_hpp_fmt *fmt)
 	return fmt->cmp == __sort__hde_cmp;
 }
 
+static bool __sort__hde_equal(struct perf_hpp_fmt *a, struct perf_hpp_fmt *b)
+{
+	struct hpp_dynamic_entry *hde_a;
+	struct hpp_dynamic_entry *hde_b;
+
+	if (!perf_hpp__is_dynamic_entry(a) || !perf_hpp__is_dynamic_entry(b))
+		return false;
+
+	hde_a = container_of(a, struct hpp_dynamic_entry, hpp);
+	hde_b = container_of(b, struct hpp_dynamic_entry, hpp);
+
+	return hde_a->field == hde_b->field;
+}
+
 static void hde_free(struct perf_hpp_fmt *fmt)
 {
 	struct hpp_dynamic_entry *hde;

@@ -1867,6 +1881,7 @@ __alloc_dynamic_entry(struct perf_evsel *evsel, struct format_field *field)
 	hde->hpp.cmp = __sort__hde_cmp;
 	hde->hpp.collapse = __sort__hde_cmp;
 	hde->hpp.sort = __sort__hde_cmp;
+	hde->hpp.equal = __sort__hde_equal;
 	hde->hpp.free = hde_free;
 
 	INIT_LIST_HEAD(&hde->hpp.list);

Signature · 1 line

2.7.1

The dynamic entry is created for each field in a tracepoint event. Since they have no fixed hpp format index, it should skip when perf_hpp__reset_width() is called.

This caused following assertion failure..

  $ perf record -e sched:sched_switch -a sleep 1

  $ perf report -s comm,next_pid --stdio
  perf: ui/hist.c:651: perf_hpp__reset_width:
    Assertion `!(fmt->idx >= PERF_HPP__MAX_INDEX)' failed.

Signed-off-by Namhyung Kim <[email protected]>

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

tools/perf/ui/hist.c +3 -0

index 1ba4117d9c2d..12223d791e9f 100644
@@ -645,6 +645,9 @@ void perf_hpp__reset_width(struct perf_hpp_fmt *fmt, struct hists *hists)
 	if (perf_hpp__is_sort_entry(fmt))
 		return perf_hpp__reset_sort_width(fmt, hists);
 
+	if (perf_hpp__is_dynamic_entry(fmt))
+		return;
+
 	BUG_ON(fmt->idx >= PERF_HPP__MAX_INDEX);
 
 	switch (fmt->idx) {

Signature · 1 line

2.7.1

Quoted 8 lines

The dynamic entry is created for each field in a tracepoint event. Since they have no fixed hpp format index, it should skip when perf_hpp__reset_width() is called.

This caused following assertion failure..

  $ perf record -e sched:sched_switch -a sleep 1

Quoted 5 lines

  $ perf report -s comm,next_pid --stdio
  perf: ui/hist.c:651: perf_hpp__reset_width:
    Assertion `!(fmt->idx >= PERF_HPP__MAX_INDEX)' failed.

Signed-off-by Namhyung Kim <[email protected]>

Acked-by Jiri Olsa <[email protected]>

Normally the hist entry's srcline and/or srcfile is set during sorting. However sometime it's possible to a hist entry's srcline is not set yet after the sorting. This is because the entry is so unique and other sort keys already make it distinct. Then the srcline/file sort didn't have a chance to be called during the sorting. In that case it has NULL srcline/srcfile field and shows nothing.

Before:

  $ perf report -s comm,sym,srcline
  ...
  Overhead  Command       Symbol
  -----------------------------------------------------------------
    34.42%  swapper       [k] intel_idle          intel_idle.c:0
     2.44%  perf          [.] __poll_nocancel     (null)
     1.70%  gnome-shell   [k] fw_domains_get      (null)
     1.04%  Xorg          [k] sock_poll           (null)

After:

    34.42%  swapper       [k] intel_idle          intel_idle.c:0
     2.44%  perf          [.] __poll_nocancel     .:0
     1.70%  gnome-shell   [k] fw_domains_get      fw_domains_get+42
     1.04%  Xorg          [k] sock_poll           socket.c:0

Signed-off-by Namhyung Kim <[email protected]>

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

tools/perf/util/sort.c +0 -0

index 7daea71691df..6808d73164b5 100644
@@ -315,6 +315,16 @@ sort__srcline_cmp(struct hist_entry *left, struct hist_entry *right)
 static int hist_entry__srcline_snprintf(struct hist_entry *he, char *bf,
 					size_t size, unsigned int width)
 {

Normally the hist entry's srcline and/or srcfile is set during sorting. However sometime it's possible to a hist entry's srcline is not set yet after the sorting. This is because the entry is so unique and other sort keys already make it distinct. Then the srcline/file sort didn't have a chance to be called during the sorting. In that case it has NULL srcline/srcfile field and shows nothing.

Before:

  $ perf report -s comm,sym,srcline
  ...
  Overhead  Command       Symbol
  -----------------------------------------------------------------
    34.42%  swapper       [k] intel_idle          intel_idle.c:0
     2.44%  perf          [.] __poll_nocancel     (null)
     1.70%  gnome-shell   [k] fw_domains_get      (null)
     1.04%  Xorg          [k] sock_poll           (null)

After:

    34.42%  swapper       [k] intel_idle          intel_idle.c:0
     2.44%  perf          [.] __poll_nocancel     .:0
     1.70%  gnome-shell   [k] fw_domains_get      fw_domains_get+42
     1.04%  Xorg          [k] sock_poll           socket.c:0

Signed-off-by Namhyung Kim <[email protected]>

The srcline, srcfile and trace sort keys can have long entries. With commit 89fee7094323 ("perf hists: Do column alignment on the format iterator"), it now aligns output with hist_entry__snprintf_alignment(). So each (possibly long) sort entries don't need to do it themselves.

Signed-off-by Namhyung Kim <[email protected]>

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

tools/perf/util/sort.c +4 -4

index 6808d73164b5..1d2b85c808d0 100644
@@ -325,7 +325,7 @@ static int hist_entry__srcline_snprintf(struct hist_entry *he, char *bf,
 						  he->ms.sym, true);
 		}
 	}
-	return repsep_snprintf(bf, size, "%-*.*s", width, width, he->srcline);
+	return repsep_snprintf(bf, size, "%-.*s", width, he->srcline);
 }
 
 struct sort_entry sort_srcline = {

@@ -384,7 +384,7 @@ static int hist_entry__srcfile_snprintf(struct hist_entry *he, char *bf,
 		else
 			he->srcfile = get_srcfile(he);
 	}
-	return repsep_snprintf(bf, size, "%-*.*s", width, width, he->srcfile);
+	return repsep_snprintf(bf, size, "%-.*s", width, he->srcfile);
 }
 
 struct sort_entry sort_srcfile = {

@@ -514,11 +514,11 @@ static int hist_entry__trace_snprintf(struct hist_entry *he, char *bf,
 
 	evsel = hists_to_evsel(he->hists);
 	if (evsel->attr.type != PERF_TYPE_TRACEPOINT)
-		return scnprintf(bf, size, "%-*.*s", width, width, "N/A");
+		return scnprintf(bf, size, "%-.*s", width, "N/A");
 
 	if (he->trace_output == NULL)
 		he->trace_output = get_trace_output(he);
-	return repsep_snprintf(bf, size, "%-*.*s", width, width, he->trace_output);
+	return repsep_snprintf(bf, size, "%-.*s", width, he->trace_output);
 }
 
 struct sort_entry sort_trace = {

Signature · 1 line

2.7.1

It missed to update column length of the 'trace' sort key in the hists__calc_col_len() so it might truncate the output. It calculated the column length in the ->cmp() callback originally but it doesn't guarantee it's called always.

Signed-off-by Namhyung Kim <[email protected]>

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

tools/perf/util/hist.c +3 -0

index 827c6cbcd05d..017eb5c42c37 100644
@@ -179,6 +179,9 @@ void hists__calc_col_len(struct hists *hists, struct hist_entry *h)
 	if (h->transaction)
 		hists__new_col_len(hists, HISTC_TRANSACTION,
 				   hist_entry__transaction_len());
+
+	if (h->trace_output)
+		hists__new_col_len(hists, HISTC_TRACE, strlen(h->trace_output));
 }
 
 void hists__output_recalc_col_len(struct hists *hists, int max_rows)

tools/perf/util/sort.c +0 -3

index 1d2b85c808d0..ea05497cfee9 100644
@@ -501,9 +501,6 @@ sort__trace_cmp(struct hist_entry *left, struct hist_entry *right)
 	if (right->trace_output == NULL)
 		right->trace_output = get_trace_output(right);
 
-	hists__new_col_len(left->hists, HISTC_TRACE, strlen(left->trace_output));
-	hists__new_col_len(right->hists, HISTC_TRACE, strlen(right->trace_output));
-
 	return strcmp(right->trace_output, left->trace_output);
 }
 

Signature · 1 line

2.7.1