Re: [PATCH v2] fstests: add basic ftrace support

[Dave Chinner <david@fromorbit.com>]

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.
-- 
Dave Chinner
david@fromorbit.com