* [RESEND x4][PATCH v3] trace: Add trace points for tasklet entry/exit
@ 2023-04-07 23:05 John Stultz
2023-04-15 8:20 ` [tip: irq/core] softirq: " tip-bot2 for Lingutla Chandrasekhar
0 siblings, 1 reply; 2+ messages in thread
From: John Stultz @ 2023-04-07 23:05 UTC (permalink / raw)
To: LKML
Cc: Lingutla Chandrasekhar, Steven Rostedt, Masami Hiramatsu,
Thomas Gleixner, Paul E. McKenney, kernel-team, J . Avila,
John Stultz
From: Lingutla Chandrasekhar <clingutla@codeaurora.org>
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.
Trivial usage example:
# echo 1 > /sys/kernel/debug/tracing/events/irq/tasklet_entry/enable
# echo 1 > /sys/kernel/debug/tracing/events/irq/tasklet_exit/enable
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 4/4 #P:4
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
<idle>-0 [003] ..s1. 314.011428: tasklet_entry: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
<idle>-0 [003] ..s1. 314.011432: tasklet_exit: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
<idle>-0 [003] ..s1. 314.017369: tasklet_entry: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
<idle>-0 [003] ..s1. 314.017371: tasklet_exit: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
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@goodmis.org>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: "Paul E. McKenney" <paulmck@kernel.org>
Cc: kernel-team@android.com
Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
Signed-off-by: Lingutla Chandrasekhar <clingutla@codeaurora.org>
[elavila: Port to android-mainline]
Signed-off-by: J. Avila <elavila@google.com>
[jstultz: Rebased to upstream, cut unused trace points, added
comments for the tracepoints, reworded commit]
Signed-off-by: John Stultz <jstultz@google.com>
---
"Helloooooo..." he yelled into the void.
v2:
* Added tasklet pointer to the trace event as suggested by Steven
v3:
* Minor tweak to commit to show usage and output example
---
include/trace/events/irq.h | 47 ++++++++++++++++++++++++++++++++++++++
kernel/softirq.c | 9 ++++++--
2 files changed, 54 insertions(+), 2 deletions(-)
diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index eeceafaaea4c..a07b4607b663 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -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 */
diff --git a/kernel/softirq.c b/kernel/softirq.c
index c8a6913c067d..1b725510dd0f 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, 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;
--
2.40.0.577.gac1e443424-goog
^ permalink raw reply related [flat|nested] 2+ messages in thread
* [tip: irq/core] softirq: Add trace points for tasklet entry/exit
2023-04-07 23:05 [RESEND x4][PATCH v3] trace: Add trace points for tasklet entry/exit John Stultz
@ 2023-04-15 8:20 ` tip-bot2 for Lingutla Chandrasekhar
0 siblings, 0 replies; 2+ messages in thread
From: tip-bot2 for Lingutla Chandrasekhar @ 2023-04-15 8:20 UTC (permalink / raw)
To: linux-tip-commits
Cc: Lingutla Chandrasekhar, J. Avila, John Stultz, Thomas Gleixner,
Steven Rostedt (Google), x86, linux-kernel, maz
The following commit has been merged into the irq/core branch of tip:
Commit-ID: f4bf3ca2e5cba655824b6e0893a98dfb33ed24e5
Gitweb: https://git.kernel.org/tip/f4bf3ca2e5cba655824b6e0893a98dfb33ed24e5
Author: Lingutla Chandrasekhar <clingutla@codeaurora.org>
AuthorDate: Fri, 07 Apr 2023 23:05:26
Committer: Thomas Gleixner <tglx@linutronix.de>
CommitterDate: Sat, 15 Apr 2023 10:17:16 +02:00
softirq: Add trace points for tasklet entry/exit
Tasklets are supposed to finish their work quickly and should not block the
current running process, but it is not guaranteed that they do so.
Currently softirq_entry/exit can be used to analyse the total tasklets
execution time, but that's not helpful to track individual tasklets
execution time. That makes it hard to identify tasklet functions, which
take more time than expected.
Add tasklet_entry/exit trace point support to track individual tasklet
execution.
Trivial usage example:
# echo 1 > /sys/kernel/debug/tracing/events/irq/tasklet_entry/enable
# echo 1 > /sys/kernel/debug/tracing/events/irq/tasklet_exit/enable
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 4/4 #P:4
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
<idle>-0 [003] ..s1. 314.011428: tasklet_entry: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
<idle>-0 [003] ..s1. 314.011432: tasklet_exit: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
<idle>-0 [003] ..s1. 314.017369: tasklet_entry: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
<idle>-0 [003] ..s1. 314.017371: tasklet_exit: tasklet=0xffffa01ef8db2740 function=tcp_tasklet_func
Signed-off-by: Lingutla Chandrasekhar <clingutla@codeaurora.org>
Signed-off-by: J. Avila <elavila@google.com>
Signed-off-by: John Stultz <jstultz@google.com>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
Link: https://lore.kernel.org/r/20230407230526.1685443-1-jstultz@google.com
[elavila: Port to android-mainline]
[jstultz: Rebased to upstream, cut unused trace points, added
comments for the tracepoints, reworded commit]
---
include/trace/events/irq.h | 47 +++++++++++++++++++++++++++++++++++++-
kernel/softirq.c | 9 +++++--
2 files changed, 54 insertions(+), 2 deletions(-)
diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index eeceafa..a07b460 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -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 */
diff --git a/kernel/softirq.c b/kernel/softirq.c
index c8a6913..1b72551 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, 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;
^ permalink raw reply related [flat|nested] 2+ messages in thread
end of thread, other threads:[~2023-04-15 8:20 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-04-07 23:05 [RESEND x4][PATCH v3] trace: Add trace points for tasklet entry/exit John Stultz
2023-04-15 8:20 ` [tip: irq/core] softirq: " tip-bot2 for Lingutla Chandrasekhar
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox