[PATCHSET 0/9] perf report: Improve srcline sort performance (v1)

[PATCHSET 0/9] perf report: Improve srcline sort performance (v1)

[Namhyung Kim]

Hello,

I noticed a performance problem in the srcline/srcfile processing during
perf report when it's using an external addr2line process.  I guess it's
also helpful even if it uses the libbfd to get the srcline info.

Also note that it's mostly from large (static) binaries, but smaller
binaries should also benefit from the fix if they have a lot of samples.

The first 5 patches are general fixes and updates.  The latter 4 patches
implemented the actual speed-up.

Let's test it with the perf tools itself.  Build a static binary like below.

  $ cd tools/perf
  $ make NO_JVMTI=1 LDFLAGS=-static

Then run the perf test workload.

  $ ./perf record -- ./perf test -w noploop

And run the perf report with srcline sort key like this.

  $ ./perf report -n -s srcline --stdio
  # To display the perf.data header info, please use --header/--header-only options.
  #
  #
  # Total Lost Samples: 0
  #
  # Samples: 4K of event 'cycles:u'
  # Event count (approx.): 3572938596
  #
  # Overhead       Samples  Source:Line
  # ........  ............  ............
  #
      99.94%          4010  noploop.c:26
       0.03%            14  ??:0
       0.03%             1  perf.c:330
       0.00%             1  wcscpy.o:0

The problem is that it runs the addr2line when it processes each sample.
But as you can see many samples can have same result.  IOW, if the samples
have same address, we don't need to run the addr2line each time.

So I changed the sort_key->cmp() to compare the addresses only and moved
the addr2line from sort_key->collapse() so that they can be run after
merging the samples with the same address.

With the change, I can get a huge speed-up in processing srcline info
while they generate the same output.

Before:

  $ ./perf stat -- ./perf report -s srcline > /dev/null

   Performance counter stats for './perf report -s srcline':

           15,397.13 msec task-clock:u                     #    0.993 CPUs utilized
                   0      context-switches:u               #    0.000 /sec
                   0      cpu-migrations:u                 #    0.000 /sec
               3,810      page-faults:u                    #  247.449 /sec
      54,516,351,820      cycles:u                         #    3.541 GHz
      31,494,118,293      instructions:u                   #    0.58  insn per cycle
       8,577,271,187      branches:u                       #  557.069 M/sec
       1,216,165,520      branch-misses:u                  #   14.18% of all branches

        15.505066606 seconds time elapsed

        15.094122000 seconds user
         0.396962000 seconds sys

After:

  $ ./perf stat -- ./perf report -s srcline > /dev/null

   Performance counter stats for './perf report -s srcline':

              105.66 msec task-clock:u                     #    0.994 CPUs utilized
                   0      context-switches:u               #    0.000 /sec
                   0      cpu-migrations:u                 #    0.000 /sec
               3,275      page-faults:u                    #   30.995 K/sec
         185,063,407      cycles:u                         #    1.751 GHz
         142,470,215      instructions:u                   #    0.77  insn per cycle
          34,584,038      branches:u                       #  327.311 M/sec
           3,226,005      branch-misses:u                  #    9.33% of all branches

         0.106270464 seconds time elapsed

         0.074254000 seconds user
         0.032871000 seconds sys

The code is available at 'perf/srcline-v1' branch in

  git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git

Thanks,
Namhyung


Namhyung Kim (9):
  perf srcline: Do not return NULL for srcline
  perf report: Ignore SIGPIPE for srcline
  perf symbol: Add filename__has_section()
  perf srcline: Skip srcline if .debug_line is missing
  perf srcline: Conditionally suppress addr2line warnings
  perf hist: Add perf_hpp_fmt->init() callback
  perf hist: Improve srcline sort key performance
  perf hist: Improve srcfile sort key performance
  perf hist: Improve srcline_{from,to} sort key performance

 tools/perf/builtin-report.c      |   1 +
 tools/perf/util/hist.c           |  10 +--
 tools/perf/util/hist.h           |   1 +
 tools/perf/util/sort.c           | 129 ++++++++++++++++++++++++++++---
 tools/perf/util/sort.h           |   1 +
 tools/perf/util/srcline.c        |  20 +++--
 tools/perf/util/symbol-elf.c     |  28 +++++++
 tools/perf/util/symbol-minimal.c |   5 ++
 tools/perf/util/symbol.h         |   1 +
 9 files changed, 176 insertions(+), 20 deletions(-)


base-commit: 818448e9cf92e5c6b3c10320372eefcbe4174e4f
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 1/9] perf srcline: Do not return NULL for srcline

[Namhyung Kim]

The code assumes non-NULL srcline value always, let's return the usual
SRCLINE_UNKNOWN ("??:0") string instead.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/util/srcline.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/util/srcline.c b/tools/perf/util/srcline.c
index af468e3bb6fa..5319efb16a5a 100644
--- a/tools/perf/util/srcline.c
+++ b/tools/perf/util/srcline.c
@@ -716,7 +716,7 @@ char *__get_srcline(struct dso *dso, u64 addr, struct symbol *sym,
 
 	if (!show_addr)
 		return (show_sym && sym) ?
-			    strndup(sym->name, sym->namelen) : NULL;
+			    strndup(sym->name, sym->namelen) : SRCLINE_UNKNOWN;
 
 	if (sym) {
 		if (asprintf(&srcline, "%s+%" PRIu64, show_sym ? sym->name : "",
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 2/9] perf report: Ignore SIGPIPE for srcline

[Namhyung Kim]

It can get SIGPIPE when it uses an external addr2line process and the
process was terminated unexpectedly.  Let's ignore the signal and move
on to the next sample.  The sample will get the default srcline value
anyway.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-report.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 2ee2ecca208e..d98112f173b0 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -949,6 +949,7 @@ static int __cmd_report(struct report *rep)
 	struct perf_data *data = session->data;
 
 	signal(SIGINT, sig_handler);
+	signal(SIGPIPE, SIG_IGN);
 
 	if (rep->cpu_list) {
 		ret = perf_session__cpu_bitmap(session, rep->cpu_list,
-- 
2.39.0.314.g84b9a713c41-goog

Re: [PATCH 2/9] perf report: Ignore SIGPIPE for srcline

[Andi Kleen]

On 12/15/2022 9:28 PM, Namhyung Kim wrote:
> It can get SIGPIPE when it uses an external addr2line process and the
> process was terminated unexpectedly.  Let's ignore the signal and move
> on to the next sample.  The sample will get the default srcline value
> anyway.


That's a bit dangerous -- if perf report output is piped to something 
else you really want to stop on SIGPIPE.

You would need to find a way to distinguish those cases.

-Andi

Re: [PATCH 2/9] perf report: Ignore SIGPIPE for srcline

[Namhyung Kim]

Hi Andi,

On Thu, Dec 15, 2022 at 11:25 PM Andi Kleen <ak@linux.intel.com> wrote:
>
>
> On 12/15/2022 9:28 PM, Namhyung Kim wrote:
> > It can get SIGPIPE when it uses an external addr2line process and the
> > process was terminated unexpectedly.  Let's ignore the signal and move
> > on to the next sample.  The sample will get the default srcline value
> > anyway.
>
>
> That's a bit dangerous -- if perf report output is piped to something
> else you really want to stop on SIGPIPE.

Maybe we can handle the pipe write errors gracefully, but it'd require
more changes in many places.

>
> You would need to find a way to distinguish those cases.

Hmm.. ok.  I guess we can just drop this for now.  With checking
the .debug_line section, problematic cases should be gone mostly.

Thanks,
Namhyung

Re: [PATCH 2/9] perf report: Ignore SIGPIPE for srcline

[Arnaldo Carvalho de Melo]

Em Fri, Dec 16, 2022 at 10:08:50AM -0800, Namhyung Kim escreveu:
> Hi Andi,
> 
> On Thu, Dec 15, 2022 at 11:25 PM Andi Kleen <ak@linux.intel.com> wrote:
> >
> >
> > On 12/15/2022 9:28 PM, Namhyung Kim wrote:
> > > It can get SIGPIPE when it uses an external addr2line process and the
> > > process was terminated unexpectedly.  Let's ignore the signal and move
> > > on to the next sample.  The sample will get the default srcline value
> > > anyway.
> >
> >
> > That's a bit dangerous -- if perf report output is piped to something
> > else you really want to stop on SIGPIPE.
> 
> Maybe we can handle the pipe write errors gracefully, but it'd require
> more changes in many places.
> 
> >
> > You would need to find a way to distinguish those cases.
> 
> Hmm.. ok.  I guess we can just drop this for now.  With checking
> the .debug_line section, problematic cases should be gone mostly.

So just skip this one, ok, I'll cherry pick the rest. Done.

- Arnaldo

[PATCH 3/9] perf symbol: Add filename__has_section()

[Namhyung Kim]

The filename__has_section() is to check if the given section name is in
the binary.  It'd be used for checking debug info for srcline.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/util/symbol-elf.c     | 28 ++++++++++++++++++++++++++++
 tools/perf/util/symbol-minimal.c |  5 +++++
 tools/perf/util/symbol.h         |  1 +
 3 files changed, 34 insertions(+)

diff --git a/tools/perf/util/symbol-elf.c b/tools/perf/util/symbol-elf.c
index 80345695b136..96767d1b3f1c 100644
--- a/tools/perf/util/symbol-elf.c
+++ b/tools/perf/util/symbol-elf.c
@@ -233,6 +233,34 @@ Elf_Scn *elf_section_by_name(Elf *elf, GElf_Ehdr *ep,
 	return NULL;
 }
 
+bool filename__has_section(const char *filename, const char *sec)
+{
+	int fd;
+	Elf *elf;
+	GElf_Ehdr ehdr;
+	GElf_Shdr shdr;
+	bool found = false;
+
+	fd = open(filename, O_RDONLY);
+	if (fd < 0)
+		return false;
+
+	elf = elf_begin(fd, PERF_ELF_C_READ_MMAP, NULL);
+	if (elf == NULL)
+		goto out;
+
+	if (gelf_getehdr(elf, &ehdr) == NULL)
+		goto elf_out;
+
+	found = !!elf_section_by_name(elf, &ehdr, &shdr, sec, NULL);
+
+elf_out:
+	elf_end(elf);
+out:
+	close(fd);
+	return found;
+}
+
 static int elf_read_program_header(Elf *elf, u64 vaddr, GElf_Phdr *phdr)
 {
 	size_t i, phdrnum;
diff --git a/tools/perf/util/symbol-minimal.c b/tools/perf/util/symbol-minimal.c
index f9eb0bee7f15..de84da3b0d96 100644
--- a/tools/perf/util/symbol-minimal.c
+++ b/tools/perf/util/symbol-minimal.c
@@ -385,3 +385,8 @@ char *dso__demangle_sym(struct dso *dso __maybe_unused,
 {
 	return NULL;
 }
+
+bool filename__has_section(const char *filename, const char *sec)
+{
+	return false;
+}
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index e297de14184c..f735108c4d4e 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -165,6 +165,7 @@ int modules__parse(const char *filename, void *arg,
 					 u64 start, u64 size));
 int filename__read_debuglink(const char *filename, char *debuglink,
 			     size_t size);
+bool filename__has_section(const char *filename, const char *sec);
 
 struct perf_env;
 int symbol__init(struct perf_env *env);
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 4/9] perf srcline: Skip srcline if .debug_line is missing

[Namhyung Kim]

The srcline info is from the .debug_line section.  No need to setup
addr2line subprocess if the section is missing.

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

diff --git a/tools/perf/util/srcline.c b/tools/perf/util/srcline.c
index 5319efb16a5a..2c212e2e1b65 100644
--- a/tools/perf/util/srcline.c
+++ b/tools/perf/util/srcline.c
@@ -550,6 +550,9 @@ static int addr2line(const char *dso_name, u64 addr,
 	size_t inline_count = 0;
 
 	if (!a2l) {
+		if (!filename__has_section(dso_name, ".debug_line"))
+			goto out;
+
 		dso->a2l = addr2line_subprocess_init(dso_name);
 		a2l = dso->a2l;
 	}
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 5/9] perf srcline: Conditionally suppress addr2line warnings

[Namhyung Kim]

It has symbol_conf.disable_add2line_warn to suppress some warnings.  Let's
make it consistent with others.

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

diff --git a/tools/perf/util/srcline.c b/tools/perf/util/srcline.c
index 2c212e2e1b65..33321867416b 100644
--- a/tools/perf/util/srcline.c
+++ b/tools/perf/util/srcline.c
@@ -573,13 +573,15 @@ static int addr2line(const char *dso_name, u64 addr,
 	 * "??"/"??:0" lines.
 	 */
 	if (fprintf(a2l->to_child, "%016"PRIx64"\n,\n", addr) < 0 || fflush(a2l->to_child) != 0) {
-		pr_warning("%s %s: could not send request\n", __func__, dso_name);
+		if (!symbol_conf.disable_add2line_warn)
+			pr_warning("%s %s: could not send request\n", __func__, dso_name);
 		goto out;
 	}
 
 	switch (read_addr2line_record(a2l, &record_function, &record_filename, &record_line_nr)) {
 	case -1:
-		pr_warning("%s %s: could not read first record\n", __func__, dso_name);
+		if (!symbol_conf.disable_add2line_warn)
+			pr_warning("%s %s: could not read first record\n", __func__, dso_name);
 		goto out;
 	case 0:
 		/*
@@ -588,14 +590,17 @@ static int addr2line(const char *dso_name, u64 addr,
 		 */
 		switch (read_addr2line_record(a2l, NULL, NULL, NULL)) {
 		case -1:
-			pr_warning("%s %s: could not read delimiter record\n", __func__, dso_name);
+			if (!symbol_conf.disable_add2line_warn)
+				pr_warning("%s %s: could not read delimiter record\n",
+					   __func__, dso_name);
 			break;
 		case 0:
 			/* As expected. */
 			break;
 		default:
-			pr_warning("%s %s: unexpected record instead of sentinel",
-				   __func__, dso_name);
+			if (!symbol_conf.disable_add2line_warn)
+				pr_warning("%s %s: unexpected record instead of sentinel",
+					   __func__, dso_name);
 			break;
 		}
 		goto out;
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 6/9] perf hist: Add perf_hpp_fmt->init() callback

[Namhyung Kim]

In __hists__insert_output_entry(), it calls fmt->sort() for dynamic
entries with NULL to update column width for tracepoint fields.
But it's a hacky abuse of the sort callback, better to have a proper
callback for that.  I'll add more use cases later.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/util/hist.c | 10 +++++-----
 tools/perf/util/hist.h |  1 +
 tools/perf/util/sort.c | 31 ++++++++++++++++++++++++++-----
 tools/perf/util/sort.h |  1 +
 4 files changed, 33 insertions(+), 10 deletions(-)

diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c
index 17a05e943b44..b6e4b4edde43 100644
--- a/tools/perf/util/hist.c
+++ b/tools/perf/util/hist.c
@@ -1781,8 +1781,8 @@ static void hierarchy_insert_output_entry(struct rb_root_cached *root,
 
 	/* update column width of dynamic entry */
 	perf_hpp_list__for_each_sort_list(he->hpp_list, fmt) {
-		if (perf_hpp__is_dynamic_entry(fmt))
-			fmt->sort(fmt, he, NULL);
+		if (fmt->init)
+			fmt->init(fmt, he);
 	}
 }
 
@@ -1879,10 +1879,10 @@ static void __hists__insert_output_entry(struct rb_root_cached *entries,
 	rb_link_node(&he->rb_node, parent, p);
 	rb_insert_color_cached(&he->rb_node, entries, leftmost);
 
+	/* update column width of dynamic 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 */
+		if (fmt->init)
+			fmt->init(fmt, he);
 	}
 }
 
diff --git a/tools/perf/util/hist.h b/tools/perf/util/hist.h
index ebd8a8f783ee..d93a4e510dc7 100644
--- a/tools/perf/util/hist.h
+++ b/tools/perf/util/hist.h
@@ -272,6 +272,7 @@ struct perf_hpp_fmt {
 		      struct hists *hists, int line, int *span);
 	int (*width)(struct perf_hpp_fmt *fmt, struct perf_hpp *hpp,
 		     struct hists *hists);
+	void (*init)(struct perf_hpp_fmt *fmt, struct hist_entry *he);
 	int (*color)(struct perf_hpp_fmt *fmt, struct perf_hpp *hpp,
 		     struct hist_entry *he);
 	int (*entry)(struct perf_hpp_fmt *fmt, struct perf_hpp *hpp,
diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index 0ecc2cb13792..f6333b3dca35 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -2251,6 +2251,19 @@ static void hse_free(struct perf_hpp_fmt *fmt)
 	free(hse);
 }
 
+static void hse_init(struct perf_hpp_fmt *fmt, struct hist_entry *he)
+{
+	struct hpp_sort_entry *hse;
+
+	if (!perf_hpp__is_sort_entry(fmt))
+		return;
+
+	hse = container_of(fmt, struct hpp_sort_entry, hpp);
+
+	if (hse->se->se_init)
+		hse->se->se_init(he);
+}
+
 static struct hpp_sort_entry *
 __sort_dimension__alloc_hpp(struct sort_dimension *sd, int level)
 {
@@ -2274,6 +2287,7 @@ __sort_dimension__alloc_hpp(struct sort_dimension *sd, int level)
 	hse->hpp.sort = __sort__hpp_sort;
 	hse->hpp.equal = __sort__hpp_equal;
 	hse->hpp.free = hse_free;
+	hse->hpp.init = hse_init;
 
 	INIT_LIST_HEAD(&hse->hpp.list);
 	INIT_LIST_HEAD(&hse->hpp.sort_list);
@@ -2556,11 +2570,6 @@ 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 & TEP_FIELD_IS_DYNAMIC) {
 		unsigned long long dyn;
@@ -2610,6 +2619,17 @@ static void hde_free(struct perf_hpp_fmt *fmt)
 	free(hde);
 }
 
+static void __sort__hde_init(struct perf_hpp_fmt *fmt, struct hist_entry *he)
+{
+	struct hpp_dynamic_entry *hde;
+
+	if (!perf_hpp__is_dynamic_entry(fmt))
+		return;
+
+	hde = container_of(fmt, struct hpp_dynamic_entry, hpp);
+	update_dynamic_len(hde, he);
+}
+
 static struct hpp_dynamic_entry *
 __alloc_dynamic_entry(struct evsel *evsel, struct tep_format_field *field,
 		      int level)
@@ -2632,6 +2652,7 @@ __alloc_dynamic_entry(struct evsel *evsel, struct tep_format_field *field,
 	hde->hpp.entry  = __sort__hde_entry;
 	hde->hpp.color  = NULL;
 
+	hde->hpp.init = __sort__hde_init;
 	hde->hpp.cmp = __sort__hde_cmp;
 	hde->hpp.collapse = __sort__hde_cmp;
 	hde->hpp.sort = __sort__hde_cmp;
diff --git a/tools/perf/util/sort.h b/tools/perf/util/sort.h
index 04ff8b61a2a7..921715e6aec4 100644
--- a/tools/perf/util/sort.h
+++ b/tools/perf/util/sort.h
@@ -282,6 +282,7 @@ struct sort_entry {
 	int	(*se_snprintf)(struct hist_entry *he, char *bf, size_t size,
 			       unsigned int width);
 	int	(*se_filter)(struct hist_entry *he, int type, const void *arg);
+	void	(*se_init)(struct hist_entry *he);
 	u8	se_width_idx;
 };
 
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 7/9] perf hist: Improve srcline sort key performance

[Namhyung Kim]

The sort_entry->cmp() will be called for eventy sample data to find a
matching entry.  When it has 'srcline' sort key, that means it needs to
call addr2line or libbfd everytime.

This is not optimal because many samples will have same address and it
just can call addr2line once.  So postpone the actual srcline check to
the sort_entry->collpase() and compare addresses in ->cmp().

Also it needs to add ->init() callback to make sure it has srcline info.
If a sample has a unique data, chances are the entry can be sorted out
by other (previous) keys and callbacks in sort_srcline never called.

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

diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index f6333b3dca35..913045c5b2b2 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -373,6 +373,18 @@ char *hist_entry__srcline(struct hist_entry *he)
 
 static int64_t
 sort__srcline_cmp(struct hist_entry *left, struct hist_entry *right)
+{
+	int64_t ret;
+
+	ret = _sort__addr_cmp(left->ip, right->ip);
+	if (ret)
+		return ret;
+
+	return sort__dso_cmp(left, right);
+}
+
+static int64_t
+sort__srcline_collapse(struct hist_entry *left, struct hist_entry *right)
 {
 	if (!left->srcline)
 		left->srcline = hist_entry__srcline(left);
@@ -382,18 +394,31 @@ sort__srcline_cmp(struct hist_entry *left, struct hist_entry *right)
 	return strcmp(right->srcline, left->srcline);
 }
 
-static int hist_entry__srcline_snprintf(struct hist_entry *he, char *bf,
-					size_t size, unsigned int width)
+static int64_t
+sort__srcline_sort(struct hist_entry *left, struct hist_entry *right)
+{
+	return sort__srcline_collapse(left, right);
+}
+
+static void
+sort__srcline_init(struct hist_entry *he)
 {
 	if (!he->srcline)
 		he->srcline = hist_entry__srcline(he);
+}
 
+static int hist_entry__srcline_snprintf(struct hist_entry *he, char *bf,
+					size_t size, unsigned int width)
+{
 	return repsep_snprintf(bf, size, "%-.*s", width, he->srcline);
 }
 
 struct sort_entry sort_srcline = {
 	.se_header	= "Source:Line",
 	.se_cmp		= sort__srcline_cmp,
+	.se_collapse	= sort__srcline_collapse,
+	.se_sort	= sort__srcline_sort,
+	.se_init	= sort__srcline_init,
 	.se_snprintf	= hist_entry__srcline_snprintf,
 	.se_width_idx	= HISTC_SRCLINE,
 };
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 8/9] perf hist: Improve srcfile sort key performance

[Namhyung Kim]

Likewise, modify ->cmp() callback to compare sample address and map
address.  And add ->collapse() and ->sort() to check the actual
srcfile string.  Also add ->init() to make sure it has the srcfile.

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

diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index 913045c5b2b2..c290539dcf43 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -569,18 +569,41 @@ sort__srcfile_cmp(struct hist_entry *left, struct hist_entry *right)
 	return strcmp(right->srcfile, left->srcfile);
 }
 
-static int hist_entry__srcfile_snprintf(struct hist_entry *he, char *bf,
-					size_t size, unsigned int width)
+static int64_t
+sort__srcfile_collapse(struct hist_entry *left, struct hist_entry *right)
+{
+	if (!left->srcfile)
+		left->srcfile = hist_entry__get_srcfile(left);
+	if (!right->srcfile)
+		right->srcfile = hist_entry__get_srcfile(right);
+
+	return strcmp(right->srcfile, left->srcfile);
+}
+
+static int64_t
+sort__srcfile_sort(struct hist_entry *left, struct hist_entry *right)
+{
+	return sort__srcfile_collapse(left, right);
+}
+
+static void sort__srcfile_init(struct hist_entry *he)
 {
 	if (!he->srcfile)
 		he->srcfile = hist_entry__get_srcfile(he);
+}
 
+static int hist_entry__srcfile_snprintf(struct hist_entry *he, char *bf,
+					size_t size, unsigned int width)
+{
 	return repsep_snprintf(bf, size, "%-.*s", width, he->srcfile);
 }
 
 struct sort_entry sort_srcfile = {
 	.se_header	= "Source File",
 	.se_cmp		= sort__srcfile_cmp,
+	.se_collapse	= sort__srcfile_collapse,
+	.se_sort	= sort__srcfile_sort,
+	.se_init	= sort__srcfile_init,
 	.se_snprintf	= hist_entry__srcfile_snprintf,
 	.se_width_idx	= HISTC_SRCFILE,
 };
-- 
2.39.0.314.g84b9a713c41-goog

[PATCH 9/9] perf hist: Improve srcline_{from,to} sort key performance

[Namhyung Kim]

Likewise, modify ->cmp() callback to compare sample address and map
address.  And add ->collapse() and ->sort() to check the actual
srcfile string.  Also add ->init() to make sure it has the srcfile.

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

diff --git a/tools/perf/util/sort.c b/tools/perf/util/sort.c
index c290539dcf43..e188f74698dd 100644
--- a/tools/perf/util/sort.c
+++ b/tools/perf/util/sort.c
@@ -432,6 +432,12 @@ static char *addr_map_symbol__srcline(struct addr_map_symbol *ams)
 
 static int64_t
 sort__srcline_from_cmp(struct hist_entry *left, struct hist_entry *right)
+{
+	return left->branch_info->from.addr - right->branch_info->from.addr;
+}
+
+static int64_t
+sort__srcline_from_collapse(struct hist_entry *left, struct hist_entry *right)
 {
 	if (!left->branch_info->srcline_from)
 		left->branch_info->srcline_from = addr_map_symbol__srcline(&left->branch_info->from);
@@ -442,6 +448,18 @@ sort__srcline_from_cmp(struct hist_entry *left, struct hist_entry *right)
 	return strcmp(right->branch_info->srcline_from, left->branch_info->srcline_from);
 }
 
+static int64_t
+sort__srcline_from_sort(struct hist_entry *left, struct hist_entry *right)
+{
+	return sort__srcline_from_collapse(left, right);
+}
+
+static void sort__srcline_from_init(struct hist_entry *he)
+{
+	if (!he->branch_info->srcline_from)
+		he->branch_info->srcline_from = addr_map_symbol__srcline(&he->branch_info->from);
+}
+
 static int hist_entry__srcline_from_snprintf(struct hist_entry *he, char *bf,
 					size_t size, unsigned int width)
 {
@@ -451,6 +469,9 @@ static int hist_entry__srcline_from_snprintf(struct hist_entry *he, char *bf,
 struct sort_entry sort_srcline_from = {
 	.se_header	= "From Source:Line",
 	.se_cmp		= sort__srcline_from_cmp,
+	.se_collapse	= sort__srcline_from_collapse,
+	.se_sort	= sort__srcline_from_sort,
+	.se_init	= sort__srcline_from_init,
 	.se_snprintf	= hist_entry__srcline_from_snprintf,
 	.se_width_idx	= HISTC_SRCLINE_FROM,
 };
@@ -459,6 +480,12 @@ struct sort_entry sort_srcline_from = {
 
 static int64_t
 sort__srcline_to_cmp(struct hist_entry *left, struct hist_entry *right)
+{
+	return left->branch_info->to.addr - right->branch_info->to.addr;
+}
+
+static int64_t
+sort__srcline_to_collapse(struct hist_entry *left, struct hist_entry *right)
 {
 	if (!left->branch_info->srcline_to)
 		left->branch_info->srcline_to = addr_map_symbol__srcline(&left->branch_info->to);
@@ -469,6 +496,18 @@ sort__srcline_to_cmp(struct hist_entry *left, struct hist_entry *right)
 	return strcmp(right->branch_info->srcline_to, left->branch_info->srcline_to);
 }
 
+static int64_t
+sort__srcline_to_sort(struct hist_entry *left, struct hist_entry *right)
+{
+	return sort__srcline_to_collapse(left, right);
+}
+
+static void sort__srcline_to_init(struct hist_entry *he)
+{
+	if (!he->branch_info->srcline_to)
+		he->branch_info->srcline_to = addr_map_symbol__srcline(&he->branch_info->to);
+}
+
 static int hist_entry__srcline_to_snprintf(struct hist_entry *he, char *bf,
 					size_t size, unsigned int width)
 {
@@ -478,6 +517,9 @@ static int hist_entry__srcline_to_snprintf(struct hist_entry *he, char *bf,
 struct sort_entry sort_srcline_to = {
 	.se_header	= "To Source:Line",
 	.se_cmp		= sort__srcline_to_cmp,
+	.se_collapse	= sort__srcline_to_collapse,
+	.se_sort	= sort__srcline_to_sort,
+	.se_init	= sort__srcline_to_init,
 	.se_snprintf	= hist_entry__srcline_to_snprintf,
 	.se_width_idx	= HISTC_SRCLINE_TO,
 };
-- 
2.39.0.314.g84b9a713c41-goog

Re: [PATCHSET 0/9] perf report: Improve srcline sort performance (v1)

[Ian Rogers]

On Thu, Dec 15, 2022 at 11:28 AM Namhyung Kim <namhyung@kernel.org> wrote:
>
> Hello,
>
> I noticed a performance problem in the srcline/srcfile processing during
> perf report when it's using an external addr2line process.  I guess it's
> also helpful even if it uses the libbfd to get the srcline info.
>
> Also note that it's mostly from large (static) binaries, but smaller
> binaries should also benefit from the fix if they have a lot of samples.
>
> The first 5 patches are general fixes and updates.  The latter 4 patches
> implemented the actual speed-up.
>
> Let's test it with the perf tools itself.  Build a static binary like below.
>
>   $ cd tools/perf
>   $ make NO_JVMTI=1 LDFLAGS=-static
>
> Then run the perf test workload.
>
>   $ ./perf record -- ./perf test -w noploop
>
> And run the perf report with srcline sort key like this.
>
>   $ ./perf report -n -s srcline --stdio
>   # To display the perf.data header info, please use --header/--header-only options.
>   #
>   #
>   # Total Lost Samples: 0
>   #
>   # Samples: 4K of event 'cycles:u'
>   # Event count (approx.): 3572938596
>   #
>   # Overhead       Samples  Source:Line
>   # ........  ............  ............
>   #
>       99.94%          4010  noploop.c:26
>        0.03%            14  ??:0
>        0.03%             1  perf.c:330
>        0.00%             1  wcscpy.o:0
>
> The problem is that it runs the addr2line when it processes each sample.
> But as you can see many samples can have same result.  IOW, if the samples
> have same address, we don't need to run the addr2line each time.
>
> So I changed the sort_key->cmp() to compare the addresses only and moved
> the addr2line from sort_key->collapse() so that they can be run after
> merging the samples with the same address.
>
> With the change, I can get a huge speed-up in processing srcline info
> while they generate the same output.
>
> Before:
>
>   $ ./perf stat -- ./perf report -s srcline > /dev/null
>
>    Performance counter stats for './perf report -s srcline':
>
>            15,397.13 msec task-clock:u                     #    0.993 CPUs utilized
>                    0      context-switches:u               #    0.000 /sec
>                    0      cpu-migrations:u                 #    0.000 /sec
>                3,810      page-faults:u                    #  247.449 /sec
>       54,516,351,820      cycles:u                         #    3.541 GHz
>       31,494,118,293      instructions:u                   #    0.58  insn per cycle
>        8,577,271,187      branches:u                       #  557.069 M/sec
>        1,216,165,520      branch-misses:u                  #   14.18% of all branches
>
>         15.505066606 seconds time elapsed
>
>         15.094122000 seconds user
>          0.396962000 seconds sys
>
> After:
>
>   $ ./perf stat -- ./perf report -s srcline > /dev/null
>
>    Performance counter stats for './perf report -s srcline':
>
>               105.66 msec task-clock:u                     #    0.994 CPUs utilized
>                    0      context-switches:u               #    0.000 /sec
>                    0      cpu-migrations:u                 #    0.000 /sec
>                3,275      page-faults:u                    #   30.995 K/sec
>          185,063,407      cycles:u                         #    1.751 GHz
>          142,470,215      instructions:u                   #    0.77  insn per cycle
>           34,584,038      branches:u                       #  327.311 M/sec
>            3,226,005      branch-misses:u                  #    9.33% of all branches
>
>          0.106270464 seconds time elapsed
>
>          0.074254000 seconds user
>          0.032871000 seconds sys
>
> The code is available at 'perf/srcline-v1' branch in
>
>   git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
>
> Thanks,
> Namhyung
>
>
> Namhyung Kim (9):
>   perf srcline: Do not return NULL for srcline
>   perf report: Ignore SIGPIPE for srcline
>   perf symbol: Add filename__has_section()
>   perf srcline: Skip srcline if .debug_line is missing
>   perf srcline: Conditionally suppress addr2line warnings
>   perf hist: Add perf_hpp_fmt->init() callback
>   perf hist: Improve srcline sort key performance
>   perf hist: Improve srcfile sort key performance
>   perf hist: Improve srcline_{from,to} sort key performance

Nice 145x performance win!

Series: Acked-by: Ian Rogers <irogers@google.com>

Thanks,
Ian

>  tools/perf/builtin-report.c      |   1 +
>  tools/perf/util/hist.c           |  10 +--
>  tools/perf/util/hist.h           |   1 +
>  tools/perf/util/sort.c           | 129 ++++++++++++++++++++++++++++---
>  tools/perf/util/sort.h           |   1 +
>  tools/perf/util/srcline.c        |  20 +++--
>  tools/perf/util/symbol-elf.c     |  28 +++++++
>  tools/perf/util/symbol-minimal.c |   5 ++
>  tools/perf/util/symbol.h         |   1 +
>  9 files changed, 176 insertions(+), 20 deletions(-)
>
>
> base-commit: 818448e9cf92e5c6b3c10320372eefcbe4174e4f
> --
> 2.39.0.314.g84b9a713c41-goog
>