Re: [PATCH] trace: Add trace points for tasklet entry/exit

[Steven Rostedt]

On Tue,  3 Jan 2023 18:54:08 +0000
John Stultz <jstultz@xxxxxxxxxx> wrote:

> From: Lingutla Chandrasekhar <clingutla@xxxxxxxxxxxxxx>
> 
> Tasklets are supposed to finish their work quickly and
> should not block the current running process, but it is not
> guaranteed that. Currently softirq_entry/exit can be used to
> know total tasklets execution time, but not helpful to track
> individual tasklet's execution time. With that we can't find
> any culprit tasklet function, which is taking more time.
> 
> Add tasklet_entry/exit trace point support to track
> individual tasklet execution.
> 
> This patch has been carried in the Android tree for awhile
> so I wanted to submit it for review upstream. Feedback would
> be appreciated!
> 
> Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
> Cc: Masami Hiramatsu <mhiramat@xxxxxxxxxx>
> Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> Cc: "Paul E. McKenney" <paulmck@xxxxxxxxxx>
> Cc: Connor O'Brien <connoro@xxxxxxxxxx>
> Cc: kernel-team@xxxxxxxxxxx
> Reviewed-by: Steven Rostedt (Google) <rostedt@xxxxxxxxxxx>
> Signed-off-by: Lingutla Chandrasekhar <clingutla@xxxxxxxxxxxxxx>
> [elavila: Port to android-mainline]
> Signed-off-by: J. Avila <elavila@xxxxxxxxxx>
> [jstultz: Rebased to upstream, cut unused trace points, added
>  comments for the tracepoints, reworded commit]
> Signed-off-by: John Stultz <jstultz@xxxxxxxxxx>
> ---
>  include/trace/events/irq.h | 43 ++++++++++++++++++++++++++++++++++++++
>  kernel/softirq.c           |  9 ++++++--
>  2 files changed, 50 insertions(+), 2 deletions(-)
> 
> diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
> index eeceafaaea4c..da85851d4ec1 100644
> --- a/include/trace/events/irq.h
> +++ b/include/trace/events/irq.h
> @@ -160,6 +160,49 @@ DEFINE_EVENT(softirq, softirq_raise,
>  	TP_ARGS(vec_nr)
>  );
>  
> +DECLARE_EVENT_CLASS(tasklet,
> +
> +	TP_PROTO(void *func),
> +
> +	TP_ARGS(func),
> +
> +	TP_STRUCT__entry(

Could you also add a pointer to the tasklet too?

		__field(	void *, tasklet)

> +		__field(	void *,	func)
> +	),
> +
> +	TP_fast_assign(

		__entry->tasklet = t;

> +		__entry->func = func;
> +	),
> +
> +	TP_printk("function=%ps", __entry->func)

This way if we wanted more information, we could use event probes:

 # echo 'e:tasklet_info tasklet/tasklet_entry state=+8($tasklet):u64' > dynamic_events

-- Steve


> +);
> +
> +/**
> + * tasklet_entry - called immediately before the tasklet is run
> + * @func:  tasklet callback or function being run
> + *
> + * Used to find individual tasklet execution time
> + */
> +DEFINE_EVENT(tasklet, tasklet_entry,
> +
> +	TP_PROTO(void *func),
> +
> +	TP_ARGS(func)
> +);
> +
> +/**
> + * tasklet_exit - called immediately after the tasklet is run
> + * @func:  tasklet callback or function being run
> + *
> + * Used to find individual tasklet execution time
> + */
> +DEFINE_EVENT(tasklet, tasklet_exit,
> +
> +	TP_PROTO(void *func),
> +
> +	TP_ARGS(func)
> +);
> +
>  #endif /*  _TRACE_IRQ_H */
>  
>  /* This part must be outside protection */
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index c8a6913c067d..dbd322524171 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -793,10 +793,15 @@ static void tasklet_action_common(struct softirq_action *a,
>  		if (tasklet_trylock(t)) {
>  			if (!atomic_read(&t->count)) {
>  				if (tasklet_clear_sched(t)) {
> -					if (t->use_callback)
> +					if (t->use_callback) {
> +						trace_tasklet_entry(t->callback);
>  						t->callback(t);
> -					else
> +						trace_tasklet_exit(t->callback);
> +					} else {
> +						trace_tasklet_entry(t->func);
>  						t->func(t->data);
> +						trace_tasklet_exit(t->func);
> +					}
>  				}
>  				tasklet_unlock(t);
>  				continue;