Re: [PATCH perf/core v3 3/3] [BUGFIX] perf probe: Show usage even if the last event is skipped
From: Arnaldo Carvalho de Melo
Date: Tue Jun 16 2015 - 10:47:12 EST
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@xxxxxxxxxxx>
> ---
> 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);
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/