[PATCH v3] selftests/ftrace: traceonoff_triggers: strip off names

[PATCH v3] selftests/ftrace: traceonoff_triggers: strip off names

[Yipeng Zou]

The func_traceonoff_triggers.tc sometimes goes to fail
on my board, Kunpeng-920.

[root@localhost]# ./ftracetest ./test.d/ftrace/func_traceonoff_triggers.tc -l fail.log
=== Ftrace unit tests ===
[1] ftrace - test for function traceon/off triggers     [FAIL]
[2] (instance)  ftrace - test for function traceon/off triggers [UNSUPPORTED]

I look up the log, and it shows that the md5sum is different between csum1 and csum2.

++ cnt=611
++ sleep .1
+++ cnt_trace
+++ grep -v '^#' trace
+++ wc -l
++ cnt2=611
++ '[' 611 -ne 611 ']'
+++ cat tracing_on
++ on=0
++ '[' 0 '!=' 0 ']'
+++ md5sum trace
++ csum1='76896aa74362fff66a6a5f3cf8a8a500  trace'
++ sleep .1
+++ md5sum trace
++ csum2='ee8625a21c058818fc26e45c1ed3f6de  trace'
++ '[' '76896aa74362fff66a6a5f3cf8a8a500  trace' '!=' 'ee8625a21c058818fc26e45c1ed3f6de  trace' ']'
++ fail 'Tracing file is still changing'
++ echo Tracing file is still changing
Tracing file is still changing
++ exit_fail
++ exit 1

So I directly dump the trace file before md5sum, the diff shows that:

[root@localhost]# diff trace_1.log trace_2.log -y --suppress-common-lines
dockerd-12285   [036] d.... 18385.510290: sched_stat | <...>-12285   [036] d.... 18385.510290: sched_stat
dockerd-12285   [036] d.... 18385.510291: sched_swit | <...>-12285   [036] d.... 18385.510291: sched_swit
<...>-740       [044] d.... 18385.602859: sched_stat | kworker/44:1-740 [044] d.... 18385.602859: sched_stat
<...>-740       [044] d.... 18385.602860: sched_swit | kworker/44:1-740 [044] d.... 18385.602860: sched_swit

And we can see that <...> filed be filled with names.

We can strip off the names there to fix that.

After strip off the names:

kworker/u257:0-12 [019] d..2.  2528.758910: sched_stat | -12 [019] d..2.  2528.758910: sched_stat_runtime: comm=k
kworker/u257:0-12 [019] d..2.  2528.758912: sched_swit | -12 [019] d..2.  2528.758912: sched_switch: prev_comm=kw
<idle>-0          [000] d.s5.  2528.762318: sched_waki | -0  [000] d.s5.  2528.762318: sched_waking: comm=sshd pi
<idle>-0          [037] dNh2.  2528.762326: sched_wake | -0  [037] dNh2.  2528.762326: sched_wakeup: comm=sshd pi
<idle>-0          [037] d..2.  2528.762334: sched_swit | -0  [037] d..2.  2528.762334: sched_switch: prev_comm=sw

Fixes: d87b29179aa0 ("selftests: ftrace: Use md5sum to take less time of checking logs")
Suggested-by: Steven Rostedt (Google) <rostedt@goodmis.org>
Signed-off-by: Yipeng Zou <zouyipeng@huawei.com>
Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 .../ftrace/test.d/ftrace/func_traceonoff_triggers.tc         | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
index aee22289536b..1b57771dbfdf 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
@@ -90,9 +90,10 @@ if [ $on != "0" ]; then
     fail "Tracing is not off"
 fi
 
-csum1=`md5sum trace`
+# Cannot rely on names being around as they are only cached, strip them
+csum1=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
 sleep $SLEEP_TIME
-csum2=`md5sum trace`
+csum2=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
 
 if [ "$csum1" != "$csum2" ]; then
     fail "Tracing file is still changing"
-- 
2.34.1

Re: [PATCH v3] selftests/ftrace: traceonoff_triggers: strip off names

[Steven Rostedt]

On Fri, 18 Aug 2023 09:32:26 +0800
Yipeng Zou <zouyipeng@huawei.com> wrote:

> The func_traceonoff_triggers.tc sometimes goes to fail
> on my board, Kunpeng-920.

Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Shuah, can you take this through your tree?

-- Steve

> 
> [root@localhost]# ./ftracetest ./test.d/ftrace/func_traceonoff_triggers.tc -l fail.log
> === Ftrace unit tests ===
> [1] ftrace - test for function traceon/off triggers     [FAIL]
> [2] (instance)  ftrace - test for function traceon/off triggers [UNSUPPORTED]
> 
> I look up the log, and it shows that the md5sum is different between csum1 and csum2.
> 
> ++ cnt=611
> ++ sleep .1
> +++ cnt_trace
> +++ grep -v '^#' trace
> +++ wc -l
> ++ cnt2=611
> ++ '[' 611 -ne 611 ']'
> +++ cat tracing_on
> ++ on=0
> ++ '[' 0 '!=' 0 ']'
> +++ md5sum trace
> ++ csum1='76896aa74362fff66a6a5f3cf8a8a500  trace'
> ++ sleep .1
> +++ md5sum trace
> ++ csum2='ee8625a21c058818fc26e45c1ed3f6de  trace'
> ++ '[' '76896aa74362fff66a6a5f3cf8a8a500  trace' '!=' 'ee8625a21c058818fc26e45c1ed3f6de  trace' ']'
> ++ fail 'Tracing file is still changing'
> ++ echo Tracing file is still changing
> Tracing file is still changing
> ++ exit_fail
> ++ exit 1
> 
> So I directly dump the trace file before md5sum, the diff shows that:
> 
> [root@localhost]# diff trace_1.log trace_2.log -y --suppress-common-lines
> dockerd-12285   [036] d.... 18385.510290: sched_stat | <...>-12285   [036] d.... 18385.510290: sched_stat
> dockerd-12285   [036] d.... 18385.510291: sched_swit | <...>-12285   [036] d.... 18385.510291: sched_swit
> <...>-740       [044] d.... 18385.602859: sched_stat | kworker/44:1-740 [044] d.... 18385.602859: sched_stat
> <...>-740       [044] d.... 18385.602860: sched_swit | kworker/44:1-740 [044] d.... 18385.602860: sched_swit
> 
> And we can see that <...> filed be filled with names.
> 
> We can strip off the names there to fix that.
> 
> After strip off the names:
> 
> kworker/u257:0-12 [019] d..2.  2528.758910: sched_stat | -12 [019] d..2.  2528.758910: sched_stat_runtime: comm=k
> kworker/u257:0-12 [019] d..2.  2528.758912: sched_swit | -12 [019] d..2.  2528.758912: sched_switch: prev_comm=kw
> <idle>-0          [000] d.s5.  2528.762318: sched_waki | -0  [000] d.s5.  2528.762318: sched_waking: comm=sshd pi
> <idle>-0          [037] dNh2.  2528.762326: sched_wake | -0  [037] dNh2.  2528.762326: sched_wakeup: comm=sshd pi
> <idle>-0          [037] d..2.  2528.762334: sched_swit | -0  [037] d..2.  2528.762334: sched_switch: prev_comm=sw
> 
> Fixes: d87b29179aa0 ("selftests: ftrace: Use md5sum to take less time of checking logs")
> Suggested-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> Signed-off-by: Yipeng Zou <zouyipeng@huawei.com>
> Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> ---
>  .../ftrace/test.d/ftrace/func_traceonoff_triggers.tc         | 5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> index aee22289536b..1b57771dbfdf 100644
> --- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> @@ -90,9 +90,10 @@ if [ $on != "0" ]; then
>      fail "Tracing is not off"
>  fi
>  
> -csum1=`md5sum trace`
> +# Cannot rely on names being around as they are only cached, strip them
> +csum1=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
>  sleep $SLEEP_TIME
> -csum2=`md5sum trace`
> +csum2=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
>  
>  if [ "$csum1" != "$csum2" ]; then
>      fail "Tracing file is still changing"

Re: [PATCH v3] selftests/ftrace: traceonoff_triggers: strip off names

[Yipeng Zou]

在 2023/8/21 23:13, Steven Rostedt 写道:
> On Fri, 18 Aug 2023 09:32:26 +0800
> Yipeng Zou <zouyipeng@huawei.com> wrote:
>
>> The func_traceonoff_triggers.tc sometimes goes to fail
>> on my board, Kunpeng-920.
> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
>
> Shuah, can you take this through your tree?
>
> -- Steve

Hi:

     I just notice that it haven't been picked in Linux-next.

     It's there other issue about this patch?

>> [root@localhost]# ./ftracetest ./test.d/ftrace/func_traceonoff_triggers.tc -l fail.log
>> === Ftrace unit tests ===
>> [1] ftrace - test for function traceon/off triggers     [FAIL]
>> [2] (instance)  ftrace - test for function traceon/off triggers [UNSUPPORTED]
>>
>> I look up the log, and it shows that the md5sum is different between csum1 and csum2.
>>
>> ++ cnt=611
>> ++ sleep .1
>> +++ cnt_trace
>> +++ grep -v '^#' trace
>> +++ wc -l
>> ++ cnt2=611
>> ++ '[' 611 -ne 611 ']'
>> +++ cat tracing_on
>> ++ on=0
>> ++ '[' 0 '!=' 0 ']'
>> +++ md5sum trace
>> ++ csum1='76896aa74362fff66a6a5f3cf8a8a500  trace'
>> ++ sleep .1
>> +++ md5sum trace
>> ++ csum2='ee8625a21c058818fc26e45c1ed3f6de  trace'
>> ++ '[' '76896aa74362fff66a6a5f3cf8a8a500  trace' '!=' 'ee8625a21c058818fc26e45c1ed3f6de  trace' ']'
>> ++ fail 'Tracing file is still changing'
>> ++ echo Tracing file is still changing
>> Tracing file is still changing
>> ++ exit_fail
>> ++ exit 1
>>
>> So I directly dump the trace file before md5sum, the diff shows that:
>>
>> [root@localhost]# diff trace_1.log trace_2.log -y --suppress-common-lines
>> dockerd-12285   [036] d.... 18385.510290: sched_stat | <...>-12285   [036] d.... 18385.510290: sched_stat
>> dockerd-12285   [036] d.... 18385.510291: sched_swit | <...>-12285   [036] d.... 18385.510291: sched_swit
>> <...>-740       [044] d.... 18385.602859: sched_stat | kworker/44:1-740 [044] d.... 18385.602859: sched_stat
>> <...>-740       [044] d.... 18385.602860: sched_swit | kworker/44:1-740 [044] d.... 18385.602860: sched_swit
>>
>> And we can see that <...> filed be filled with names.
>>
>> We can strip off the names there to fix that.
>>
>> After strip off the names:
>>
>> kworker/u257:0-12 [019] d..2.  2528.758910: sched_stat | -12 [019] d..2.  2528.758910: sched_stat_runtime: comm=k
>> kworker/u257:0-12 [019] d..2.  2528.758912: sched_swit | -12 [019] d..2.  2528.758912: sched_switch: prev_comm=kw
>> <idle>-0          [000] d.s5.  2528.762318: sched_waki | -0  [000] d.s5.  2528.762318: sched_waking: comm=sshd pi
>> <idle>-0          [037] dNh2.  2528.762326: sched_wake | -0  [037] dNh2.  2528.762326: sched_wakeup: comm=sshd pi
>> <idle>-0          [037] d..2.  2528.762334: sched_swit | -0  [037] d..2.  2528.762334: sched_switch: prev_comm=sw
>>
>> Fixes: d87b29179aa0 ("selftests: ftrace: Use md5sum to take less time of checking logs")
>> Suggested-by: Steven Rostedt (Google) <rostedt@goodmis.org>
>> Signed-off-by: Yipeng Zou <zouyipeng@huawei.com>
>> Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
>> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
>> ---
>>   .../ftrace/test.d/ftrace/func_traceonoff_triggers.tc         | 5 +++--
>>   1 file changed, 3 insertions(+), 2 deletions(-)
>>
>> diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
>> index aee22289536b..1b57771dbfdf 100644
>> --- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
>> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
>> @@ -90,9 +90,10 @@ if [ $on != "0" ]; then
>>       fail "Tracing is not off"
>>   fi
>>   
>> -csum1=`md5sum trace`
>> +# Cannot rely on names being around as they are only cached, strip them
>> +csum1=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
>>   sleep $SLEEP_TIME
>> -csum2=`md5sum trace`
>> +csum2=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
>>   
>>   if [ "$csum1" != "$csum2" ]; then
>>       fail "Tracing file is still changing"
>
-- 
Regards,
Yipeng Zou