[PATCH v3 0/5] Add "func_no_repete" tracing option

[PATCH v3 0/5] Add "func_no_repete" tracing option

[Yordan Karadzhov (VMware)]

The new option for function tracing aims to save space on the ring
buffer and to make it more readable in the case when a single function
is called number of times consecutively:

	while (cond)
		do_func();

Instead of having an identical records for each call of the function
we will record only the first call, followed by an event showing the
number of repeats.

v3 changes:
  * FUNC_REPEATS_SET_DELTA_TS macro has been optimised.

  * Fixed bug in func_set_flag(): In the previous version the value
    of the "new_flags" variable was not properly calculated because
    I misinterpreted the meaning of the "bit" argument of the function.
    This bug in v2 had no real effect, because for the moment we have
    only two "function options" so the value of "new_flags" was correct,
    although its way of calculating was wrong.

v2 changes:
  * As suggested by Steven in his review, we now record not only the
    repetition count, but also the time elapsed between the last
    repetition of the function and the actual generation of the
    "func_repeats" event. 16 bits are used to record the repetition
    count. In the case of an overflow of the counter a second pair of
    "function" and "func_repeats" events will be generated. The time
    interval gets codded by using up to 48 (32 + 16) bits.


Yordan Karadzhov (VMware) (5):
  tracing: Define new ftrace event "func_repeats"
  tracing: Add "last_func_repeats" to struct trace_array
  tracing: Add method for recording "func_repeats" events
  tracing: Unify the logic for function tracing options
  tracing: Add "func_no_repeats" option for function tracing

 kernel/trace/trace.c           |  27 ++++
 kernel/trace/trace.h           |  25 ++++
 kernel/trace/trace_entries.h   |  28 +++++
 kernel/trace/trace_functions.c | 222 ++++++++++++++++++++++++++++-----
 kernel/trace/trace_output.c    |  47 +++++++
 5 files changed, 321 insertions(+), 28 deletions(-)

-- 
2.25.1

[PATCH v3 1/5] tracing: Define new ftrace event "func_repeats"

[Yordan Karadzhov (VMware)]

The event aims to consolidate the function tracing record in the cases
when a single function is called number of times consecutively.

	while (cond)
		do_func();

This may happen in various scenarios (busy waiting for example).
The new ftrace event can be used to show repeated function events with
a single event and save space on the ring buffer

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 kernel/trace/trace.h         |  3 +++
 kernel/trace/trace_entries.h | 22 +++++++++++++++++
 kernel/trace/trace_output.c  | 47 ++++++++++++++++++++++++++++++++++++
 3 files changed, 72 insertions(+)

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 5506424eae2a..6a5b4c2a0fa7 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -45,6 +45,7 @@ enum trace_type {
 	TRACE_BPUTS,
 	TRACE_HWLAT,
 	TRACE_RAW_DATA,
+	TRACE_FUNC_REPEATS,
 
 	__TRACE_LAST_TYPE,
 };
@@ -442,6 +443,8 @@ extern void __ftrace_bad_type(void);
 			  TRACE_GRAPH_ENT);		\
 		IF_ASSIGN(var, ent, struct ftrace_graph_ret_entry,	\
 			  TRACE_GRAPH_RET);		\
+		IF_ASSIGN(var, ent, struct func_repeats_entry,		\
+			  TRACE_FUNC_REPEATS);				\
 		__ftrace_bad_type();					\
 	} while (0)
 
diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
index 4547ac59da61..fdd022a7aecf 100644
--- a/kernel/trace/trace_entries.h
+++ b/kernel/trace/trace_entries.h
@@ -338,3 +338,25 @@ FTRACE_ENTRY(hwlat, hwlat_entry,
 		 __entry->nmi_total_ts,
 		 __entry->nmi_count)
 );
+
+#define FUNC_REPEATS_GET_DELTA_TS(entry)			\
+(((u64)entry->top_delta_ts << 32) | entry->bottom_delta_ts)	\
+
+FTRACE_ENTRY(func_repeats, func_repeats_entry,
+
+	TRACE_FUNC_REPEATS,
+
+	F_STRUCT(
+		__field(	unsigned long,	ip		)
+		__field(	unsigned long,	parent_ip	)
+		__field(	u16	,	count		)
+		__field(	u16	,	top_delta_ts	)
+		__field(	u32	,	bottom_delta_ts	)
+	),
+
+	F_printk(" %ps <-%ps\t(repeats:%u  delta_ts: -%llu)",
+		 (void *)__entry->ip,
+		 (void *)__entry->parent_ip,
+		 __entry->count,
+		 FUNC_REPEATS_GET_DELTA_TS(__entry))
+);
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index a0146e1fffdf..55b08e146afc 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -1373,6 +1373,52 @@ static struct trace_event trace_raw_data_event = {
 	.funcs		= &trace_raw_data_funcs,
 };
 
+static enum print_line_t
+trace_func_repeats_raw(struct trace_iterator *iter, int flags,
+			 struct trace_event *event)
+{
+	struct func_repeats_entry *field;
+	struct trace_seq *s = &iter->seq;
+
+	trace_assign_type(field, iter->ent);
+
+	trace_seq_printf(s, "%lu %lu %u %llu\n",
+			 field->ip,
+			 field->parent_ip,
+			 field->count,
+			 FUNC_REPEATS_GET_DELTA_TS(field));
+
+	return trace_handle_return(s);
+}
+
+static enum print_line_t
+trace_func_repeats_print(struct trace_iterator *iter, int flags,
+			 struct trace_event *event)
+{
+	struct func_repeats_entry *field;
+	struct trace_seq *s = &iter->seq;
+
+	trace_assign_type(field, iter->ent);
+
+	seq_print_ip_sym(s, field->ip, flags);
+	trace_seq_puts(s, " <-");
+	seq_print_ip_sym(s, field->parent_ip, flags);
+	trace_seq_printf(s, " (repeats: %u, delta_ts: -%llu)\n",
+			 field->count,
+			 FUNC_REPEATS_GET_DELTA_TS(field));
+
+	return trace_handle_return(s);
+}
+
+static struct trace_event_functions trace_func_repeats_funcs = {
+	.trace		= trace_func_repeats_print,
+	.raw		= trace_func_repeats_raw,
+};
+
+static struct trace_event trace_func_repeats_event = {
+	.type	 	= TRACE_FUNC_REPEATS,
+	.funcs		= &trace_func_repeats_funcs,
+};
 
 static struct trace_event *events[] __initdata = {
 	&trace_fn_event,
@@ -1385,6 +1431,7 @@ static struct trace_event *events[] __initdata = {
 	&trace_print_event,
 	&trace_hwlat_event,
 	&trace_raw_data_event,
+	&trace_func_repeats_event,
 	NULL
 };
 
-- 
2.25.1

Re: [PATCH v3 1/5] tracing: Define new ftrace event "func_repeats"

[Steven Rostedt]

On Fri,  9 Apr 2021 21:10:27 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:

> The event aims to consolidate the function tracing record in the cases
> when a single function is called number of times consecutively.
> 
> 	while (cond)
> 		do_func();
> 
> This may happen in various scenarios (busy waiting for example).
> The new ftrace event can be used to show repeated function events with
> a single event and save space on the ring buffer
> 
> Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
> ---
>  kernel/trace/trace.h         |  3 +++
>  kernel/trace/trace_entries.h | 22 +++++++++++++++++
>  kernel/trace/trace_output.c  | 47 ++++++++++++++++++++++++++++++++++++
>  3 files changed, 72 insertions(+)
> 
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 5506424eae2a..6a5b4c2a0fa7 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -45,6 +45,7 @@ enum trace_type {
>  	TRACE_BPUTS,
>  	TRACE_HWLAT,
>  	TRACE_RAW_DATA,
> +	TRACE_FUNC_REPEATS,
>  
>  	__TRACE_LAST_TYPE,
>  };
> @@ -442,6 +443,8 @@ extern void __ftrace_bad_type(void);
>  			  TRACE_GRAPH_ENT);		\
>  		IF_ASSIGN(var, ent, struct ftrace_graph_ret_entry,	\
>  			  TRACE_GRAPH_RET);		\
> +		IF_ASSIGN(var, ent, struct func_repeats_entry,		\
> +			  TRACE_FUNC_REPEATS);				\
>  		__ftrace_bad_type();					\
>  	} while (0)
>  
> diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
> index 4547ac59da61..fdd022a7aecf 100644
> --- a/kernel/trace/trace_entries.h
> +++ b/kernel/trace/trace_entries.h
> @@ -338,3 +338,25 @@ FTRACE_ENTRY(hwlat, hwlat_entry,
>  		 __entry->nmi_total_ts,
>  		 __entry->nmi_count)
>  );
> +
> +#define FUNC_REPEATS_GET_DELTA_TS(entry)			\
> +(((u64)entry->top_delta_ts << 32) | entry->bottom_delta_ts)	\

Have macros have side effects by their parameters, it is always recommended
to wrap them around parenthesis:

#define FUNC_REPEATS_GET_DELTA_TS(entry)			\
	(((u64)(entry)->top_delta_ts << 32) | (entry)->bottom_delta_ts)	\

And have the next line start with at tab after the #define.

I would normally ignore this issue if it was just used in this header file,
because tracing macros are "special", but it's used in actual code as well.

-- Steve


> +
> +FTRACE_ENTRY(func_repeats, func_repeats_entry,
> +
> +	TRACE_FUNC_REPEATS,
> +
> +	F_STRUCT(
> +		__field(	unsigned long,	ip		)
> +		__field(	unsigned long,	parent_ip	)
> +		__field(	u16	,	count		)
> +		__field(	u16	,	top_delta_ts	)
> +		__field(	u32	,	bottom_delta_ts	)
> +	),
> +
> +	F_printk(" %ps <-%ps\t(repeats:%u  delta_ts: -%llu)",
> +		 (void *)__entry->ip,
> +		 (void *)__entry->parent_ip,
> +		 __entry->count,
> +		 FUNC_REPEATS_GET_DELTA_TS(__entry))
> +);
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index a0146e1fffdf..55b08e146afc 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -1373,6 +1373,52 @@ static struct trace_event trace_raw_data_event = {
>  	.funcs		= &trace_raw_data_funcs,
>  };
>  
> +static enum print_line_t
> +trace_func_repeats_raw(struct trace_iterator *iter, int flags,
> +			 struct trace_event *event)
> +{
> +	struct func_repeats_entry *field;
> +	struct trace_seq *s = &iter->seq;
> +
> +	trace_assign_type(field, iter->ent);
> +
> +	trace_seq_printf(s, "%lu %lu %u %llu\n",
> +			 field->ip,
> +			 field->parent_ip,
> +			 field->count,
> +			 FUNC_REPEATS_GET_DELTA_TS(field));
> +
> +	return trace_handle_return(s);
> +}
> +
> +static enum print_line_t
> +trace_func_repeats_print(struct trace_iterator *iter, int flags,
> +			 struct trace_event *event)
> +{
> +	struct func_repeats_entry *field;
> +	struct trace_seq *s = &iter->seq;
> +
> +	trace_assign_type(field, iter->ent);
> +
> +	seq_print_ip_sym(s, field->ip, flags);
> +	trace_seq_puts(s, " <-");
> +	seq_print_ip_sym(s, field->parent_ip, flags);
> +	trace_seq_printf(s, " (repeats: %u, delta_ts: -%llu)\n",
> +			 field->count,
> +			 FUNC_REPEATS_GET_DELTA_TS(field));
> +
> +	return trace_handle_return(s);
> +}
> +
> +static struct trace_event_functions trace_func_repeats_funcs = {
> +	.trace		= trace_func_repeats_print,
> +	.raw		= trace_func_repeats_raw,
> +};
> +
> +static struct trace_event trace_func_repeats_event = {
> +	.type	 	= TRACE_FUNC_REPEATS,
> +	.funcs		= &trace_func_repeats_funcs,
> +};
>  
>  static struct trace_event *events[] __initdata = {
>  	&trace_fn_event,
> @@ -1385,6 +1431,7 @@ static struct trace_event *events[] __initdata = {
>  	&trace_print_event,
>  	&trace_hwlat_event,
>  	&trace_raw_data_event,
> +	&trace_func_repeats_event,
>  	NULL
>  };
>  

Re: [PATCH v3 1/5] tracing: Define new ftrace event "func_repeats"

[Steven Rostedt]

On Fri,  9 Apr 2021 21:10:27 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:

> ---
>  kernel/trace/trace.h         |  3 +++
>  kernel/trace/trace_entries.h | 22 +++++++++++++++++
>  kernel/trace/trace_output.c  | 47 ++++++++++++++++++++++++++++++++++++
>  3 files changed, 72 insertions(+)
> 
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 5506424eae2a..6a5b4c2a0fa7 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -45,6 +45,7 @@ enum trace_type {
>  	TRACE_BPUTS,
>  	TRACE_HWLAT,
>  	TRACE_RAW_DATA,
> +	TRACE_FUNC_REPEATS,
>  
>  	__TRACE_LAST_TYPE,
>  };
> @@ -442,6 +443,8 @@ extern void __ftrace_bad_type(void);
>  			  TRACE_GRAPH_ENT);		\
>  		IF_ASSIGN(var, ent, struct ftrace_graph_ret_entry,	\
>  			  TRACE_GRAPH_RET);		\
> +		IF_ASSIGN(var, ent, struct func_repeats_entry,		\
> +			  TRACE_FUNC_REPEATS);				\
>  		__ftrace_bad_type();					\
>  	} while (0)
>  
> diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
> index 4547ac59da61..fdd022a7aecf 100644
> --- a/kernel/trace/trace_entries.h
> +++ b/kernel/trace/trace_entries.h
> @@ -338,3 +338,25 @@ FTRACE_ENTRY(hwlat, hwlat_entry,
>  		 __entry->nmi_total_ts,
>  		 __entry->nmi_count)
>  );
> +
> +#define FUNC_REPEATS_GET_DELTA_TS(entry)			\
> +(((u64)entry->top_delta_ts << 32) | entry->bottom_delta_ts)	\
> +
> +FTRACE_ENTRY(func_repeats, func_repeats_entry,
> +
> +	TRACE_FUNC_REPEATS,
> +
> +	F_STRUCT(
> +		__field(	unsigned long,	ip		)
> +		__field(	unsigned long,	parent_ip	)
> +		__field(	u16	,	count		)
> +		__field(	u16	,	top_delta_ts	)
> +		__field(	u32	,	bottom_delta_ts	)
> +	),
> +
> +	F_printk(" %ps <-%ps\t(repeats:%u  delta_ts: -%llu)",
> +		 (void *)__entry->ip,
> +		 (void *)__entry->parent_ip,
> +		 __entry->count,
> +		 FUNC_REPEATS_GET_DELTA_TS(__entry))
> +);

Running this with trace-cmd record, this displays:

          <idle>-0     [001]   261.848848: function:                            next_zone
          <idle>-0     [001]   261.848849: func_repeats:          next_zone <-need_update       (repeats:3  delta_ts: -189)

Which is confusing in a number of ways.

1. It would be better to have it be the actual timestamp of the last repeat.
   But that can be done in a trace-cmd plugin (like the function trace has).

2. It should be "delta_ns:" because it is not -189 from the timestamp, as
   the above time stamp is truncated to microseconds and this is not
   obvious to the user.


> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index a0146e1fffdf..55b08e146afc 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -1373,6 +1373,52 @@ static struct trace_event trace_raw_data_event = {
>  	.funcs		= &trace_raw_data_funcs,
>  };
>  
> +static enum print_line_t
> +trace_func_repeats_raw(struct trace_iterator *iter, int flags,
> +			 struct trace_event *event)
> +{
> +	struct func_repeats_entry *field;
> +	struct trace_seq *s = &iter->seq;
> +
> +	trace_assign_type(field, iter->ent);
> +
> +	trace_seq_printf(s, "%lu %lu %u %llu\n",
> +			 field->ip,
> +			 field->parent_ip,
> +			 field->count,
> +			 FUNC_REPEATS_GET_DELTA_TS(field));
> +
> +	return trace_handle_return(s);
> +}
> +
> +static enum print_line_t
> +trace_func_repeats_print(struct trace_iterator *iter, int flags,
> +			 struct trace_event *event)
> +{
> +	struct func_repeats_entry *field;
> +	struct trace_seq *s = &iter->seq;
> +
> +	trace_assign_type(field, iter->ent);
> +
> +	seq_print_ip_sym(s, field->ip, flags);
> +	trace_seq_puts(s, " <-");
> +	seq_print_ip_sym(s, field->parent_ip, flags);
> +	trace_seq_printf(s, " (repeats: %u, delta_ts: -%llu)\n",
> +			 field->count,
> +			 FUNC_REPEATS_GET_DELTA_TS(field));

Here there's no reason to have either of the above issues.
We should show the timestamp of the last event.

	trace_seq_printf(s, " (repeats: %u, last_ts:", field->count);
	trace_print_time(s, iter,
			 iter->ts - FUNC_REPEATS_GET_DELTA_TS(field));
	trace_seq_puts(s, ")\n");

Where we can add another patch to create the trace_print_time() that
uses the code from trace_print_context().

static void trace_print_time(struct trace_seq *s, struct trace_iterator *iter,
			     unsigned long long ts)
{
	unsigned long secs, usec_rem;
	unsigned long long t;

	if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) {
		t = ns2usecs(iter->ts);
		usec_rem = do_div(t, USEC_PER_SEC);
		secs = (unsigned long)t;
		trace_seq_printf(s, " %5lu.%06lu: ", secs, usec_rem);
	} else
		trace_seq_printf(s, " %12llu: ", iter->ts);
}

And we may need to do something interesting if this is a latency format as
well. But we can add that another day.

-- Steve

> +
> +	return trace_handle_return(s);
> +}
> +
> +static struct trace_event_functions trace_func_repeats_funcs = {
> +	.trace		= trace_func_repeats_print,
> +	.raw		= trace_func_repeats_raw,
> +};
> +
> +static struct trace_event trace_func_repeats_event = {
> +	.type	 	= TRACE_FUNC_REPEATS,
> +	.funcs		= &trace_func_repeats_funcs,
> +};
>  
>  static struct trace_event *events[] __initdata = {
>  	&trace_fn_event,
> @@ -1385,6 +1431,7 @@ static struct trace_event *events[] __initdata = {
>  	&trace_print_event,
>  	&trace_hwlat_event,
>  	&trace_raw_data_event,
> +	&trace_func_repeats_event,
>  	NULL
>  };
>  

Re: [PATCH v3 1/5] tracing: Define new ftrace event "func_repeats"

[Steven Rostedt]

On Tue, 13 Apr 2021 15:17:36 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Running this with trace-cmd record, this displays:
> 
>           <idle>-0     [001]   261.848848: function:                            next_zone
>           <idle>-0     [001]   261.848849: func_repeats:          next_zone <-need_update       (repeats:3  delta_ts: -189)
> 
> Which is confusing in a number of ways.
> 
> 1. It would be better to have it be the actual timestamp of the last repeat.
>    But that can be done in a trace-cmd plugin (like the function trace has).
> 
> 2. It should be "delta_ns:" because it is not -189 from the timestamp, as
>    the above time stamp is truncated to microseconds and this is not
>    obvious to the user.

With the below patch to libtraceevent, I now see this:

          <idle>-0     [001]   261.848847: function:                      quiet_vmstat
          <idle>-0     [001]   261.848847: function:                         need_update
          <idle>-0     [001]   261.848848: function:                            first_online_pgdat
          <idle>-0     [001]   261.848848: function:                            next_zone
          <idle>-0     [001]   261.848849: func_repeats:                        next_zone (count: 3  last_ts:   261.848849)
          <idle>-0     [001]   261.848849: function:                   hrtimer_start_range_ns
          <idle>-0     [001]   261.848849: function:                      _raw_spin_lock_irqsave
          <idle>-0     [001]   261.848849: function:                         preempt_count_add

And because I made the format used weak, it can be overwritten by the
application, in which I had trace-cmd update it with the format it uses to
produce the timestamp:

	if (tracecmd_get_flags(handle) & TRACECMD_FL_RAW_TS) {
		tep_func_repeat_format = "%d";
	} else if (tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS) {
		if (tep_test_flag(tracecmd_get_tep(handle), TEP_NSEC_OUTPUT))
			tep_func_repeat_format = "%9.1d";
		else
			tep_func_repeat_format = "%6.1000d";
	} else {
		tep_func_repeat_format = "%12d";
	}

Which produces this when I add "-t" (to see the full timestamp)

          <idle>-0     [001]   261.848847195: function:                      quiet_vmstat
          <idle>-0     [001]   261.848847431: function:                         need_update
          <idle>-0     [001]   261.848847654: function:                            first_online_pgdat
          <idle>-0     [001]   261.848848109: function:                            next_zone
          <idle>-0     [001]   261.848848740: func_repeats:                        next_zone (count: 3  last_ts:   261.848848551)
          <idle>-0     [001]   261.848849014: function:                   hrtimer_start_range_ns
          <idle>-0     [001]   261.848849254: function:                      _raw_spin_lock_irqsave
          <idle>-0     [001]   261.848849481: function:                         preempt_count_add

I was able to reuse the function code thanks to you for having the same
fields as the function event ;-)

And because it only requires updating a weak variable, new code can set
that variable without requiring the library to support it, and we do not
need to change the patch version of the library!

-- Steve

diff --git a/plugins/plugin_function.c b/plugins/plugin_function.c
index 93bdcc2..7777569 100644
--- a/plugins/plugin_function.c
+++ b/plugins/plugin_function.c
@@ -10,6 +10,11 @@
 #include "event-utils.h"
 #include "trace-seq.h"
 
+#define __weak __attribute__((weak))
+
+/* Export this for applications to override it */
+__weak const char *tep_func_repeat_format = "%6.1000d";
+
 static struct func_stack {
 	int size;
 	char **stack;
@@ -169,6 +174,36 @@ static int function_handler(struct trace_seq *s, struct tep_record *record,
 	return 0;
 }
 
+static int trace_func_repeat_handler(struct trace_seq *s, struct tep_record *record,
+				    struct tep_event *event, void *context)
+{
+	struct tep_handle *tep = event->tep;
+	unsigned long long count, top_delta, bottom_delta;
+	struct tep_record dummy;
+
+	function_handler(s, record, event, context);
+
+	if (tep_get_field_val(s, event, "count", record, &count, 1))
+		return trace_seq_putc(s, '!');
+
+	if (tep_get_field_val(s, event, "top_delta_ts", record, &top_delta, 1))
+		return trace_seq_putc(s, '!');
+
+	if (tep_get_field_val(s, event, "bottom_delta_ts", record, &bottom_delta, 1))
+		return trace_seq_putc(s, '!');
+
+	trace_seq_printf(s, " (count: %lld  last_ts: ", count);
+
+	memcpy(&dummy, record, sizeof(dummy));
+	dummy.ts -= (top_delta << 32) | bottom_delta;
+
+	tep_print_event(tep, s, &dummy, tep_func_repeat_format, TEP_PRINT_TIME);
+
+	trace_seq_puts(s, ")");
+
+	return 0;
+}
+
 static int
 trace_stack_handler(struct trace_seq *s, struct tep_record *record,
 		    struct tep_event *event, void *context)
@@ -256,6 +291,9 @@ int TEP_PLUGIN_LOADER(struct tep_handle *tep)
 	tep_register_event_handler(tep, -1, "ftrace", "raw_data",
 				      trace_raw_data_handler, NULL);
 
+	tep_register_event_handler(tep, -1, "ftrace", "func_repeats",
+				      trace_func_repeat_handler, NULL);
+
 	tep_plugin_add_options("ftrace", plugin_options);
 
 	return 0;

Re: [PATCH v3 1/5] tracing: Define new ftrace event "func_repeats"

[Steven Rostedt]

On Tue, 13 Apr 2021 15:17:36 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Running this with trace-cmd record, this displays:
> 
>           <idle>-0     [001]   261.848848: function:                            next_zone
>           <idle>-0     [001]   261.848849: func_repeats:          next_zone <-need_update       (repeats:3  delta_ts: -189)
> 
> Which is confusing in a number of ways.
> 
> 1. It would be better to have it be the actual timestamp of the last repeat.
>    But that can be done in a trace-cmd plugin (like the function trace has).
> 
> 2. It should be "delta_ns:" because it is not -189 from the timestamp, as
>    the above time stamp is truncated to microseconds and this is not
>    obvious to the user.

After playing with this some more, I take back #2. As we don't know what
units the time stamp is actually in. As it is best to simply show the time
stamp of the last event where it matches the other time stamps (which we
can do, as I demonstrated in other emails), I think the best answer is to
leave the default ambiguous as simply "delta:". That way if it's not
processed, all you see is "delta: -189" and if people don't know what that
means, they'll either ignore it, or look up its meaning. I think both
"delta_ts" and "delta_ns" can be misleading if what is displayed does not
match the raw time stamps.

-- Steve

[PATCH v3 2/5] tracing: Add "last_func_repeats" to struct trace_array

[Yordan Karadzhov (VMware)]

The field is used to keep track of the consecutive (on the same CPU) calls
of a single function. This information is needed in order to consolidate
the function tracing record in the cases when a single function is called
number of times.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 kernel/trace/trace.c |  1 +
 kernel/trace/trace.h | 18 ++++++++++++++++++
 2 files changed, 19 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 507a30bf26e4..82833be07c1e 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -9104,6 +9104,7 @@ static int __remove_instance(struct trace_array *tr)
 	ftrace_clear_pids(tr);
 	ftrace_destroy_function_files(tr);
 	tracefs_remove(tr->dir);
+	free_percpu(tr->last_func_repeats);
 	free_trace_buffers(tr);
 
 	for (i = 0; i < tr->nr_topts; i++) {
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 6a5b4c2a0fa7..1cd4da7ba769 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -262,6 +262,17 @@ struct cond_snapshot {
 	cond_update_fn_t		update;
 };
 
+/*
+ * struct trace_func_repeats - used to keep track of the consecutive
+ * (on the same CPU) calls of a single function.
+ */
+struct trace_func_repeats {
+	unsigned long	ip;
+	unsigned long	parent_ip;
+	unsigned long	count;
+	u64		ts_last_call;
+};
+
 /*
  * The trace array - an array of per-CPU trace arrays. This is the
  * highest level data structure that individual tracers deal with.
@@ -358,8 +369,15 @@ struct trace_array {
 #ifdef CONFIG_TRACER_SNAPSHOT
 	struct cond_snapshot	*cond_snapshot;
 #endif
+	struct trace_func_repeats	__percpu *last_func_repeats;
 };
 
+static inline struct trace_func_repeats __percpu *
+tracer_alloc_func_repeats(struct trace_array *tr)
+{
+	return tr->last_func_repeats = alloc_percpu(struct trace_func_repeats);
+}
+
 enum {
 	TRACE_ARRAY_FL_GLOBAL	= (1 << 0)
 };
-- 
2.25.1

Re: [PATCH v3 2/5] tracing: Add "last_func_repeats" to struct trace_array

[Steven Rostedt]

On Fri,  9 Apr 2021 21:10:28 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:

> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -262,6 +262,17 @@ struct cond_snapshot {
>  	cond_update_fn_t		update;
>  };
>  
> +/*
> + * struct trace_func_repeats - used to keep track of the consecutive
> + * (on the same CPU) calls of a single function.
> + */
> +struct trace_func_repeats {
> +	unsigned long	ip;
> +	unsigned long	parent_ip;
> +	unsigned long	count;
> +	u64		ts_last_call;
> +};
> +
>  /*
>   * The trace array - an array of per-CPU trace arrays. This is the
>   * highest level data structure that individual tracers deal with.
> @@ -358,8 +369,15 @@ struct trace_array {
>  #ifdef CONFIG_TRACER_SNAPSHOT
>  	struct cond_snapshot	*cond_snapshot;
>  #endif
> +	struct trace_func_repeats	__percpu *last_func_repeats;
>  };
>  
> +static inline struct trace_func_repeats __percpu *
> +tracer_alloc_func_repeats(struct trace_array *tr)
> +{
> +	return tr->last_func_repeats = alloc_percpu(struct trace_func_repeats);
> +}

Also, is there a reason this is in the header file? It's only used in one C
file, and should be a static function there.

-- Steve


> +
>  enum {
>  	TRACE_ARRAY_FL_GLOBAL	= (1 << 0)
>  };

[PATCH v3 3/5] tracing: Add method for recording "func_repeats" events

[Yordan Karadzhov (VMware)]

This patch only provides the implementation of the method.
Later we will used it in a combination with a new option for
function tracing.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 kernel/trace/trace.c         | 26 ++++++++++++++++++++++++++
 kernel/trace/trace.h         |  4 ++++
 kernel/trace/trace_entries.h |  6 ++++++
 3 files changed, 36 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 82833be07c1e..bbc57cf3bda4 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3117,6 +3117,32 @@ static void ftrace_trace_userstack(struct trace_array *tr,
 
 #endif /* CONFIG_STACKTRACE */
 
+void trace_last_func_repeats(struct trace_array *tr,
+			     struct trace_func_repeats *last_info,
+			     unsigned int trace_ctx)
+{
+	struct trace_buffer *buffer = tr->array_buffer.buffer;
+	struct func_repeats_entry *entry;
+	struct ring_buffer_event *event;
+	u64 delta;
+
+	event = __trace_buffer_lock_reserve(buffer, TRACE_FUNC_REPEATS,
+					    sizeof(*entry), trace_ctx);
+	if (!event)
+		return;
+
+	delta = ring_buffer_event_time_stamp(buffer, event) -
+		last_info->ts_last_call;
+
+	entry = ring_buffer_event_data(event);
+	entry->ip = last_info->ip;
+	entry->parent_ip = last_info->parent_ip;
+	entry->count = last_info->count;
+	FUNC_REPEATS_SET_DELTA_TS(entry, delta)
+
+	__buffer_unlock_commit(buffer, event);
+}
+
 /* created for use with alloc_percpu */
 struct trace_buffer_struct {
 	int nesting;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 1cd4da7ba769..e1f34119c036 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -701,6 +701,10 @@ static inline void __trace_stack(struct trace_array *tr, unsigned int trace_ctx,
 }
 #endif /* CONFIG_STACKTRACE */
 
+void trace_last_func_repeats(struct trace_array *tr,
+			     struct trace_func_repeats *last_info,
+			     unsigned int trace_ctx);
+
 extern u64 ftrace_now(int cpu);
 
 extern void trace_find_cmdline(int pid, char comm[]);
diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
index fdd022a7aecf..5e9dc56af4b1 100644
--- a/kernel/trace/trace_entries.h
+++ b/kernel/trace/trace_entries.h
@@ -342,6 +342,12 @@ FTRACE_ENTRY(hwlat, hwlat_entry,
 #define FUNC_REPEATS_GET_DELTA_TS(entry)			\
 (((u64)entry->top_delta_ts << 32) | entry->bottom_delta_ts)	\
 
+#define FUNC_REPEATS_SET_DELTA_TS(entry, delta)			\
+	do {							\
+		entry->bottom_delta_ts = delta & U32_MAX;	\
+		entry->top_delta_ts = (delta >> 32);		\
+	} while (0);						\
+
 FTRACE_ENTRY(func_repeats, func_repeats_entry,
 
 	TRACE_FUNC_REPEATS,
-- 
2.25.1

Re: [PATCH v3 3/5] tracing: Add method for recording "func_repeats" events

[Steven Rostedt]

On Fri,  9 Apr 2021 21:10:29 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:

> @@ -342,6 +342,12 @@ FTRACE_ENTRY(hwlat, hwlat_entry,
>  #define FUNC_REPEATS_GET_DELTA_TS(entry)			\
>  (((u64)entry->top_delta_ts << 32) | entry->bottom_delta_ts)	\
>  
> +#define FUNC_REPEATS_SET_DELTA_TS(entry, delta)			\
> +	do {							\
> +		entry->bottom_delta_ts = delta & U32_MAX;	\
> +		entry->top_delta_ts = (delta >> 32);		\
> +	} while (0);						\
> +

This needs the parenthesis around the parameters as well.

Or just make it into a static inline function. The GET_DELTA_TS is used in
printing to of the event for user space where it makes sense to have it as
a macro (it will be expanded in the "print fmt" of the format file for the
event). But the setting doesn't have that limitation.

static inline void
func_repeats_set_delta_ts(struct func_repeats_entry *entry,
			  unsigned long long delta)
{
	entry->bottom_delta_ts = delta & U32_MAX;
	entry->top_delta_ts = (delta >> 32);
}

And then you can have the compiler type check everything for you. Macros
are nasty when it comes to build errors.

-- Steve


>  FTRACE_ENTRY(func_repeats, func_repeats_entry,
>  
>  	TRACE_FUNC_REPEATS,
> -- 

[PATCH v3 4/5] tracing: Unify the logic for function tracing options

[Yordan Karadzhov (VMware)]

Currently the logic for dealing with the options for function tracing
has two different implementations. One is used when we set the flags
(in "static int func_set_flag()") and another used when we initialize
the tracer (in "static int function_trace_init()"). Those two
implementations are meant to do essentially the same thing and they
are both not very convenient for adding new options. In this patch
we add a helper function that provides a single implementation of
the logic for dealing with the options and we make it such that new
options can be easily added.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 kernel/trace/trace_functions.c | 65 ++++++++++++++++++++--------------
 1 file changed, 38 insertions(+), 27 deletions(-)

diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
index f93723ca66bc..f37f73a9b1b8 100644
--- a/kernel/trace/trace_functions.c
+++ b/kernel/trace/trace_functions.c
@@ -31,9 +31,12 @@ static struct tracer_flags func_flags;
 
 /* Our option */
 enum {
+	TRACE_FUNC_NO_OPTS	= 0x0, /* No flags set. */
 	TRACE_FUNC_OPT_STACK	= 0x1,
 };
 
+#define TRACE_FUNC_OPT_MASK	(TRACE_FUNC_OPT_STACK)
+
 int ftrace_allocate_ftrace_ops(struct trace_array *tr)
 {
 	struct ftrace_ops *ops;
@@ -86,6 +89,18 @@ void ftrace_destroy_function_files(struct trace_array *tr)
 	ftrace_free_ftrace_ops(tr);
 }
 
+static ftrace_func_t select_trace_function(u32 flags_val)
+{
+	switch (flags_val & TRACE_FUNC_OPT_MASK) {
+	case TRACE_FUNC_NO_OPTS:
+		return function_trace_call;
+	case TRACE_FUNC_OPT_STACK:
+		return function_stack_trace_call;
+	default:
+		return NULL;
+	}
+}
+
 static int function_trace_init(struct trace_array *tr)
 {
 	ftrace_func_t func;
@@ -97,12 +112,9 @@ static int function_trace_init(struct trace_array *tr)
 	if (!tr->ops)
 		return -ENOMEM;
 
-	/* Currently only the global instance can do stack tracing */
-	if (tr->flags & TRACE_ARRAY_FL_GLOBAL &&
-	    func_flags.val & TRACE_FUNC_OPT_STACK)
-		func = function_stack_trace_call;
-	else
-		func = function_trace_call;
+	func = select_trace_function(func_flags.val);
+	if (!func)
+		return -EINVAL;
 
 	ftrace_init_array_ops(tr, func);
 
@@ -213,7 +225,7 @@ static struct tracer_opt func_opts[] = {
 };
 
 static struct tracer_flags func_flags = {
-	.val = 0, /* By default: all flags disabled */
+	.val = TRACE_FUNC_NO_OPTS, /* By default: all flags disabled */
 	.opts = func_opts
 };
 
@@ -235,30 +247,29 @@ static struct tracer function_trace;
 static int
 func_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set)
 {
-	switch (bit) {
-	case TRACE_FUNC_OPT_STACK:
-		/* do nothing if already set */
-		if (!!set == !!(func_flags.val & TRACE_FUNC_OPT_STACK))
-			break;
-
-		/* We can change this flag when not running. */
-		if (tr->current_trace != &function_trace)
-			break;
+	ftrace_func_t func;
+	u32 new_flags;
 
-		unregister_ftrace_function(tr->ops);
+	/* Do nothing if already set. */
+	if (!!set == !!(func_flags.val & bit))
+		return 0;
 
-		if (set) {
-			tr->ops->func = function_stack_trace_call;
-			register_ftrace_function(tr->ops);
-		} else {
-			tr->ops->func = function_trace_call;
-			register_ftrace_function(tr->ops);
-		}
+	/* We can change this flag only when not running. */
+	if (tr->current_trace != &function_trace)
+		return 0;
 
-		break;
-	default:
+	new_flags = (func_flags.val & ~bit) | (set ? bit : 0);
+	func = select_trace_function(new_flags);
+	if (!func)
 		return -EINVAL;
-	}
+
+	/* Check if there's anything to change. */
+	if (tr->ops->func == func)
+		return 0;
+
+	unregister_ftrace_function(tr->ops);
+	tr->ops->func = func;
+	register_ftrace_function(tr->ops);
 
 	return 0;
 }
-- 
2.25.1

[PATCH v3 5/5] tracing: Add "func_no_repeats" option for function tracing

[Yordan Karadzhov (VMware)]

If the option is activated the function tracing record gets
consolidated in the cases when a single function is called number
of times consecutively. Instead of having an identical record for
each call of the function we will record only the first call
following by event showing the number of repeats.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 kernel/trace/trace_functions.c | 161 ++++++++++++++++++++++++++++++++-
 1 file changed, 158 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
index f37f73a9b1b8..9a3cbdbfd1f7 100644
--- a/kernel/trace/trace_functions.c
+++ b/kernel/trace/trace_functions.c
@@ -27,15 +27,27 @@ function_trace_call(unsigned long ip, unsigned long parent_ip,
 static void
 function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
 			  struct ftrace_ops *op, struct ftrace_regs *fregs);
+static void
+function_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
+			       struct ftrace_ops *op, struct ftrace_regs *fregs);
+static void
+function_stack_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
+				     struct ftrace_ops *op,
+				     struct ftrace_regs *fregs);
 static struct tracer_flags func_flags;
 
 /* Our option */
 enum {
-	TRACE_FUNC_NO_OPTS	= 0x0, /* No flags set. */
-	TRACE_FUNC_OPT_STACK	= 0x1,
+
+	TRACE_FUNC_NO_OPTS		= 0x0, /* No flags set. */
+	TRACE_FUNC_OPT_STACK		= 0x1,
+	TRACE_FUNC_OPT_NO_REPEATS	= 0x2,
+
+	/* Update this to next highest bit. */
+	TRACE_FUNC_OPT_HIGHEST_BIT	= 0x4
 };
 
-#define TRACE_FUNC_OPT_MASK	(TRACE_FUNC_OPT_STACK)
+#define TRACE_FUNC_OPT_MASK	(TRACE_FUNC_OPT_HIGHEST_BIT - 1)
 
 int ftrace_allocate_ftrace_ops(struct trace_array *tr)
 {
@@ -96,11 +108,26 @@ static ftrace_func_t select_trace_function(u32 flags_val)
 		return function_trace_call;
 	case TRACE_FUNC_OPT_STACK:
 		return function_stack_trace_call;
+	case TRACE_FUNC_OPT_NO_REPEATS:
+		return function_no_repeats_trace_call;
+	case TRACE_FUNC_OPT_STACK | TRACE_FUNC_OPT_NO_REPEATS:
+		return function_stack_no_repeats_trace_call;
 	default:
 		return NULL;
 	}
 }
 
+static bool handle_func_repeats(struct trace_array *tr, u32 flags_val)
+{
+	if (!tr->last_func_repeats &&
+	    (flags_val & TRACE_FUNC_OPT_NO_REPEATS)) {
+		if (!tracer_alloc_func_repeats(tr))
+			return false;
+	}
+
+	return true;
+}
+
 static int function_trace_init(struct trace_array *tr)
 {
 	ftrace_func_t func;
@@ -116,6 +143,9 @@ static int function_trace_init(struct trace_array *tr)
 	if (!func)
 		return -EINVAL;
 
+	if (!handle_func_repeats(tr, func_flags.val))
+		return -ENOMEM;
+
 	ftrace_init_array_ops(tr, func);
 
 	tr->array_buffer.cpu = raw_smp_processor_id();
@@ -217,10 +247,132 @@ function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
 	local_irq_restore(flags);
 }
 
+static inline bool is_repeat_check(struct trace_array *tr,
+				   struct trace_func_repeats *last_info,
+				   unsigned long ip, unsigned long parent_ip)
+{
+	if (last_info->ip == ip &&
+	    last_info->parent_ip == parent_ip &&
+	    last_info->count < U16_MAX) {
+		last_info->ts_last_call =
+			ring_buffer_time_stamp(tr->array_buffer.buffer);
+		last_info->count++;
+		return true;
+	}
+
+	return false;
+}
+
+static inline void process_repeats(struct trace_array *tr,
+				   unsigned long ip, unsigned long parent_ip,
+				   struct trace_func_repeats *last_info,
+				   unsigned int trace_ctx)
+{
+	if (last_info->count) {
+		trace_last_func_repeats(tr, last_info, trace_ctx);
+		last_info->count = 0;
+	}
+
+	last_info->ip = ip;
+	last_info->parent_ip = parent_ip;
+}
+
+static void
+function_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
+			       struct ftrace_ops *op,
+			       struct ftrace_regs *fregs)
+{
+	struct trace_func_repeats *last_info;
+	struct trace_array *tr = op->private;
+	struct trace_array_cpu *data;
+	unsigned int trace_ctx;
+	unsigned long flags;
+	int bit;
+	int cpu;
+
+	if (unlikely(!tr->function_enabled))
+		return;
+
+	bit = ftrace_test_recursion_trylock(ip, parent_ip);
+	if (bit < 0)
+		return;
+
+	preempt_disable_notrace();
+
+	cpu = smp_processor_id();
+	data = per_cpu_ptr(tr->array_buffer.data, cpu);
+	if (atomic_read(&data->disabled))
+		goto out;
+
+	/*
+	 * An interrupt may happen at any place here. But as far as I can see,
+	 * the only damage that this can cause is to mess up the repetition
+	 * counter without valuable data being lost.
+	 * TODO: think about a solution that is better than just hoping to be
+	 * lucky.
+	 */
+	last_info = per_cpu_ptr(tr->last_func_repeats, cpu);
+	if (is_repeat_check(tr, last_info, ip, parent_ip))
+		goto out;
+
+	local_save_flags(flags);
+	trace_ctx = tracing_gen_ctx_flags(flags);
+	process_repeats(tr, ip, parent_ip, last_info, trace_ctx);
+
+	trace_function(tr, ip, parent_ip, trace_ctx);
+
+out:
+	ftrace_test_recursion_unlock(bit);
+	preempt_enable_notrace();
+}
+
+static void
+function_stack_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
+				     struct ftrace_ops *op,
+				     struct ftrace_regs *fregs)
+{
+	struct trace_func_repeats *last_info;
+	struct trace_array *tr = op->private;
+	struct trace_array_cpu *data;
+	unsigned long flags;
+	long disabled;
+	int cpu;
+	unsigned int trace_ctx;
+
+	if (unlikely(!tr->function_enabled))
+		return;
+
+	/*
+	 * Need to use raw, since this must be called before the
+	 * recursive protection is performed.
+	 */
+	local_irq_save(flags);
+	cpu = raw_smp_processor_id();
+	data = per_cpu_ptr(tr->array_buffer.data, cpu);
+	disabled = atomic_inc_return(&data->disabled);
+
+	if (likely(disabled == 1)) {
+		last_info = per_cpu_ptr(tr->last_func_repeats, cpu);
+		if (is_repeat_check(tr, last_info, ip, parent_ip))
+			goto out;
+
+		trace_ctx = tracing_gen_ctx_flags(flags);
+		process_repeats(tr, ip, parent_ip, last_info, trace_ctx);
+
+		trace_function(tr, ip, parent_ip, trace_ctx);
+		__trace_stack(tr, trace_ctx, STACK_SKIP);
+	}
+
+ out:
+	atomic_dec(&data->disabled);
+	local_irq_restore(flags);
+}
+
 static struct tracer_opt func_opts[] = {
 #ifdef CONFIG_STACKTRACE
 	{ TRACER_OPT(func_stack_trace, TRACE_FUNC_OPT_STACK) },
 #endif
+	{ TRACER_OPT(func-no-repeats, TRACE_FUNC_OPT_NO_REPEATS) },
 	{ } /* Always set a last empty entry */
 };
 
@@ -267,6 +419,9 @@ func_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set)
 	if (tr->ops->func == func)
 		return 0;
 
+	if (!handle_func_repeats(tr, new_flags))
+		return -ENOMEM;
+
 	unregister_ftrace_function(tr->ops);
 	tr->ops->func = func;
 	register_ftrace_function(tr->ops);
-- 
2.25.1