[PATCH] sched: Add trace for task wake up latency and leave running time
From: Dongjiu Geng
Date: Fri Aug 21 2020 - 11:37:37 EST
1) The perf event sched_switch is used to record scheduling tracks,
which consumes a large amount of CPU resources and disk space.
Therefore, a mechanism is required to record only the scheduling
delay greater than a certain threshold. This patch supports this
feature. For example, if the threshold is 10 ms, you can run the
following command to only record the scheduling track with the
scheduling delay greater than 10 ms.
echo 'time > 10000000' > /sys/kernel/debug/tracing/events/sched/sched_wakeup_latency/filter
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup_latency/enable
2) Similarly, when tune performance, we usually want to know which
tasks are not running for a long time, Use the following methods
to save CPU overhead and storage space.
echo 'time > 10000000' > /sys/kernel/debug/tracing/events/sched/sched_leave_running_time/filter
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_leave_running_time/enable
Signed-off-by: Dongjiu Geng <gengdongjiu@xxxxxxxxxx>
---
include/linux/sched.h | 7 ++++
include/trace/events/sched.h | 66 ++++++++++++++++++++++++++++++++++++
kernel/sched/core.c | 20 +++++++++++
3 files changed, 93 insertions(+)
diff --git a/include/linux/sched.h b/include/linux/sched.h
index 93ecd930efd3..edb622c40a90 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -1324,6 +1324,13 @@ struct task_struct {
/* CPU-specific state of this task: */
struct thread_struct thread;
+ /* Task wake up time stamp */
+ u64 ts_wakeup;
+ /* Previous task switch out time stamp */
+ u64 pre_ts_end;
+ /* Next task switch in time stamp */
+ u64 next_ts_start;
+ bool wakeup_state;
/*
* WARNING: on x86, 'thread_struct' contains a variable-sized
* structure. It *MUST* be at the end of 'task_struct'.
diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index fec25b9cfbaf..e99c6d573a42 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -183,6 +183,72 @@ TRACE_EVENT(sched_switch,
__entry->next_comm, __entry->next_pid, __entry->next_prio)
);
+DECLARE_EVENT_CLASS(sched_latency_template,
+
+ TP_PROTO(bool preempt,
+ struct task_struct *prev,
+ struct task_struct *next,
+ u64 time),
+
+ TP_ARGS(preempt, prev, next, time),
+
+ TP_STRUCT__entry(
+ __array( char, prev_comm, TASK_COMM_LEN )
+ __field( pid_t, prev_pid )
+ __field( int, prev_prio )
+ __field( long, prev_state )
+ __array( char, next_comm, TASK_COMM_LEN )
+ __field( pid_t, next_pid )
+ __field( int, next_prio )
+ __field( u64, time )
+ ),
+
+ TP_fast_assign(
+ memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
+ __entry->prev_pid = prev->pid;
+ __entry->prev_prio = prev->prio;
+ __entry->prev_state = __trace_sched_switch_state(preempt, prev);
+ memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
+ __entry->next_pid = next->pid;
+ __entry->next_prio = next->prio;
+ __entry->time = time;
+ /* XXX SCHED_DEADLINE */
+ ),
+
+ TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d passed time=%llu (ns)",
+ __entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
+
+ (__entry->prev_state & (TASK_REPORT_MAX - 1)) ?
+ __print_flags(__entry->prev_state & (TASK_REPORT_MAX - 1), "|",
+ { TASK_INTERRUPTIBLE, "S" },
+ { TASK_UNINTERRUPTIBLE, "D" },
+ { __TASK_STOPPED, "T" },
+ { __TASK_TRACED, "t" },
+ { EXIT_DEAD, "X" },
+ { EXIT_ZOMBIE, "Z" },
+ { TASK_PARKED, "P" },
+ { TASK_DEAD, "I" }) :
+ "R",
+
+ __entry->prev_state & TASK_REPORT_MAX ? "+" : "",
+ __entry->next_comm, __entry->next_pid, __entry->next_prio,
+ __entry->time)
+);
+
+DEFINE_EVENT(sched_latency_template, sched_wakeup_latency,
+ TP_PROTO(bool preempt,
+ struct task_struct *prev,
+ struct task_struct *next,
+ u64 time),
+ TP_ARGS(preempt, prev, next, time));
+
+DEFINE_EVENT(sched_latency_template, sched_leave_running_time,
+ TP_PROTO(bool preempt,
+ struct task_struct *prev,
+ struct task_struct *next,
+ u64 time),
+ TP_ARGS(preempt, prev, next, time));
+
/*
* Tracepoint for a task being migrated:
*/
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 8471a0f7eb32..b5a1928dc948 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2464,6 +2464,8 @@ static void ttwu_do_wakeup(struct rq *rq, struct task_struct *p, int wake_flags,
{
check_preempt_curr(rq, p, wake_flags);
p->state = TASK_RUNNING;
+ p->ts_wakeup = local_clock();
+ p->wakeup_state = true;
trace_sched_wakeup(p);
#ifdef CONFIG_SMP
@@ -2846,6 +2848,8 @@ try_to_wake_up(struct task_struct *p, unsigned int state, int wake_flags)
success = 1;
trace_sched_waking(p);
p->state = TASK_RUNNING;
+ p->ts_wakeup = local_clock();
+ p->wakeup_state = true;
trace_sched_wakeup(p);
goto out;
}
@@ -3299,6 +3303,9 @@ int sched_fork(unsigned long clone_flags, struct task_struct *p)
plist_node_init(&p->pushable_tasks, MAX_PRIO);
RB_CLEAR_NODE(&p->pushable_dl_tasks);
#endif
+ p->ts_wakeup = 0;
+ p->wakeup_state = false;
+ p->pre_ts_end = p->next_ts_start = 0;
return 0;
}
@@ -3355,6 +3362,8 @@ void wake_up_new_task(struct task_struct *p)
post_init_entity_util_avg(p);
activate_task(rq, p, ENQUEUE_NOCLOCK);
+ p->ts_wakeup = local_clock();
+ p->wakeup_state = true;
trace_sched_wakeup_new(p);
check_preempt_curr(rq, p, WF_FORK);
#ifdef CONFIG_SMP
@@ -4521,8 +4530,19 @@ static void __sched notrace __schedule(bool preempt)
psi_sched_switch(prev, next, !task_on_rq_queued(prev));
+ next->next_ts_start = prev->pre_ts_end = local_clock();
+
trace_sched_switch(preempt, prev, next);
+ if (next->ts_wakeup && next->wakeup_state) {
+ trace_sched_wakeup_latency(preempt, prev, next,
+ next->next_ts_start - next->ts_wakeup);
+ next->wakeup_state = false;
+ }
+
+ trace_sched_leave_running_time(preempt, prev,
+ next, next->next_ts_start - next->pre_ts_end);
+
/* Also unlocks the rq: */
rq = context_switch(rq, prev, next, &rf);
} else {
--
2.17.1