Skip to contentSkip to conversation

perf-probe bugfixes

PATCH In review Masami Hiramatsu 3 participants 13 messages Jun 16, 2015 – Jun 18, 2015 perf events

lore
Share & tools
lore
#0 lore raw

v3 cover perf-probe bugfixes

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(-)
Signature · 5 lines
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering 
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]
#1 lore raw

PATCH v3 1/3 perf probe: List probes in stdout

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)
  -----

---
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(-)
tools/perf/util/probe-event.c +35 -14
index daa24a2..c4ab588 100644
@@ -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;
#2 lore raw

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

In reply to 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.
  ----

---
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(-)
tools/perf/util/probe-event.c +71 -42
index c4ab588..85c8207 100644
@@ -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++) {
#3 lore raw

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

perf probe: Fix to return error if no probe is added
Commit-ID:  b031220d520238075bd99513a420e65cf37866ad
Gitweb:     http://git.kernel.org/tip/b031220d520238075bd99513a420e65cf37866ad
Author:     Masami Hiramatsu <[email protected]>
AuthorDate: Tue, 16 Jun 2015 20:50:55 +0900
Committer:  Arnaldo Carvalho de Melo <[email protected]>
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.
---
 tools/perf/util/probe-event.c | 113 ++++++++++++++++++++++++++----------------
 1 file changed, 71 insertions(+), 42 deletions(-)
tools/perf/util/probe-event.c +71 -42
index c4ab588..85c8207 100644
@@ -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++) {
#4 lore raw

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

In reply to 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.

---
 tools/perf/util/probe-event.c |   35 +++++++++++++++++------------------
 1 file changed, 17 insertions(+), 18 deletions(-)
tools/perf/util/probe-event.c +17 -18
index 85c8207..65a1c82 100644
@@ -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);
#5 lore raw

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

Em Tue, Jun 16, 2015 at 08:50:57PM +0900, Masami Hiramatsu escreveu:

Quoted 6 lines

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

Quoted 133 lines

----

  # 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.

---
 tools/perf/util/probe-event.c |   35 +++++++++++++++++------------------
 1 file changed, 17 insertions(+), 18 deletions(-)
tools/perf/util/probe-event.c +17 -18
index 85c8207..65a1c82 100644
@@ -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);
#6 lore raw

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

Quoted 9 lines · Arnaldo Carvalho de Melo

Em Tue, Jun 16, 2015 at 08:50:57PM +0900, Masami Hiramatsu escreveu:

Quoted 6 lines

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.

Quoted 4 lines

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 :)

----

Quoted 5 lines
Quoted 5 lines

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.

[...]

Quoted 24 lines

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

Quoted 5 lines

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,

Signature · 5 lines
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]
#7 lore raw

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

Quoted 24 lines · Masami Hiramatsu
Quoted 24 lines
Quoted 24 lines

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

Quoted 9 lines
Quoted 5 lines
Quoted 5 lines
      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!

Signature · 5 lines
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]
#8 lore raw

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

Em Wed, Jun 17, 2015 at 11:58:18PM +0900, Masami Hiramatsu escreveu:

Quoted 54 lines · Masami Hiramatsu
Quoted 24 lines
Quoted 24 lines
Quoted 24 lines

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

Quoted 9 lines
Quoted 5 lines
Quoted 5 lines
      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. :)

Quoted 7 lines

[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

#9 lore raw

PATCH 1/1 perf probe: Speed up perf probe --list by caching debuginfo

In reply to 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

----

---
 tools/perf/util/probe-event.c |   48 ++++++++++++++++++++++++++++++++++++++---
 1 file changed, 44 insertions(+), 4 deletions(-)
tools/perf/util/probe-event.c +44 -4
index 65a1c82..076527b 100644
@@ -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;
 }
#10 lore raw

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

perf probe: Speed up perf probe --list by caching debuginfo
Commit-ID:  7737af010b097f3c1e2aeded21774d58b4aa2698
Gitweb:     http://git.kernel.org/tip/7737af010b097f3c1e2aeded21774d58b4aa2698
Author:     Masami Hiramatsu <[email protected]>
AuthorDate: Wed, 17 Jun 2015 23:58:54 +0900
Committer:  Arnaldo Carvalho de Melo <[email protected]>
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
---
 tools/perf/util/probe-event.c | 48 +++++++++++++++++++++++++++++++++++++++----
 1 file changed, 44 insertions(+), 4 deletions(-)
tools/perf/util/probe-event.c +44 -4
index 65a1c82..076527b 100644
@@ -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;
 }
#11 lore raw

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

In reply to Masami Hiramatsu
perf probe: Show usage even if the last event is skipped
Commit-ID:  d350bd571ffa89fc3bd07cfa9685d5210f459be8
Gitweb:     http://git.kernel.org/tip/d350bd571ffa89fc3bd07cfa9685d5210f459be8
Author:     Masami Hiramatsu <[email protected]>
AuthorDate: Tue, 16 Jun 2015 20:50:57 +0900
Committer:  Arnaldo Carvalho de Melo <[email protected]>
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.

---
 tools/perf/util/probe-event.c | 35 +++++++++++++++++------------------
 1 file changed, 17 insertions(+), 18 deletions(-)
tools/perf/util/probe-event.c +17 -18
index 85c8207..65a1c82 100644
@@ -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);
#12 lore raw
In reply to Masami Hiramatsu

Em Tue, Jun 16, 2015 at 08:50:50PM +0900, Masami Hiramatsu escreveu:

Quoted 7 lines

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;

Quoted 8 lines

- --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

Quoted 20 lines

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(-)
Signature · 5 lines
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering 
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]