[PATCH perf/core v3 0/3] perf-probe bugfixes

[PATCH perf/core v3 0/3] perf-probe bugfixes

[Masami Hiramatsu]

Hi Arnaldo,

Here is the v3 series of bugfix patches for perf-probe.
I've rewriten the patch description of 2/3 (no code changed)
and added a comment on the 3/3 for reproductivity.
This series fixes below bugs;

 - --list shows the list of probes in stderr.
   (It is refined from https://lkml.org/lkml/2015/5/30/34)
 - return success even if no probe is added.
 - usage message is not shown if the last event is skipped.

BTW, this series still include 1/3, since I couldn't find it
in the latest(published) perf/core. If you've already merged
it on your local tree, please skip it.

Thank you,

---

Masami Hiramatsu (3):
      [BUGFIX] perf probe: List probes in stdout
      [BUGFIX] perf probe: Fix to return error if no-probe is added
      [BUGFIX] perf probe: Show usage even if the last event is skipped


 tools/perf/util/probe-event.c |  187 ++++++++++++++++++++++++++---------------
 1 file changed, 118 insertions(+), 69 deletions(-)


-- 
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering 
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu.pt@hitachi.com

[PATCH perf/core v3 1/3] [BUGFIX] perf probe: List probes in stdout

[Masami Hiramatsu]

Since commit 5e17b28f1e24 ("perf probe: Add --quiet option to
suppress output result message") have replaced printf with pr_info,
perf probe -l outputs its result in stderr. However, that is not
what the commit expected.
e.g.
  -----
  # perf probe -l > /dev/null
    probe:vfs_read       (on vfs_read@ksrc/linux-3/fs/read_write.c)
  -----
With this fix,
  -----
  # perf probe -l > list
  # cat list
    probe:vfs_read       (on vfs_read@ksrc/linux-3/fs/read_write.c)
  -----
Of course, --quiet(-q) still works on --add/--del.
  -----
  # perf probe -q vfs_write
  # perf probe -l
    probe:vfs_read       (on vfs_read@ksrc/linux-3/fs/read_write.c)
    probe:vfs_write      (on vfs_write@ksrc/linux-3/fs/read_write.c)
  -----

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Reported-by: Naohiro Aota <naota@elisp.net>

---
 Changes in v2:
  - Fix to reverse the use_stdio flag at each caller.
---
 tools/perf/util/probe-event.c |   49 +++++++++++++++++++++++++++++------------
 1 file changed, 35 insertions(+), 14 deletions(-)

diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
index daa24a2..c4ab588 100644
--- a/tools/perf/util/probe-event.c
+++ b/tools/perf/util/probe-event.c
@@ -2126,9 +2126,9 @@ kprobe_blacklist__find_by_address(struct list_head *blacklist,
 	return NULL;
 }
 
-/* Show an event */
-static int show_perf_probe_event(struct perf_probe_event *pev,
-				 const char *module)
+static int perf_probe_event__sprintf(struct perf_probe_event *pev,
+				     const char *module,
+				     struct strbuf *result)
 {
 	int i, ret;
 	char buf[128];
@@ -2141,27 +2141,47 @@ static int show_perf_probe_event(struct perf_probe_event *pev,
 
 	ret = e_snprintf(buf, 128, "%s:%s", pev->group, pev->event);
 	if (ret < 0)
-		return ret;
+		goto out;
 
-	pr_info("  %-20s (on %s", buf, place);
+	strbuf_addf(result, "  %-20s (on %s", buf, place);
 	if (module)
-		pr_info(" in %s", module);
+		strbuf_addf(result, " in %s", module);
 
 	if (pev->nargs > 0) {
-		pr_info(" with");
+		strbuf_addstr(result, " with");
 		for (i = 0; i < pev->nargs; i++) {
 			ret = synthesize_perf_probe_arg(&pev->args[i],
 							buf, 128);
 			if (ret < 0)
-				break;
-			pr_info(" %s", buf);
+				goto out;
+			strbuf_addf(result, " %s", buf);
 		}
 	}
-	pr_info(")\n");
+	strbuf_addch(result, ')');
+out:
 	free(place);
 	return ret;
 }
 
+/* Show an event */
+static int show_perf_probe_event(struct perf_probe_event *pev,
+				 const char *module, bool use_stdout)
+{
+	struct strbuf buf = STRBUF_INIT;
+	int ret;
+
+	ret = perf_probe_event__sprintf(pev, module, &buf);
+	if (ret >= 0) {
+		if (use_stdout)
+			printf("%s\n", buf.buf);
+		else
+			pr_info("%s\n", buf.buf);
+	}
+	strbuf_release(&buf);
+
+	return ret;
+}
+
 static bool filter_probe_trace_event(struct probe_trace_event *tev,
 				     struct strfilter *filter)
 {
@@ -2200,9 +2220,10 @@ static int __show_perf_probe_events(int fd, bool is_kprobe,
 				goto next;
 			ret = convert_to_perf_probe_event(&tev, &pev,
 								is_kprobe);
-			if (ret >= 0)
-				ret = show_perf_probe_event(&pev,
-							    tev.point.module);
+			if (ret < 0)
+				goto next;
+			ret = show_perf_probe_event(&pev, tev.point.module,
+						    true);
 		}
 next:
 		clear_perf_probe_event(&pev);
@@ -2468,7 +2489,7 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 		group = pev->group;
 		pev->event = tev->event;
 		pev->group = tev->group;
-		show_perf_probe_event(pev, tev->point.module);
+		show_perf_probe_event(pev, tev->point.module, false);
 		/* Trick here - restore current event/group */
 		pev->event = (char *)event;
 		pev->group = (char *)group;

[PATCH perf/core v3 2/3] [BUGFIX] perf probe: Fix to return error if no-probe is added

[Masami Hiramatsu]

Fix perf probe to return an error if no-probe is added since
the given probe point is on the blacklist.
To fix this problem, this moves blacklist checking right
after finding symbols/probe-points and marks it as skipped.
If all the symbols are skipped, perf-probe returns error as
it fails to find corresponding probe address.

e.g. currently if we give a blacklisted probe is given,
  ----
  # perf probe do_trap && echo 'succeed'
  Added new event:
  Warning: Skipped probing on blacklisted function: sync_regs
  succeed
  ----
No! it must be failed. With this patch, it correctly failed.
  ----
  # perf probe do_trap && echo 'succeed'
  do_trap is blacklisted function, skip it.
  Probe point 'do_trap' not found.
    Error: Failed to add events.
  ----

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
---
 Changes in v3:
  - Rewrite the comment and ensure what was fixed.
---
 tools/perf/util/probe-event.c |  113 ++++++++++++++++++++++++++---------------
 1 file changed, 71 insertions(+), 42 deletions(-)

diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
index c4ab588..85c8207 100644
--- a/tools/perf/util/probe-event.c
+++ b/tools/perf/util/probe-event.c
@@ -246,6 +246,20 @@ static void clear_probe_trace_events(struct probe_trace_event *tevs, int ntevs)
 		clear_probe_trace_event(tevs + i);
 }
 
+static bool kprobe_blacklist__listed(unsigned long address);
+static bool kprobe_warn_out_range(const char *symbol, unsigned long address)
+{
+	/* Get the address of _etext for checking non-probable text symbol */
+	if (kernel_get_symbol_address_by_name("_etext", false) < address)
+		pr_warning("%s is out of .text, skip it.\n", symbol);
+	else if (kprobe_blacklist__listed(address))
+		pr_warning("%s is blacklisted function, skip it.\n", symbol);
+	else
+		return false;
+
+	return true;
+}
+
 #ifdef HAVE_DWARF_SUPPORT
 
 static int kernel_get_module_dso(const char *module, struct dso **pdso)
@@ -559,7 +573,6 @@ static int post_process_probe_trace_events(struct probe_trace_event *tevs,
 					   bool uprobe)
 {
 	struct ref_reloc_sym *reloc_sym;
-	u64 etext_addr;
 	char *tmp;
 	int i, skipped = 0;
 
@@ -575,31 +588,28 @@ static int post_process_probe_trace_events(struct probe_trace_event *tevs,
 		pr_warning("Relocated base symbol is not found!\n");
 		return -EINVAL;
 	}
-	/* Get the address of _etext for checking non-probable text symbol */
-	etext_addr = kernel_get_symbol_address_by_name("_etext", false);
 
 	for (i = 0; i < ntevs; i++) {
-		if (tevs[i].point.address && !tevs[i].point.retprobe) {
-			/* If we found a wrong one, mark it by NULL symbol */
-			if (etext_addr < tevs[i].point.address) {
-				pr_warning("%s+%lu is out of .text, skip it.\n",
-				   tevs[i].point.symbol, tevs[i].point.offset);
-				tmp = NULL;
-				skipped++;
-			} else {
-				tmp = strdup(reloc_sym->name);
-				if (!tmp)
-					return -ENOMEM;
-			}
-			/* If we have no realname, use symbol for it */
-			if (!tevs[i].point.realname)
-				tevs[i].point.realname = tevs[i].point.symbol;
-			else
-				free(tevs[i].point.symbol);
-			tevs[i].point.symbol = tmp;
-			tevs[i].point.offset = tevs[i].point.address -
-					       reloc_sym->unrelocated_addr;
+		if (!tevs[i].point.address || tevs[i].point.retprobe)
+			continue;
+		/* If we found a wrong one, mark it by NULL symbol */
+		if (kprobe_warn_out_range(tevs[i].point.symbol,
+					  tevs[i].point.address)) {
+			tmp = NULL;
+			skipped++;
+		} else {
+			tmp = strdup(reloc_sym->name);
+			if (!tmp)
+				return -ENOMEM;
 		}
+		/* If we have no realname, use symbol for it */
+		if (!tevs[i].point.realname)
+			tevs[i].point.realname = tevs[i].point.symbol;
+		else
+			free(tevs[i].point.symbol);
+		tevs[i].point.symbol = tmp;
+		tevs[i].point.offset = tevs[i].point.address -
+				       reloc_sym->unrelocated_addr;
 	}
 	return skipped;
 }
@@ -2126,6 +2136,27 @@ kprobe_blacklist__find_by_address(struct list_head *blacklist,
 	return NULL;
 }
 
+static LIST_HEAD(kprobe_blacklist);
+
+static void kprobe_blacklist__init(void)
+{
+	if (!list_empty(&kprobe_blacklist))
+		return;
+
+	if (kprobe_blacklist__load(&kprobe_blacklist) < 0)
+		pr_debug("No kprobe blacklist support, ignored\n");
+}
+
+static void kprobe_blacklist__release(void)
+{
+	kprobe_blacklist__delete(&kprobe_blacklist);
+}
+
+static bool kprobe_blacklist__listed(unsigned long address)
+{
+	return !!kprobe_blacklist__find_by_address(&kprobe_blacklist, address);
+}
+
 static int perf_probe_event__sprintf(struct perf_probe_event *pev,
 				     const char *module,
 				     struct strbuf *result)
@@ -2409,8 +2440,6 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 	char buf[64];
 	const char *event, *group;
 	struct strlist *namelist;
-	LIST_HEAD(blacklist);
-	struct kprobe_blacklist_node *node;
 	bool safename;
 
 	if (pev->uprobes)
@@ -2430,28 +2459,15 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 		ret = -ENOMEM;
 		goto close_out;
 	}
-	/* Get kprobe blacklist if exists */
-	if (!pev->uprobes) {
-		ret = kprobe_blacklist__load(&blacklist);
-		if (ret < 0)
-			pr_debug("No kprobe blacklist support, ignored\n");
-	}
 
 	safename = (pev->point.function && !strisglob(pev->point.function));
 	ret = 0;
 	pr_info("Added new event%s\n", (ntevs > 1) ? "s:" : ":");
 	for (i = 0; i < ntevs; i++) {
 		tev = &tevs[i];
-		/* Skip if the symbol is out of .text (marked previously) */
+		/* Skip if the symbol is out of .text or blacklisted */
 		if (!tev->point.symbol)
 			continue;
-		/* Ensure that the address is NOT blacklisted */
-		node = kprobe_blacklist__find_by_address(&blacklist,
-							 tev->point.address);
-		if (node) {
-			pr_warning("Warning: Skipped probing on blacklisted function: %s\n", node->symbol);
-			continue;
-		}
 
 		if (pev->event)
 			event = pev->event;
@@ -2513,7 +2529,6 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 			 tev->event);
 	}
 
-	kprobe_blacklist__delete(&blacklist);
 	strlist__delete(namelist);
 close_out:
 	close(fd);
@@ -2563,7 +2578,7 @@ static int find_probe_trace_events_from_map(struct perf_probe_event *pev,
 	struct perf_probe_point *pp = &pev->point;
 	struct probe_trace_point *tp;
 	int num_matched_functions;
-	int ret, i, j;
+	int ret, i, j, skipped = 0;
 
 	map = get_target_map(pev->target, pev->uprobes);
 	if (!map) {
@@ -2631,7 +2646,12 @@ static int find_probe_trace_events_from_map(struct perf_probe_event *pev,
 		}
 		/* Add one probe point */
 		tp->address = map->unmap_ip(map, sym->start) + pp->offset;
-		if (reloc_sym) {
+		/* If we found a wrong one, mark it by NULL symbol */
+		if (!pev->uprobes &&
+		    kprobe_warn_out_range(sym->name, tp->address)) {
+			tp->symbol = NULL;	/* Skip it */
+			skipped++;
+		} else if (reloc_sym) {
 			tp->symbol = strdup_or_goto(reloc_sym->name, nomem_out);
 			tp->offset = tp->address - reloc_sym->addr;
 		} else {
@@ -2667,6 +2687,10 @@ static int find_probe_trace_events_from_map(struct perf_probe_event *pev,
 		}
 		arch__fix_tev_from_maps(pev, tev, map);
 	}
+	if (ret == skipped) {
+		ret = -ENOENT;
+		goto err_out;
+	}
 
 out:
 	put_target_map(map, pev->uprobes);
@@ -2737,6 +2761,9 @@ int add_perf_probe_events(struct perf_probe_event *pevs, int npevs)
 	/* Loop 1: convert all events */
 	for (i = 0; i < npevs; i++) {
 		pkgs[i].pev = &pevs[i];
+		/* Init kprobe blacklist if needed */
+		if (!pkgs[i].pev->uprobes)
+			kprobe_blacklist__init();
 		/* Convert with or without debuginfo */
 		ret  = convert_to_probe_trace_events(pkgs[i].pev,
 						     &pkgs[i].tevs);
@@ -2744,6 +2771,8 @@ int add_perf_probe_events(struct perf_probe_event *pevs, int npevs)
 			goto end;
 		pkgs[i].ntevs = ret;
 	}
+	/* This just release blacklist only if allocated */
+	kprobe_blacklist__release();
 
 	/* Loop 2: add all events */
 	for (i = 0; i < npevs; i++) {

[tip:perf/core] perf probe: Fix to return error if no probe is added

[tip-bot for Masami Hiramatsu]

Commit-ID:  b031220d520238075bd99513a420e65cf37866ad
Gitweb:     http://git.kernel.org/tip/b031220d520238075bd99513a420e65cf37866ad
Author:     Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
AuthorDate: Tue, 16 Jun 2015 20:50:55 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 16 Jun 2015 11:39:51 -0300

perf probe: Fix to return error if no probe is added

Fix perf probe to return an error if no probe is added due to the given
probe point being on the blacklist.

To fix this problem, this moves the blacklist checking to right after
finding symbols/probe-points and marks them as skipped.

If all the symbols are skipped, "perf probe"  returns an error as it
fails to find the corresponding probe address.

E.g. currently if a blacklisted probe is given:

  # perf probe do_trap && echo 'succeed'
  Added new event:
  Warning: Skipped probing on blacklisted function: sync_regs
  succeed

No! It must fail! With this patch, it correctly fails:

  # perf probe do_trap && echo 'succeed'
  do_trap is blacklisted function, skip it.
  Probe point 'do_trap' not found.
    Error: Failed to add events.

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Naohiro Aota <naota@elisp.net>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20150616115055.19906.31359.stgit@localhost.localdomain
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/probe-event.c | 113 ++++++++++++++++++++++++++----------------
 1 file changed, 71 insertions(+), 42 deletions(-)

diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
index c4ab588..85c8207 100644
--- a/tools/perf/util/probe-event.c
+++ b/tools/perf/util/probe-event.c
@@ -246,6 +246,20 @@ static void clear_probe_trace_events(struct probe_trace_event *tevs, int ntevs)
 		clear_probe_trace_event(tevs + i);
 }
 
+static bool kprobe_blacklist__listed(unsigned long address);
+static bool kprobe_warn_out_range(const char *symbol, unsigned long address)
+{
+	/* Get the address of _etext for checking non-probable text symbol */
+	if (kernel_get_symbol_address_by_name("_etext", false) < address)
+		pr_warning("%s is out of .text, skip it.\n", symbol);
+	else if (kprobe_blacklist__listed(address))
+		pr_warning("%s is blacklisted function, skip it.\n", symbol);
+	else
+		return false;
+
+	return true;
+}
+
 #ifdef HAVE_DWARF_SUPPORT
 
 static int kernel_get_module_dso(const char *module, struct dso **pdso)
@@ -559,7 +573,6 @@ static int post_process_probe_trace_events(struct probe_trace_event *tevs,
 					   bool uprobe)
 {
 	struct ref_reloc_sym *reloc_sym;
-	u64 etext_addr;
 	char *tmp;
 	int i, skipped = 0;
 
@@ -575,31 +588,28 @@ static int post_process_probe_trace_events(struct probe_trace_event *tevs,
 		pr_warning("Relocated base symbol is not found!\n");
 		return -EINVAL;
 	}
-	/* Get the address of _etext for checking non-probable text symbol */
-	etext_addr = kernel_get_symbol_address_by_name("_etext", false);
 
 	for (i = 0; i < ntevs; i++) {
-		if (tevs[i].point.address && !tevs[i].point.retprobe) {
-			/* If we found a wrong one, mark it by NULL symbol */
-			if (etext_addr < tevs[i].point.address) {
-				pr_warning("%s+%lu is out of .text, skip it.\n",
-				   tevs[i].point.symbol, tevs[i].point.offset);
-				tmp = NULL;
-				skipped++;
-			} else {
-				tmp = strdup(reloc_sym->name);
-				if (!tmp)
-					return -ENOMEM;
-			}
-			/* If we have no realname, use symbol for it */
-			if (!tevs[i].point.realname)
-				tevs[i].point.realname = tevs[i].point.symbol;
-			else
-				free(tevs[i].point.symbol);
-			tevs[i].point.symbol = tmp;
-			tevs[i].point.offset = tevs[i].point.address -
-					       reloc_sym->unrelocated_addr;
+		if (!tevs[i].point.address || tevs[i].point.retprobe)
+			continue;
+		/* If we found a wrong one, mark it by NULL symbol */
+		if (kprobe_warn_out_range(tevs[i].point.symbol,
+					  tevs[i].point.address)) {
+			tmp = NULL;
+			skipped++;
+		} else {
+			tmp = strdup(reloc_sym->name);
+			if (!tmp)
+				return -ENOMEM;
 		}
+		/* If we have no realname, use symbol for it */
+		if (!tevs[i].point.realname)
+			tevs[i].point.realname = tevs[i].point.symbol;
+		else
+			free(tevs[i].point.symbol);
+		tevs[i].point.symbol = tmp;
+		tevs[i].point.offset = tevs[i].point.address -
+				       reloc_sym->unrelocated_addr;
 	}
 	return skipped;
 }
@@ -2126,6 +2136,27 @@ kprobe_blacklist__find_by_address(struct list_head *blacklist,
 	return NULL;
 }
 
+static LIST_HEAD(kprobe_blacklist);
+
+static void kprobe_blacklist__init(void)
+{
+	if (!list_empty(&kprobe_blacklist))
+		return;
+
+	if (kprobe_blacklist__load(&kprobe_blacklist) < 0)
+		pr_debug("No kprobe blacklist support, ignored\n");
+}
+
+static void kprobe_blacklist__release(void)
+{
+	kprobe_blacklist__delete(&kprobe_blacklist);
+}
+
+static bool kprobe_blacklist__listed(unsigned long address)
+{
+	return !!kprobe_blacklist__find_by_address(&kprobe_blacklist, address);
+}
+
 static int perf_probe_event__sprintf(struct perf_probe_event *pev,
 				     const char *module,
 				     struct strbuf *result)
@@ -2409,8 +2440,6 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 	char buf[64];
 	const char *event, *group;
 	struct strlist *namelist;
-	LIST_HEAD(blacklist);
-	struct kprobe_blacklist_node *node;
 	bool safename;
 
 	if (pev->uprobes)
@@ -2430,28 +2459,15 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 		ret = -ENOMEM;
 		goto close_out;
 	}
-	/* Get kprobe blacklist if exists */
-	if (!pev->uprobes) {
-		ret = kprobe_blacklist__load(&blacklist);
-		if (ret < 0)
-			pr_debug("No kprobe blacklist support, ignored\n");
-	}
 
 	safename = (pev->point.function && !strisglob(pev->point.function));
 	ret = 0;
 	pr_info("Added new event%s\n", (ntevs > 1) ? "s:" : ":");
 	for (i = 0; i < ntevs; i++) {
 		tev = &tevs[i];
-		/* Skip if the symbol is out of .text (marked previously) */
+		/* Skip if the symbol is out of .text or blacklisted */
 		if (!tev->point.symbol)
 			continue;
-		/* Ensure that the address is NOT blacklisted */
-		node = kprobe_blacklist__find_by_address(&blacklist,
-							 tev->point.address);
-		if (node) {
-			pr_warning("Warning: Skipped probing on blacklisted function: %s\n", node->symbol);
-			continue;
-		}
 
 		if (pev->event)
 			event = pev->event;
@@ -2513,7 +2529,6 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 			 tev->event);
 	}
 
-	kprobe_blacklist__delete(&blacklist);
 	strlist__delete(namelist);
 close_out:
 	close(fd);
@@ -2563,7 +2578,7 @@ static int find_probe_trace_events_from_map(struct perf_probe_event *pev,
 	struct perf_probe_point *pp = &pev->point;
 	struct probe_trace_point *tp;
 	int num_matched_functions;
-	int ret, i, j;
+	int ret, i, j, skipped = 0;
 
 	map = get_target_map(pev->target, pev->uprobes);
 	if (!map) {
@@ -2631,7 +2646,12 @@ static int find_probe_trace_events_from_map(struct perf_probe_event *pev,
 		}
 		/* Add one probe point */
 		tp->address = map->unmap_ip(map, sym->start) + pp->offset;
-		if (reloc_sym) {
+		/* If we found a wrong one, mark it by NULL symbol */
+		if (!pev->uprobes &&
+		    kprobe_warn_out_range(sym->name, tp->address)) {
+			tp->symbol = NULL;	/* Skip it */
+			skipped++;
+		} else if (reloc_sym) {
 			tp->symbol = strdup_or_goto(reloc_sym->name, nomem_out);
 			tp->offset = tp->address - reloc_sym->addr;
 		} else {
@@ -2667,6 +2687,10 @@ static int find_probe_trace_events_from_map(struct perf_probe_event *pev,
 		}
 		arch__fix_tev_from_maps(pev, tev, map);
 	}
+	if (ret == skipped) {
+		ret = -ENOENT;
+		goto err_out;
+	}
 
 out:
 	put_target_map(map, pev->uprobes);
@@ -2737,6 +2761,9 @@ int add_perf_probe_events(struct perf_probe_event *pevs, int npevs)
 	/* Loop 1: convert all events */
 	for (i = 0; i < npevs; i++) {
 		pkgs[i].pev = &pevs[i];
+		/* Init kprobe blacklist if needed */
+		if (!pkgs[i].pev->uprobes)
+			kprobe_blacklist__init();
 		/* Convert with or without debuginfo */
 		ret  = convert_to_probe_trace_events(pkgs[i].pev,
 						     &pkgs[i].tevs);
@@ -2744,6 +2771,8 @@ int add_perf_probe_events(struct perf_probe_event *pevs, int npevs)
 			goto end;
 		pkgs[i].ntevs = ret;
 	}
+	/* This just release blacklist only if allocated */
+	kprobe_blacklist__release();
 
 	/* Loop 2: add all events */
 	for (i = 0; i < npevs; i++) {

[PATCH perf/core v3 3/3] [BUGFIX] perf probe: Show usage even if the last event is skipped

[Masami Hiramatsu]

When the last part of converted events are blacklisted or out-of-text,
those are skipped and perf probe doesn't show usage examples.
This fixes it to show the example even if the last part of event list
is skipped.

E.g. without this patch, events are added, but suddenly end;
  ----
  # perf probe vfs_*
  vfs_caches_init_early is out of .text, skip it.
  vfs_caches_init is out of .text, skip it.
  Added new events:
    probe:vfs_fallocate  (on vfs_*)
    probe:vfs_open       (on vfs_*)
  ...
    probe:vfs_dentry_acceptable (on vfs_*)
    probe:vfs_load_quota_inode (on vfs_*)
  #
  ----
With this fix;
  ----
  # perf probe vfs_*
  vfs_caches_init_early is out of .text, skip it.
  vfs_caches_init is out of .text, skip it.
  Added new events:
    probe:vfs_fallocate  (on vfs_*)
  ...
    probe:vfs_load_quota_inode (on vfs_*)

  You can now use it in all perf tools, such as:

	perf record -e probe:vfs_load_quota_inode -aR sleep 1

  #
  ----

Note that this can be reproduced ONLY IF the vfs_caches_init*
is the last part of matched symbol list. I've checked this happens
on "3.19.0-generic #18-Ubuntu" kernel binary.

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
---
 tools/perf/util/probe-event.c |   35 +++++++++++++++++------------------
 1 file changed, 17 insertions(+), 18 deletions(-)

diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
index 85c8207..65a1c82 100644
--- a/tools/perf/util/probe-event.c
+++ b/tools/perf/util/probe-event.c
@@ -2157,7 +2157,8 @@ static bool kprobe_blacklist__listed(unsigned long address)
 	return !!kprobe_blacklist__find_by_address(&kprobe_blacklist, address);
 }
 
-static int perf_probe_event__sprintf(struct perf_probe_event *pev,
+static int perf_probe_event__sprintf(const char *group, const char *event,
+				     struct perf_probe_event *pev,
 				     const char *module,
 				     struct strbuf *result)
 {
@@ -2170,7 +2171,7 @@ static int perf_probe_event__sprintf(struct perf_probe_event *pev,
 	if (!place)
 		return -EINVAL;
 
-	ret = e_snprintf(buf, 128, "%s:%s", pev->group, pev->event);
+	ret = e_snprintf(buf, 128, "%s:%s", group, event);
 	if (ret < 0)
 		goto out;
 
@@ -2195,13 +2196,14 @@ out:
 }
 
 /* Show an event */
-static int show_perf_probe_event(struct perf_probe_event *pev,
+static int show_perf_probe_event(const char *group, const char *event,
+				 struct perf_probe_event *pev,
 				 const char *module, bool use_stdout)
 {
 	struct strbuf buf = STRBUF_INIT;
 	int ret;
 
-	ret = perf_probe_event__sprintf(pev, module, &buf);
+	ret = perf_probe_event__sprintf(group, event, pev, module, &buf);
 	if (ret >= 0) {
 		if (use_stdout)
 			printf("%s\n", buf.buf);
@@ -2253,7 +2255,8 @@ static int __show_perf_probe_events(int fd, bool is_kprobe,
 								is_kprobe);
 			if (ret < 0)
 				goto next;
-			ret = show_perf_probe_event(&pev, tev.point.module,
+			ret = show_perf_probe_event(pev.group, pev.event,
+						    &pev, tev.point.module,
 						    true);
 		}
 next:
@@ -2438,7 +2441,7 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 	int i, fd, ret;
 	struct probe_trace_event *tev = NULL;
 	char buf[64];
-	const char *event, *group;
+	const char *event = NULL, *group = NULL;
 	struct strlist *namelist;
 	bool safename;
 
@@ -2500,15 +2503,12 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 		/* Add added event name to namelist */
 		strlist__add(namelist, event);
 
-		/* Trick here - save current event/group */
-		event = pev->event;
-		group = pev->group;
-		pev->event = tev->event;
-		pev->group = tev->group;
-		show_perf_probe_event(pev, tev->point.module, false);
-		/* Trick here - restore current event/group */
-		pev->event = (char *)event;
-		pev->group = (char *)group;
+		/* We use tev's name for showing new events */
+		show_perf_probe_event(tev->group, tev->event, pev,
+				      tev->point.module, false);
+		/* Save the last valid name */
+		event = tev->event;
+		group = tev->group;
 
 		/*
 		 * Probes after the first probe which comes from same
@@ -2522,11 +2522,10 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 		warn_uprobe_event_compat(tev);
 
 	/* Note that it is possible to skip all events because of blacklist */
-	if (ret >= 0 && tev->event) {
+	if (ret >= 0 && event) {
 		/* Show how to use the event. */
 		pr_info("\nYou can now use it in all perf tools, such as:\n\n");
-		pr_info("\tperf record -e %s:%s -aR sleep 1\n\n", tev->group,
-			 tev->event);
+		pr_info("\tperf record -e %s:%s -aR sleep 1\n\n", group, event);
 	}
 
 	strlist__delete(namelist);

Re: [PATCH perf/core v3 3/3] [BUGFIX] perf probe: Show usage even if the last event is skipped

[Arnaldo Carvalho de Melo]

Em Tue, Jun 16, 2015 at 08:50:57PM +0900, Masami Hiramatsu escreveu:
> When the last part of converted events are blacklisted or out-of-text,
> those are skipped and perf probe doesn't show usage examples.
> This fixes it to show the example even if the last part of event list
> is skipped.
> 
> E.g. without this patch, events are added, but suddenly end;

End what? Stop being added? I.e. not all eligible events are added? From
your description the problem seems to be that that last message: "You
can now use it..."  is not presented, but here, without this patch, it
is:

[root@zoo ~]# perf probe vfs_*
vfs_caches_init_early is out of .text, skip it.
vfs_caches_init is out of .text, skip it.
Added new events:
  probe:vfs_open       (on vfs_*)
  probe:vfs_open_1     (on vfs_*)
  probe:vfs_fallocate  (on vfs_*)
  probe:vfs_open_2     (on vfs_*)
  probe:vfs_truncate   (on vfs_*)
  probe:vfs_setpos     (on vfs_*)
  probe:vfs_setpos_1   (on vfs_*)
  probe:vfs_setpos_2   (on vfs_*)
<SNIP>
  probe:vfs_test_lock  (on vfs_*)
  probe:vfs_lock_file_3 (on vfs_*)
  probe:vfs_setlease   (on vfs_*)
  probe:vfs_pressure_ratio_1 (on vfs_*)
  probe:vfs_dentry_acceptable (on vfs_*)
  probe:vfs_pressure_ratio_2 (on vfs_*)
  probe:vfs_load_quota_inode (on vfs_*)

You can now use it in all perf tools, such as:

	perf record -e probe:vfs_load_quota_inode -aR sleep 1

[root@zoo ~]# echo $?
0
[root@zoo ~]#

But here I stumbled into a problem, 'perf probe -l'  gets into a long loop
calling brk(), i.e. allocating memory:

[root@zoo ~]# time perf trace -o /tmp/bla -S perf probe -l
  probe:vfs_cancel_lock (on vfs_cancel_lock@/home/git/linux/fs/locks.c)
  probe:vfs_create     (on vfs_create@/home/git/linux/fs/namei.c)
  probe:vfs_create_1   (on lookup_open:55@/home/git/linux/fs/namei.c)
  probe:vfs_create_2   (on SyS_mknodat+504@/home/git/linux/fs/namei.c)
  probe:vfs_create_3   (on SyS_mknod+521@/home/git/linux/fs/namei.c)
  probe:vfs_create_4   (on vfs_create@/home/git/linux/fs/namei.c)
<SNIP>
  probe:vfs_lock_file_1 (on locks_remove_posix:25@/home/git/linux/fs/locks.c)
  probe:vfs_lock_file_2 (on do_lock_file_wait:11@/home/git/linux/fs/locks.c)
  probe:vfs_lock_file_3 (on vfs_lock_file@/home/git/linux/fs/locks.c)
  probe:vfs_lstat      (on vfs_lstat@/home/git/linux/fs/stat.c)
  probe:vfs_lstat_1    (on SYSC_lstat:6@/home/git/linux/fs/stat.c)
  probe:vfs_lstat_2    (on SYSC_newlstat:6@/home/git/linux/fs/stat.c)
  probe:vfs_lstat_3    (on vfs_lstat@/home/git/linux/fs/stat.c)
^C

[root@zoo ~]# grep -w brk /tmp/bla | wc -l
6083
[root@zoo ~]#

[root@zoo ~]# perf probe -F vfs_* | wc -l
45

And there were ~100 probes added, probably due to those _N aliases.

I.e.:

[root@zoo ~]# perf probe -F vfs_* | tail
vfs_statfs
vfs_symlink
vfs_test_lock
vfs_truncate
vfs_unlink
vfs_ustat
vfs_whiteout
vfs_write
vfs_writev
vfs_xattr_cmp
[root@zoo ~]# pref probe -l | tail
bash: pref: command not found...
[root@zoo ~]# perf probe -l | tail
  probe:vfs_symlink_3  (on vfs_symlink@/home/git/linux/fs/namei.c)
  probe:vfs_test_lock  (on vfs_test_lock@/home/git/linux/fs/locks.c)
  probe:vfs_truncate   (on vfs_truncate@/home/git/linux/fs/open.c)
  probe:vfs_unlink     (on vfs_unlink@/home/git/linux/fs/namei.c)
  probe:vfs_ustat      (on vfs_ustat@/home/git/linux/fs/statfs.c)
  probe:vfs_whiteout   (on vfs_whiteout@/home/git/linux/fs/namei.c)
  probe:vfs_whiteout_1 (on vfs_whiteout@/home/git/linux/fs/namei.c)
  probe:vfs_write      (on vfs_write@git/linux/fs/read_write.c)
  probe:vfs_writev     (on vfs_writev@git/linux/fs/read_write.c)
  probe:vfs_xattr_cmp  (on vfs_xattr_cmp@/home/git/linux/fs/xattr.c)
[root@zoo ~]#

I am pushing my perf/core branch now, and I see no need to apply your patch as
I am not reproducing the problem described in the changeset log, not the output
copy'n'pasted in it.

I.e. the only problem I found was this:

[root@zoo ~]# time perf probe -l > /dev/null

real	0m15.408s
user	0m14.892s
sys	0m0.534s
[root@zoo ~]# 
[root@zoo ~]# perf stat perf probe -l > /dev/null

 Performance counter stats for 'perf probe -l':

      15256.588897      task-clock (msec)         #    1.001 CPUs utilized          
               116      context-switches          #    0.008 K/sec                  
                 4      cpu-migrations            #    0.000 K/sec                  
           230,720      page-faults               #    0.015 M/sec                  
    47,830,405,530      cycles                    #    3.135 GHz                    
    43,974,134,505      stalled-cycles-frontend   #   91.94% frontend cycles idle   
   <not supported>      stalled-cycles-backend   
    11,540,587,038      instructions              #    0.24  insns per cycle        
                                                  #    3.81  stalled cycles per insn
     2,807,769,592      branches                  #  184.037 M/sec                  
        20,087,075      branch-misses             #    0.72% of all branches        

      15.240796324 seconds time elapsed

[root@zoo ~]#

Can you check why it takes so long and check the need for this patch?

- Arnaldo

>   ----
>   # perf probe vfs_*
>   vfs_caches_init_early is out of .text, skip it.
>   vfs_caches_init is out of .text, skip it.
>   Added new events:
>     probe:vfs_fallocate  (on vfs_*)
>     probe:vfs_open       (on vfs_*)
>   ...
>     probe:vfs_dentry_acceptable (on vfs_*)
>     probe:vfs_load_quota_inode (on vfs_*)
>   #
>   ----
> With this fix;
>   ----
>   # perf probe vfs_*
>   vfs_caches_init_early is out of .text, skip it.
>   vfs_caches_init is out of .text, skip it.
>   Added new events:
>     probe:vfs_fallocate  (on vfs_*)
>   ...
>     probe:vfs_load_quota_inode (on vfs_*)
> 
>   You can now use it in all perf tools, such as:
> 
> 	perf record -e probe:vfs_load_quota_inode -aR sleep 1
> 
>   #
>   ----
> 
> Note that this can be reproduced ONLY IF the vfs_caches_init*
> is the last part of matched symbol list. I've checked this happens
> on "3.19.0-generic #18-Ubuntu" kernel binary.
> 
> Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
> ---
>  tools/perf/util/probe-event.c |   35 +++++++++++++++++------------------
>  1 file changed, 17 insertions(+), 18 deletions(-)
> 
> diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
> index 85c8207..65a1c82 100644
> --- a/tools/perf/util/probe-event.c
> +++ b/tools/perf/util/probe-event.c
> @@ -2157,7 +2157,8 @@ static bool kprobe_blacklist__listed(unsigned long address)
>  	return !!kprobe_blacklist__find_by_address(&kprobe_blacklist, address);
>  }
>  
> -static int perf_probe_event__sprintf(struct perf_probe_event *pev,
> +static int perf_probe_event__sprintf(const char *group, const char *event,
> +				     struct perf_probe_event *pev,
>  				     const char *module,
>  				     struct strbuf *result)
>  {
> @@ -2170,7 +2171,7 @@ static int perf_probe_event__sprintf(struct perf_probe_event *pev,
>  	if (!place)
>  		return -EINVAL;
>  
> -	ret = e_snprintf(buf, 128, "%s:%s", pev->group, pev->event);
> +	ret = e_snprintf(buf, 128, "%s:%s", group, event);
>  	if (ret < 0)
>  		goto out;
>  
> @@ -2195,13 +2196,14 @@ out:
>  }
>  
>  /* Show an event */
> -static int show_perf_probe_event(struct perf_probe_event *pev,
> +static int show_perf_probe_event(const char *group, const char *event,
> +				 struct perf_probe_event *pev,
>  				 const char *module, bool use_stdout)
>  {
>  	struct strbuf buf = STRBUF_INIT;
>  	int ret;
>  
> -	ret = perf_probe_event__sprintf(pev, module, &buf);
> +	ret = perf_probe_event__sprintf(group, event, pev, module, &buf);
>  	if (ret >= 0) {
>  		if (use_stdout)
>  			printf("%s\n", buf.buf);
> @@ -2253,7 +2255,8 @@ static int __show_perf_probe_events(int fd, bool is_kprobe,
>  								is_kprobe);
>  			if (ret < 0)
>  				goto next;
> -			ret = show_perf_probe_event(&pev, tev.point.module,
> +			ret = show_perf_probe_event(pev.group, pev.event,
> +						    &pev, tev.point.module,
>  						    true);
>  		}
>  next:
> @@ -2438,7 +2441,7 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
>  	int i, fd, ret;
>  	struct probe_trace_event *tev = NULL;
>  	char buf[64];
> -	const char *event, *group;
> +	const char *event = NULL, *group = NULL;
>  	struct strlist *namelist;
>  	bool safename;
>  
> @@ -2500,15 +2503,12 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
>  		/* Add added event name to namelist */
>  		strlist__add(namelist, event);
>  
> -		/* Trick here - save current event/group */
> -		event = pev->event;
> -		group = pev->group;
> -		pev->event = tev->event;
> -		pev->group = tev->group;
> -		show_perf_probe_event(pev, tev->point.module, false);
> -		/* Trick here - restore current event/group */
> -		pev->event = (char *)event;
> -		pev->group = (char *)group;
> +		/* We use tev's name for showing new events */
> +		show_perf_probe_event(tev->group, tev->event, pev,
> +				      tev->point.module, false);
> +		/* Save the last valid name */
> +		event = tev->event;
> +		group = tev->group;
>  
>  		/*
>  		 * Probes after the first probe which comes from same
> @@ -2522,11 +2522,10 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
>  		warn_uprobe_event_compat(tev);
>  
>  	/* Note that it is possible to skip all events because of blacklist */
> -	if (ret >= 0 && tev->event) {
> +	if (ret >= 0 && event) {
>  		/* Show how to use the event. */
>  		pr_info("\nYou can now use it in all perf tools, such as:\n\n");
> -		pr_info("\tperf record -e %s:%s -aR sleep 1\n\n", tev->group,
> -			 tev->event);
> +		pr_info("\tperf record -e %s:%s -aR sleep 1\n\n", group, event);
>  	}
>  
>  	strlist__delete(namelist);

Re: [PATCH perf/core v3 3/3] [BUGFIX] perf probe: Show usage even if the last event is skipped

[Masami Hiramatsu]

On 2015/06/16 23:46, Arnaldo Carvalho de Melo wrote:
> Em Tue, Jun 16, 2015 at 08:50:57PM +0900, Masami Hiramatsu escreveu:
>> When the last part of converted events are blacklisted or out-of-text,
>> those are skipped and perf probe doesn't show usage examples.
>> This fixes it to show the example even if the last part of event list
>> is skipped.
>>
>> E.g. without this patch, events are added, but suddenly end;
> 
> End what? Stop being added?

"End without the last message", I meant.

> I.e. not all eligible events are added? From
> your description the problem seems to be that that last message: "You
> can now use it..."  is not presented, but here, without this patch, it
> is:

I see, actually, this happens only if the skipped symbols (
vfs_caches_init_early or vfs_caches_init) are placed at the end of the
matched symbol list. On Ubuntu 15.04 kernel, it doesn't have
vfs_load_quota_inode etc. and the vfs_caches_init is the last part of
the matched list. Since it is hard to reproduce, I've added a Note on
the end of description :)

----

>>
>> Note that this can be reproduced ONLY IF the vfs_caches_init*
>> is the last part of matched symbol list. I've checked this happens
>> on "3.19.0-generic #18-Ubuntu" kernel binary.
>>

----

To reproduce this bug, you need to find a good symbol matching pattern
which (1) matches both of valid function in .text and invalid function
in .inittext (2) invalid one must be on the end of matched function list.

I fortunately hit such pattern and found this bug, but it depends on
the kernel binary.

[...]


> I.e. the only problem I found was this:
> 
> [root@zoo ~]# time perf probe -l > /dev/null
> 
> real	0m15.408s
> user	0m14.892s
> sys	0m0.534s
> [root@zoo ~]# 
> [root@zoo ~]# perf stat perf probe -l > /dev/null
> 
>  Performance counter stats for 'perf probe -l':
> 
>       15256.588897      task-clock (msec)         #    1.001 CPUs utilized          
>                116      context-switches          #    0.008 K/sec                  
>                  4      cpu-migrations            #    0.000 K/sec                  
>            230,720      page-faults               #    0.015 M/sec                  
>     47,830,405,530      cycles                    #    3.135 GHz                    
>     43,974,134,505      stalled-cycles-frontend   #   91.94% frontend cycles idle   
>    <not supported>      stalled-cycles-backend   
>     11,540,587,038      instructions              #    0.24  insns per cycle        
>                                                   #    3.81  stalled cycles per insn
>      2,807,769,592      branches                  #  184.037 M/sec                  
>         20,087,075      branch-misses             #    0.72% of all branches        
> 
>       15.240796324 seconds time elapsed
> 
> [root@zoo ~]#
> 
> Can you check why it takes so long and check the need for this patch?

It is because perf probe -l is not optimized to show a lot of probes yet.
It initializes and loads debuginfo for each probe. I guess we can reuse
debuginfo among them. let me try...

Thank you,


-- 
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu.pt@hitachi.com

Re: Re: [PATCH perf/core v3 3/3] [BUGFIX] perf probe: Show usage even if the last event is skipped

[Masami Hiramatsu]

On 2015/06/17 14:31, Masami Hiramatsu wrote:
>> > I.e. the only problem I found was this:
>> > 
>> > [root@zoo ~]# time perf probe -l > /dev/null
>> > 
>> > real	0m15.408s
>> > user	0m14.892s
>> > sys	0m0.534s
>> > [root@zoo ~]# 
>> > [root@zoo ~]# perf stat perf probe -l > /dev/null
>> > 
>> >  Performance counter stats for 'perf probe -l':
>> > 
>> >       15256.588897      task-clock (msec)         #    1.001 CPUs utilized          
>> >                116      context-switches          #    0.008 K/sec                  
>> >                  4      cpu-migrations            #    0.000 K/sec                  
>> >            230,720      page-faults               #    0.015 M/sec                  
>> >     47,830,405,530      cycles                    #    3.135 GHz                    
>> >     43,974,134,505      stalled-cycles-frontend   #   91.94% frontend cycles idle   
>> >    <not supported>      stalled-cycles-backend   
>> >     11,540,587,038      instructions              #    0.24  insns per cycle        
>> >                                                   #    3.81  stalled cycles per insn
>> >      2,807,769,592      branches                  #  184.037 M/sec                  
>> >         20,087,075      branch-misses             #    0.72% of all branches        
>> > 
>> >       15.240796324 seconds time elapsed
>> > 
>> > [root@zoo ~]#
>> > 
>> > Can you check why it takes so long and check the need for this patch?
> It is because perf probe -l is not optimized to show a lot of probes yet.
> It initializes and loads debuginfo for each probe. I guess we can reuse
> debuginfo among them. let me try...
> 

OK, I've ensured that's true,

[root@localhost perf]# time  ./perf probe -l &> /dev/null

real    0m25.376s
user    0m24.381s
sys     0m1.012s

[root@localhost perf]# time  ./perf probe --no-dwarf -l &> /dev/null

real    0m0.059s
user    0m0.039s
sys     0m0.020s

(Note that --no-dwarf is my local patch for debugging, not sending yet)

So, the problem is on the debuginfo processing. I've also fixed that
by caching the last used debuginfo. :)

[root@localhost perf]#  time  ./perf probe -l &> /dev/null

real    0m0.161s
user    0m0.136s
sys     0m0.025s

I'll send the patch asap.

Thank you!

-- 
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu.pt@hitachi.com

[PATCH perf/core ] perf probe: Speed up perf probe --list by caching debuginfo

[Masami Hiramatsu]

Speed up the "perf probe --list" by caching the last used
debuginfo. perf probe --list always open and load debuginfo
for each entry of probe list. This takes very a long time.

E.g. with vfs_* events (total 96 probes)
  ----
  [root@localhost perf]# time  ./perf probe -l &> /dev/null

  real    0m25.376s
  user    0m24.381s
  sys     0m1.012s
  ----

To solve this issue, this adds debuginfo_cache to cache the
last used debuginfo on memory.

With this fix, the perf-probe --list significantly improves
its speed.

  ----
  [root@localhost perf]#  time  ./perf probe -l &> /dev/null

  real    0m0.161s
  user    0m0.136s
  sys     0m0.025s
  ----

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
---
 tools/perf/util/probe-event.c |   48 ++++++++++++++++++++++++++++++++++++++---
 1 file changed, 44 insertions(+), 4 deletions(-)

diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
index 65a1c82..076527b 100644
--- a/tools/perf/util/probe-event.c
+++ b/tools/perf/util/probe-event.c
@@ -429,6 +429,41 @@ static struct debuginfo *open_debuginfo(const char *module, bool silent)
 	return ret;
 }
 
+/* For caching the last debuginfo */
+static struct debuginfo *debuginfo_cache;
+static char *debuginfo_cache_path;
+
+static struct debuginfo *debuginfo_cache__open(const char *module, bool silent)
+{
+	if ((debuginfo_cache_path && !strcmp(debuginfo_cache_path, module)) ||
+	    (!debuginfo_cache_path && !module && debuginfo_cache))
+		goto out;
+
+	/* Copy module path */
+	free(debuginfo_cache_path);
+	if (module) {
+		debuginfo_cache_path = strdup(module);
+		if (!debuginfo_cache_path) {
+			debuginfo__delete(debuginfo_cache);
+			debuginfo_cache = NULL;
+			goto out;
+		}
+	}
+
+	debuginfo_cache = open_debuginfo(module, silent);
+	if (!debuginfo_cache)
+		zfree(&debuginfo_cache_path);
+out:
+	return debuginfo_cache;
+}
+
+static void debuginfo_cache__exit(void)
+{
+	debuginfo__delete(debuginfo_cache);
+	debuginfo_cache = NULL;
+	zfree(&debuginfo_cache_path);
+}
+
 
 static int get_text_start_address(const char *exec, unsigned long *address)
 {
@@ -490,12 +525,11 @@ static int find_perf_probe_point_from_dwarf(struct probe_trace_point *tp,
 	pr_debug("try to find information at %" PRIx64 " in %s\n", addr,
 		 tp->module ? : "kernel");
 
-	dinfo = open_debuginfo(tp->module, verbose == 0);
-	if (dinfo) {
+	dinfo = debuginfo_cache__open(tp->module, verbose == 0);
+	if (dinfo)
 		ret = debuginfo__find_probe_point(dinfo,
 						 (unsigned long)addr, pp);
-		debuginfo__delete(dinfo);
-	} else
+	else
 		ret = -ENOENT;
 
 	if (ret > 0) {
@@ -930,6 +964,10 @@ out:
 
 #else	/* !HAVE_DWARF_SUPPORT */
 
+static void debuginfo_cache__exit(void)
+{
+}
+
 static int
 find_perf_probe_point_from_dwarf(struct probe_trace_point *tp __maybe_unused,
 				 struct perf_probe_point *pp __maybe_unused,
@@ -2266,6 +2304,8 @@ next:
 			break;
 	}
 	strlist__delete(rawlist);
+	/* Cleanup cached debuginfo if needed */
+	debuginfo_cache__exit();
 
 	return ret;
 }

[tip:perf/core] perf probe: Speed up perf probe --list by caching debuginfo

[tip-bot for Masami Hiramatsu]

Commit-ID:  7737af010b097f3c1e2aeded21774d58b4aa2698
Gitweb:     http://git.kernel.org/tip/7737af010b097f3c1e2aeded21774d58b4aa2698
Author:     Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
AuthorDate: Wed, 17 Jun 2015 23:58:54 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 17 Jun 2015 16:37:53 -0300

perf probe: Speed up perf probe --list by caching debuginfo

Speed up the "perf probe --list" by caching the last used debuginfo.
perf probe --list always open and load debuginfo for each entry of probe
list. This takes very a long time.

E.g. with vfs_* events (total 96 probes)

  [root@localhost perf]# time  ./perf probe -l &> /dev/null

  real    0m25.376s
  user    0m24.381s
  sys     0m1.012s

To solve this issue, this adds debuginfo_cache to cache the
last used debuginfo on memory.

With this fix, the perf-probe --list significantly improves
its speed.

  [root@localhost perf]#  time  ./perf probe -l &> /dev/null

  real    0m0.161s
  user    0m0.136s
  sys     0m0.025s

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Naohiro Aota <naota@elisp.net>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20150617145854.19715.15314.stgit@localhost.localdomain
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/probe-event.c | 48 +++++++++++++++++++++++++++++++++++++++----
 1 file changed, 44 insertions(+), 4 deletions(-)

diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
index 65a1c82..076527b 100644
--- a/tools/perf/util/probe-event.c
+++ b/tools/perf/util/probe-event.c
@@ -429,6 +429,41 @@ static struct debuginfo *open_debuginfo(const char *module, bool silent)
 	return ret;
 }
 
+/* For caching the last debuginfo */
+static struct debuginfo *debuginfo_cache;
+static char *debuginfo_cache_path;
+
+static struct debuginfo *debuginfo_cache__open(const char *module, bool silent)
+{
+	if ((debuginfo_cache_path && !strcmp(debuginfo_cache_path, module)) ||
+	    (!debuginfo_cache_path && !module && debuginfo_cache))
+		goto out;
+
+	/* Copy module path */
+	free(debuginfo_cache_path);
+	if (module) {
+		debuginfo_cache_path = strdup(module);
+		if (!debuginfo_cache_path) {
+			debuginfo__delete(debuginfo_cache);
+			debuginfo_cache = NULL;
+			goto out;
+		}
+	}
+
+	debuginfo_cache = open_debuginfo(module, silent);
+	if (!debuginfo_cache)
+		zfree(&debuginfo_cache_path);
+out:
+	return debuginfo_cache;
+}
+
+static void debuginfo_cache__exit(void)
+{
+	debuginfo__delete(debuginfo_cache);
+	debuginfo_cache = NULL;
+	zfree(&debuginfo_cache_path);
+}
+
 
 static int get_text_start_address(const char *exec, unsigned long *address)
 {
@@ -490,12 +525,11 @@ static int find_perf_probe_point_from_dwarf(struct probe_trace_point *tp,
 	pr_debug("try to find information at %" PRIx64 " in %s\n", addr,
 		 tp->module ? : "kernel");
 
-	dinfo = open_debuginfo(tp->module, verbose == 0);
-	if (dinfo) {
+	dinfo = debuginfo_cache__open(tp->module, verbose == 0);
+	if (dinfo)
 		ret = debuginfo__find_probe_point(dinfo,
 						 (unsigned long)addr, pp);
-		debuginfo__delete(dinfo);
-	} else
+	else
 		ret = -ENOENT;
 
 	if (ret > 0) {
@@ -930,6 +964,10 @@ out:
 
 #else	/* !HAVE_DWARF_SUPPORT */
 
+static void debuginfo_cache__exit(void)
+{
+}
+
 static int
 find_perf_probe_point_from_dwarf(struct probe_trace_point *tp __maybe_unused,
 				 struct perf_probe_point *pp __maybe_unused,
@@ -2266,6 +2304,8 @@ next:
 			break;
 	}
 	strlist__delete(rawlist);
+	/* Cleanup cached debuginfo if needed */
+	debuginfo_cache__exit();
 
 	return ret;
 }

Re: Re: [PATCH perf/core v3 3/3] [BUGFIX] perf probe: Show usage even if the last event is skipped

[Arnaldo Carvalho de Melo]

Em Wed, Jun 17, 2015 at 11:58:18PM +0900, Masami Hiramatsu escreveu:
> On 2015/06/17 14:31, Masami Hiramatsu wrote:
> >> > I.e. the only problem I found was this:
> >> > 
> >> > [root@zoo ~]# time perf probe -l > /dev/null
> >> > 
> >> > real	0m15.408s
> >> > user	0m14.892s
> >> > sys	0m0.534s
> >> > [root@zoo ~]# 
> >> > [root@zoo ~]# perf stat perf probe -l > /dev/null
> >> > 
> >> >  Performance counter stats for 'perf probe -l':
> >> > 
> >> >       15256.588897      task-clock (msec)         #    1.001 CPUs utilized          
> >> >                116      context-switches          #    0.008 K/sec                  
> >> >                  4      cpu-migrations            #    0.000 K/sec                  
> >> >            230,720      page-faults               #    0.015 M/sec                  
> >> >     47,830,405,530      cycles                    #    3.135 GHz                    
> >> >     43,974,134,505      stalled-cycles-frontend   #   91.94% frontend cycles idle   
> >> >    <not supported>      stalled-cycles-backend   
> >> >     11,540,587,038      instructions              #    0.24  insns per cycle        
> >> >                                                   #    3.81  stalled cycles per insn
> >> >      2,807,769,592      branches                  #  184.037 M/sec                  
> >> >         20,087,075      branch-misses             #    0.72% of all branches        
> >> > 
> >> >       15.240796324 seconds time elapsed
> >> > 
> >> > [root@zoo ~]#
> >> > 
> >> > Can you check why it takes so long and check the need for this patch?
> > It is because perf probe -l is not optimized to show a lot of probes yet.
> > It initializes and loads debuginfo for each probe. I guess we can reuse
> > debuginfo among them. let me try...
> > 
> 
> OK, I've ensured that's true,
> 
> [root@localhost perf]# time  ./perf probe -l &> /dev/null
> 
> real    0m25.376s
> user    0m24.381s
> sys     0m1.012s
> 
> [root@localhost perf]# time  ./perf probe --no-dwarf -l &> /dev/null
> 
> real    0m0.059s
> user    0m0.039s
> sys     0m0.020s
> 
> (Note that --no-dwarf is my local patch for debugging, not sending yet)
> 
> So, the problem is on the debuginfo processing. I've also fixed that
> by caching the last used debuginfo. :)
> 
> [root@localhost perf]#  time  ./perf probe -l &> /dev/null
> 
> real    0m0.161s
> user    0m0.136s
> sys     0m0.025s
> 
> I'll send the patch asap.

Thanks! I really need to go thru builtin-probe.c looking at how it uses
the symbol functions, to see what I can change in symbol*.[ch] to help
it with its needs.

Till then tho, please send the patch, that is a really great speedup! :-)

- Arnaldo

[tip:perf/core] perf probe: Show usage even if the last event is skipped

[tip-bot for Masami Hiramatsu]

Commit-ID:  d350bd571ffa89fc3bd07cfa9685d5210f459be8
Gitweb:     http://git.kernel.org/tip/d350bd571ffa89fc3bd07cfa9685d5210f459be8
Author:     Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
AuthorDate: Tue, 16 Jun 2015 20:50:57 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 17 Jun 2015 16:31:42 -0300

perf probe: Show usage even if the last event is skipped

When the last part of converted events are blacklisted or out-of-text,
those are skipped and perf probe doesn't show usage examples.  This
fixes it to show the example even if the last part of event list is
skipped.

E.g. without this patch, events are added, but suddenly end:

  # perf probe vfs_*
  vfs_caches_init_early is out of .text, skip it.
  vfs_caches_init is out of .text, skip it.
  Added new events:
    probe:vfs_fallocate  (on vfs_*)
    probe:vfs_open       (on vfs_*)
  ...
    probe:vfs_dentry_acceptable (on vfs_*)
    probe:vfs_load_quota_inode (on vfs_*)
  #

With this fix:

  # perf probe vfs_*
  vfs_caches_init_early is out of .text, skip it.
  vfs_caches_init is out of .text, skip it.
  Added new events:
    probe:vfs_fallocate  (on vfs_*)
  ...
    probe:vfs_load_quota_inode (on vfs_*)

  You can now use it in all perf tools, such as:

	perf record -e probe:vfs_load_quota_inode -aR sleep 1

Note that this can be reproduced ONLY IF the vfs_caches_init* is the
last part of matched symbol list. I've checked this happens on
"3.19.0-generic #18-Ubuntu" kernel binary.

Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Naohiro Aota <naota@elisp.net>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20150616115057.19906.5502.stgit@localhost.localdomain
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/probe-event.c | 35 +++++++++++++++++------------------
 1 file changed, 17 insertions(+), 18 deletions(-)

diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c
index 85c8207..65a1c82 100644
--- a/tools/perf/util/probe-event.c
+++ b/tools/perf/util/probe-event.c
@@ -2157,7 +2157,8 @@ static bool kprobe_blacklist__listed(unsigned long address)
 	return !!kprobe_blacklist__find_by_address(&kprobe_blacklist, address);
 }
 
-static int perf_probe_event__sprintf(struct perf_probe_event *pev,
+static int perf_probe_event__sprintf(const char *group, const char *event,
+				     struct perf_probe_event *pev,
 				     const char *module,
 				     struct strbuf *result)
 {
@@ -2170,7 +2171,7 @@ static int perf_probe_event__sprintf(struct perf_probe_event *pev,
 	if (!place)
 		return -EINVAL;
 
-	ret = e_snprintf(buf, 128, "%s:%s", pev->group, pev->event);
+	ret = e_snprintf(buf, 128, "%s:%s", group, event);
 	if (ret < 0)
 		goto out;
 
@@ -2195,13 +2196,14 @@ out:
 }
 
 /* Show an event */
-static int show_perf_probe_event(struct perf_probe_event *pev,
+static int show_perf_probe_event(const char *group, const char *event,
+				 struct perf_probe_event *pev,
 				 const char *module, bool use_stdout)
 {
 	struct strbuf buf = STRBUF_INIT;
 	int ret;
 
-	ret = perf_probe_event__sprintf(pev, module, &buf);
+	ret = perf_probe_event__sprintf(group, event, pev, module, &buf);
 	if (ret >= 0) {
 		if (use_stdout)
 			printf("%s\n", buf.buf);
@@ -2253,7 +2255,8 @@ static int __show_perf_probe_events(int fd, bool is_kprobe,
 								is_kprobe);
 			if (ret < 0)
 				goto next;
-			ret = show_perf_probe_event(&pev, tev.point.module,
+			ret = show_perf_probe_event(pev.group, pev.event,
+						    &pev, tev.point.module,
 						    true);
 		}
 next:
@@ -2438,7 +2441,7 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 	int i, fd, ret;
 	struct probe_trace_event *tev = NULL;
 	char buf[64];
-	const char *event, *group;
+	const char *event = NULL, *group = NULL;
 	struct strlist *namelist;
 	bool safename;
 
@@ -2500,15 +2503,12 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 		/* Add added event name to namelist */
 		strlist__add(namelist, event);
 
-		/* Trick here - save current event/group */
-		event = pev->event;
-		group = pev->group;
-		pev->event = tev->event;
-		pev->group = tev->group;
-		show_perf_probe_event(pev, tev->point.module, false);
-		/* Trick here - restore current event/group */
-		pev->event = (char *)event;
-		pev->group = (char *)group;
+		/* We use tev's name for showing new events */
+		show_perf_probe_event(tev->group, tev->event, pev,
+				      tev->point.module, false);
+		/* Save the last valid name */
+		event = tev->event;
+		group = tev->group;
 
 		/*
 		 * Probes after the first probe which comes from same
@@ -2522,11 +2522,10 @@ static int __add_probe_trace_events(struct perf_probe_event *pev,
 		warn_uprobe_event_compat(tev);
 
 	/* Note that it is possible to skip all events because of blacklist */
-	if (ret >= 0 && tev->event) {
+	if (ret >= 0 && event) {
 		/* Show how to use the event. */
 		pr_info("\nYou can now use it in all perf tools, such as:\n\n");
-		pr_info("\tperf record -e %s:%s -aR sleep 1\n\n", tev->group,
-			 tev->event);
+		pr_info("\tperf record -e %s:%s -aR sleep 1\n\n", group, event);
 	}
 
 	strlist__delete(namelist);

Re: [PATCH perf/core v3 0/3] perf-probe bugfixes

[Arnaldo Carvalho de Melo]

Em Tue, Jun 16, 2015 at 08:50:50PM +0900, Masami Hiramatsu escreveu:
> Hi Arnaldo,
> 
> Here is the v3 series of bugfix patches for perf-probe.
> I've rewriten the patch description of 2/3 (no code changed)
> and added a comment on the 3/3 for reproductivity.
> This series fixes below bugs;
> 
>  - --list shows the list of probes in stderr.
>    (It is refined from https://lkml.org/lkml/2015/5/30/34)
>  - return success even if no probe is added.
>  - usage message is not shown if the last event is skipped.
> 
> BTW, this series still include 1/3, since I couldn't find it
> in the latest(published) perf/core. If you've already merged
> it on your local tree, please skip it.

Right, I forgot to push my perf/core branch yesterday, thanks for the
corrections, trying to apply the series now.

- Arnaldo
 
> Thank you,
> 
> ---
> 
> Masami Hiramatsu (3):
>       [BUGFIX] perf probe: List probes in stdout
>       [BUGFIX] perf probe: Fix to return error if no-probe is added
>       [BUGFIX] perf probe: Show usage even if the last event is skipped
> 
> 
>  tools/perf/util/probe-event.c |  187 ++++++++++++++++++++++++++---------------
>  1 file changed, 118 insertions(+), 69 deletions(-)
> 
> 
> -- 
> Masami HIRAMATSU
> Linux Technology Research Center, System Productivity Research Dept.
> Center for Technology Innovation - Systems Engineering 
> Hitachi, Ltd., Research & Development Group
> E-mail: masami.hiramatsu.pt@hitachi.com