From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by smtp.subspace.kernel.org (Postfix) with ESMTP id 0CD4A152E1C; Tue, 18 Jun 2024 10:44:21 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=217.140.110.172 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1718707464; cv=none; b=Bfmi1KfP/pslhcTkxo/fwrPGp2nU69C3RvlobTc2VrpZCkOK06qpHJYL05UiFJQj5r1uxsPNIBC4tvOqIVGxXvIrKVSzbhzRnVAk0eyzK9p0fpFv7aPEAZxJUtr6qUx1wVAbFOXoRm78j6RFPL3c9OiSbUQcAyA36n6zjTzS+II= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1718707464; c=relaxed/simple; bh=nS3DjpodKySDKeNA2ccBur3bRnA0OzGWPb1zIrGDU6I=; h=Message-ID:Date:MIME-Version:From:Subject:To:Cc:References: In-Reply-To:Content-Type; b=I37BLvUtg9qdpekp6HGcenndcS1/4Jrk9VCC058G4X5Y7tx5eUi5MTD+SRiP2/l7bNh5/55ioldRhysVOWkgjBrtjk/2uTuVS+N93ASpcZ0JNKM5wkgU51dZNlsTVshGQx+okixlE6twqnU6m5PWWJSPYyUZduYiIXqYFeA0Qzs= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=arm.com; spf=pass smtp.mailfrom=arm.com; arc=none smtp.client-ip=217.140.110.172 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=arm.com Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=arm.com Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id ED3DCDA7; Tue, 18 Jun 2024 03:44:45 -0700 (PDT) Received: from [192.168.1.100] (usa-sjc-mx-foss1.foss.arm.com [172.31.20.19]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id A72B93F6A8; Tue, 18 Jun 2024 03:44:18 -0700 (PDT) Message-ID: <5a0edf86-fe42-41d6-aa9a-8e88c1ad3f4c@arm.com> Date: Tue, 18 Jun 2024 11:44:16 +0100 Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 User-Agent: Mozilla Thunderbird From: James Clark Subject: Re: [PATCH] tools/perf: Handle perftool-testsuite_probe testcases fail when kernel debuginfo is not present To: Athira Rajeev Cc: LKML , linux-perf-users , linuxppc-dev , akanksha@linux.ibm.com, Madhavan Srinivasan , Kajol Jain , Disha Goel , Arnaldo Carvalho de Melo , Jiri Olsa , Adrian Hunter , Ian Rogers , Namhyung Kim References: <20240617122121.7484-1-atrajeev@linux.vnet.ibm.com> <588beeaf-2015-40f4-a34b-e36556e20707@arm.com> Content-Language: en-US In-Reply-To: Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit On 17/06/2024 17:47, Athira Rajeev wrote: > > >> On 17 Jun 2024, at 8:30 PM, James Clark 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@fs/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@fs/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 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 >>> --- >>> .../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 += $? )) >>> >>> >