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

[Yordan Karadzhov (VMware)]

On 4.03.21 г. 18:38, Steven Rostedt wrote:
> On Thu,  4 Mar 2021 11:01:37 +0200
> "Yordan Karadzhov (VMware)" <y.karadz@xxxxxxxxx> wrote:
>
> Thanks Yordan for doing this!
>
> I have some comments below.

Hi Steven,

Thank you very much for looking into this!

Your suggestion makes perfect sense. I only have one clarifying question 
below.

> > diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
> > index 4547ac59da61..8007f9b6417f 100644
> > --- a/kernel/trace/trace_entries.h
> > +++ b/kernel/trace/trace_entries.h
> > @@ -338,3 +338,19 @@ FTRACE_ENTRY(hwlat, hwlat_entry,
> >   		 __entry->nmi_total_ts,
> >   		 __entry->nmi_count)
> >   );
> > +
> > +FTRACE_ENTRY(func_repeats, func_repeats_entry,
> > +
> > +	TRACE_FUNC_REPEATS,
> > +
> > +	F_STRUCT(
> > +		__field(	unsigned long,	ip	)
> > +		__field(	unsigned long,	pip	)
> > +		__field(	unsigned long,	count	)
> > +	),
> > +
> > +	F_printk(" %ps <-%ps\t(repeats:%lu)",
> > +		 (void *)__entry->ip,
> > +		 (void *)__entry->pip,
> > +		 __entry->count)
>
> After playing with this a little, I realized that we should also store the
> last timestamp as well. I think that would be interesting information.
>
>             <...>-37      [004] ...1  2022.303820: gc_worker <-process_one_work
>             <...>-37      [004] ...1  2022.303820: ___might_sleep <-gc_worker
>             <...>-37      [004] ...1  2022.303831: ___might_sleep <-gc_worker (repeats: 127)
>             <...>-37      [004] ...1  2022.303831: queue_delayed_work_on <-process_one_work
>
> The above shows that __might_sleep() was called 128 times, but what I don't
> get from the above, is when that last call was made. You'll see that the
> timestamp for the repeat output is the same as the next function shown
> (queue_delayed_work_on()). But the timestamp for the last call to
> __might_sleep() is lost, and the repeat event ends up being written when
> it is detected that there are no more repeats.
>
> If we had:
>
>             <...>-37      [004] ...1  2022.303820: gc_worker <-process_one_work
>             <...>-37      [004] ...1  2022.303820: ___might_sleep <-gc_worker
>             <...>-37      [004] ...1  2022.303831: ___might_sleep <-gc_worker (last ts: 2022.303828 repeats: 127)
>             <...>-37      [004] ...1  2022.303831: queue_delayed_work_on <-process_one_work
>
> We would know the last time __might_sleep was called.
>
> That is, not only should we save the ip and pip in the trace_func_repeats
> structure, but we should also be storing the last time stamp of the last
> function event that repeated. Otherwise the above looks like the last
> __might_sleep called above happened when the queue_delayed_work_on
> happened, where that may not be the case.

If we store the last timestamp, this means we will need to use 
additional 64b on the buffer, every time we record the "func_repeats" 
event. This looks like an overkill to me.
Can we store only the duration of the repeats (the difference between 
the timestamp)? This way we can use less memory at the price of having 
one extra arithmetic operation.
Alternative approach can be to store only the least-significant bits of 
the timestamp.

What do you think?

Best regards,
Yordan

> -- Steve