| Message ID | 20230818013226.2182299-1-zouyipeng@huawei.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | [v3] selftests/ftrace: traceonoff_triggers: strip off names | expand |
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"
在 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" >
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"
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(-)