Re: Linux next breaks s390 test cases perf test vfs_getname
From: Thomas Richter
Date: Wed Sep 11 2024 - 05:16:23 EST
On 9/10/24 22:24, Arnaldo Carvalho de Melo wrote:
> On Tue, Sep 10, 2024 at 02:05:42PM +0200, Thomas Richter wrote:
>> Arnaldo,
>>
>> On linux-next
>> commit a68080e1a21b ("perf test vfs_getname: Look for alternative line where to collect the pathname")
>> breaks the following tests on s390:
>>
>> # perf test vfs_getname
>> 85: Add vfs_getname probe to get syscall args filenames : FAILED!
>> 87: Use vfs_getname probe to get syscall args filenames : FAILED!
>> 120: Check open filename arg using perf trace + vfs_getname : FAILED!
>>
>> I used the linux next kernel from yesterdays build on s390 and the corresponding
>> perf tools also built from that kernel repository:
>> # uname -a
>> Linux a35lp62.lnxne.boe 6.11.0-20240909.rc7.git205.100cc857359b.300.fc40.s390x+next #1 SMP Mon Sep 9 20:05:44 CEST 2024 s390x GNU/Linux
>> # perf -v
>> perf version 6.11.0-20240909.rc7.git205.100cc857359b.300.fc40.s390x+next
>> #
>>
>> The root cause is a changed regular expression. Before the change the command
>> extracts this line and strips everything after the line number:
>> # perf probe -L getname_flags 2>&1 | grep -E 'result.*=.*filename;'
>> 79 result->uptr = filename;
>> # perf probe -L getname_flags 2>&1 | grep -E 'result.*=.*filename;' | \
>> sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/'
>> 79
>> # perf probe -q "vfs_getname=getname_flags:79 pathname=result->name:string"
>> # echo $?
>> 0
>> # perf probe -l
>> probe:vfs_getname (on getname_flags:79@fs/namei.c with pathname)
>> # perf probe -d '*'
>> Removed event: probe:vfs_getname
>> #
>>
>> With your changes the result is slightly different. The first part still matches the
>> same line:
>> #perf probe -L getname_flags| grep -E '[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*='
>> 79 result->uptr = filename;
>> but the sed command does not return the proper line number:
>> # perf probe -L getname_flags| grep -E '[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*=' | \
>> sed -r "s/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*=/\1/"
>> 79 filename;
>> #
>> The filename; is not stripped and the perf probe command looks like
>> # perf probe -q "vfs_getname=getname_flags:79 filename; pathname=result->name:string"
>> # echo $?
>> 254
>> # perf probe -l
>> # perf probe "vfs_getname=getname_flags:79 filename; pathname=result->name:string"
>> Failed to find the location of the 'filename;' variable at this address.
>> Perhaps it has been optimized out.
>> Use -V with the --range option to show 'filename;' location range.
>> Error: Failed to add events.
>> #
>>
>>
>> The issue is that trailing equal sign (=) in the regular expression:
>> + result_filename_re="[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*"
>> + line=$(perf probe -L getname_flags 2>&1 | grep -E "$result_filename_re=" | \
>> sed -r "s/$result_filename_re=/\1/")
>> ^--------here-----
>> which prevents word filename; from being stripped away.
>> I wonder if this works on x86_64 platforms and if we need a archtecture specific
>
> root@x1:~# perf test getname
> 91: Add vfs_getname probe to get syscall args filenames : Ok
> 93: Use vfs_getname probe to get syscall args filenames : FAILED!
> 126: Check open filename arg using perf trace + vfs_getname : Ok
> root@x1:~#
> root@x1:~# uname -a
> Linux x1 6.10.8-200.fc40.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Sep 4 21:41:11 UTC 2024 x86_64 GNU/Linux
> root@x1:~#
>
> I forgot to mention the kernel version wher I did that a68080e1a21b
> patch, but IIRC it was a recent, locally built kernel (not a distro
> kernel, but with the fedora, probably 39, config):
>
> kernel="/boot/vmlinuz-6.11.0-rc5+"
>
> But even with the distro kernel I'm getting the same results:
>
> root@x1:~# perf test getname
> 91: Add vfs_getname probe to get syscall args filenames : Ok
> 93: Use vfs_getname probe to get syscall args filenames : FAILED!
> 126: Check open filename arg using perf trace + vfs_getname : Ok
> root@x1:~# perf test getname
> 91: Add vfs_getname probe to get syscall args filenames : Ok
> 93: Use vfs_getname probe to get syscall args filenames : FAILED!
> 126: Check open filename arg using perf trace + vfs_getname : Ok
> root@x1:~# perf test getname
> 91: Add vfs_getname probe to get syscall args filenames : Ok
> 93: Use vfs_getname probe to get syscall args filenames : FAILED!
> 126: Check open filename arg using perf trace + vfs_getname : Ok
> root@x1:~# perf test getname
> 91: Add vfs_getname probe to get syscall args filenames : Ok
> 93: Use vfs_getname probe to get syscall args filenames : FAILED!
> 126: Check open filename arg using perf trace + vfs_getname : Ok
> root@x1:~# perf test getname
> 91: Add vfs_getname probe to get syscall args filenames : Ok
> 93: Use vfs_getname probe to get syscall args filenames : FAILED!
> 126: Check open filename arg using perf trace + vfs_getname : Ok
> root@x1:~#
>
> With my changes, i.e. what is in perf-tools-next now:
>
> root@x1:~# perf probe -L getname_flags 2>&1 | grep -E 'result.*=.*filename;'
> result->uptr = filename;
> root@x1:~#
>
> So no line number to be found:
>
> root@x1:~# perf probe -L getname_flags 2>&1 | grep -E 'result.*=.*filename;'
> perf probe -L getname_flags 2>&1 | grep -E 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/'
> result->uptr = filename;
> root@x1:~#
>
> Then, with the change in place:
>
> The first part continues not to find the info:
>
> root@x1:~# perf probe -L getname_flags| grep -E '[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*='
> root@x1:~#
>
> Then it falls back to the new way of finding where to put the probe:
>
> root@x1:~# perf probe -L getname_flags 2>&1 | grep -E "$result_aname_re="
> root@x1:~# perf probe -L getname_flags 2>&1 | grep -E "$result_aname_re"
> 73 result->aname = NULL;
> root@x1:~#
>
> Yeah, that = shouldn't be there
>
> root@x1:~# perf probe -L getname_flags 2>&1 | grep -E "$result_aname_re" | sed -r "s/$result_aname_re/\1/"
> 73
> root@x1:~# line=$(perf probe -L getname_flags 2>&1 | grep -E "$result_aname_re" | sed -r "s/$result_aname_re/\1/")
> root@x1:~# echo $line
> 73
> root@x1:~#
>
> Can you try with the patch below, that ending '=' is noise :-\
>
> - Arnaldo
>
> From 9ccaf9a0ebcff9b4c45c34d92ca97be9926da636 Mon Sep 17 00:00:00 2001
> From: Arnaldo Carvalho de Melo <acme@xxxxxxxxxx>
> Date: Tue, 10 Sep 2024 17:18:26 -0300
> Subject: [PATCH 1/1] perf test shell probe_vfs_getname: Remove extraneous '='
> from probe line number regex
>
> Thomas reported the vfs_getname perf tests failing on s/390, it seems it
> was just to some extraneous '=' somehow getting into the regexp, remove
> it, now:
>
> root@x1:~# perf test getname
> 91: Add vfs_getname probe to get syscall args filenames : Ok
> 93: Use vfs_getname probe to get syscall args filenames : FAILED!
> 126: Check open filename arg using perf trace + vfs_getname : Ok
> root@x1:~#
>
I applied your patch to linux-next kernel and it works:
# ./perf test vfs
85: Add vfs_getname probe to get syscall args filenames : Ok
87: Use vfs_getname probe to get syscall args filenames : Ok
120: Check open filename arg using perf trace + vfs_getname : Ok
#
When I remove your patch the error shows up again:
# git reset --hard HEAD^
HEAD is now at 6708132e80a2 Add linux-next specific files for 20240910
# ./perf test vfs
85: Add vfs_getname probe to get syscall args filenames : FAILED!
87: Use vfs_getname probe to get syscall args filenames : FAILED!
120: Check open filename arg using perf trace + vfs_getname : FAILED!
]#
Your have my Tested-by:
Thanks a lot for your help.
--
Thomas Richter, Dept 3303, IBM s390 Linux Development, Boeblingen, Germany
--
IBM Deutschland Research & Development GmbH
Vorsitzender des Aufsichtsrats: Wolfgang Wendt
Geschäftsführung: David Faller
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294