2020-02-13 12:21:35

by Thomas Richter

[permalink] [raw]
Subject: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

This test places a kprobe to function getname_flags() in the kernel
which has the following prototype:

struct filename *
getname_flags(const char __user *filename, int flags, int *empty)

Variable filename points to a filename located in user space memory.
Looking at
commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
the kprobe should indicate that user space memory is accessed.

The following patch specifies user space memory access first and if this
fails use type 'string' in case 'ustring' is not supported.

Signed-off-by: Thomas Richter <[email protected]>
---
tools/perf/tests/shell/lib/probe_vfs_getname.sh | 4 +++-
1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
index 7cb99b433888..30c1eadbc5be 100644
--- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
+++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
@@ -13,7 +13,9 @@ add_probe_vfs_getname() {
local verbose=$1
if [ $had_vfs_getname -eq 1 ] ; then
line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
- perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
+ perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
+ perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
+ perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
fi
}
--
2.21.0


2020-02-13 14:32:32

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
> This test places a kprobe to function getname_flags() in the kernel
> which has the following prototype:
>
> struct filename *
> getname_flags(const char __user *filename, int flags, int *empty)
>
> Variable filename points to a filename located in user space memory.
> Looking at
> commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
> the kprobe should indicate that user space memory is accessed.
>
> The following patch specifies user space memory access first and if this
> fails use type 'string' in case 'ustring' is not supported.

What are you fixing?

I haven't seen any example of this test failing, and right now testing
it with:

[root@quaco ~]# uname -a
Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
[root@quaco ~]#

Shows it is working:

[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: Ok
[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: Ok
[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: Ok
[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: Ok
[root@quaco ~]#

Making sure this is what is upstream _using_ that vfs_getname thing:

[root@quaco ~]# grep 'vfs_getname=g' ~acme/libexec/perf-core/tests/shell/lib/probe_vfs_getname.sh
perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
[root@quaco ~]#

Lets try the first line:

# perf probe -l
# perf probe 'vfs_getname=getname_flags:72 pathname=result->name:string'
Added new event:
probe:vfs_getname (on getname_flags:72 with pathname=result->name:string)

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

perf record -e probe:vfs_getname -aR sleep 1

# perf probe -l
probe:vfs_getname (on getname_flags:72@acme/git/linux/fs/namei.c with pathname)
#

Lets run it again using 'perf trace', that will see that
probe:vfs_getname in place and will use it:

[root@quaco ~]# perf trace -e open* perf test "trace + vfs" |& egrep '(trace\+probe_vf|touch|Ok)'
30.496 ( 0.055 ms): perf/23673 openat(dfd: CWD, filename: /home/acme/libexec/perf-core/tests/shell/trace+probe_vfs_getname.sh) = 4
31.621 ( 0.061 ms): perf/23673 openat(dfd: CWD, filename: /home/acme/libexec/perf-core/tests/shell/trace+probe_vfs_getname.sh) = 4
38.807 ( 0.064 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: RDONLY|CLOEXEC) = 3
39.013 ( 0.063 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /lib64/libtinfo.so.6, flags: RDONLY|CLOEXEC) = 3
39.253 ( 0.073 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /lib64/libdl.so.2, flags: RDONLY|CLOEXEC) = 3
39.477 ( 0.068 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: RDONLY|CLOEXEC) = 3
40.177 ( 0.079 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /dev/tty, flags: RDWR|NONBLOCK) = 3
40.431 ( 0.067 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive, flags: RDONLY|CLOEXEC) = 3
40.661 ( 0.065 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /usr/lib64/gconv/gconv-modules.cache) = 3
42.236 ( 0.076 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /home/acme/libexec/perf-core/tests/shell/trace+probe_vfs_getname.sh) = 3
46.023 ( 0.027 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /home/acme/libexec/perf-core/tests/shell/lib/probe.sh) = 3
110.521 ( 0.023 ms): trace+probe_vf/23675 openat(dfd: CWD, filename: /home/acme/libexec/perf-core/tests/shell/lib/probe_vfs_getname.sh) = 3
2040.036 ( 0.012 ms): trace+probe_vf/23898 openat(dfd: CWD, filename: ., flags: RDONLY|CLOEXEC|DIRECTORY|NONBLOCK) = 3
2731.204 ( 0.017 ms): touch/23948 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: RDONLY|CLOEXEC) = 3
2731.254 ( 0.017 ms): touch/23948 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: RDONLY|CLOEXEC) = 3
2731.668 ( 0.019 ms): touch/23948 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive, flags: RDONLY|CLOEXEC) = 3
2731.765 ( 0.017 ms): touch/23948 openat(dfd: CWD, filename: /tmp/temporary_file.ipQ2W, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3
2732.089 ( 0.010 ms): perf/23917 openat(dfd: CWD, filename: /usr/bin/touch, flags: RDONLY|CLOEXEC) = 6
Ok
[root@quaco ~]# echo $?
0
[root@quaco ~]#

Then, I apply this patch and it starts consistently failing:

First clean up everything:

[root@quaco ~]# perf probe -d probe:*
Removed event: probe:vfs_getname
[root@quaco ~]# perf probe -l
[root@quaco ~]#

Then try again with this patch:

[acme@quaco perf]$ git cherry-pick d87c35073ec84736c08ef9a62bfed9cff1e5d9d5
[perf/urgent 8d9f3054a71c] perf test: Fix test trace+probe_vfs_getname.sh
Author: Thomas Richter <[email protected]>
Date: Thu Feb 13 13:20:09 2020 +0100
1 file changed, 3 insertions(+), 1 deletion(-)
[acme@quaco perf]$

install it and check:

[root@quaco ~]# grep 'vfs_getname=g' ~acme/libexec/perf-core/tests/shell/lib/probe_vfs_getname.sh
perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
[root@quaco ~]#

Then run the test:

[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: FAILED!
[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: FAILED!
[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: FAILED!
[root@quaco ~]# perf test "trace + vfs"
72: Check open filename arg using perf trace + vfs_getname: FAILED!
[root@quaco ~]#
[root@quaco ~]#
[root@quaco ~]# for a in $(seq 5) ; do perf test "trace + vfs" ; done
72: Check open filename arg using perf trace + vfs_getname: FAILED!
72: Check open filename arg using perf trace + vfs_getname: FAILED!
72: Check open filename arg using perf trace + vfs_getname: FAILED!
72: Check open filename arg using perf trace + vfs_getname: FAILED!
72: Check open filename arg using perf trace + vfs_getname: FAILED!
[root@quaco ~]#

Now lets try putting in place the probes as you did, using "ustring":

[root@quaco ~]# perf probe -l
[root@quaco ~]# perf probe "vfs_getname=getname_flags:72 pathname=result->uptr:ustring"
Added new event:
probe:vfs_getname (on getname_flags:72 with pathname=result->uptr:ustring)

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

perf record -e probe:vfs_getname -aR sleep 1

[root@quaco ~]#

[root@quaco ~]# perf trace -e open* perf test "trace + vfs" |& egrep '(trace\+probe_vf|touch|Ok|FAIL)'
7.658 ( 0.003 ms): perf/19334 openat(dfd: CWD, filename: ts/shell/trace+probe_vfs_getname.sh) = 4
7.787 ( 0.004 ms): perf/19334 openat(dfd: CWD, filename: ts/shell/trace+probe_vfs_getname.sh) = 72: Check open filename arg using perf trace + vfs_getname:4
10.242 ( 0.004 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: /etc/ld.so.preload, flags: RDONLY|CLOEXEC) = 3
10.259 ( 0.005 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: RDONLY|CLOEXEC) = 3
10.295 ( 0.006 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: /lib64/libtinfo.so.6, flags: RDONLY|CLOEXEC) = 3
10.334 ( 0.006 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: /lib64/libdl.so.2, flags: RDONLY|CLOEXEC) = 3
10.546 ( 0.008 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: RDWR|NONBLOCK) = 3
10.596 ( 0.005 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: /dev/tty, flags: RDONLY|CLOEXEC) = 3
10.627 ( 0.005 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive) = 3
11.070 ( 0.007 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: OLDPWD) = 3
12.076 ( 0.008 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: ) = 3
30.957 ( 0.012 ms): trace+probe_vf/19336 openat(dfd: CWD, filename: ) = 3
471.042 ( 0.010 ms): trace+probe_vf/19541 openat(dfd: CWD, filename: , flags: RDONLY|CLOEXEC|DIRECTORY|NONBLOCK) = 3
789.676 ( 0.007 ms): touch/19627 openat(dfd: CWD, filename: /etc/ld.so.preload, flags: RDONLY|CLOEXEC) = 3
789.700 ( 0.008 ms): touch/19627 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: RDONLY|CLOEXEC) = 3
789.820 ( 0.004 ms): perf/19610 openat(dfd: CWD, filename: /usr/bin/touch, flags: RDONLY|CLOEXEC) = 6
789.936 ( 0.011 ms): touch/19627 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: RDONLY|CLOEXEC) = 3
790.002 ( 0.125 ms): touch/19627 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3
FAILED!
[root@quaco ~]#
[root@quaco ~]# perf trace -e open* perf test "trace + vfs" |& egrep '(trace\+probe_vf|touch|Ok|FAIL)'
27.182 ( 0.047 ms): perf/23632 openat(dfd: CWD, filename: ts/shell/trace+probe_vfs_getname.sh) = 4
28.189 ( 0.049 ms): perf/23632 openat(dfd: CWD, filename: ts/shell/trace+probe_vfs_getname.sh) = 4
35.281 ( 0.062 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: /etc/ld.so.preload, flags: RDONLY|CLOEXEC) = 3
35.488 ( 0.060 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: RDONLY|CLOEXEC) = 3
35.707 ( 0.070 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: /lib64/libtinfo.so.6, flags: RDONLY|CLOEXEC) = 3
35.921 ( 0.069 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: /lib64/libdl.so.2, flags: RDONLY|CLOEXEC) = 3
36.634 ( 0.082 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: RDWR|NONBLOCK) = 3
36.895 ( 0.063 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: /dev/tty, flags: RDONLY|CLOEXEC) = 3
37.113 ( 0.058 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive) = 3
38.738 ( 0.071 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: OLDPWD) = 3
42.446 ( 0.025 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: ) = 3
105.135 ( 0.024 ms): trace+probe_vf/23634 openat(dfd: CWD, filename: ) = 3
2027.596 ( 0.012 ms): trace+probe_vf/23815 openat(dfd: CWD, filename: , flags: RDONLY|CLOEXEC|DIRECTORY|NONBLOCK) = 3
2302.961 ( 0.138 ms): perf/23824 openat(dfd: CWD, filename: /lib/modules/5.6.0-rc1+/kernel/drivers/usb/storage/ums-onetouch.ko, flags: RDONLY|CLOEXEC|DIRECTORY|NONBLOCK) = 8
2661.047 ( 0.008 ms): perf/23824 openat(dfd: CWD, filename: /usr/bin/touch, flags: RDONLY|CLOEXEC) = 6
2661.940 ( ): touch/23885 openat(dfd: CWD, filename: , flags: RDONLY|CLOEXEC) ...
2661.940 ( 0.326 ms): touch/23885 ... [continued]: openat()) = 3
2662.386 ( 0.075 ms): touch/23885 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: RDONLY|CLOEXEC) = 3
2662.940 ( 0.099 ms): touch/23885 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: RDONLY|CLOEXEC) = 3
2663.185 ( 0.076 ms): touch/23885 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3
FAILED!
[root@quaco ~]#

If we use it directly:

[root@quaco ~]# perf trace -e probe:vfs_getname sleep 1
0.000 sleep/30276 probe:vfs_getname(__probe_ip: -1942877253, pathname: "")
1.107 sleep/30276 probe:vfs_getname(__probe_ip: -1942877253, pathname: "")
1.186 sleep/30276 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/etc/ld.so.cache")
1.589 sleep/30276 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/lib64/libc.so.6")
[root@quaco ~]# perf trace -e probe:vfs_getname sleep 1
0.000 sleep/30782 probe:vfs_getname(__probe_ip: -1942877253, pathname: "")
0.016 sleep/30782 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/etc/ld.so.preload")
0.048 sleep/30782 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/etc/ld.so.cache")
0.405 sleep/30782 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/lib64/libc.so.6")
[root@quaco ~]# perf trace -e probe:vfs_getname sleep 1
0.000 sleep/31237 probe:vfs_getname(__probe_ip: -1942877253, pathname: "")
0.016 sleep/31237 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/etc/ld.so.preload")
0.049 sleep/31237 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/etc/ld.so.cache")
0.376 sleep/31237 probe:vfs_getname(__probe_ip: -1942877253, pathname: "/lib64/libc.so.6")
[root@quaco ~]#

While:

[root@quaco ~]# strace -e open,openat,access sleep 1
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
+++ exited with 0 +++
[root@quaco ~]# strace -e open,openat,access sleep 1
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
+++ exited with 0 +++
[root@quaco ~]# strace -e open,openat,access sleep 1
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
+++ exited with 0 +++
[root@quaco ~]#

Also for completeness:

[root@quaco ~]# strace -f -e open,openat perf test "trace + vfs" |& egrep '(vfs_getname\.sh|trace\+probe_vf|touch|Ok|FAILED)'
openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/record+script_probe_vfs_getname.sh", O_RDONLY) = 4
openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/probe_vfs_getname.sh", O_RDONLY) = 4
openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/trace+probe_vfs_getname.sh", O_RDONLY) = 4
openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/record+script_probe_vfs_getname.sh", O_RDONLY) = 4
openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/probe_vfs_getname.sh", O_RDONLY) = 4
openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/trace+probe_vfs_getname.sh", O_RDONLY) = 4
[pid 7538] openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/trace+probe_vfs_getname.sh", O_RDONLY) = 3
[pid 7538] openat(AT_FDCWD, "/home/acme/libexec/perf-core/tests/shell/lib/probe_vfs_getname.sh", O_RDONLY) = 3
[pid 7768] openat(AT_FDCWD, "/usr/bin/touch", O_RDONLY|O_CLOEXEC) = 6
FAILED!
[root@quaco ~]# grep 'vfs_getname=g' /home/acme/libexec/perf-core/tests/shell/lib/probe_vfs_getname.sh
perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
[root@quaco ~]#

[root@quaco ~]# cat /sys/kernel/debug/tracing/README | grep -B6 -A5 ustring
place (uprobe): <path>:<offset>[(ref_ctr_offset)]
args: <name>=fetcharg[:type]
fetcharg: %<register>, @<address>, @<symbol>[+|-<offset>],
$stack<index>, $stack, $retval, $comm, $arg<N>,
+|-[u]<offset>(<fetcharg>), \imm-value, \"imm-string"
type: s8/16/32/64, u8/16/32/64, x8/16/32/64, string, symbol,
b<bit-width>@<bit-offset>/<container-size>, ustring,
<type>\[<array-size>\]
field: <stype> <name>;
stype: u8/u16/u32/u64, s8/s16/s32/s64, pid_t,
[unsigned] char/int/long
events/ - Directory containing all trace event subsystems:
[root@quaco ~]#

So this needs some more investigation :-\

I'm not applying this patch till we get to the bottom of this, ok?

- Arnaldo

> Signed-off-by: Thomas Richter <[email protected]>
> ---
> tools/perf/tests/shell/lib/probe_vfs_getname.sh | 4 +++-
> 1 file changed, 3 insertions(+), 1 deletion(-)
>
> diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> index 7cb99b433888..30c1eadbc5be 100644
> --- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> +++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> @@ -13,7 +13,9 @@ add_probe_vfs_getname() {
> local verbose=$1
> if [ $had_vfs_getname -eq 1 ] ; then
> line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
> - perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
> perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
> fi
> }
> --
> 2.21.0
>

--

- Arnaldo

2020-02-13 17:02:49

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

Hi Thomas and Arnaldo,

On Thu, 13 Feb 2020 11:30:48 -0300
Arnaldo Carvalho de Melo <[email protected]> wrote:

> Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
> > This test places a kprobe to function getname_flags() in the kernel
> > which has the following prototype:
> >
> > struct filename *
> > getname_flags(const char __user *filename, int flags, int *empty)
> >
> > Variable filename points to a filename located in user space memory.
> > Looking at
> > commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
> > the kprobe should indicate that user space memory is accessed.
> >
> > The following patch specifies user space memory access first and if this
> > fails use type 'string' in case 'ustring' is not supported.
>
> What are you fixing?
>
> I haven't seen any example of this test failing, and right now testing
> it with:
>
> [root@quaco ~]# uname -a
> Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
> [root@quaco ~]#

This bug doesn't happen on x86 or other archs on which user-address space and
kernel address space is same. On some arch (ppc64 in this case?) user-address
space is partially or completely same as kernel address space. (Yes, they switch
the world when running into the kernel) In this case, we need to use different
data access functions for each spaces. That is why I introduced "ustring" type
for kprobe event.
As far as I can see, Thomas's patch is sane. Thomas, could you show us your
result on your test environment?

Thank you,

--
Masami Hiramatsu <[email protected]>

2020-02-13 18:13:07

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

Em Fri, Feb 14, 2020 at 02:01:51AM +0900, Masami Hiramatsu escreveu:
> On Thu, 13 Feb 2020 11:30:48 -0300 Arnaldo Carvalho de Melo <[email protected]> wrote:

> > Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
> > > This test places a kprobe to function getname_flags() in the kernel
> > > which has the following prototype:

> > > struct filename *
> > > getname_flags(const char __user *filename, int flags, int *empty)

> > > Variable filename points to a filename located in user space memory.
> > > Looking at
> > > commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
> > > the kprobe should indicate that user space memory is accessed.

> > > The following patch specifies user space memory access first and if this
> > > fails use type 'string' in case 'ustring' is not supported.

> > What are you fixing?

> > I haven't seen any example of this test failing, and right now testing
> > it with:

> > [root@quaco ~]# uname -a
> > Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
> > [root@quaco ~]#

> This bug doesn't happen on x86 or other archs on which user-address space and
> kernel address space is same. On some arch (ppc64 in this case?) user-address
> space is partially or completely same as kernel address space. (Yes, they switch
> the world when running into the kernel) In this case, we need to use different
> data access functions for each spaces. That is why I introduced "ustring" type
> for kprobe event.
> As far as I can see, Thomas's patch is sane.

Well, without his patch, on x86, the test he is claiming to be fixing
works well, with his patch it stops working, see the rest of my reply.

- Arnaldo

> Thomas, could you show us your result on your test environment?

2020-02-14 00:46:19

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

On Thu, 13 Feb 2020 15:11:40 -0300
Arnaldo Carvalho de Melo <[email protected]> wrote:

> Em Fri, Feb 14, 2020 at 02:01:51AM +0900, Masami Hiramatsu escreveu:
> > On Thu, 13 Feb 2020 11:30:48 -0300 Arnaldo Carvalho de Melo <[email protected]> wrote:
>
> > > Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
> > > > This test places a kprobe to function getname_flags() in the kernel
> > > > which has the following prototype:
>
> > > > struct filename *
> > > > getname_flags(const char __user *filename, int flags, int *empty)
>
> > > > Variable filename points to a filename located in user space memory.
> > > > Looking at
> > > > commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
> > > > the kprobe should indicate that user space memory is accessed.
>
> > > > The following patch specifies user space memory access first and if this
> > > > fails use type 'string' in case 'ustring' is not supported.
>
> > > What are you fixing?
>
> > > I haven't seen any example of this test failing, and right now testing
> > > it with:
>
> > > [root@quaco ~]# uname -a
> > > Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
> > > [root@quaco ~]#
>
> > This bug doesn't happen on x86 or other archs on which user-address space and
> > kernel address space is same. On some arch (ppc64 in this case?) user-address
> > space is partially or completely same as kernel address space. (Yes, they switch
> > the world when running into the kernel) In this case, we need to use different
> > data access functions for each spaces. That is why I introduced "ustring" type
> > for kprobe event.
> > As far as I can see, Thomas's patch is sane.
>
> Well, without his patch, on x86, the test he is claiming to be fixing
> works well, with his patch it stops working, see the rest of my reply.

OK, let me see.


> diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> index 7cb99b433888..30c1eadbc5be 100644
> --- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> +++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> @@ -13,7 +13,9 @@ add_probe_vfs_getname() {
> local verbose=$1
> if [ $had_vfs_getname -eq 1 ] ; then
> line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
> - perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
> perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
> fi
> }

This looks no good (depends on architecture or debuginfo). In fs/namei.c,

struct filename *
getname_flags(const char __user *filename, int flags, int *empty)
...
kname = (char *)result->iname;
result->name = kname;
...
result->uptr = filename;
result->aname = NULL;
audit_getname(result);
return result;
}

And the line number script, egreps below line.

result->uptr = filename;

However, the probe on this line will hit *before* execute this line.
Note that kprobes is a breakpoint, which breaks into this line execution,
not after executed.

So, I thik at this point, result->uptr should be NULL, but filename and
result->name already have assigned value.

Thus, the fix should be something like below.

> perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
> - perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \

Thomas, is this OK for you too, or would you have any reason to trace
result->uptr?

Thank you,

--
Masami Hiramatsu <[email protected]>

2020-02-14 09:45:05

by Thomas Richter

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

On 2/14/20 1:45 AM, Masami Hiramatsu wrote:
> On Thu, 13 Feb 2020 15:11:40 -0300
> Arnaldo Carvalho de Melo <[email protected]> wrote:
>
>> Em Fri, Feb 14, 2020 at 02:01:51AM +0900, Masami Hiramatsu escreveu:
>>> On Thu, 13 Feb 2020 11:30:48 -0300 Arnaldo Carvalho de Melo <[email protected]> wrote:
>>
>>>> Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
>>>>> This test places a kprobe to function getname_flags() in the kernel
>>>>> which has the following prototype:
>>
>>>>> struct filename *
>>>>> getname_flags(const char __user *filename, int flags, int *empty)
>>
>>>>> Variable filename points to a filename located in user space memory.
>>>>> Looking at
>>>>> commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
>>>>> the kprobe should indicate that user space memory is accessed.
>>
>>>>> The following patch specifies user space memory access first and if this
>>>>> fails use type 'string' in case 'ustring' is not supported.
>>
>>>> What are you fixing?
>>
>>>> I haven't seen any example of this test failing, and right now testing
>>>> it with:
>>
>>>> [root@quaco ~]# uname -a
>>>> Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
>>>> [root@quaco ~]#
>>
>>> This bug doesn't happen on x86 or other archs on which user-address space and
>>> kernel address space is same. On some arch (ppc64 in this case?) user-address
>>> space is partially or completely same as kernel address space. (Yes, they switch
>>> the world when running into the kernel) In this case, we need to use different
>>> data access functions for each spaces. That is why I introduced "ustring" type
>>> for kprobe event.
>>> As far as I can see, Thomas's patch is sane.
>>
>> Well, without his patch, on x86, the test he is claiming to be fixing
>> works well, with his patch it stops working, see the rest of my reply.
>
> OK, let me see.
>
>
>> diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>> index 7cb99b433888..30c1eadbc5be 100644
>> --- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>> +++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>> @@ -13,7 +13,9 @@ add_probe_vfs_getname() {
>> local verbose=$1
>> if [ $had_vfs_getname -eq 1 ] ; then
>> line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
>> - perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
>> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
>> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
>> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
>> perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
>> fi
>> }
>
> This looks no good (depends on architecture or debuginfo). In fs/namei.c,
>
> struct filename *
> getname_flags(const char __user *filename, int flags, int *empty)
> ...
> kname = (char *)result->iname;
> result->name = kname;
> ...
> result->uptr = filename;
> result->aname = NULL;
> audit_getname(result);
> return result;
> }
>
> And the line number script, egreps below line.
>
> result->uptr = filename;
>
> However, the probe on this line will hit *before* execute this line.
> Note that kprobes is a breakpoint, which breaks into this line execution,
> not after executed.
>
> So, I thik at this point, result->uptr should be NULL, but filename and
> result->name already have assigned value.
>
> Thus, the fix should be something like below.
>
>> perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
>> - perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
>> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
>
> Thomas, is this OK for you too, or would you have any reason to trace
> result->uptr?
>
> Thank you,
>

Thank you very much for your help!!!

I started from scratch and just installed linux 5.6.0rc1 without
any changes and got this failure:

[root@m35lp76 perf]# ./perf test 66 67
66: Use vfs_getname probe to get syscall args filenames : FAILED!
67: Check open filename arg using perf trace + vfs_getname: FAILED!
[root@m35lp76 perf]#

Now I applied Masami's patch and this is the result

[root@m35lp76 perf]# ./perf test 66 67
66: Use vfs_getname probe to get syscall args filenames : Ok
67: Check open filename arg using perf trace + vfs_getname: Ok
[root@m35lp76 perf

Can we commit this patch?
Thanks a lot
--
Thomas Richter, Dept 3252, IBM s390 Linux Development, Boeblingen, Germany
--
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

2020-02-14 10:04:23

by Thomas Richter

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

On 2/14/20 1:45 AM, Masami Hiramatsu wrote:
> On Thu, 13 Feb 2020 15:11:40 -0300
> Arnaldo Carvalho de Melo <[email protected]> wrote:
>
>> Em Fri, Feb 14, 2020 at 02:01:51AM +0900, Masami Hiramatsu escreveu:
>>> On Thu, 13 Feb 2020 11:30:48 -0300 Arnaldo Carvalho de Melo <[email protected]> wrote:
>>
>>>> Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
>>>>> This test places a kprobe to function getname_flags() in the kernel
>>>>> which has the following prototype:
>>
>>>>> struct filename *
>>>>> getname_flags(const char __user *filename, int flags, int *empty)
>>
>>>>> Variable filename points to a filename located in user space memory.
>>>>> Looking at
>>>>> commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
>>>>> the kprobe should indicate that user space memory is accessed.
>>
>>>>> The following patch specifies user space memory access first and if this
>>>>> fails use type 'string' in case 'ustring' is not supported.
>>
>>>> What are you fixing?
>>
>>>> I haven't seen any example of this test failing, and right now testing
>>>> it with:
>>
>>>> [root@quaco ~]# uname -a
>>>> Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
>>>> [root@quaco ~]#
>>
>>> This bug doesn't happen on x86 or other archs on which user-address space and
>>> kernel address space is same. On some arch (ppc64 in this case?) user-address
>>> space is partially or completely same as kernel address space. (Yes, they switch
>>> the world when running into the kernel) In this case, we need to use different
>>> data access functions for each spaces. That is why I introduced "ustring" type
>>> for kprobe event.
>>> As far as I can see, Thomas's patch is sane.
>>
>> Well, without his patch, on x86, the test he is claiming to be fixing
>> works well, with his patch it stops working, see the rest of my reply.
>
> OK, let me see.
>
>
>> diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>> index 7cb99b433888..30c1eadbc5be 100644
>> --- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>> +++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>> @@ -13,7 +13,9 @@ add_probe_vfs_getname() {
>> local verbose=$1
>> if [ $had_vfs_getname -eq 1 ] ; then
>> line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
>> - perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
>> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
>> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
>> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
>> perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
>> fi
>> }
>
> This looks no good (depends on architecture or debuginfo). In fs/namei.c,
>
> struct filename *
> getname_flags(const char __user *filename, int flags, int *empty)
> ...
> kname = (char *)result->iname;
> result->name = kname;
> ...
> result->uptr = filename;
> result->aname = NULL;
> audit_getname(result);
> return result;
> }
>
> And the line number script, egreps below line.
>
> result->uptr = filename;
>
> However, the probe on this line will hit *before* execute this line.
> Note that kprobes is a breakpoint, which breaks into this line execution,
> not after executed.
>
> So, I thik at this point, result->uptr should be NULL, but filename and
> result->name already have assigned value.
>
> Thus, the fix should be something like below.
>
>> perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
>> - perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
>> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
>
> Thomas, is this OK for you too, or would you have any reason to trace
> result->uptr?
>
> Thank you,
>


Masami, thanks very much for your help!

I started from scratch and just installed linux 5.6.0rc1 without
any changes and got this failure:

[root@m35lp76 perf]# ./perf test 66 67
66: Use vfs_getname probe to get syscall args filenames : FAILED!
67: Check open filename arg using perf trace + vfs_getname: FAILED!
[root@m35lp76 perf]#

Now I applied Masami's patch and this is the result

[root@m35lp76 perf]# ./perf test 66 67
66: Use vfs_getname probe to get syscall args filenames : Ok
67: Check open filename arg using perf trace + vfs_getname: Ok
[root@m35lp76 perf

This is what I wanted to achieve.
And I think I know what went wrong. I supplied an initial patch and when
I rewrote it for V3 I kprobed the wrong line.

Again thanks a lot and sorry for the noise...
--
Thomas Richter, Dept 3252, IBM s390 Linux Development, Boeblingen, Germany
--
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

2020-02-14 13:01:21

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

Em Fri, Feb 14, 2020 at 10:44:06AM +0100, Thomas Richter escreveu:
> On 2/14/20 1:45 AM, Masami Hiramatsu wrote:
> > On Thu, 13 Feb 2020 15:11:40 -0300
> > Arnaldo Carvalho de Melo <[email protected]> wrote:
> >
> >> Em Fri, Feb 14, 2020 at 02:01:51AM +0900, Masami Hiramatsu escreveu:
> >>> On Thu, 13 Feb 2020 11:30:48 -0300 Arnaldo Carvalho de Melo <[email protected]> wrote:
> >>
> >>>> Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
> >>>>> This test places a kprobe to function getname_flags() in the kernel
> >>>>> which has the following prototype:
> >>
> >>>>> struct filename *
> >>>>> getname_flags(const char __user *filename, int flags, int *empty)
> >>
> >>>>> Variable filename points to a filename located in user space memory.
> >>>>> Looking at
> >>>>> commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
> >>>>> the kprobe should indicate that user space memory is accessed.
> >>
> >>>>> The following patch specifies user space memory access first and if this
> >>>>> fails use type 'string' in case 'ustring' is not supported.
> >>
> >>>> What are you fixing?
> >>
> >>>> I haven't seen any example of this test failing, and right now testing
> >>>> it with:
> >>
> >>>> [root@quaco ~]# uname -a
> >>>> Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
> >>>> [root@quaco ~]#
> >>
> >>> This bug doesn't happen on x86 or other archs on which user-address space and
> >>> kernel address space is same. On some arch (ppc64 in this case?) user-address
> >>> space is partially or completely same as kernel address space. (Yes, they switch
> >>> the world when running into the kernel) In this case, we need to use different
> >>> data access functions for each spaces. That is why I introduced "ustring" type
> >>> for kprobe event.
> >>> As far as I can see, Thomas's patch is sane.
> >>
> >> Well, without his patch, on x86, the test he is claiming to be fixing
> >> works well, with his patch it stops working, see the rest of my reply.
> >
> > OK, let me see.
> >
> >
> >> diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> >> index 7cb99b433888..30c1eadbc5be 100644
> >> --- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> >> +++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> >> @@ -13,7 +13,9 @@ add_probe_vfs_getname() {
> >> local verbose=$1
> >> if [ $had_vfs_getname -eq 1 ] ; then
> >> line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
> >> - perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
> >> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
> >> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
> >> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
> >> perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
> >> fi
> >> }
> >
> > This looks no good (depends on architecture or debuginfo). In fs/namei.c,
> >
> > struct filename *
> > getname_flags(const char __user *filename, int flags, int *empty)
> > ...
> > kname = (char *)result->iname;
> > result->name = kname;
> > ...
> > result->uptr = filename;
> > result->aname = NULL;
> > audit_getname(result);
> > return result;
> > }
> >
> > And the line number script, egreps below line.
> >
> > result->uptr = filename;
> >
> > However, the probe on this line will hit *before* execute this line.
> > Note that kprobes is a breakpoint, which breaks into this line execution,
> > not after executed.
> >
> > So, I thik at this point, result->uptr should be NULL, but filename and
> > result->name already have assigned value.
> >
> > Thus, the fix should be something like below.
> >
> >> perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
> >> - perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
> >> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
> >
> > Thomas, is this OK for you too, or would you have any reason to trace
> > result->uptr?
> >
> > Thank you,
> >
>
> Thank you very much for your help!!!
>
> I started from scratch and just installed linux 5.6.0rc1 without
> any changes and got this failure:
>
> [root@m35lp76 perf]# ./perf test 66 67
> 66: Use vfs_getname probe to get syscall args filenames : FAILED!
> 67: Check open filename arg using perf trace + vfs_getname: FAILED!
> [root@m35lp76 perf]#
>
> Now I applied Masami's patch and this is the result
>
> [root@m35lp76 perf]# ./perf test 66 67
> 66: Use vfs_getname probe to get syscall args filenames : Ok
> 67: Check open filename arg using perf trace + vfs_getname: Ok
> [root@m35lp76 perf
>
> Can we commit this patch?
> Thanks a lot

So, I'll keep authorship to Thomas but will add a committer note stating
Masami's correction, is that ok?

- Arnaldo

2020-02-14 13:05:01

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

Em Fri, Feb 14, 2020 at 09:45:50AM +0900, Masami Hiramatsu escreveu:
> On Thu, 13 Feb 2020 15:11:40 -0300
> Arnaldo Carvalho de Melo <[email protected]> wrote:
>
> > Em Fri, Feb 14, 2020 at 02:01:51AM +0900, Masami Hiramatsu escreveu:
> > > On Thu, 13 Feb 2020 11:30:48 -0300 Arnaldo Carvalho de Melo <[email protected]> wrote:
> >
> > > > Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
> > > > > This test places a kprobe to function getname_flags() in the kernel
> > > > > which has the following prototype:
> >
> > > > > struct filename *
> > > > > getname_flags(const char __user *filename, int flags, int *empty)
> >
> > > > > Variable filename points to a filename located in user space memory.
> > > > > Looking at
> > > > > commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
> > > > > the kprobe should indicate that user space memory is accessed.
> >
> > > > > The following patch specifies user space memory access first and if this
> > > > > fails use type 'string' in case 'ustring' is not supported.
> >
> > > > What are you fixing?
> >
> > > > I haven't seen any example of this test failing, and right now testing
> > > > it with:
> >
> > > > [root@quaco ~]# uname -a
> > > > Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
> > > > [root@quaco ~]#
> >
> > > This bug doesn't happen on x86 or other archs on which user-address space and
> > > kernel address space is same. On some arch (ppc64 in this case?) user-address
> > > space is partially or completely same as kernel address space. (Yes, they switch
> > > the world when running into the kernel) In this case, we need to use different
> > > data access functions for each spaces. That is why I introduced "ustring" type
> > > for kprobe event.
> > > As far as I can see, Thomas's patch is sane.
> >
> > Well, without his patch, on x86, the test he is claiming to be fixing
> > works well, with his patch it stops working, see the rest of my reply.
>
> OK, let me see.
>
>
> > diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> > index 7cb99b433888..30c1eadbc5be 100644
> > --- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> > +++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
> > @@ -13,7 +13,9 @@ add_probe_vfs_getname() {
> > local verbose=$1
> > if [ $had_vfs_getname -eq 1 ] ; then
> > line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
> > - perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
> > + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
> > + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
> > + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
> > perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
> > fi
> > }
>
> This looks no good (depends on architecture or debuginfo). In fs/namei.c,
>
> struct filename *
> getname_flags(const char __user *filename, int flags, int *empty)
> ...
> kname = (char *)result->iname;
> result->name = kname;
> ...
> result->uptr = filename;
> result->aname = NULL;
> audit_getname(result);
> return result;
> }
>
> And the line number script, egreps below line.
>
> result->uptr = filename;
>
> However, the probe on this line will hit *before* execute this line.
> Note that kprobes is a breakpoint, which breaks into this line execution,
> not after executed.
>
> So, I thik at this point, result->uptr should be NULL, but filename and
> result->name already have assigned value.
>
> Thus, the fix should be something like below.
>
> > perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
> > - perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
> > + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
>
> Thomas, is this OK for you too, or would you have any reason to trace
> result->uptr?

Ok, I retract my last e-mail, can you provide a final patch with the fix?

- Arnaldo

2020-02-14 13:54:57

by Thomas Richter

[permalink] [raw]
Subject: Re: [PATCH v3] perf test: Fix test trace+probe_vfs_getname.sh

On 2/14/20 2:00 PM, Arnaldo Carvalho de Melo wrote:
> Em Fri, Feb 14, 2020 at 10:44:06AM +0100, Thomas Richter escreveu:
>> On 2/14/20 1:45 AM, Masami Hiramatsu wrote:
>>> On Thu, 13 Feb 2020 15:11:40 -0300
>>> Arnaldo Carvalho de Melo <[email protected]> wrote:
>>>
>>>> Em Fri, Feb 14, 2020 at 02:01:51AM +0900, Masami Hiramatsu escreveu:
>>>>> On Thu, 13 Feb 2020 11:30:48 -0300 Arnaldo Carvalho de Melo <[email protected]> wrote:
>>>>
>>>>>> Em Thu, Feb 13, 2020 at 01:20:09PM +0100, Thomas Richter escreveu:
>>>>>>> This test places a kprobe to function getname_flags() in the kernel
>>>>>>> which has the following prototype:
>>>>
>>>>>>> struct filename *
>>>>>>> getname_flags(const char __user *filename, int flags, int *empty)
>>>>
>>>>>>> Variable filename points to a filename located in user space memory.
>>>>>>> Looking at
>>>>>>> commit 88903c464321c ("tracing/probe: Add ustring type for user-space string")
>>>>>>> the kprobe should indicate that user space memory is accessed.
>>>>
>>>>>>> The following patch specifies user space memory access first and if this
>>>>>>> fails use type 'string' in case 'ustring' is not supported.
>>>>
>>>>>> What are you fixing?
>>>>
>>>>>> I haven't seen any example of this test failing, and right now testing
>>>>>> it with:
>>>>
>>>>>> [root@quaco ~]# uname -a
>>>>>> Linux quaco 5.6.0-rc1+ #1 SMP Wed Feb 12 15:42:16 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
>>>>>> [root@quaco ~]#
>>>>
>>>>> This bug doesn't happen on x86 or other archs on which user-address space and
>>>>> kernel address space is same. On some arch (ppc64 in this case?) user-address
>>>>> space is partially or completely same as kernel address space. (Yes, they switch
>>>>> the world when running into the kernel) In this case, we need to use different
>>>>> data access functions for each spaces. That is why I introduced "ustring" type
>>>>> for kprobe event.
>>>>> As far as I can see, Thomas's patch is sane.
>>>>
>>>> Well, without his patch, on x86, the test he is claiming to be fixing
>>>> works well, with his patch it stops working, see the rest of my reply.
>>>
>>> OK, let me see.
>>>
>>>
>>>> diff --git a/tools/perf/tests/shell/lib/probe_vfs_getname.sh b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>>>> index 7cb99b433888..30c1eadbc5be 100644
>>>> --- a/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>>>> +++ b/tools/perf/tests/shell/lib/probe_vfs_getname.sh
>>>> @@ -13,7 +13,9 @@ add_probe_vfs_getname() {
>>>> local verbose=$1
>>>> if [ $had_vfs_getname -eq 1 ] ; then
>>>> line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
>>>> - perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
>>>> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
>>>> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
>>>> + perf probe -q "vfs_getname=getname_flags:${line} pathname=result->uptr:string" || \
>>>> perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
>>>> fi
>>>> }
>>>
>>> This looks no good (depends on architecture or debuginfo). In fs/namei.c,
>>>
>>> struct filename *
>>> getname_flags(const char __user *filename, int flags, int *empty)
>>> ...
>>> kname = (char *)result->iname;
>>> result->name = kname;
>>> ...
>>> result->uptr = filename;
>>> result->aname = NULL;
>>> audit_getname(result);
>>> return result;
>>> }
>>>
>>> And the line number script, egreps below line.
>>>
>>> result->uptr = filename;
>>>
>>> However, the probe on this line will hit *before* execute this line.
>>> Note that kprobes is a breakpoint, which breaks into this line execution,
>>> not after executed.
>>>
>>> So, I thik at this point, result->uptr should be NULL, but filename and
>>> result->name already have assigned value.
>>>
>>> Thus, the fix should be something like below.
>>>
>>>> perf probe -q "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
>>>> - perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
>>>> + perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring" || \
>>>
>>> Thomas, is this OK for you too, or would you have any reason to trace
>>> result->uptr?
>>>
>>> Thank you,
>>>
>>
>> Thank you very much for your help!!!
>>
>> I started from scratch and just installed linux 5.6.0rc1 without
>> any changes and got this failure:
>>
>> [root@m35lp76 perf]# ./perf test 66 67
>> 66: Use vfs_getname probe to get syscall args filenames : FAILED!
>> 67: Check open filename arg using perf trace + vfs_getname: FAILED!
>> [root@m35lp76 perf]#
>>
>> Now I applied Masami's patch and this is the result
>>
>> [root@m35lp76 perf]# ./perf test 66 67
>> 66: Use vfs_getname probe to get syscall args filenames : Ok
>> 67: Check open filename arg using perf trace + vfs_getname: Ok
>> [root@m35lp76 perf
>>
>> Can we commit this patch?
>> Thanks a lot
>
> So, I'll keep authorship to Thomas but will add a committer note stating
> Masami's correction, is that ok?
>
> - Arnaldo
>

Sure go ahead.


--
Thomas Richter, Dept 3252, IBM s390 Linux Development, Boeblingen, Germany
--
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294