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

[Arnaldo Carvalho de Melo <acme@kernel.org>]

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