[PATCH v2] tracing/selftests: Add test to test max subbuf size with trace_marker

[PATCH v2] tracing/selftests: Add test to test max subbuf size with trace_marker

[Steven Rostedt]

From: "Steven Rostedt (Google)" <rostedt@goodmis.org>

Now that the trace_marker can write up to the max size of the sub buffer.
Add a test to see if it actually can happen.

The README is updated to state that the trace_marker writes can be broken
up, and the test checks the README for that statement so that it does not
fail on older kernels that does not support this.

If the README does not have the specified update, the test will still test
if all the string is written, as that should work with older kernels.

Cc: Shuah Khan <shuah@kernel.org>
Cc: linux-kselftest@vger.kernel.org
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
Changes since v1: https://lore.kernel.org/linux-trace-kernel/20231212135441.0337c3e9@gandalf.local.home/

- Fix description as it was a cut and paste from the subbuffer size tests
  that are not added yet.

 kernel/trace/trace.c                          |   1 +
 .../ftrace/test.d/00basic/trace_marker.tc     | 112 ++++++++++++++++++
 2 files changed, 113 insertions(+)
 create mode 100755 tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 2f8d59834c00..cbfcdd882590 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -5595,6 +5595,7 @@ static const char readme_msg[] =
 	"       delta:   Delta difference against a buffer-wide timestamp\n"
 	"    absolute:   Absolute (standalone) timestamp\n"
 	"\n  trace_marker\t\t- Writes into this file writes into the kernel buffer\n"
+	"\n           May be broken into multiple events based on sub-buffer size.\n"
 	"\n  trace_marker_raw\t\t- Writes into this file writes binary data into the kernel buffer\n"
 	"  tracing_cpumask\t- Limit which CPUs to trace\n"
 	"  instances\t\t- Make sub-buffers with: mkdir instances/foo\n"
diff --git a/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc b/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
new file mode 100755
index 000000000000..bf7f6f50c88a
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
@@ -0,0 +1,112 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: Basic tests on writing to trace_marker
+# requires: trace_marker
+# flags: instance
+
+get_buffer_data_size() {
+	sed -ne 's/^.*data.*size:\([0-9][0-9]*\).*/\1/p' events/header_page
+}
+
+get_buffer_data_offset() {
+	sed -ne 's/^.*data.*offset:\([0-9][0-9]*\).*/\1/p' events/header_page
+}
+
+get_event_header_size() {
+	type_len=`sed -ne 's/^.*type_len.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
+	time_len=`sed -ne 's/^.*time_delta.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
+	array_len=`sed -ne 's/^.*array.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
+	total_bits=$((type_len+time_len+array_len))
+	total_bits=$((total_bits+7))
+	echo $((total_bits/8))
+}
+
+get_print_event_buf_offset() {
+	sed -ne 's/^.*buf.*offset:\([0-9][0-9]*\).*/\1/p' events/ftrace/print/format
+}
+
+event_header_size=`get_event_header_size`
+print_header_size=`get_print_event_buf_offset`
+
+# Find the README
+README=""
+if [ -f README ]; then
+	README="README"
+# instance?
+elif [ -f ../../README ]; then
+	README="../../README"
+fi
+
+testone=0
+if [ ! -z "$README" ]; then
+	if grep -q  "May be broken into multiple events based on sub-buffer size" $README; then
+		testone=1
+	fi
+fi
+
+data_offset=`get_buffer_data_offset`
+
+marker_meta=$((event_header_size+print_header_size))
+
+make_str() {
+        cnt=$1
+	# subtract two for \n\0 as marker adds these
+	cnt=$((cnt-2))
+	printf -- 'X%.0s' $(seq $cnt)
+}
+
+write_buffer() {
+	size=$1
+
+	str=`make_str $size`
+
+	# clear the buffer
+	echo > trace
+
+	# write the string into the marker
+	echo -n $str > trace_marker
+
+	echo $str
+}
+
+test_buffer() {
+
+	size=`get_buffer_data_size`
+	oneline_size=$((size-marker_meta))
+	echo size = $size
+	echo meta size = $marker_meta
+
+	if [ $testone -eq 1 ]; then
+		echo oneline size = $oneline_size
+
+		str=`write_buffer $oneline_size`
+
+		# Should be in one single event
+		new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: */,"");printf "%s", $0; exit}' trace`
+
+		if [ "$new_str" != "$str" ]; then
+			exit fail;
+		fi
+	fi
+
+	# Now add a little more the meta data overhead will overflow
+
+	str=`write_buffer $size`
+
+	# Make sure the line was broken
+	new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: /,"");printf "%s", $0; exit}' trace`
+
+	if [ "$new_str" = "$str" ]; then
+		exit fail;
+	fi
+
+	# Make sure the entire line can be found
+	new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: */,"");printf "%s", $0; }' trace`
+
+	if [ "$new_str" != "$str" ]; then
+		exit fail;
+	fi
+}
+
+test_buffer
+
-- 
2.42.0

Re: [PATCH v2] tracing/selftests: Add test to test max subbuf size with trace_marker

[Masami Hiramatsu]

On Tue, 12 Dec 2023 15:16:32 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> 
> Now that the trace_marker can write up to the max size of the sub buffer.
> Add a test to see if it actually can happen.
> 
> The README is updated to state that the trace_marker writes can be broken
> up, and the test checks the README for that statement so that it does not
> fail on older kernels that does not support this.

I think it is better that the feature patch include README update or a separate
patch because it identifies the feature is implemented or not.

> 
> If the README does not have the specified update, the test will still test
> if all the string is written, as that should work with older kernels.
> 
> Cc: Shuah Khan <shuah@kernel.org>
> Cc: linux-kselftest@vger.kernel.org
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> ---
> Changes since v1: https://lore.kernel.org/linux-trace-kernel/20231212135441.0337c3e9@gandalf.local.home/
> 
> - Fix description as it was a cut and paste from the subbuffer size tests
>   that are not added yet.
> 
>  kernel/trace/trace.c                          |   1 +
>  .../ftrace/test.d/00basic/trace_marker.tc     | 112 ++++++++++++++++++
>  2 files changed, 113 insertions(+)
>  create mode 100755 tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 2f8d59834c00..cbfcdd882590 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -5595,6 +5595,7 @@ static const char readme_msg[] =
>  	"       delta:   Delta difference against a buffer-wide timestamp\n"
>  	"    absolute:   Absolute (standalone) timestamp\n"
>  	"\n  trace_marker\t\t- Writes into this file writes into the kernel buffer\n"
> +	"\n           May be broken into multiple events based on sub-buffer size.\n"
>  	"\n  trace_marker_raw\t\t- Writes into this file writes binary data into the kernel buffer\n"
>  	"  tracing_cpumask\t- Limit which CPUs to trace\n"
>  	"  instances\t\t- Make sub-buffers with: mkdir instances/foo\n"
> diff --git a/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc b/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
> new file mode 100755
> index 000000000000..bf7f6f50c88a
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
> @@ -0,0 +1,112 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: Basic tests on writing to trace_marker
> +# requires: trace_marker
> +# flags: instance
> +
> +get_buffer_data_size() {
> +	sed -ne 's/^.*data.*size:\([0-9][0-9]*\).*/\1/p' events/header_page
> +}
> +
> +get_buffer_data_offset() {
> +	sed -ne 's/^.*data.*offset:\([0-9][0-9]*\).*/\1/p' events/header_page
> +}
> +
> +get_event_header_size() {
> +	type_len=`sed -ne 's/^.*type_len.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
> +	time_len=`sed -ne 's/^.*time_delta.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
> +	array_len=`sed -ne 's/^.*array.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
> +	total_bits=$((type_len+time_len+array_len))
> +	total_bits=$((total_bits+7))
> +	echo $((total_bits/8))
> +}
> +
> +get_print_event_buf_offset() {
> +	sed -ne 's/^.*buf.*offset:\([0-9][0-9]*\).*/\1/p' events/ftrace/print/format
> +}
> +
> +event_header_size=`get_event_header_size`
> +print_header_size=`get_print_event_buf_offset`
> +
> +# Find the README
> +README=""
> +if [ -f README ]; then
> +	README="README"
> +# instance?
> +elif [ -f ../../README ]; then
> +	README="../../README"
> +fi
> +
> +testone=0
> +if [ ! -z "$README" ]; then
> +	if grep -q  "May be broken into multiple events based on sub-buffer size" $README; then
> +		testone=1
> +	fi
> +fi

Hmm, this should be a common function if we see this pattern somewhere else.

> +
> +data_offset=`get_buffer_data_offset`
> +
> +marker_meta=$((event_header_size+print_header_size))
> +
> +make_str() {
> +        cnt=$1
> +	# subtract two for \n\0 as marker adds these
> +	cnt=$((cnt-2))
> +	printf -- 'X%.0s' $(seq $cnt)
> +}
> +
> +write_buffer() {
> +	size=$1
> +
> +	str=`make_str $size`
> +
> +	# clear the buffer
> +	echo > trace
> +
> +	# write the string into the marker
> +	echo -n $str > trace_marker
> +
> +	echo $str
> +}
> +
> +test_buffer() {
> +
> +	size=`get_buffer_data_size`
> +	oneline_size=$((size-marker_meta))
> +	echo size = $size
> +	echo meta size = $marker_meta
> +
> +	if [ $testone -eq 1 ]; then
> +		echo oneline size = $oneline_size
> +
> +		str=`write_buffer $oneline_size`
> +
> +		# Should be in one single event
> +		new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: */,"");printf "%s", $0; exit}' trace`
> +
> +		if [ "$new_str" != "$str" ]; then
> +			exit fail;
> +		fi
> +	fi

Or, maybe we can split this part into another testcase.

Thank you,

> +
> +	# Now add a little more the meta data overhead will overflow
> +
> +	str=`write_buffer $size`
> +
> +	# Make sure the line was broken
> +	new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: /,"");printf "%s", $0; exit}' trace`
> +
> +	if [ "$new_str" = "$str" ]; then
> +		exit fail;
> +	fi
> +
> +	# Make sure the entire line can be found
> +	new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: */,"");printf "%s", $0; }' trace`
> +
> +	if [ "$new_str" != "$str" ]; then
> +		exit fail;
> +	fi
> +}
> +
> +test_buffer
> +
> -- 
> 2.42.0
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH v2] tracing/selftests: Add test to test max subbuf size with trace_marker

[Steven Rostedt]

On Wed, 13 Dec 2023 09:33:18 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> On Tue, 12 Dec 2023 15:16:32 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> > 
> > Now that the trace_marker can write up to the max size of the sub buffer.
> > Add a test to see if it actually can happen.
> > 
> > The README is updated to state that the trace_marker writes can be broken
> > up, and the test checks the README for that statement so that it does not
> > fail on older kernels that does not support this.  
> 
> I think it is better that the feature patch include README update or a separate
> patch because it identifies the feature is implemented or not.
> 

No need, my v3 removes all this as I found it will not work with the sub
buffer resize update.

> > 
> > If the README does not have the specified update, the test will still test
> > if all the string is written, as that should work with older kernels.
> > 
> > Cc: Shuah Khan <shuah@kernel.org>
> > Cc: linux-kselftest@vger.kernel.org
> > Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> > ---
> > Changes since v1: https://lore.kernel.org/linux-trace-kernel/20231212135441.0337c3e9@gandalf.local.home/
> > 
> > - Fix description as it was a cut and paste from the subbuffer size tests
> >   that are not added yet.
> > 
> >  kernel/trace/trace.c                          |   1 +
> >  .../ftrace/test.d/00basic/trace_marker.tc     | 112 ++++++++++++++++++
> >  2 files changed, 113 insertions(+)
> >  create mode 100755 tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
> > 
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index 2f8d59834c00..cbfcdd882590 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -5595,6 +5595,7 @@ static const char readme_msg[] =
> >  	"       delta:   Delta difference against a buffer-wide timestamp\n"
> >  	"    absolute:   Absolute (standalone) timestamp\n"
> >  	"\n  trace_marker\t\t- Writes into this file writes into the kernel buffer\n"
> > +	"\n           May be broken into multiple events based on sub-buffer size.\n"
> >  	"\n  trace_marker_raw\t\t- Writes into this file writes binary data into the kernel buffer\n"
> >  	"  tracing_cpumask\t- Limit which CPUs to trace\n"
> >  	"  instances\t\t- Make sub-buffers with: mkdir instances/foo\n"
> > diff --git a/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc b/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
> > new file mode 100755
> > index 000000000000..bf7f6f50c88a
> > --- /dev/null
> > +++ b/tools/testing/selftests/ftrace/test.d/00basic/trace_marker.tc
> > @@ -0,0 +1,112 @@
> > +#!/bin/sh
> > +# SPDX-License-Identifier: GPL-2.0
> > +# description: Basic tests on writing to trace_marker
> > +# requires: trace_marker
> > +# flags: instance
> > +
> > +get_buffer_data_size() {
> > +	sed -ne 's/^.*data.*size:\([0-9][0-9]*\).*/\1/p' events/header_page
> > +}
> > +
> > +get_buffer_data_offset() {
> > +	sed -ne 's/^.*data.*offset:\([0-9][0-9]*\).*/\1/p' events/header_page
> > +}
> > +
> > +get_event_header_size() {
> > +	type_len=`sed -ne 's/^.*type_len.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
> > +	time_len=`sed -ne 's/^.*time_delta.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
> > +	array_len=`sed -ne 's/^.*array.*:[^0-9]*\([0-9][0-9]*\).*/\1/p' events/header_event`
> > +	total_bits=$((type_len+time_len+array_len))
> > +	total_bits=$((total_bits+7))
> > +	echo $((total_bits/8))
> > +}
> > +
> > +get_print_event_buf_offset() {
> > +	sed -ne 's/^.*buf.*offset:\([0-9][0-9]*\).*/\1/p' events/ftrace/print/format
> > +}
> > +
> > +event_header_size=`get_event_header_size`
> > +print_header_size=`get_print_event_buf_offset`
> > +
> > +# Find the README
> > +README=""
> > +if [ -f README ]; then
> > +	README="README"
> > +# instance?
> > +elif [ -f ../../README ]; then
> > +	README="../../README"
> > +fi
> > +
> > +testone=0
> > +if [ ! -z "$README" ]; then
> > +	if grep -q  "May be broken into multiple events based on sub-buffer size" $README; then
> > +		testone=1
> > +	fi
> > +fi  
> 
> Hmm, this should be a common function if we see this pattern somewhere else.

I remove this in the next version. But yeah, there's a bug in the selftests
that if a test has an instance flag set, then the requirements will not
check the README, as the instance has no README.

> 
> > +
> > +data_offset=`get_buffer_data_offset`
> > +
> > +marker_meta=$((event_header_size+print_header_size))
> > +
> > +make_str() {
> > +        cnt=$1
> > +	# subtract two for \n\0 as marker adds these
> > +	cnt=$((cnt-2))
> > +	printf -- 'X%.0s' $(seq $cnt)
> > +}
> > +
> > +write_buffer() {
> > +	size=$1
> > +
> > +	str=`make_str $size`
> > +
> > +	# clear the buffer
> > +	echo > trace
> > +
> > +	# write the string into the marker
> > +	echo -n $str > trace_marker
> > +
> > +	echo $str
> > +}
> > +
> > +test_buffer() {
> > +
> > +	size=`get_buffer_data_size`
> > +	oneline_size=$((size-marker_meta))
> > +	echo size = $size
> > +	echo meta size = $marker_meta
> > +
> > +	if [ $testone -eq 1 ]; then
> > +		echo oneline size = $oneline_size
> > +
> > +		str=`write_buffer $oneline_size`
> > +
> > +		# Should be in one single event
> > +		new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: */,"");printf "%s", $0; exit}' trace`
> > +
> > +		if [ "$new_str" != "$str" ]; then
> > +			exit fail;
> > +		fi
> > +	fi  
> 
> Or, maybe we can split this part into another testcase.

I removed this anyway. But it may come back in the future if we can get
dynamically sized trace_seq working.

-- Steve


> 
> > +
> > +	# Now add a little more the meta data overhead will overflow
> > +
> > +	str=`write_buffer $size`
> > +
> > +	# Make sure the line was broken
> > +	new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: /,"");printf "%s", $0; exit}' trace`
> > +
> > +	if [ "$new_str" = "$str" ]; then
> > +		exit fail;
> > +	fi
> > +
> > +	# Make sure the entire line can be found
> > +	new_str=`awk ' /tracing_mark_write:/ { sub(/^.*tracing_mark_write: */,"");printf "%s", $0; }' trace`
> > +
> > +	if [ "$new_str" != "$str" ]; then
> > +		exit fail;
> > +	fi
> > +}
> > +
> > +test_buffer
> > +
> > -- 
> > 2.42.0
> >   
> 
>