| Message ID | 20230817025028.3953490-1-zouyipeng@huawei.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | [v2] selftests/ftrace: traceonoff_triggers: strip off names | expand |
On Thu, 17 Aug 2023 10:50:28 +0800 Yipeng Zou <zouyipeng@huawei.com> 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@kernel.org> Thank you! > 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> > --- > .../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 >
Shuah, Can you take this in your tree? Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org> -- Steve On Thu, 17 Aug 2023 14:16:03 +0900 Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote: > On Thu, 17 Aug 2023 10:50:28 +0800 > Yipeng Zou <zouyipeng@huawei.com> 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@kernel.org> > > Thank you! > > > 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> > > --- > > .../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 > > > >
On Thu, 17 Aug 2023 09:02:33 -0400 Steven Rostedt <rostedt@goodmis.org> wrote: > Shuah, > > Can you take this in your tree? Actually, hold off please. > > Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org> > > -- Steve > > > On Thu, 17 Aug 2023 14:16:03 +0900 > Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote: > > > On Thu, 17 Aug 2023 10:50:28 +0800 > > Yipeng Zou <zouyipeng@huawei.com> wrote: > > > > > 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> > > > --- > > > .../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` Yipeng, can you please add the comment here: # 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` -- Steve > > > 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 > > > > > > > >
在 2023/8/17 21:04, Steven Rostedt 写道: > On Thu, 17 Aug 2023 09:02:33 -0400 > Steven Rostedt <rostedt@goodmis.org> wrote: > >> Shuah, >> >> Can you take this in your tree? > Actually, hold off please. > >> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org> >> >> -- Steve >> >> >> On Thu, 17 Aug 2023 14:16:03 +0900 >> Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote: >> >>> On Thu, 17 Aug 2023 10:50:28 +0800 >>> Yipeng Zou <zouyipeng@huawei.com> wrote: >>> > >>>> 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> >>>> --- >>>> .../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` > Yipeng, can you please add the comment here: > > # Cannot rely on names being around as they are only cached, strip them Of course, There is need to have some comment here. Sending v3 right now. >>>> +csum1=`cat trace | sed -e 's/^ *[^ ]*\(-[0-9][0-9]*\)/\1/' | md5sum` > -- Steve > >>>> 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 >>>> >>> >
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"
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> --- .../ftrace/test.d/ftrace/func_traceonoff_triggers.tc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)