diff mbox series

selftests/ftrace: Fix event filter target_func selection

Message ID 20240320141844.1779984-1-mark.rutland@arm.com (mailing list archive)
State Accepted
Headers show
Series selftests/ftrace: Fix event filter target_func selection | expand

Commit Message

Mark Rutland March 20, 2024, 2:18 p.m. UTC
The event filter function test has been failing in our internal test
farm:

| # not ok 33 event filter function - test event filtering on functions

Running the test in verbose mode indicates that this is because the test
erroneously determines that kmem_cache_free() is the most common caller
of kmem_cache_free():

  # # + cut -d: -f3 trace
  # # + sed s/call_site=([^+]*)+0x.*/1/
  # # + sort
  # # + uniq -c
  # # + sort
  # # + tail -n 1
  # # + sed s/^[ 0-9]*//
  # # + target_func=kmem_cache_free

... and as kmem_cache_free() doesn't call itself, setting this as the
filter function for kmem_cache_free() results in no hits, and
consequently the test fails:

  # # + grep kmem_cache_free trace
  # # + grep kmem_cache_free
  # # + wc -l
  # # + hitcnt=0
  # # + grep kmem_cache_free trace
  # # + grep -v kmem_cache_free
  # # + wc -l
  # # + misscnt=0
  # # + [ 0 -eq 0 ]
  # # + exit_fail

This seems to be because the system in question has tasks with ':' in
their name (which a number of kernel worker threads have). These show up
in the trace, e.g.

  test:.sh-1299    [004] .....  2886.040608: kmem_cache_free: call_site=putname+0xa4/0xc8 ptr=000000000f4d22f4 name=names_cache

... and so when we try to extact the call_site with:

  cut -d: -f3 trace | sed 's/call_site=\([^+]*\)+0x.*/\1/'

... the 'cut' command will extrace the column containing
'kmem_cache_free' rather than the column containing 'call_site=...', and
the 'sed' command will leave this unchanged. Consequently, the test will
decide to use 'kmem_cache_free' as the filter function, resulting in the
failure seen above.

Fix this by matching the 'call_site=<func>' part specifically to extract
the function name.

Signed-off-by: Mark Rutland <mark.rutland@arm.com>
Reported-by: Aishwarya TCV <aishwarya.tcv@arm.com>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Shuah Khan <shuah@kernel.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: linux-kernel@vger.kernel.org
Cc: linux-kselftest@vger.kernel.org
Cc: linux-trace-kernel@vger.kernel.org
---
 .../selftests/ftrace/test.d/filter/event-filter-function.tc     | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Comments

Masami Hiramatsu (Google) March 21, 2024, 12:09 a.m. UTC | #1
On Wed, 20 Mar 2024 14:18:44 +0000
Mark Rutland <mark.rutland@arm.com> wrote:

> The event filter function test has been failing in our internal test
> farm:
> 
> | # not ok 33 event filter function - test event filtering on functions
> 
> Running the test in verbose mode indicates that this is because the test
> erroneously determines that kmem_cache_free() is the most common caller
> of kmem_cache_free():
> 
>   # # + cut -d: -f3 trace
>   # # + sed s/call_site=([^+]*)+0x.*/1/
>   # # + sort
>   # # + uniq -c
>   # # + sort
>   # # + tail -n 1
>   # # + sed s/^[ 0-9]*//
>   # # + target_func=kmem_cache_free
> 
> .. and as kmem_cache_free() doesn't call itself, setting this as the
> filter function for kmem_cache_free() results in no hits, and
> consequently the test fails:
> 
>   # # + grep kmem_cache_free trace
>   # # + grep kmem_cache_free
>   # # + wc -l
>   # # + hitcnt=0
>   # # + grep kmem_cache_free trace
>   # # + grep -v kmem_cache_free
>   # # + wc -l
>   # # + misscnt=0
>   # # + [ 0 -eq 0 ]
>   # # + exit_fail
> 
> This seems to be because the system in question has tasks with ':' in
> their name (which a number of kernel worker threads have). These show up
> in the trace, e.g.
> 
>   test:.sh-1299    [004] .....  2886.040608: kmem_cache_free: call_site=putname+0xa4/0xc8 ptr=000000000f4d22f4 name=names_cache
> 
> .. and so when we try to extact the call_site with:
> 
>   cut -d: -f3 trace | sed 's/call_site=\([^+]*\)+0x.*/\1/'
> 
> .. the 'cut' command will extrace the column containing
> 'kmem_cache_free' rather than the column containing 'call_site=...', and
> the 'sed' command will leave this unchanged. Consequently, the test will
> decide to use 'kmem_cache_free' as the filter function, resulting in the
> failure seen above.
> 
> Fix this by matching the 'call_site=<func>' part specifically to extract
> the function name.
> 

Looks good to me.

Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>

I think this should be a fix because test task name can have ':'.

Fixes: eb50d0f250e9 ("selftests/ftrace: Choose target function for filter test from samples")
Cc: stable@vger.kernel.org

Shuah, can you pick this as a fix?

Thank you,

> Signed-off-by: Mark Rutland <mark.rutland@arm.com>
> Reported-by: Aishwarya TCV <aishwarya.tcv@arm.com>
> Cc: Masami Hiramatsu <mhiramat@kernel.org>
> Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> Cc: Shuah Khan <shuah@kernel.org>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: linux-kernel@vger.kernel.org
> Cc: linux-kselftest@vger.kernel.org
> Cc: linux-trace-kernel@vger.kernel.org
> ---
>  .../selftests/ftrace/test.d/filter/event-filter-function.tc     | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc b/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
> index 2de7c61d1ae3..3f74c09c56b6 100644
> --- a/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
> +++ b/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
> @@ -24,7 +24,7 @@ echo 0 > events/enable
>  echo "Get the most frequently calling function"
>  sample_events
>  
> -target_func=`cut -d: -f3 trace | sed 's/call_site=\([^+]*\)+0x.*/\1/' | sort | uniq -c | sort | tail -n 1 | sed 's/^[ 0-9]*//'`
> +target_func=`cat trace | grep -o 'call_site=\([^+]*\)' | sed 's/call_site=//' | sort | uniq -c | sort | tail -n 1 | sed 's/^[ 0-9]*//'`
>  if [ -z "$target_func" ]; then
>      exit_fail
>  fi
> -- 
> 2.39.2
> 
>
Shuah Khan March 26, 2024, 7:24 p.m. UTC | #2
On 3/20/24 18:09, Masami Hiramatsu (Google) wrote:
> On Wed, 20 Mar 2024 14:18:44 +0000
> Mark Rutland <mark.rutland@arm.com> wrote:
> 
>> The event filter function test has been failing in our internal test
>> farm:
>>
>> | # not ok 33 event filter function - test event filtering on functions
>>
>> Running the test in verbose mode indicates that this is because the test
>> erroneously determines that kmem_cache_free() is the most common caller
>> of kmem_cache_free():
>>
>>    # # + cut -d: -f3 trace
>>    # # + sed s/call_site=([^+]*)+0x.*/1/
>>    # # + sort
>>    # # + uniq -c
>>    # # + sort
>>    # # + tail -n 1
>>    # # + sed s/^[ 0-9]*//
>>    # # + target_func=kmem_cache_free
>>
>> .. and as kmem_cache_free() doesn't call itself, setting this as the
>> filter function for kmem_cache_free() results in no hits, and
>> consequently the test fails:
>>
>>    # # + grep kmem_cache_free trace
>>    # # + grep kmem_cache_free
>>    # # + wc -l
>>    # # + hitcnt=0
>>    # # + grep kmem_cache_free trace
>>    # # + grep -v kmem_cache_free
>>    # # + wc -l
>>    # # + misscnt=0
>>    # # + [ 0 -eq 0 ]
>>    # # + exit_fail
>>
>> This seems to be because the system in question has tasks with ':' in
>> their name (which a number of kernel worker threads have). These show up
>> in the trace, e.g.
>>
>>    test:.sh-1299    [004] .....  2886.040608: kmem_cache_free: call_site=putname+0xa4/0xc8 ptr=000000000f4d22f4 name=names_cache
>>
>> .. and so when we try to extact the call_site with:
>>
>>    cut -d: -f3 trace | sed 's/call_site=\([^+]*\)+0x.*/\1/'
>>
>> .. the 'cut' command will extrace the column containing
>> 'kmem_cache_free' rather than the column containing 'call_site=...', and
>> the 'sed' command will leave this unchanged. Consequently, the test will
>> decide to use 'kmem_cache_free' as the filter function, resulting in the
>> failure seen above.
>>
>> Fix this by matching the 'call_site=<func>' part specifically to extract
>> the function name.
>>
> 
> Looks good to me.
> 
> Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> 
> I think this should be a fix because test task name can have ':'.
> 
> Fixes: eb50d0f250e9 ("selftests/ftrace: Choose target function for filter test from samples")
> Cc: stable@vger.kernel.org
> 
> Shuah, can you pick this as a fix?
> 

Applied to linux-ksleftest fixes for next rc

thanks,
-- Shuah
diff mbox series

Patch

diff --git a/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc b/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
index 2de7c61d1ae3..3f74c09c56b6 100644
--- a/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
+++ b/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
@@ -24,7 +24,7 @@  echo 0 > events/enable
 echo "Get the most frequently calling function"
 sample_events
 
-target_func=`cut -d: -f3 trace | sed 's/call_site=\([^+]*\)+0x.*/\1/' | sort | uniq -c | sort | tail -n 1 | sed 's/^[ 0-9]*//'`
+target_func=`cat trace | grep -o 'call_site=\([^+]*\)' | sed 's/call_site=//' | sort | uniq -c | sort | tail -n 1 | sed 's/^[ 0-9]*//'`
 if [ -z "$target_func" ]; then
     exit_fail
 fi