Sleep Profiling v2
cover Sleep Profiling v2
Changes since v1:
* Define a new sched_stat tracepoint
* Rebased to -tip
When debugging latency, users want to know where their code is executing on the CPU (cycle profiling) as well as where it's waiting sleeping or waiting for IO. The following patch set tries to address the latter.
Normal users can use this tracepoint without root privileges and on a system with lots of context switches, load can be reduced by filtering out uninteresting switches.
Sample command lines:
perf record -gPe sched:sched_stat_sleeptime --filter "sleeptime > 10000" -- ./test perf report --stdio -g graph -G
Arun Sharma (2):
sched: Retain sleep/block information tracing, sched: Add a new tracepoint for sleeptime
include/trace/events/sched.h | 48 ++++++++++++++++++++++++++++++++++++++++++ kernel/sched/core.c | 1 + kernel/sched/fair.c | 6 +++- 3 files changed, 53 insertions(+), 2 deletions(-)
Signature · 1 line
1.7.4
PATCH 1/2 sched: Retain sleep/block information
This is so that we can compute the sleep/block delay at context switch time for the purpose of sleep profiling.
--- kernel/sched/fair.c | 6 ++++-- 1 files changed, 4 insertions(+), 2 deletions(-)
kernel/sched/fair.c +4 -2
@@ -1003,7 +1003,6 @@ static void enqueue_sleeper(struct cfs_rq *cfs_rq, struct sched_entity *se)if (unlikely (delta > se->statistics.sleep_max)) se->statistics.sleep_max = delta; - se->statistics.sleep_start =0 ; se->statistics.sum_sleep_runtime += delta;if (tsk) {
@@ -1020,7 +1019,6 @@ static void enqueue_sleeper(struct cfs_rq *cfs_rq, struct sched_entity *se)if (unlikely (delta > se->statistics.block_max)) se->statistics.block_max = delta; - se->statistics.block_start =0 ; se->statistics.sum_sleep_runtime += delta;if (tsk) {
@@ -1193,8 +1191,12 @@ dequeue_entity(struct cfs_rq *cfs_rq, struct sched_entity *se, int flags)if (tsk->state &TASK_INTERRUPTIBLE ) se->statistics.sleep_start =rq_of (cfs_rq)->clock; +else + se->statistics.sleep_start =0 ;if (tsk->state &TASK_UNINTERRUPTIBLE ) se->statistics.block_start =rq_of (cfs_rq)->clock; +else + se->statistics.block_start = 0; }#endif }
Signature · 1 line
1.7.4
PATCH 2/2 tracing, sched: Add a new tracepoint for sleeptime
In reply to Arun SharmaIf CONFIG_SCHEDSTATS is defined, the kernel maintains information about how long the task was sleeping or in the case of iowait, blocking in the kernel before getting woken up.
Note: this information is only provided for sched_fair. Other scheduling classes may choose to provide this in the future.
Note: the delay includes the time spent on the runqueue as well.
--- include/trace/events/sched.h | 48 ++++++++++++++++++++++++++++++++++++++++++ kernel/sched/core.c | 1 + 2 files changed, 49 insertions(+), 0 deletions(-)
include/trace/events/sched.h +48 -0
@@ -363,6 +363,54 @@ TRACE_EVENT(sched_stat_runtime, (unsigned long long)__entry->vruntime) ); +#ifdef CREATE_TRACE_POINTS +static inline u64 trace_get_sleeptime (struct task_struct *tsk) +{ +#ifdef CONFIG_SCHEDSTATS +u64 block, sleep; + + block = tsk->se.statistics.block_start; + sleep = tsk->se.statistics.sleep_start; + +return block ? block : sleep ? sleep :0 ; +#else +return 0 ; +#endif +} +#endif + +/* +* Tracepoint for accounting sleeptime (time the task is sleeping +* or waiting for I/O). +*/ +TRACE_EVENT (sched_stat_sleeptime, + + TP_PROTO(struct task_struct *tsk, u64 now), + +TP_ARGS (tsk, now), + +TP_STRUCT__entry ( + __array( char, comm, TASK_COMM_LEN ) + __field( pid_t, pid ) +__field ( u64, sleeptime ) + ), + + TP_fast_assign( + memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN); + __entry->pid = tsk->pid; + __entry->sleeptime = trace_get_sleeptime(tsk); + __entry->sleeptime = __entry->sleeptime ? + now - __entry->sleeptime : 0; + ) +TP_perf_assign ( + __perf_count(__entry->sleeptime); + ), + +TP_printk ("comm=%s pid=%d sleeptime=%Lu [ns]" , + __entry->comm, __entry->pid, + (unsigned long long )__entry->sleeptime) +); +/* * Tracepoint for showing priority inheritance modifying a tasks * priority.
kernel/sched/core.c +1 -0
@@ -1899,6 +1899,7 @@ static void finish_task_switch(struct rq *rq, struct task_struct *prev)local_irq_enable ();#endif /* __ARCH_WANT_INTERRUPTS_ON_CTXSW */ finish_lock_switch (rq, prev); +trace_sched_stat_sleeptime (current, rq->clock);fire_sched_in_preempt_notifiers (current);if (mm)
Signature · 1 line
1.7.4
Steven Rostedt
maintainerRe: [PATCH 2/2] tracing, sched: Add a new tracepoint for sleeptime
Quoted 31 lines · Arun Sharma
If
CONFIG_SCHEDSTATSis defined, the kernel maintains information about how long the task was sleeping or in the case of iowait, blocking in the kernel before getting woken up.Note: this information is only provided for
sched_fair. Other scheduling classes may choose to provide this in the future.Note: the delay includes the time spent on the runqueue as well.
Signed-off-by Arun Sharma <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Steven Rostedt <[email protected]>Cc Mathieu Desnoyers <[email protected]>Cc Arnaldo Carvalho de Melo <[email protected]>Cc Andrew Vagin <[email protected]>Cc Frederic Weisbecker <[email protected]>Cc Ingo Molnar <[email protected]>--- include/trace/events/sched.h | 48 ++++++++++++++++++++++++++++++++++++++++++ kernel/sched/core.c | 1 + 2 files changed, 49 insertions(+), 0 deletions(-)include/trace/events/sched.h +0
-0
include/trace/events/sched.h TRACE_EVENT(sched_stat_runtime, · line 366
Quoted 4 lines
include/trace/events/sched.h +1
-0@@ -363,6 +363,54 @@ TRACE_EVENT(sched_stat_runtime, (unsigned long long)__entry->vruntime) ); +#ifdef CREATE_TRACE_POINTS
Why the #ifdef? a static inline is fine to keep in the open. If nothing uses it, then it just wont be used or defined.
-- Steve
Quoted 16 lines
include/trace/events/sched.h +16
-0+static inline u64 trace_get_sleeptime (struct task_struct *tsk) +{ +#ifdef CONFIG_SCHEDSTATS +u64 block, sleep; + + block = tsk->se.statistics.block_start; + sleep = tsk->se.statistics.sleep_start; + +return block ? block : sleep ? sleep :0 ; +#else +return 0 ; +#endif +} +#endif + +
Re: [PATCH 2/2] tracing, sched: Add a new tracepoint for sleeptime
Quoted 5 lines · Steven Rostedt
Quoted 1 line
+#ifdef
CREATE_TRACE_POINTSWhy the #ifdef? a static inline is fine to keep in the open. If nothing uses it, then it just wont be used or defined.
Without the ifdef I get:
In file included from include/trace/define_trace.h:80,
from include/trace/events/sched.h:445,
from kernel/sched/core.c:86:include/trace/events/sched.h:366: error: redefinition of ‘trace_get_sleeptime’ include/trace/events/sched.h:366: note: previous definition of ‘trace_get_sleeptime’ was here
So I shamelessly copied what the other static inline function in the file does.
I also noticed that sched_stat_sleeptime() is very similar to sched_stat_sleep(). The latter covers sleeps but not iowait and doesn't include the scheduler latency. Let me know if you think this is a show stopper that needs a rename.
-Arun
Steven Rostedt
maintainerRe: [PATCH 2/2] tracing, sched: Add a new tracepoint for sleeptime
Quoted 18 lines · Arun Sharma
Quoted 5 lines · Steven Rostedt
Quoted 1 line
+#ifdef
CREATE_TRACE_POINTSWhy the #ifdef? a static inline is fine to keep in the open. If nothing uses it, then it just wont be used or defined.
Without the ifdef I get:
In file included from
include/trace/define_trace.h:80,
frominclude/trace/events/sched.h:445, fromkernel/sched/core.c:86:include/trace/events/sched.h:366: error: redefinition of ‘trace_get_sleeptime’include/trace/events/sched.h:366: note: previous definition of ‘trace_get_sleeptime’ was here
Quoted 2 lines
So I shamelessly copied what the other static inline function in the file does.
Ah, OK, it's because of the duplicate includes. Still ugly though. But we can clean that up later.
Quoted 5 lines
I also noticed that
sched_stat_sleeptime()is very similar tosched_stat_sleep(). The latter covers sleeps but not iowait and doesn't include the scheduler latency. Let me know if you think this is a show stopper that needs a rename.
what about sched_stat_iowait() too. As for latency, I don't know. That's more Peter's decision.
-- Steve
Re: [PATCH 2/2] tracing, sched: Add a new tracepoint for sleeptime
In reply to Arun Sharmainclude/trace/events/sched.h TRACE_EVENT(sched_stat_runtime, · line 373
Quoted 10 lines
include/trace/events/sched.h +8
-0+#ifdef CREATE_TRACE_POINTS +static inline u64 trace_get_sleeptime (struct task_struct *tsk) +{ +#ifdef CONFIG_SCHEDSTATS +u64 block, sleep; + + block = tsk->se.statistics.block_start; + sleep = tsk->se.statistics.sleep_start;
Arun, probably you have missed one of my comments. block_start and sleep_start should be zeroized here.
tsk->se.statistics.block_start = 0;tsk->se.statistics.sleep_start = 0;
The following program provokes this problem:
#include<unistd.h>
#include<time.h>
#include<sys/select.h>
int main()
{
struct timespec ts1;
struct timeval tv1;
int i;
long s;
for (i = 0; i< 1000; i++) {
ts1.tv_sec = 0;
ts1.tv_nsec = 1000000;
nanosleep(&ts1, NULL);
tv1.tv_sec = 0;
tv1.tv_usec = 4000;
select(0, NULL, NULL, NULL,&tv1);
if (i % 100 == 0) {
s = time(NULL);
while (time(NULL) - s < 4);
}
}
return 1;
}Quoted 55 lines
include/trace/events/sched.h +40
-0+ +return block ? block : sleep ? sleep :0 ; +#else +return 0 ; +#endif +} +#endif + +/* +* Tracepoint for accounting sleeptime (time the task is sleeping +* or waiting for I/O). +*/ +TRACE_EVENT (sched_stat_sleeptime, + + TP_PROTO(struct task_struct *tsk, u64 now), + +TP_ARGS (tsk, now), + +TP_STRUCT__entry ( + __array( char, comm, TASK_COMM_LEN ) + __field( pid_t, pid ) +__field ( u64, sleeptime ) + ), + + TP_fast_assign( + memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN); + __entry->pid = tsk->pid; + __entry->sleeptime = trace_get_sleeptime(tsk); + __entry->sleeptime = __entry->sleeptime ? + now - __entry->sleeptime : 0; + ) +TP_perf_assign ( + __perf_count(__entry->sleeptime); + ), + +TP_printk ("comm=%s pid=%d sleeptime=%Lu [ns]" , + __entry->comm, __entry->pid, + (unsigned long long )__entry->sleeptime) +); +/* * Tracepoint for showing priority inheritance modifying a tasks * priority. kernel/sched/core.c +1
-0@@ -1899,6 +1899,7 @@ static void finish_task_switch(struct rq *rq, struct task_struct *prev)local_irq_enable ();#endif /* __ARCH_WANT_INTERRUPTS_ON_CTXSW */ finish_lock_switch (rq, prev); +trace_sched_stat_sleeptime (current, rq->clock);fire_sched_in_preempt_notifiers (current);if (mm)
Re: [PATCH 2/2] tracing, sched: Add a new tracepoint for sleeptime
Quoted 7 lines · Andrey Vagin
Arun, probably you have missed one of my comments.
block_startandsleep_startshould be zeroized here.
tsk->se.statistics.block_start= 0;tsk->se.statistics.sleep_start= 0;The following program provokes this problem:
Yes - I overlooked the comment. Thanks for bringing it up (especially the test program). Fixed in v3.
-Arun
Re: [PATCH 2/2] tracing, sched: Add a new tracepoint for sleeptime
In reply to Andrey VaginQuoted 13 lines · Andrey Vagin
include/trace/events/sched.h TRACE_EVENT(sched_stat_runtime, · line 373
Quoted 10 lines
include/trace/events/sched.h +8
-0+#ifdef CREATE_TRACE_POINTS +static inline u64 trace_get_sleeptime (struct task_struct *tsk) +{ +#ifdef CONFIG_SCHEDSTATS +u64 block, sleep; + + block = tsk->se.statistics.block_start; + sleep = tsk->se.statistics.sleep_start;Arun, probably you have missed one of my comments.
block_startandsleep_startshould be zeroized here.
Quoted 2 lines
tsk->se.statistics.block_start= 0;tsk->se.statistics.sleep_start= 0;
This still doesn't solve one minor problem: the first sample we get might be bad. Here's the sequence that could trigger it:
t1: task goes to sleep. sleep_start=t1
t2: task gets woken up. sleep_start is still t1
t3: context switch. trace_get_sleeptime() is not active. sleep_start is still t1
t4: trace_get_sleeptime() is activated
t5: task gets context switched out involuntarily.
t6: task gets context switched in. first sample from the task.
We compute sleeptime=t6-t1. The correct answer should be sleeptime=0.
We should set {sleep,block}_start to 0 regardless of whether the tracepoint is active or not.
I'll post a patch shortly.
-Arun