On Wed, 20 Mar 2024 14:18:44 +0000
Mark Rutland <mark.rutland@xxxxxxx> 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@xxxxxxxxxx>
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@xxxxxxxxxxxxxxx
Shuah, can you pick this as a fix?
Thank you,
> Signed-off-by: Mark Rutland <mark.rutland@xxxxxxx>
> Reported-by: Aishwarya TCV <aishwarya.tcv@xxxxxxx>
> Cc: Masami Hiramatsu <mhiramat@xxxxxxxxxx>
> Cc: Mathieu Desnoyers <mathieu.desnoyers@xxxxxxxxxxxx>
> Cc: Shuah Khan <shuah@xxxxxxxxxx>
> Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
> Cc: linux-kernel@xxxxxxxxxxxxxxx
> Cc: linux-kselftest@xxxxxxxxxxxxxxx
> Cc: linux-trace-kernel@xxxxxxxxxxxxxxx
> ---
> .../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
>
>
--
Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>
