Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756473AbbFPOrK (ORCPT ); Tue, 16 Jun 2015 10:47:10 -0400 Received: from mail.kernel.org ([198.145.29.136]:55477 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754399AbbFPOrB (ORCPT ); Tue, 16 Jun 2015 10:47:01 -0400 Date: Tue, 16 Jun 2015 11:46:55 -0300 From: Arnaldo Carvalho de Melo To: Masami Hiramatsu Cc: Naohiro Aota , Peter Zijlstra , Linux Kernel Mailing List , David Ahern , namhyung@kernel.org, Jiri Olsa , Ingo Molnar Subject: Re: [PATCH perf/core v3 3/3] [BUGFIX] perf probe: Show usage even if the last event is skipped Message-ID: <20150616144655.GE10374@kernel.org> References: <20150616115050.19906.77371.stgit@localhost.localdomain> <20150616115057.19906.5502.stgit@localhost.localdomain> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20150616115057.19906.5502.stgit@localhost.localdomain> X-Url: http://acmel.wordpress.com User-Agent: Mutt/1.5.23 (2014-03-12) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 9929 Lines: 273 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_*) 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) 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 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 > --- > 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@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/