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@xxxxxxxxxxx> 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;