Message-ID: <CAM9d7cj6dRjppQtncwKuu_XhJPv33PKZWG7_kAgBXG9Y0fYH3Q@mail.gmail.com>
Date: Wed, 19 Jun 2024 14:04:24 -0400
From: Namhyung Kim <namhyung@...nel.org>
To: James Clark <james.clark@....com>
Cc: Athira Rajeev <atrajeev@...ux.vnet.ibm.com>, LKML <linux-kernel@...r.kernel.org>, 
	linux-perf-users <linux-perf-users@...r.kernel.org>, 
	linuxppc-dev <linuxppc-dev@...ts.ozlabs.org>, akanksha@...ux.ibm.com, 
	Madhavan Srinivasan <maddy@...ux.ibm.com>, Kajol Jain <kjain@...ux.ibm.com>, 
	Disha Goel <disgoel@...ux.vnet.ibm.com>, Arnaldo Carvalho de Melo <acme@...nel.org>, 
	Jiri Olsa <jolsa@...nel.org>, Adrian Hunter <adrian.hunter@...el.com>, 
	Ian Rogers <irogers@...gle.com>, Veronika Molnarova <vmolnaro@...hat.com>, 
	Michael Petlan <mpetlan@...hat.com>
Subject: Re: [PATCH] tools/perf: Handle perftool-testsuite_probe testcases
 fail when kernel debuginfo is not present

Hello,

Adding Veronika and Michael to CC.

Thanks,
Namhyung


On Tue, Jun 18, 2024 at 6:44 AM James Clark <james.clark@....com> wrote:
>
>
>
> On 17/06/2024 17:47, Athira Rajeev wrote:
> >
> >
> >> On 17 Jun 2024, at 8:30 PM, James Clark <james.clark@....com> wrote:
> >>
> >>
> >>
> >> On 17/06/2024 13:21, Athira Rajeev wrote:
> >>> Running "perftool-testsuite_probe" fails as below:
> >>>
> >>> ./perf test -v "perftool-testsuite_probe"
> >>> 83: perftool-testsuite_probe  : FAILED
> >>>
> >>> There are three fails:
> >>>
> >>> 1. Regexp not found: "\s*probe:inode_permission(?:_\d+)?\s+\(on inode_permission(?:[:\+][0-9A-Fa-f]+)?@.+\)"
> >>>   -- [ FAIL ] -- perf_probe :: test_adding_kernel :: listing added probe :: perf probe -l (output regexp parsing)
> >>>
> >>
> >> On a machine where NO_DEBUGINFO gets set, this one skips for me. But on
> >> a machine where there _is_ debug info this test still fails.
> >>
> >> But in both cases the probe looks like it was added successfully. So I'm
> >> wondering if this one does need to be skipped, or it's just always
> >> failing? Do you have this test passing anywhere where there is debug info?
> >>
> >> The list command looks like it successfully lists the probe for me in
> >> both cases, it just doesn't have an address on the end:
> >>
> >> perf list 'probe:*'
> >>
> >>   probe:inode_permission (on inode_permission)
> >>
> >> Does the missing address mean anything or is it just not handled
> >> properly by the test?
> >>
> >> Ironically the machine that _does_ pass the debug info test also prints
> >> this, but it looks like it still adds and lists the probe correctly:
> >>
> >>  perf probe -l probe:*
> >>
> >>  Failed to find debug information for address 0xffff80008047ac30
> >>    probe:inode_permission (on inode_permission)
> >
> > Hi James,
> >
> > Thanks for checking this patch.
> >
> > In environment where kernel is compiled with debuginfo:
> >
> > 1) Add probe point
> >
> > # ./perf probe --add inode_permission
> > Added new event:
> >   probe:inode_permission (on inode_permission)
> >
> > You can now use it in all perf tools, such as:
> >
> > perf record -e probe:inode_permission -aR sleep 1
> >
> >
> > 2) Check using perf probe -l
> >
> > # ./perf probe -l
> > probe:inode_permission (on inode_permission:2@...namei.c)
> >
> > With debuginfo, the result has additional info.
> >  The test looks for matching pattern "\s*probe:inode_permission(?:_\d+)?\s+\(on inode_permission(?:[:\+][0-9A-Fa-f]+)?@.+\)” in result
> > where it is expecting "inode_permission:2@...namei.c” . The “@fs/namei.c” info needs debuginfo here.
> >
>
> Hi Athira,
>
> Maybe there is a real bug and this patch is ok to go in and we should leave
> it as failing. Probe -L shows there is debug info available for inode_permission:
>
>    $ ./perf probe -L inode_permission
>
>   <inode_permission@...ux/fs/namei.c:0>
>       0  int inode_permission(struct mnt_idmap *idmap,
>                              struct inode *inode, int mask)
>   ... more source code ...
>
> But probe -l has an error which could be related to the following
> line not showing the filename details:
>
>   $ ./perf probe -l
>
>   Failed to find debug information for address 0xffff80008047ac30
>     probe:inode_permission (on inode_permission)
>
> I'm running a clang kernel and sometimes I see issues with debug
> info or toolchain stuff, that could be the reason.
>
> > The function I am using in patch to check for debuginfo (skip_if_no_debuginfo) is from "tests/shell/lib/probe_vfs_getname.sh"
> >
> > skip_if_no_debuginfo() {
> >         add_probe_vfs_getname -v 2>&1 | grep -E -q "^(Failed to find the path for the kernel|Debuginfo-analysis is not supported)|(file has no debug information)" && return 2
> >         return 1
> > }
> >
> > So the debuginfo test passes in your case since the log has "Failed to find debug information” which is not present in above grep string.
> >
>
> It passes because there is debug info for getname_flags() which is what the
> debug info check looks for. After some greps and seds it ultimately does this
> which succeeds:
>
>  $ 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)
>
> "Failed to find debug information for address" is only ever printed
> with "perf probe -l" when there are probes added. The stderr
> of that command is never piped into any grep anyway, which is why I
> see it on the test output.
>
> So "probe -L" is working but "probe -l" isn't. Ultimately it looks like a real
> issue and we should leave the failure in.
>
> > James,
> >
> > Only “perf probe -l” subtest fails with debuginfo enabled or other two subtests as well? Can you also share result on how other two subtests behaves ?
> >
> > 1. Fail 2 :
> >    perf probe -nf --max-probes=512 -a 'vfs_* $params’
> >
> >
> > 2. Fail 3 :
> >   perf probe 'vfs_read somenonexistingrandomstuffwhichisalsoprettylongorevenlongertoexceed64'
> >
>
> Here's the full output:
>
> $ sudo ./perf test -vvv "testsuite_probe"
>  84: perftool-testsuite_probe:
> --- start ---
> test child forked, pid 4872
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: adding probe inode_permission ::
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: adding probe inode_permission :: -a
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: adding probe inode_permission :: --add
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: listing added probe :: perf list
> Failed to find debug information for address 0xffff80008047ac30
> Regexp not found: "\s*probe:inode_permission(?:_\d+)?\s+\(on inode_permission(?:[:\+][0-9A-Fa-f]+)?@.+\)"
> -- [ FAIL ] -- perf_probe :: test_adding_kernel :: listing added probe :: perf probe -l (output regexp parsing)
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: using added probe
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: deleting added probe
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: listing removed probe (should NOT be listed)
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: dry run :: adding probe
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: force-adding probes :: first probe adding
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: force-adding probes :: second probe adding (without force)
> Failed to find debug information for address 0xffff80008047ac30
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: force-adding probes :: second probe adding (with force)
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: using doubled probe
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: removing multiple probes
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: wildcard adding support
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: non-existing variable
> -- [ PASS ] -- perf_probe :: test_adding_kernel :: function with retval :: add
> Regexp not found: "^\[\s+perf\s+record:\s+Woken up [0-9\.]+ times? to write data\s+\].*$"
> Regexp not found: "^\[\s+perf\s+record:\s+Captured and wrote [0-9\.]+\s*MB\s+(?:[\w\+\.-]*(?:(?:[\w\+\.-]+)?(?:\/[\w\+\.-]+)+)?\/)?perf\.data(?:\.\d+)?\s*\(~?[0-9\.]+ samples\)\s+\].*$"
> -- [ FAIL ] -- perf_probe :: test_adding_kernel :: function with retval :: record (command exitcode + output regexp parsing)
> zero-sized data (/tmp/perftool-testsuite_probe.VMU/perf_probe/perf.data), nothing to do!
> Regexp not found: "\s*cat\s+[0-9\.]+\s+\[[0-9\.]+\]\s+[0-9\.]+:\s+probe:inode_permission\w*:\s+\([0-9A-Fa-f]+\s+<\-\s+[0-9A-Fa-f]+\)\s+arg1=[0-9A-Fa-f]+"
> -- [ FAIL ] -- perf_probe :: test_adding_kernel :: function argument probing :: script (command exitcode + output regexp parsing)
> ## [ FAIL ] ## perf_probe :: test_adding_kernel SUMMARY :: 3 failures found
> ---- end(-1) ----
>  84: perftool-testsuite_probe                                        : FAILED!
>
>
> >
> > Also since you mentioned this gets skipped when debuginfo is not enabled, curious to know what is debuginfo message from your setup with debuginfo disabled.
> >
>
>   $ sudo ./perf probe -L getname_flags
>   Failed to find the path for the kernel: Invalid ELF file
>     Error: Failed to show lines.
>
> > Thanks again for checking.
> >
> > Athira
> >
> >>
> >
> >
> >>
> >>> 2. Regexp not found: "probe:vfs_mknod"
> >>>   Regexp not found: "probe:vfs_create"
> >>>   Regexp not found: "probe:vfs_rmdir"
> >>>   Regexp not found: "probe:vfs_link"
> >>>   Regexp not found: "probe:vfs_write"
> >>>   -- [ FAIL ] -- perf_probe :: test_adding_kernel :: wildcard adding support (command exitcode + output regexp parsing)
> >>>
> >>> 3. Regexp not found: "Failed to find"
> >>>   Regexp not found: "somenonexistingrandomstuffwhichisalsoprettylongorevenlongertoexceed64"
> >>>   Regexp not found: "in this function|at this address"
> >>>   Line did not match any pattern: "The /boot/vmlinux file has no debug information."
> >>>   Line did not match any pattern: "Rebuild with CONFIG_DEBUG_INFO=y, or install an appropriate debuginfo package."
> >>>
> >>> These three tests depends on kernel debug info.
> >>> 1. Fail 1 expects file name along with probe which needs debuginfo
> >>> 2. Fail 2 :
> >>>    perf probe -nf --max-probes=512 -a 'vfs_* $params'
> >>>    Debuginfo-analysis is not supported.
> >>>     Error: Failed to add events.
> >>>
> >>> 3. Fail 3 :
> >>>   perf probe 'vfs_read somenonexistingrandomstuffwhichisalsoprettylongorevenlongertoexceed64'
> >>>   Debuginfo-analysis is not supported.
> >>>   Error: Failed to add events.
> >>>
> >>> There is already helper function skip_if_no_debuginfo in
> >>> lib/probe_vfs_getname.sh which does perf probe and returns
> >>> "2" if debug info is not present. Use the skip_if_no_debuginfo
> >>> function and skip only the three tests which needs debuginfo
> >>> based on the result.
> >>>
> >>> With the patch:
> >>>
> >>>    83: perftool-testsuite_probe:
> >>>   --- start ---
> >>>   test child forked, pid 3927
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: adding probe inode_permission ::
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: adding probe inode_permission :: -a
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: adding probe inode_permission :: --add
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: listing added probe :: perf list
> >>>   Regexp not found: "\s*probe:inode_permission(?:_\d+)?\s+\(on inode_permission(?:[:\+][0-9A-Fa-f]+)?@.+\)"
> >>>   -- [ SKIP ] -- perf_probe :: test_adding_kernel :: 2 2 Skipped due to missing debuginfo :: testcase skipped
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: using added probe
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: deleting added probe
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: listing removed probe (should NOT be listed)
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: dry run :: adding probe
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: force-adding probes :: first probe adding
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: force-adding probes :: second probe adding (without force)
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: force-adding probes :: second probe adding (with force)
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: using doubled probe
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: removing multiple probes
> >>>   Regexp not found: "probe:vfs_mknod"
> >>>   Regexp not found: "probe:vfs_create"
> >>>   Regexp not found: "probe:vfs_rmdir"
> >>>   Regexp not found: "probe:vfs_link"
> >>>   Regexp not found: "probe:vfs_write"
> >>>   -- [ SKIP ] -- perf_probe :: test_adding_kernel :: 2 2 Skipped due to missing debuginfo :: testcase skipped
> >>>   Regexp not found: "Failed to find"
> >>>   Regexp not found: "somenonexistingrandomstuffwhichisalsoprettylongorevenlongertoexceed64"
> >>>   Regexp not found: "in this function|at this address"
> >>>   Line did not match any pattern: "The /boot/vmlinux file has no debug information."
> >>>   Line did not match any pattern: "Rebuild with CONFIG_DEBUG_INFO=y, or install an appropriate debuginfo package."
> >>>   -- [ SKIP ] -- perf_probe :: test_adding_kernel :: 2 2 Skipped due to missing debuginfo :: testcase skipped
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: function with retval :: add
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: function with retval :: record
> >>>   -- [ PASS ] -- perf_probe :: test_adding_kernel :: function argument probing :: script
> >>>   ## [ PASS ] ## perf_probe :: test_adding_kernel SUMMARY
> >>>   ---- end(0) ----
> >>>   83: perftool-testsuite_probe                                        : Ok
> >>>
> >>> Only the three specific tests are skipped and remaining
> >>> ran successfully.
> >>>
> >>> Signed-off-by: Athira Rajeev <atrajeev@...ux.vnet.ibm.com>
> >>> ---
> >>> .../shell/base_probe/test_adding_kernel.sh    | 31 +++++++++++++++++--
> >>> 1 file changed, 28 insertions(+), 3 deletions(-)
> >>>
> >>> diff --git a/tools/perf/tests/shell/base_probe/test_adding_kernel.sh b/tools/perf/tests/shell/base_probe/test_adding_kernel.sh
> >>> index 63bb8974b38e..187dc8d4b163 100755
> >>> --- a/tools/perf/tests/shell/base_probe/test_adding_kernel.sh
> >>> +++ b/tools/perf/tests/shell/base_probe/test_adding_kernel.sh
> >>> @@ -21,8 +21,18 @@
> >>> THIS_TEST_NAME=`basename $0 .sh`
> >>> TEST_RESULT=0
> >>>
> >>> +# shellcheck source=lib/probe_vfs_getname.sh
> >>> +. "$(dirname "$0")/../lib/probe_vfs_getname.sh"
> >>> +
> >>> TEST_PROBE=${TEST_PROBE:-"inode_permission"}
> >>>
> >>> +# set NO_DEBUGINFO to skip testcase if debuginfo is not present
> >>> +# skip_if_no_debuginfo returns 2 if debuginfo is not present
> >>> +skip_if_no_debuginfo
> >>> +if [ $? -eq 2 ]; then
> >>> + NO_DEBUGINFO=1
> >>> +fi
> >>> +
> >>> check_kprobes_available
> >>> if [ $? -ne 0 ]; then
> >>> print_overall_skipped
> >>> @@ -67,7 +77,12 @@ PERF_EXIT_CODE=$?
> >>> ../common/check_all_patterns_found.pl "\s*probe:${TEST_PROBE}(?:_\d+)?\s+\(on ${TEST_PROBE}(?:[:\+]$RE_NUMBER_HEX)?@.+\)" < $LOGS_DIR/adding_kernel_list-l.log
> >>> CHECK_EXIT_CODE=$?
> >>>
> >>> -print_results $PERF_EXIT_CODE $CHECK_EXIT_CODE "listing added probe :: perf probe -l"
> >>> +if [ $NO_DEBUGINFO ] ; then
> >>> + print_testcase_skipped $NO_DEBUGINFO $NO_DEBUGINFO "Skipped due to missing debuginfo"
> >>> +else
> >>> + print_results $PERF_EXIT_CODE $CHECK_EXIT_CODE "listing added probe :: perf probe -l"
> >>> +fi
> >>> +
> >>> (( TEST_RESULT += $? ))
> >>>
> >>>
> >>> @@ -208,7 +223,12 @@ PERF_EXIT_CODE=$?
> >>> ../common/check_all_patterns_found.pl "probe:vfs_mknod" "probe:vfs_create" "probe:vfs_rmdir" "probe:vfs_link" "probe:vfs_write" < $LOGS_DIR/adding_kernel_adding_wildcard.err
> >>> CHECK_EXIT_CODE=$?
> >>>
> >>> -print_results $PERF_EXIT_CODE $CHECK_EXIT_CODE "wildcard adding support"
> >>> +if [ $NO_DEBUGINFO ] ; then
> >>> + print_testcase_skipped $NO_DEBUGINFO $NO_DEBUGINFO "Skipped due to missing debuginfo"
> >>> +else
> >>> + print_results $PERF_EXIT_CODE $CHECK_EXIT_CODE "wildcard adding support"
> >>> +fi
> >>> +
> >>> (( TEST_RESULT += $? ))
> >>>
> >>>
> >>> @@ -232,7 +252,12 @@ CHECK_EXIT_CODE=$?
> >>> ../common/check_no_patterns_found.pl "$RE_SEGFAULT" < $LOGS_DIR/adding_kernel_nonexisting.err
> >>> (( CHECK_EXIT_CODE += $? ))
> >>>
> >>> -print_results $PERF_EXIT_CODE $CHECK_EXIT_CODE "non-existing variable"
> >>> +if [ $NO_DEBUGINFO ]; then
> >>> + print_testcase_skipped $NO_DEBUGINFO $NO_DEBUGINFO "Skipped due to missing debuginfo"
> >>> +else
> >>> + print_results $PERF_EXIT_CODE $CHECK_EXIT_CODE "non-existing variable"
> >>> +fi
> >>> +
> >>> (( TEST_RESULT += $? ))
> >>>
> >>>
> >

Powered by blists - more mailing lists