perf tool: perf diff sort changes

From: Kan Liang <[email protected]>

Current perf diff has some issues. E.g. the default sort key is symbol, but it doesn't work well. It sorts as address. Furthermore, the old perf diff can only work on perf.data from the same binary.

This patch set fixes the symbol issue and extends it to compare the perf.data from different binaries and different kernels. It's useful for debugging the regression issue.
Current perf diff can do address compare, the patch set also keep this feature. A new sort key "symoff" is introduced. It can let the user sort differential profile by the address. It should be useful for debugging the scaling issue, if the user think function level diff is too high granularity.

Here is an example.

v1_1_6perf.data is perf record result of version one tchain on 1.6 kernel. v2_1_8perf.data is perf record result of version two tchain on 1.8 kernel. They are from different binaries.

v1_1_8_1perf.data and v1_1_8_2perf.data are perf record result of version one tchain on 1.8 kernel. I run perf record twice.
They are from same binary.

Old perf diff with default sort key "dso,symbol" for different binary ./perf diff -s dso,symbol v1_1_6perf.data v2_1_8perf.data

Event 'cycles'

 Baseline    Delta  Shared Object      Symbol
 ........  .......  .................  .........................

     0.01%           [kernel.kallsyms]  [k] native_write_msr_safe
     0.01%           [kernel.kallsyms]  [k] notifier_call_chain
     0.01%           [kernel.kallsyms]  [k] perf_event_task_tick
     0.01%           [kernel.kallsyms]  [k] run_posix_cpu_timers
     0.01%           [kernel.kallsyms]  [k] run_timer_softirq
     0.01%           [kernel.kallsyms]  [k] trigger_load_balance
     0.01%           [kernel.kallsyms]  [k] update_vsyscall
                     [kernel.vmlinux]   [k] __run_hrtimer
                     [kernel.vmlinux]   [k] apic_timer_interrupt
                     [kernel.vmlinux]   [k] enqueue_task
                     [kernel.vmlinux]   [k] hrtimer_interrupt
                     [kernel.vmlinux]   [k] native_write_msr_safe
                     [kernel.vmlinux]   [k] trigger_load_balance
                     [kernel.vmlinux]   [k] update_wall_time
     0.05%           [unknown]          [.] 0x0000000000400540
     0.04%           [unknown]          [.] 0x0000000000400541
     0.03%           [unknown]          [.] 0x000000000040054b
     0.04%           [unknown]          [.] 0x0000000000400552
    33.55%           [unknown]          [.] 0x0000000000400554
     1.22%           [unknown]          [.] 0x000000000040055a
     8.00%           [unknown]          [.] 0x000000000040055e
     0.02%           [unknown]          [.] 0x0000000000400562
     8.41%           [unknown]          [.] 0x0000000000400564
    48.13%           [unknown]          [.] 0x000000000040056b
     0.16%           [unknown]          [.] 0x0000000000400570
     0.17%           [unknown]          [.] 0x0000000000400571
             +0.45%  [unknown]          [.] 0x0000000000400580
             +0.29%  [unknown]          [.] 0x0000000000400581
     0.01%           [unknown]          [.] 0x0000000000400583
     0.01%           [unknown]          [.] 0x0000000000400588
             +0.22%  [unknown]          [.] 0x000000000040058b
     0.01%  +13.35%  [unknown]          [.] 0x000000000040058d
     0.06%           [unknown]          [.] 0x0000000000400591
             +0.78%  [unknown]          [.] 0x0000000000400593
     0.04%           [unknown]          [.] 0x0000000000400595
     0.01%   +6.18%  [unknown]          [.] 0x0000000000400597
             +1.47%  [unknown]          [.] 0x000000000040059b
             +6.46%  [unknown]          [.] 0x000000000040059d
             +1.28%  [unknown]          [.] 0x00000000004005a1
            +66.38%  [unknown]          [.] 0x00000000004005a5
             +1.34%  [unknown]          [.] 0x00000000004005a7
             +1.15%  [unknown]          [.] 0x00000000004005a8
             +0.05%  [unknown]          [.] 0x00000000004005ba
             +0.03%  [unknown]          [.] 0x00000000004005bf
             +0.02%  [unknown]          [.] 0x00000000004005c4
             +0.05%  [unknown]          [.] 0x00000000004005c9
             +0.03%  [unknown]          [.] 0x00000000004005ce
             +0.27%  [unknown]          [.] 0x00000000004005d2
             +0.15%  [unknown]          [.] 0x00000000004005d6
                     [unknown]          [.] 0x00000000004005d8
                     [unknown]          [.] 0x00000000004005d9

New perf diff with default sort key "dso,symbol" for different binary ./perf diff -s dso,symbol v1_1_6perf.data v2_1_8perf.data

Event 'cycles'

 Baseline    Delta  Shared Object      Symbol
 ........  .......  .................  .........................

     0.01%           [kernel.kallsyms]  [k] native_write_msr_safe
     0.01%           [kernel.kallsyms]  [k] notifier_call_chain
     0.01%           [kernel.kallsyms]  [k] perf_event_task_tick
     0.01%           [kernel.kallsyms]  [k] run_posix_cpu_timers
     0.01%           [kernel.kallsyms]  [k] run_timer_softirq
     0.01%           [kernel.kallsyms]  [k] trigger_load_balance
     0.01%           [kernel.kallsyms]  [k] update_vsyscall
                     [kernel.vmlinux]   [k] __run_hrtimer
                     [kernel.vmlinux]   [k] apic_timer_interrupt
                     [kernel.vmlinux]   [k] enqueue_task
                     [kernel.vmlinux]   [k] hrtimer_interrupt
                     [kernel.vmlinux]   [k] native_write_msr_safe
                     [kernel.vmlinux]   [k] trigger_load_balance
                     [kernel.vmlinux]   [k] update_wall_time
     0.14%   +0.47%  tchain        [.] f2
    99.82%   -0.47%  tchain        [.] f3

New perf diff with sort key "symbol,symoff" ffor same binary perf diff -s symbol,symoff v1_1_8_1perf.data v1_1_8_2perf.data

Event 'cycles'

 Baseline    Delta  Symbol                           Symbol+Offset
 ........  .......  ...............................  ...............................

     0.00%           [k] __update_cpu_load            [k] 0xffffffff810b9b8c
                     [k] _raw_spin_lock_irqsave       [k] 0xffffffff81759364
                     [k] _raw_spin_unlock_irqrestore  [k] 0xffffffff817594ba
     0.00%           [k] apic_timer_interrupt         [k] 0xffffffff8175a9f0
                     [k] apic_timer_interrupt         [k] 0xffffffff8175aa58
                     [k] check_preempt_curr           [k] 0xffffffff810b461c
     0.00%           [.] f1                           [.] 0x00000000004005fa
     0.03%   +0.03%  [.] f2                           [.] 0x00000000004005ba
     0.03%   +0.01%  [.] f2                           [.] 0x00000000004005bf
     0.05%           [.] f2                           [.] 0x00000000004005c4
     0.04%   -0.02%  [.] f2                           [.] 0x00000000004005c9
     0.03%           [.] f2                           [.] 0x00000000004005ce
     0.17%   +0.11%  [.] f2                           [.] 0x00000000004005d2
     0.15%           [.] f2                           [.] 0x00000000004005d6
                     [.] f2                           [.] 0x00000000004005d9
     0.37%   +0.02%  [.] f3                           [.] 0x0000000000400580
     0.18%   +0.03%  [.] f3                           [.] 0x0000000000400581
     0.01%           [.] f3                           [.] 0x0000000000400584
     0.18%   +0.04%  [.] f3                           [.] 0x000000000040058b
    12.31%   +0.11%  [.] f3                           [.] 0x000000000040058d
     0.03%           [.] f3                           [.] 0x0000000000400590
     0.80%   -0.12%  [.] f3                           [.] 0x0000000000400593
     6.66%   +0.09%  [.] f3                           [.] 0x0000000000400597
     1.81%   -0.36%  [.] f3                           [.] 0x000000000040059b
     6.35%   +0.24%  [.] f3                           [.] 0x000000000040059d
     1.42%   -0.22%  [.] f3                           [.] 0x00000000004005a1
    66.83%   +0.22%  [.] f3                           [.] 0x00000000004005a5
     1.29%   -0.12%  [.] f3                           [.] 0x00000000004005a7
     1.22%   -0.04%  [.] f3                           [.] 0x00000000004005a8
     0.00%           [k] load_balance                 [k] 0xffffffff810be7f6
     0.00%           [k] native_apic_mem_write        [k] 0xffffffff81077920
     0.00%           [k] native_write_msr_safe        [k] 0xffffffff8107d7ba
     0.00%           [k] native_write_msr_safe        [k] 0xffffffff8107d7bd
     0.00%           [k] rb_erase                     [k] 0xffffffff813346b1
                     [k] resched_curr                 [k] 0xffffffff810b4095
                     [k] restore_args                 [k] 0xffffffff8175a744
     0.00%           [k] run_timer_softirq            [k] 0xffffffff810e306f
                     [k] select_task_rq_fair          [k] 0xffffffff810bbab9
     0.00%           [k] select_task_rq_fair          [k] 0xffffffff810bbc89
                     [k] task_tick_fair               [k] 0xffffffff810bd286
     0.00%           [k] task_tick_fair               [k] 0xffffffff810bd40e
                     [k] task_waking_fair             [k] 0xffffffff810baf97
     0.00%           [k] try_to_wake_up               [k] 0xffffffff810b75e8
                     [k] update_cfs_rq_blocked_load   [k] 0xffffffff810bb129
     0.00%           [k] update_cpu_load_active       [k] 0xffffffff810ba08b
                     [k] update_group_capacity        [k] 0xffffffff810bdde0
                     [k] update_wall_time             [k] 0xffffffff810eac46

Changes from V1:
- mmap2 as default of tool's definition
- Using se_collapse to match symbol name.
- Sort key "addr" is introduced to compare address from same binary.

Changes from V2:
- rename sort key name to "symoff"

Kan Liang (3):
perf tool: Fix perf diff symble sort issue perf tool:perf diff support for different binaries perf tool: Add sort key symoff for perf diff

 tools/perf/Documentation/perf-diff.txt |  8 +++++--
 tools/perf/builtin-diff.c              |  3 ++-
 tools/perf/util/hist.c                 |  5 +++--
 tools/perf/util/hist.h                 |  1 +
 tools/perf/util/sort.c                 | 38 ++++++++++++++++++++++++++++++++++
 tools/perf/util/sort.h                 |  2 ++
 6 files changed, 52 insertions(+), 5 deletions(-)

1.8.3.2

From: Kan Liang <[email protected]>

This patch fixes a bug for perf diff.
Without mmap2, perf diff fails to find the symbol name. The default symbol sort key doesn't work well.

---
 tools/perf/builtin-diff.c | 1 +
 1 file changed, 1 insertion(+)

index 25114c9..1ce425d 100644
@@ -357,6 +357,7 @@ static int diff__process_sample_event(struct perf_tool *tool __maybe_unused,
 static struct perf_tool tool = {
 	.sample	= diff__process_sample_event,
 	.mmap	= perf_event__process_mmap,
+	.mmap2	= perf_event__process_mmap2,
 	.comm	= perf_event__process_comm,
 	.exit	= perf_event__process_exit,
 	.fork	= perf_event__process_fork,

1.8.3.2

From: Kan Liang <[email protected]>

Currently, the perf diff only works with same binaries. That's because it compares the symbol start address. It doesn't work if the perf.data comes from different binaries. This patch matches the function names.

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

index 9402885..5b6c57d 100644
@@ -1430,6 +1430,15 @@ int sort_dimension__add(const char *tok)
 			sort__has_parent = 1;
 		} else if (sd->entry == &sort_sym) {
 			sort__has_sym = 1;
+			/*
+			 * perf diff displays the performance difference amongst
+			 * two or more perf.data files. Those files could come
+			 * from different binaries. So we should not compare
+			 * their ips, but the name of symble.
+			 */
+			if (sort__mode == SORT_MODE__DIFF)
+				sd->entry->se_collapse = sort__sym_sort;
+
 		} else if (sd->entry == &sort_dso) {
 			sort__has_dso = 1;
 		}

1.8.3.2

From: Kan Liang <[email protected]>

Sometime, especially debugging scaling issue, the function level diff may be high granularity. The user may want to do deeper diff analysis for some cache or lock issue. The "symoff" key can let the user sort differential profile by ips. This feature should only work when the perf.data comes from same binary.

---
 tools/perf/Documentation/perf-diff.txt |  8 ++++++--
 tools/perf/builtin-diff.c              |  2 +-
 tools/perf/util/hist.c                 |  5 +++--
 tools/perf/util/hist.h                 |  1 +
 tools/perf/util/sort.c                 | 29 +++++++++++++++++++++++++++++
 tools/perf/util/sort.h                 |  2 ++
 6 files changed, 42 insertions(+), 5 deletions(-)

index e463caa..9e13911 100644
@@ -50,8 +50,12 @@ OPTIONS
 
 -s::
 --sort=::
-	Sort by key(s): pid, comm, dso, symbol, cpu, parent, srcline.
-	Please see description of --sort in the perf-report man page.
+	Sort by key(s): pid, comm, dso, symbol, cpu, parent, srcline, symoff.
+
+	- symoff: exact symbol +  offset address executed at the time of sample.
+	(for same binary compare)
+
+	For other keys, please see description of --sort in the perf-report man page.
 
 -t::
 --field-separator=::

index 1ce425d..03a4001 100644
@@ -744,7 +744,7 @@ static const struct option options[] = {
 	OPT_STRING('S', "symbols", &symbol_conf.sym_list_str, "symbol[,symbol...]",
 		   "only consider these symbols"),
 	OPT_STRING('s', "sort", &sort_order, "key[,key2...]",
-		   "sort by key(s): pid, comm, dso, symbol, parent, cpu, srcline, ..."
+		   "sort by key(s): pid, comm, dso, symbol, parent, cpu, srcline, symoff, ..."
 		   " Please refer the man page for the complete list."),
 	OPT_STRING('t', "field-separator", &symbol_conf.field_sep, "separator",
 		   "separator for columns, no spaces will be added between "

index 6e88b9e..3d8a71b 100644
@@ -67,13 +67,14 @@ void hists__calc_col_len(struct hists *hists, struct hist_entry *h)
 		symlen = h->ms.sym->namelen + 4;
 		if (verbose)
 			symlen += BITS_PER_LONG / 4 + 2 + 3;
-		hists__new_col_len(hists, HISTC_SYMBOL, symlen);
 	} else {
 		symlen = unresolved_col_width + 4 + 2;
-		hists__new_col_len(hists, HISTC_SYMBOL, symlen);
 		hists__set_unres_dso_col_len(hists, HISTC_DSO);
 	}
 
+	hists__new_col_len(hists, HISTC_SYMBOL, symlen);
+	hists__new_col_len(hists, HISTC_SYMOFF, symlen);
+
 	len = thread__comm_len(h->thread);
 	if (hists__new_col_len(hists, HISTC_COMM, len))
 		hists__set_col_len(hists, HISTC_THREAD, len + 6);

index d0ef9a1..874b203 100644
@@ -24,6 +24,7 @@ enum hist_filter {
 
 enum hist_column {
 	HISTC_SYMBOL,
+	HISTC_SYMOFF,
 	HISTC_DSO,
 	HISTC_THREAD,
 	HISTC_COMM,

index 5b6c57d..370a799 100644
@@ -280,6 +280,34 @@ struct sort_entry sort_sym = {
 	.se_width_idx	= HISTC_SYMBOL,
 };
 
+static int64_t
+sort__addr_cmp(struct hist_entry *left, struct hist_entry *right)
+{
+	return _sort__addr_cmp(left->ip, right->ip);
+}
+
+static int hist_entry__addr_snprintf(struct hist_entry *he, char *bf,
+				    size_t size, unsigned int width)
+{
+	struct map *map = he->ms.map;
+	u64 ip;
+
+	if (map)
+		ip = map->unmap_ip(map, he->ip);
+	else
+		ip = he->ip;
+
+	return _hist_entry__sym_snprintf(NULL, NULL, ip,
+					 he->level, bf, size, width);
+}
+
+struct sort_entry sort_symoff = {
+	.se_header	= "Symbol+Offset",
+	.se_cmp		= sort__addr_cmp,
+	.se_snprintf	= hist_entry__addr_snprintf,
+	.se_width_idx	= HISTC_SYMOFF,
+};
+
 /* --sort srcline */
 
 static int64_t

@@ -1170,6 +1198,7 @@ static struct sort_dimension common_sort_dimensions[] = {
 	DIM(SORT_COMM, "comm", sort_comm),
 	DIM(SORT_DSO, "dso", sort_dso),
 	DIM(SORT_SYM, "symbol", sort_sym),
+	DIM(SORT_SYMOFF, "symoff", sort_symoff),
 	DIM(SORT_PARENT, "parent", sort_parent),
 	DIM(SORT_CPU, "cpu", sort_cpu),
 	DIM(SORT_SRCLINE, "srcline", sort_srcline),

index c03e4ff..ea0122f 100644
@@ -38,6 +38,7 @@ extern enum sort_mode sort__mode;
 extern struct sort_entry sort_comm;
 extern struct sort_entry sort_dso;
 extern struct sort_entry sort_sym;
+extern struct sort_entry sort_symoff;
 extern struct sort_entry sort_parent;
 extern struct sort_entry sort_dso_from;
 extern struct sort_entry sort_dso_to;

@@ -161,6 +162,7 @@ enum sort_type {
 	SORT_COMM,
 	SORT_DSO,
 	SORT_SYM,
+	SORT_SYMOFF,
 	SORT_PARENT,
 	SORT_CPU,
 	SORT_SRCLINE,

1.8.3.2

Hi kan,

It'd be better to include output of symoff here IMHO.

{
	return _sort__addr_cmp(left->ip, right->ip);
}

{
	int64_t ret;
	u64 symoff_l, symoff_r;

	if (!left->ms.sym || right->ms.sym)
		return cmp_null(...);

	ret = strcmp(left->ms.sym, right->ms.sym);
	if (ret)
		return ret;

	symoff_l = left->ip - left->ms.sym->start;
	symoff_r = right->ip - right->ms.sym->start;

        return (int64_t)(symoff_r - symoff_l);
}

{
	size_t ret;

	if (he->ms.sym)
		ret = repsep_snprintf(bf, size, "%s+0x%llx", he->ms.sym->name,
				he->ip - he->ms.sym->start);
	else
		ret = repsep_snprintf(bf, size, "%-#*llx",
				BITS_PER_LONG / 4 + 2, he->ip); // unmap?

	ret += repsep_snprintf(bf + ret, size - ret, "%-*s",
			       width - ret, "");

	if (ret > width)
		bf[width] = '\0';

	return width;
}

struct sort_entry sort_symoff = {
	.se_header	= "Symbol+Offset",
	.se_cmp		= sort__symoff_cmp,
	.se_snprintf	= hist_entry__symoff_snprintf,
	.se_width_idx	= HISTC_SYMOFF,

{
	...
	else if (sd->entry == &sort_symoff) {
		if (sort__mode == SORT_MODE__DIFF)
			se->entry->se_collapse = sort__symoff_collapse;
	}
	...
}