trace: Add trace points for tasklet entry/exit
PATCH 1/1 trace: Add trace points for tasklet entry/exit
From: Lingutla Chandrasekhar <[email protected]>
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!
[jstultz: Rebased to upstream, cut unused trace points, added
comments for the tracepoints, reworded commit]
--- include/trace/events/irq.h | 43 ++++++++++++++++++++++++++++++++++++++ kernel/softirq.c | 9 ++++++-- 2 files changed, 50 insertions(+), 2 deletions(-)
include/trace/events/irq.h +43 -0
@@ -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 ( + __field( void *, func) + ), + +TP_fast_assign ( + __entry->func = func; + ), + +TP_printk ("function=%ps" , __entry->func) +); + +/** +* 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 */
kernel/softirq.c +7 -2
@@ -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 ;
Signature · 1 line
2.39.0.314.g84b9a713c41-goog
Steven Rostedt
maintainerQuoted 39 lines · On Tue, 3 Jan 2023 18:54:08 +0000 John Stultz <[email protected]> wrote:
From: Lingutla Chandrasekhar <[email protected]>
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 <[email protected]>Cc Masami Hiramatsu <[email protected]>Cc Thomas Gleixner <[email protected]>Cc "Paul E. McKenney" <[email protected]>Cc Connor O'Brien <[email protected]>Reviewed-by Steven Rostedt (Google) <[email protected]>Signed-off-by Lingutla Chandrasekhar <[email protected]>[elavila: Port to android-mainline]Signed-off-by J. Avila <[email protected]>[jstultz: Rebased to upstream, cut unused trace points, added
comments for the tracepoints, reworded commit]Signed-off-by John Stultz <[email protected]>--- include/trace/events/irq.h | 43 ++++++++++++++++++++++++++++++++++++++ kernel/softirq.c | 9 ++++++-- 2 files changed, 50 insertions(+), 2 deletions(-)include/trace/events/irq.h +0
-0
include/trace/events/irq.h DEFINE_EVENT(softirq, softirq_raise, · line 169
Quoted 10 lines
include/trace/events/irq.h +7
-0@@ -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)
include/trace/events/irq.h DEFINE_EVENT(softirq, softirq_raise, · line 173
Quoted 4 lines
include/trace/events/irq.h +4
-0+ __field( void *, func) + ), + + TP_fast_assign(
__entry->tasklet = t;
include/trace/events/irq.h DEFINE_EVENT(softirq, softirq_raise, · line 177
Quoted 4 lines
include/trace/events/irq.h +4
-0+ __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
Quoted 53 lines
include/trace/events/irq.h +28
-0+); + +/** +* 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 */ kernel/softirq.c +7
-2@@ -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 ;
PATCH v2 1/1 trace: Add trace points for tasklet entry/exit
From: Lingutla Chandrasekhar <[email protected]>
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!
[jstultz: Rebased to upstream, cut unused trace points, added
comments for the tracepoints, reworded commit]
---
v2:
* Added tasklet pointer to the trace event as suggested by Steven
--- include/trace/events/irq.h | 47 ++++++++++++++++++++++++++++++++++++++ kernel/softirq.c | 9 ++++++-- 2 files changed, 54 insertions(+), 2 deletions(-)
include/trace/events/irq.h +47 -0
@@ -160,6 +160,53 @@ DEFINE_EVENT(softirq, softirq_raise,TP_ARGS (vec_nr) ); +DECLARE_EVENT_CLASS (tasklet, + + TP_PROTO(struct tasklet_struct *t, void *func), + +TP_ARGS (t, func), + +TP_STRUCT__entry ( + __field( void *, tasklet) + __field( void *, func) + ), + +TP_fast_assign ( + __entry->tasklet = t; + __entry->func = func; + ), + +TP_printk ("tasklet=%ps function=%ps" , __entry->tasklet, __entry->func) +); + +/** +* tasklet_entry - called immediately before the tasklet is run +* @t: tasklet pointer +* @func: tasklet callback or function being run +* +* Used to find individual tasklet execution time +*/ +DEFINE_EVENT (tasklet, tasklet_entry, + + TP_PROTO(struct tasklet_struct *t, void *func), + +TP_ARGS (t, func) +); + +/** +* tasklet_exit - called immediately after the tasklet is run +* @t: tasklet pointer +* @func: tasklet callback or function being run +* +* Used to find individual tasklet execution time +*/ +DEFINE_EVENT (tasklet, tasklet_exit, + + TP_PROTO(struct tasklet_struct *t, void *func), + +TP_ARGS (t, func) +); +#endif /* _TRACE_IRQ_H */ /* This part must be outside protection */
kernel/softirq.c +7 -2
@@ -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, t->callback); t->callback (t); -else +trace_tasklet_exit (t, t->callback); + }else { +trace_tasklet_entry (t, t->func); t->func (t->data); +trace_tasklet_exit (t, t->func); + } }tasklet_unlock (t);continue ;
Signature · 1 line
2.39.0.314.g84b9a713c41-goog
Masami Hiramatsu (Google)
maintainerQuoted 64 lines · On Tue, 3 Jan 2023 15:15:54 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 39 lines · On Tue, 3 Jan 2023 18:54:08 +0000 John Stultz <[email protected]> wrote:
From: Lingutla Chandrasekhar <[email protected]>
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 <[email protected]>Cc Masami Hiramatsu <[email protected]>Cc Thomas Gleixner <[email protected]>Cc "Paul E. McKenney" <[email protected]>Cc Connor O'Brien <[email protected]>Reviewed-by Steven Rostedt (Google) <[email protected]>Signed-off-by Lingutla Chandrasekhar <[email protected]>[elavila: Port to android-mainline]Signed-off-by J. Avila <[email protected]>[jstultz: Rebased to upstream, cut unused trace points, added
comments for the tracepoints, reworded commit]Signed-off-by John Stultz <[email protected]>--- include/trace/events/irq.h | 43 ++++++++++++++++++++++++++++++++++++++ kernel/softirq.c | 9 ++++++-- 2 files changed, 50 insertions(+), 2 deletions(-)include/trace/events/irq.h +0
-0include/trace/events/irq.h DEFINE_EVENT(softirq, softirq_raise, · line 169
Quoted 10 lines
include/trace/events/irq.h +7
-0@@ -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)include/trace/events/irq.h DEFINE_EVENT(softirq, softirq_raise, · line 173
Quoted 4 lines
include/trace/events/irq.h +4
-0+ __field( void *, func) + ), + + TP_fast_assign(__entry->tasklet = t;
Quoted 8 lines
include/trace/events/irq.h DEFINE_EVENT(softirq, softirq_raise, · line 177
Quoted 4 lines
include/trace/events/irq.h +4
-0+ __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
Hmm, what about saving 'state' and 'count' instead of 'tasklet'?
I have a question about the basic policy of making a new tracepoint.
Of course we can expand the event with eprobes as you said, but without eprobe, this 'tasklet' field of this event just exposing a kernel internal object address. That is useless in most cases. And also the offset (layout) in the kernel data structure can be changed by some debug options. We need an external tool to find correct offset (e.g. perf probe).
So my question is when adding a new event, whether it should expose a (address of) related data structure, or expose some value fields of the structure. IMHO, the basic policy is latter. Of course if the data structure is enough big and most of its fields are usually not interesting, it may be better to save the data structure itself.
Thank you,
Quoted 58 lines
-- Steve
Quoted 53 lines
include/trace/events/irq.h +28
-0+); + +/** +* 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 */ kernel/softirq.c +7
-2@@ -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 ;
Signature · 1 line
Masami Hiramatsu (Google) <[email protected]>
Steven Rostedt
maintainerQuoted 5 lines · On Wed, 4 Jan 2023 23:29:18 +0900 Masami Hiramatsu (Google)…
Quoted 1 line
# echo 'e:tasklet_info tasklet/tasklet_entry state=+8($tasklet):u64' > dynamic_eventsHmm, what about saving 'state' and 'count' instead of 'tasklet'?
I have a question about the basic policy of making a new tracepoint.
The policy is to have something that is useful for analysis and debugging ;-)
Quoted 8 lines
Of course we can expand the event with eprobes as you said, but without eprobe, this 'tasklet' field of this event just exposing a kernel internal object address. That is useless in most cases. And also the offset (layout) in the kernel data structure can be changed by some debug options. We need an external tool to find correct offset (e.g. perf probe).
Quoted 5 lines
So my question is when adding a new event, whether it should expose a (address of) related data structure, or expose some value fields of the structure. IMHO, the basic policy is latter. Of course if the data structure is enough big and most of its fields are usually not interesting, it may be better to save the data structure itself.
This isn't unprecedented. Lots of tracepoints expose a pointer to a structure. It's useful as that pointer becomes an identifier and can be tracked.
The reason I prefer eprobe, is because it prevents anything from making it into a ABI. We should try not exposing internally used fields if possible. By exposing state and count, something can easily depend on those fields as they are then exposed in the format file. Where as, eprobes is just reading offsets of a pointer, and not something that can become ABI, especially because the addresses may change with different compiled options.
-- Steve