| Message ID | 20240320141844.1779984-1-mark.rutland@arm.com (mailing list archive) |
|---|---|
| State | Handled Elsewhere |
| Delegated to: | Masami Hiramatsu |
| Headers | show |
| Series | selftests/ftrace: Fix event filter target_func selection | expand |
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 > >
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 --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
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(-)