On Thu, 17 Aug 2023 10:50:28 +0800
Yipeng Zou <zouyipeng@xxxxxxxxxx> wrote:
> 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
>
Looks good to me.
Acked-by: Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>
Thank you!
> Fixes: d87b29179aa0 ("selftests: ftrace: Use md5sum to take less time of checking logs")
> Suggested-by: Steven Rostedt (Google) <rostedt@xxxxxxxxxxx>
> Signed-off-by: Yipeng Zou <zouyipeng@xxxxxxxxxx>
> ---
> .../ftrace/test.d/ftrace/func_traceonoff_triggers.tc | 4 ++--
> 1 file changed, 2 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..c5783999582d 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,9 @@ if [ $on != "0" ]; then
> fail "Tracing is not off"
> fi
>
> -csum1=`md5sum trace`
> +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
>
--
Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>
