| Message ID | 20210603062113.133326-1-wqu@suse.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [v2] fstests: add basic ftrace support | expand |
On Thu, Jun 03, 2021 at 02:21:13PM +0800, Qu Wenruo wrote: > Sometimes developers want trace dump for certain test cases. > > Normally I just add "trace-cmd" calls in "check", but it would be much > better to let fstests to support ftrace dumping. > > This patchset will add basic ftrace dumping support by: > > - Clear all buffers before running each test > - Start tracing before running each test > - End tracing after test finished > - Copy the trace to "$seqres.trace" if needed > The condition is either: > * $KEEP_TRACE environment is set to "yes" > * The test case failed > > Currently we only support the main ftrace buffer, but all supporting > functions have support for ftrace instances, for later expansion. > > Signed-off-by: Qu Wenruo <wqu@suse.com> > --- > Changelog: > v2: > - Add explanation in "common/config" for how to use it > - Make variables local > - Don't create the instance when clearing buffers > --- > check | 12 +++++++- > common/config | 8 +++++ > common/ftrace | 83 +++++++++++++++++++++++++++++++++++++++++++++++++++ > common/rc | 1 + > 4 files changed, 103 insertions(+), 1 deletion(-) > create mode 100644 common/ftrace > > diff --git a/check b/check > index ba192042..0a09dcf9 100755 > --- a/check > +++ b/check > @@ -801,7 +801,7 @@ function run_section() > fi > > # really going to try and run this one > - rm -f $seqres.out.bad > + rm -f $seqres.out.bad $seqres.trace > > # check if we really should run it > _expunge_test $seqnum > @@ -839,6 +839,10 @@ function run_section() > # to be reported for each test > (echo 1 > $DEBUGFS_MNT/clear_warn_once) > /dev/null 2>&1 > > + # Clear previous trace and start new trace > + _clear_trace_buffers > + _start_trace So how does one enable all 500+ xfs tracepoints for this? Or just some subset? i.e. how do we pass it a list of events like we do trace-cmd? IOWs, for this to be actually useful as a replacement for trace-cmd, it has to be able to replace invocations like this: # trace-cmd record -e xfs_i*lock* -e xfs_buf* -e printk -e iomap* .... which is how I use trace-cmd 99.9% of the time I'm debugging fstests using tracepoints. Next: some tests will generate gigabytes of trace data on XFS. I'm not joking here - I regularly am looking for single traces in an output file that contains tens of millions of events in it. Having fstests run with tracing enabled is going to rapidly cause ENOSPC problems on test machines, and that's going to cause test harness issues... Hence I don't think that unilaterally turning on tracing is a good idea. I think it should only run if we set a value in the config section for the test run. This allows a user to define two identical test sections except one has "ENABLE_TRACE=true" in it and the other doesn't. Hence they can run: # check -s xfs -g auto to get a normal, non-traced run done. Then, for all the failures reported, run: # check -s xfs_trace <trace specification> <failed tests> and get those tests run with tracing enabled instead of running # trace-cmd record <trace specification> check -s xfs <failed tests> Finally, I also don't want fstests perturbing whatever tracing I'm doing externally to fstests, so being having it enable tracing only when I want it to enable tracing is somewhat important... > +# NOTE: to dump ftrace buffer one needs to enable ftrace > +# events or add custom trace_printk() into the fs code. > +# And since fstest will clear buffer before running one > +# test case, existing trace-cmd can be interrupted. trace_printk is only a small part of the tracing I use with trace-cmd. If we can't configure trace event output through this interface, then it's really not a replacement for using trace-cmd... Cheers, Dave.
On 2021/6/4 上午10:35, Dave Chinner wrote: > On Thu, Jun 03, 2021 at 02:21:13PM +0800, Qu Wenruo wrote: >> Sometimes developers want trace dump for certain test cases. >> >> Normally I just add "trace-cmd" calls in "check", but it would be much >> better to let fstests to support ftrace dumping. >> >> This patchset will add basic ftrace dumping support by: >> >> - Clear all buffers before running each test >> - Start tracing before running each test >> - End tracing after test finished >> - Copy the trace to "$seqres.trace" if needed >> The condition is either: >> * $KEEP_TRACE environment is set to "yes" >> * The test case failed >> >> Currently we only support the main ftrace buffer, but all supporting >> functions have support for ftrace instances, for later expansion. >> >> Signed-off-by: Qu Wenruo <wqu@suse.com> >> --- >> Changelog: >> v2: >> - Add explanation in "common/config" for how to use it >> - Make variables local >> - Don't create the instance when clearing buffers >> --- >> check | 12 +++++++- >> common/config | 8 +++++ >> common/ftrace | 83 +++++++++++++++++++++++++++++++++++++++++++++++++++ >> common/rc | 1 + >> 4 files changed, 103 insertions(+), 1 deletion(-) >> create mode 100644 common/ftrace >> >> diff --git a/check b/check >> index ba192042..0a09dcf9 100755 >> --- a/check >> +++ b/check >> @@ -801,7 +801,7 @@ function run_section() >> fi >> >> # really going to try and run this one >> - rm -f $seqres.out.bad >> + rm -f $seqres.out.bad $seqres.trace >> >> # check if we really should run it >> _expunge_test $seqnum >> @@ -839,6 +839,10 @@ function run_section() >> # to be reported for each test >> (echo 1 > $DEBUGFS_MNT/clear_warn_once) > /dev/null 2>&1 >> >> + # Clear previous trace and start new trace >> + _clear_trace_buffers >> + _start_trace > > So how does one enable all 500+ xfs tracepoints for this? Or just > some subset? i.e. how do we pass it a list of events like we do > trace-cmd? IOWs, for this to be actually useful as a replacement > for trace-cmd, it has to be able to replace invocations like this: > > # trace-cmd record -e xfs_i*lock* -e xfs_buf* -e printk -e iomap* .... That's not a big problem, you can do the same thing just using tracefs interface, without invovling trace-cmd at all. For your above case, you can do the same thing without trace_cmd at all: # cat ${tracefs}/available_events | grep xfs_i*lock >> \ ${tracefs}/set_event # cat ${tracefs}/available_events | grep xfs_buf* >> \ ${tracefs}/set_event # cat ${tracefs}/available_events | grep iomap* >> \ ${tracefs}/set_event # cat ${tracefs}/available_events | grep printk >> \ ${tracefs}/set_event > > which is how I use trace-cmd 99.9% of the time I'm debugging fstests > using tracepoints. I don't bevelive above commands can be hard to use, although it's indeed a little complex than trace-cmd. > > Next: some tests will generate gigabytes of trace data on XFS. I'm > not joking here That's exactly why I use custom trace_printk() to filter out certain events, and only print what I care. > - I regularly am looking for single traces in an > output file that contains tens of millions of events in it. Having > fstests run with tracing enabled is going to rapidly cause ENOSPC > problems on test machines, and that's going to cause test harness > issues... > > Hence I don't think that unilaterally turning on tracing is a good > idea. I think it should only run if we set a value in the config > section for the test run. This allows a user to define two identical > test sections except one has "ENABLE_TRACE=true" in it and the other > doesn't. Hence they can run: > > # check -s xfs -g auto And in the expected use case, trace is only used to test certain failure, not to do a full test run. It would only make things miserably slow and make your storage explode. But we still need to clear/start/end the events for whatever test cases that is going to be executed. > > to get a normal, non-traced run done. Then, for all the failures > reported, run: > > # check -s xfs_trace <trace specification> <failed tests> > > and get those tests run with tracing enabled instead of running > > # trace-cmd record <trace specification> check -s xfs <failed tests> > > Finally, I also don't want fstests perturbing whatever tracing I'm > doing externally to fstests, so being having it enable tracing only > when I want it to enable tracing is somewhat important... > >> +# NOTE: to dump ftrace buffer one needs to enable ftrace >> +# events or add custom trace_printk() into the fs code. >> +# And since fstest will clear buffer before running one >> +# test case, existing trace-cmd can be interrupted. > > trace_printk is only a small part of the tracing I use with > trace-cmd. If we can't configure trace event output through this > interface, then it's really not a replacement for using trace-cmd... I mean, if you can use trace-cmd, I see now reason you can't pack your trace events into a small script to enable it before running the tests. Or is trace-cmd really making us forget how to manually setup ftrace evetnts? Thanks, Qu > > Cheers, > > Dave. >
On Fri, Jun 04, 2021 at 10:45:52AM +0800, Qu Wenruo wrote: > > > On 2021/6/4 上午10:35, Dave Chinner wrote: > > On Thu, Jun 03, 2021 at 02:21:13PM +0800, Qu Wenruo wrote: > > > Sometimes developers want trace dump for certain test cases. > > > > > > Normally I just add "trace-cmd" calls in "check", but it would be much > > > better to let fstests to support ftrace dumping. > > > > > > This patchset will add basic ftrace dumping support by: > > > > > > - Clear all buffers before running each test > > > - Start tracing before running each test > > > - End tracing after test finished > > > - Copy the trace to "$seqres.trace" if needed > > > The condition is either: > > > * $KEEP_TRACE environment is set to "yes" > > > * The test case failed > > > > > > Currently we only support the main ftrace buffer, but all supporting > > > functions have support for ftrace instances, for later expansion. > > > > > > Signed-off-by: Qu Wenruo <wqu@suse.com> > > > --- > > > Changelog: > > > v2: > > > - Add explanation in "common/config" for how to use it > > > - Make variables local > > > - Don't create the instance when clearing buffers > > > --- > > > check | 12 +++++++- > > > common/config | 8 +++++ > > > common/ftrace | 83 +++++++++++++++++++++++++++++++++++++++++++++++++++ > > > common/rc | 1 + > > > 4 files changed, 103 insertions(+), 1 deletion(-) > > > create mode 100644 common/ftrace > > > > > > diff --git a/check b/check > > > index ba192042..0a09dcf9 100755 > > > --- a/check > > > +++ b/check > > > @@ -801,7 +801,7 @@ function run_section() > > > fi > > > # really going to try and run this one > > > - rm -f $seqres.out.bad > > > + rm -f $seqres.out.bad $seqres.trace > > > # check if we really should run it > > > _expunge_test $seqnum > > > @@ -839,6 +839,10 @@ function run_section() > > > # to be reported for each test > > > (echo 1 > $DEBUGFS_MNT/clear_warn_once) > /dev/null 2>&1 > > > + # Clear previous trace and start new trace > > > + _clear_trace_buffers > > > + _start_trace > > > > So how does one enable all 500+ xfs tracepoints for this? Or just > > some subset? i.e. how do we pass it a list of events like we do > > trace-cmd? IOWs, for this to be actually useful as a replacement > > for trace-cmd, it has to be able to replace invocations like this: > > > > # trace-cmd record -e xfs_i*lock* -e xfs_buf* -e printk -e iomap* .... > > That's not a big problem, you can do the same thing just using tracefs > interface, without invovling trace-cmd at all. > > For your above case, you can do the same thing without trace_cmd at all: > > # cat ${tracefs}/available_events | grep xfs_i*lock >> \ > ${tracefs}/set_event > # cat ${tracefs}/available_events | grep xfs_buf* >> \ > ${tracefs}/set_event > # cat ${tracefs}/available_events | grep iomap* >> \ > ${tracefs}/set_event > # cat ${tracefs}/available_events | grep printk >> \ > ${tracefs}/set_event This is **much** more work than a single trace-cmd. Tools like trace-cmd exist to simplify configuring complex functionality. You can stubbornly insist that manually fiddling around in tracefs is the end all solution for you, but you don't get to break the entire community's ability to use cli wrappers. Dave and I are /not/ going to retool our entire workflows just so you can break trace-cmd (and any other tools that use ftrace/perf monitoring) while offering nothing even close to being a replacement. I do not consent to disrupting well-established tracing tools. You rejected my earlier suggestion, so NAK. --D > > > > > which is how I use trace-cmd 99.9% of the time I'm debugging fstests > > using tracepoints. > > I don't bevelive above commands can be hard to use, although it's indeed a > little complex than trace-cmd. > > > > > Next: some tests will generate gigabytes of trace data on XFS. I'm > > not joking here > > That's exactly why I use custom trace_printk() to filter out certain events, > and only print what I care. > > > - I regularly am looking for single traces in an > > output file that contains tens of millions of events in it. Having > > fstests run with tracing enabled is going to rapidly cause ENOSPC > > problems on test machines, and that's going to cause test harness > > issues... > > > > Hence I don't think that unilaterally turning on tracing is a good > > idea. I think it should only run if we set a value in the config > > section for the test run. This allows a user to define two identical > > test sections except one has "ENABLE_TRACE=true" in it and the other > > doesn't. Hence they can run: > > > > # check -s xfs -g auto > > And in the expected use case, trace is only used to test certain failure, > not to do a full test run. > It would only make things miserably slow and make your storage explode. > > But we still need to clear/start/end the events for whatever test cases that > is going to be executed. > > > > > to get a normal, non-traced run done. Then, for all the failures > > reported, run: > > > > # check -s xfs_trace <trace specification> <failed tests> > > > > and get those tests run with tracing enabled instead of running > > > > # trace-cmd record <trace specification> check -s xfs <failed tests> > > > > Finally, I also don't want fstests perturbing whatever tracing I'm > > doing externally to fstests, so being having it enable tracing only > > when I want it to enable tracing is somewhat important... > > > > > +# NOTE: to dump ftrace buffer one needs to enable ftrace > > > +# events or add custom trace_printk() into the fs code. > > > +# And since fstest will clear buffer before running one > > > +# test case, existing trace-cmd can be interrupted. > > > > trace_printk is only a small part of the tracing I use with > > trace-cmd. If we can't configure trace event output through this > > interface, then it's really not a replacement for using trace-cmd... > > I mean, if you can use trace-cmd, I see now reason you can't pack your trace > events into a small script to enable it before running the tests. > > Or is trace-cmd really making us forget how to manually setup ftrace > evetnts? > > Thanks, > Qu > > > > > Cheers, > > > > Dave. > > >
On Fri, Jun 04, 2021 at 10:45:52AM +0800, Qu Wenruo wrote: > > So how does one enable all 500+ xfs tracepoints for this? Or just > > some subset? i.e. how do we pass it a list of events like we do > > trace-cmd? IOWs, for this to be actually useful as a replacement > > for trace-cmd, it has to be able to replace invocations like this: > > > > # trace-cmd record -e xfs_i*lock* -e xfs_buf* -e printk -e iomap* .... > > That's not a big problem, you can do the same thing just using tracefs > interface, without invovling trace-cmd at all. > > For your above case, you can do the same thing without trace_cmd at all: > > # cat ${tracefs}/available_events | grep xfs_i*lock >> \ > ${tracefs}/set_event > # cat ${tracefs}/available_events | grep xfs_buf* >> \ > ${tracefs}/set_event > # cat ${tracefs}/available_events | grep iomap* >> \ > ${tracefs}/set_event > # cat ${tracefs}/available_events | grep printk >> \ > ${tracefs}/set_event .... You forgot that now I have to turn all the events off again manually. And if the script crashes and doesn't clean up, then I've got to do that manually. Talk about going back to the dark ages.... > I mean, if you can use trace-cmd, I see now reason you can't pack your trace > events into a small script to enable it before running the tests. The whole point of using tools like perf and trace-cmd is so we don't need to know how the underlying mechanisms work, and we don't have to relearn this crap every time the developers decide they are going to change how it works. > Or is trace-cmd really making us forget how to manually setup ftrace > evetnts? You have got to be joking, right? The whole point of trace-cmd and perf existing is so that nobody except the developers of those tools need to know how the complex, obscure, whacky low level kernel interfaces work. Nor do people have to keep up with how they change from kernel to kernel, because the tools abstract all this bullshit away from the user. I forgot about that interface when trace-cmd was first written (2009, IIRC). IOWs, I haven't used the low level tracing interfaces at all for over a decade because it's an utter PITA to use. Can you imaging saying to another developer "we don't need a mkfs command because I can write the structures direct to the block device myself!". It doesn't make much sense, does it? Yet that's pretty much exactly what you are saying here.... So, no, I don't think poking at low level tracing interfaces inside fstests is a good idea, especially as it also requires wrapping fstests in more scripts to control it. Just use trace-cmd to control trace recording like everyone else already does. Cheers, Dave.
diff --git a/check b/check index ba192042..0a09dcf9 100755 --- a/check +++ b/check @@ -801,7 +801,7 @@ function run_section() fi # really going to try and run this one - rm -f $seqres.out.bad + rm -f $seqres.out.bad $seqres.trace # check if we really should run it _expunge_test $seqnum @@ -839,6 +839,10 @@ function run_section() # to be reported for each test (echo 1 > $DEBUGFS_MNT/clear_warn_once) > /dev/null 2>&1 + # Clear previous trace and start new trace + _clear_trace_buffers + _start_trace + if [ "$DUMP_OUTPUT" = true ]; then _run_seq 2>&1 | tee $tmp.out # Because $? would get tee's return code @@ -848,6 +852,11 @@ function run_section() sts=$? fi + _end_trace + if [ "$KEEP_TRACE" == "yes" ]; then + _copy_trace "$seqres.trace" + fi + if [ -f core ]; then _dump_err_cont "[dumped core]" mv core $RESULT_BASE/$seqnum.core @@ -932,6 +941,7 @@ function run_section() # make sure we record the status of the last test we ran. if $err ; then + _copy_trace "$seqres.trace" bad="$bad $seqnum" n_bad=`expr $n_bad + 1` tc_status="fail" diff --git a/common/config b/common/config index ad1c9eb0..4dec2bfa 100644 --- a/common/config +++ b/common/config @@ -25,6 +25,14 @@ # KEEP_DMESG - whether to keep all dmesg for each test case. # yes: keep all dmesg # no: only keep dmesg with error/warning (default) +# KEEP_TRACE - whether to keep all non-empty ftrace buffer for each test case. +# yes: keep all non-empty ftrace buffer +# no: only keep non-empty ftrace buffer when the test fails (default) +# +# NOTE: to dump ftrace buffer one needs to enable ftrace +# events or add custom trace_printk() into the fs code. +# And since fstest will clear buffer before running one +# test case, existing trace-cmd can be interrupted. # # - These can be added to $HOST_CONFIG_DIR (witch default to ./config) # below or a separate local configuration file can be used (using diff --git a/common/ftrace b/common/ftrace new file mode 100644 index 00000000..9eec0f53 --- /dev/null +++ b/common/ftrace @@ -0,0 +1,83 @@ +# SPDX-License-Identifier: GPL-2.0 +# +# Common ftrace related helpers +# + +TRACE_DIR="/sys/kernel/debug/tracing" + +_clear_trace_buffers() +{ + if [ ! -d "${TRACE_DIR}" ]; then + return + fi + + # Clear the main buffer + echo 0 > "${TRACE_DIR}/trace" + + # Clear each instance buffer + for i in $(ls "${TRACE_DIR}/instances"); do + echo 0 > "${i}/trace" + done +} + +_start_trace() +{ + local instance=$1 + + if [ ! -d "${TRACE_DIR}" ]; then + return + fi + + if [ -z "${instance}" ]; then + echo 1 > "${TRACE_DIR}/tracing_on" + else + mkdir -p "${TRACE_DIR}/instances/${instance}" + echo 1 > "${TRACE_DIR}/instances/${instance}/tracing_on" + fi +} + +_end_trace() +{ + local instance=$1 + + if [ ! -d "${TRACE_DIR}" ]; then + return + fi + + if [ -z "${instance}" ]; then + echo 0 > "${TRACE_DIR}/tracing_on" + elif [ -d "${TRACE_DIR}/instances/${instance}" ]; then + echo 0 > "${TRACE_DIR}/instances/${instance}/tracing_on" + fi +} + +_remove_empty_trace() +{ + local file="$1" + + if [ ! -f "$file" ]; then + return + fi + + if [ -z "$(head -n 15 $file | sed '/^#/d')" ]; then + rm $file + fi +} + +_copy_trace() +{ + local dest="$1" + local instance="$2" + + if [ ! -d "${TRACE_DIR}" ]; then + return + fi + + if [ -z "${instance}" ]; then + cp "${TRACE_DIR}/trace" "$dest" + elif [ -d "${TRACE_DIR}/instances/${instance}" ]; then + cp "${TRACE_DIR}/instances/${instance}/trace" "$dest" + fi + + _remove_empty_trace "$dest" +} diff --git a/common/rc b/common/rc index a0aa7300..d828dca8 100644 --- a/common/rc +++ b/common/rc @@ -3,6 +3,7 @@ # Copyright (c) 2000-2006 Silicon Graphics, Inc. All Rights Reserved. . common/config +. common/ftrace BC=$(which bc 2> /dev/null) || BC=
Sometimes developers want trace dump for certain test cases. Normally I just add "trace-cmd" calls in "check", but it would be much better to let fstests to support ftrace dumping. This patchset will add basic ftrace dumping support by: - Clear all buffers before running each test - Start tracing before running each test - End tracing after test finished - Copy the trace to "$seqres.trace" if needed The condition is either: * $KEEP_TRACE environment is set to "yes" * The test case failed Currently we only support the main ftrace buffer, but all supporting functions have support for ftrace instances, for later expansion. Signed-off-by: Qu Wenruo <wqu@suse.com> --- Changelog: v2: - Add explanation in "common/config" for how to use it - Make variables local - Don't create the instance when clearing buffers --- check | 12 +++++++- common/config | 8 +++++ common/ftrace | 83 +++++++++++++++++++++++++++++++++++++++++++++++++++ common/rc | 1 + 4 files changed, 103 insertions(+), 1 deletion(-) create mode 100644 common/ftrace