[PATCH] selftests/ftrace: let traceonoff_triggers testcase without md5sum

[PATCH] selftests/ftrace: let traceonoff_triggers testcase without md5sum

[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 the saved_cmdlines in kernel was changed.

So Maybe there is no safe to use md5sum here to verify whether
the file whether it has changed.

From my point of view, we only need to verify traceoff event
is valid there.

Maybe it is enough to check first that the tracing_on equals 0,
and then check that the total number of rows of trace does not
increase?

Fixes: d87b29179aa0 ("selftests: ftrace: Use md5sum to take less time of checking logs")
Signed-off-by: Yipeng Zou <zouyipeng@huawei.com>
---
 .../test.d/ftrace/func_traceonoff_triggers.tc    | 16 ++++------------
 1 file changed, 4 insertions(+), 12 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..180c60605d7b 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
@@ -77,25 +77,17 @@ if [ $cnt -ne 1 ]; then
    fail "Did not find traceoff trigger"
 fi
 
-cnt=`cnt_trace`
-sleep $SLEEP_TIME
-cnt2=`cnt_trace`
-
-if [ $cnt -ne $cnt2 ]; then
-   fail "Tracing is not stopped"
-fi
-
 on=`cat tracing_on`
 if [ $on != "0" ]; then
     fail "Tracing is not off"
 fi
 
-csum1=`md5sum trace`
+cnt=`cnt_trace`
 sleep $SLEEP_TIME
-csum2=`md5sum trace`
+cnt2=`cnt_trace`
 
-if [ "$csum1" != "$csum2" ]; then
-    fail "Tracing file is still changing"
+if [ $cnt -ne $cnt2 ]; then
+   fail "Tracing is not stopped"
 fi
 
 clear_trace
-- 
2.34.1

Re: [PATCH] selftests/ftrace: let traceonoff_triggers testcase without md5sum

[Steven Rostedt]

On Mon, 14 Aug 2023 10:59:18 +0800
Yipeng Zou <zouyipeng@huawei.com> wrote:

> 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

So the problem is the <..> being added?

> 
> And we can see that the saved_cmdlines in kernel was changed.
> 
> So Maybe there is no safe to use md5sum here to verify whether
> the file whether it has changed.
> 
> >From my point of view, we only need to verify traceoff event  
> is valid there.
> 
> Maybe it is enough to check first that the tracing_on equals 0,
> and then check that the total number of rows of trace does not
> increase?
> 
> Fixes: d87b29179aa0 ("selftests: ftrace: Use md5sum to take less time of checking logs")
> Signed-off-by: Yipeng Zou <zouyipeng@huawei.com>
> ---
>  .../test.d/ftrace/func_traceonoff_triggers.tc    | 16 ++++------------
>  1 file changed, 4 insertions(+), 12 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..180c60605d7b 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
> @@ -77,25 +77,17 @@ if [ $cnt -ne 1 ]; then
>     fail "Did not find traceoff trigger"
>  fi
>  
> -cnt=`cnt_trace`
> -sleep $SLEEP_TIME
> -cnt2=`cnt_trace`
> -
> -if [ $cnt -ne $cnt2 ]; then
> -   fail "Tracing is not stopped"
> -fi
> -
>  on=`cat tracing_on`
>  if [ $on != "0" ]; then
>      fail "Tracing is not off"
>  fi
>  
> -csum1=`md5sum trace`

What about just changing the above to:

 # Can not rely on names being around as they are only cached
 csum1=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`

> +cnt=`cnt_trace`
>  sleep $SLEEP_TIME
> -csum2=`md5sum trace`

And this:

 csum2=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`

That will strip off the names an leave just the -[PID]... part of the line?

-- Steve



> +cnt2=`cnt_trace`
>  
> -if [ "$csum1" != "$csum2" ]; then
> -    fail "Tracing file is still changing"
> +if [ $cnt -ne $cnt2 ]; then
> +   fail "Tracing is not stopped"
>  fi
>  
>  clear_trace

Re: [PATCH] selftests/ftrace: let traceonoff_triggers testcase without md5sum

[Yipeng Zou]

在 2023/8/17 4:20, Steven Rostedt 写道:
> On Mon, 14 Aug 2023 10:59:18 +0800
> Yipeng Zou <zouyipeng@huawei.com> wrote:
>
>> 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
> So the problem is the <..> being added?
>
>> And we can see that the saved_cmdlines in kernel was changed.
>>
>> So Maybe there is no safe to use md5sum here to verify whether
>> the file whether it has changed.
>>
>> >From my point of view, we only need to verify traceoff event  
>> is valid there.
>>
>> Maybe it is enough to check first that the tracing_on equals 0,
>> and then check that the total number of rows of trace does not
>> increase?
>>
>> Fixes: d87b29179aa0 ("selftests: ftrace: Use md5sum to take less time of checking logs")
>> Signed-off-by: Yipeng Zou <zouyipeng@huawei.com>
>> ---
>>   .../test.d/ftrace/func_traceonoff_triggers.tc    | 16 ++++------------
>>   1 file changed, 4 insertions(+), 12 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..180c60605d7b 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
>> @@ -77,25 +77,17 @@ if [ $cnt -ne 1 ]; then
>>      fail "Did not find traceoff trigger"
>>   fi
>>   
>> -cnt=`cnt_trace`
>> -sleep $SLEEP_TIME
>> -cnt2=`cnt_trace`
>> -
>> -if [ $cnt -ne $cnt2 ]; then
>> -   fail "Tracing is not stopped"
>> -fi
>> -
>>   on=`cat tracing_on`
>>   if [ $on != "0" ]; then
>>       fail "Tracing is not off"
>>   fi
>>   
>> -csum1=`md5sum trace`
> What about just changing the above to:
>
>   # Can not rely on names being around as they are only cached
>   csum1=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
>
>> +cnt=`cnt_trace`
>>   sleep $SLEEP_TIME
>> -csum2=`md5sum trace`
> And this:
>
>   csum2=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum`
>
> That will strip off the names an leave just the -[PID]... part of the line?
>
> -- Steve
>
>
Hi Steve:

     Thanks for your suggests, this is indeed more effective.

     The problem was that <...> filed be filled with names, and it 
causes the md5 value changed.

     I will send v2 in that ways, thanks !

-- Yipeng

>> +cnt2=`cnt_trace`
>>   
>> -if [ "$csum1" != "$csum2" ]; then
>> -    fail "Tracing file is still changing"
>> +if [ $cnt -ne $cnt2 ]; then
>> +   fail "Tracing is not stopped"
>>   fi
>>   
>>   clear_trace
>
-- 
Regards,
Yipeng Zou