@@ -1894,6 +1894,9 @@ struct task_struct {
#ifdef CONFIG_TRACE_DELAYED_TIMER_OFFSETS
long timer_offset;
#endif /* CONFIG_TRACE_DELAYED_TIMER_OFFSETS */
+#ifdef CONFIG_TRACE_EVENTS_WAKEUP_LATENCY
+ u64 wakeup_timestamp_start;
+#endif
#ifdef CONFIG_KCOV
/* Coverage collection mode enabled for this task (0 if disabled). */
enum kcov_mode kcov_mode;
@@ -562,6 +562,40 @@ TRACE_EVENT(sched_wake_idle_without_ipi,
TP_printk("cpu=%d", __entry->cpu)
);
+
+#ifdef CONFIG_TRACE_EVENTS_WAKEUP_LATENCY
+/**
+ * latency_wakeup - Called when process is woken up
+ * @next: task to be woken up
+ * @wakeup_lat: process wakeup latency in nano seconds
+ */
+TRACE_EVENT(latency_wakeup,
+
+ TP_PROTO(struct task_struct *next, u64 wakeup_latency),
+ TP_ARGS(next, wakeup_latency),
+
+ TP_STRUCT__entry(
+ __array(char, ccomm, TASK_COMM_LEN)
+ __field(int, cprio)
+ __field(unsigned long, wakeup_lat)
+ __field(unsigned long, timeroffset)
+ __field(unsigned long, total_lat)
+ ),
+
+ TP_fast_assign(
+ memcpy(__entry->ccomm, next->comm, TASK_COMM_LEN);
+ __entry->cprio = next->prio;
+ __entry->wakeup_lat = wakeup_latency;
+ __entry->timeroffset = next->timer_offset;
+ __entry->total_lat = wakeup_latency + next->timer_offset;
+ ),
+
+ TP_printk("curr=%s[%d] wakeup_lat=%lu timeroffset=%ld total_lat=%lu",
+ __entry->ccomm, __entry->cprio, __entry->wakeup_lat,
+ __entry->timeroffset, __entry->total_lat)
+);
+#endif
+
#endif /* _TRACE_SCHED_H */
/* This part must be outside protection */
@@ -634,6 +634,16 @@ config RING_BUFFER_STARTUP_TEST
If unsure, say N
+config TRACE_EVENTS_WAKEUP_LATENCY
+ bool "Trace wakeup latency events"
+ depends on TRACE_DELAYED_TIMER_OFFSETS
+ depends on SCHED_TRACER
+ help
+ Generate the total wakeup latency of a process. It includes the
+ wakeup latency and the timer offset latency. Wakeup latency is the
+ difference in the time when a process is scheduled to be woken up
+ and when it is actually woken up. It depends on the wakeup tracer.
+
config TRACE_ENUM_MAP_FILE
bool "Show enum mappings for trace events"
depends on TRACING
@@ -423,6 +423,29 @@ tracing_sched_wakeup_trace(struct trace_array *tr,
trace_buffer_unlock_commit(tr, buffer, event, flags, pc);
}
+#ifdef CONFIG_TRACE_EVENTS_WAKEUP_LATENCY
+static inline void latency_wakeup_start(struct task_struct *task, u64 ts)
+{
+ task->wakeup_timestamp_start = ts;
+}
+
+static inline void latency_wakeup_stop(struct task_struct *next, u64 ts)
+{
+ if (next->wakeup_timestamp_start != 0) {
+ trace_latency_wakeup(next, ts - next->wakeup_timestamp_start);
+ next->wakeup_timestamp_start = 0;
+ }
+}
+#else
+static inline void latency_wakeup_start(struct task_struct *task, u64 ts)
+{
+}
+
+static inline void latency_wakeup_stop(struct task_struct *next, u64 ts)
+{
+}
+#endif
+
static void notrace
probe_wakeup_sched_switch(void *ignore, bool preempt,
struct task_struct *prev, struct task_struct *next)
@@ -436,6 +459,10 @@ probe_wakeup_sched_switch(void *ignore, bool preempt,
tracing_record_cmdline(prev);
+ cpu = raw_smp_processor_id();
+ T1 = ftrace_now(cpu);
+ latency_wakeup_stop(next, (u64) T1);
+
if (unlikely(!tracer_enabled))
return;
@@ -454,7 +481,6 @@ probe_wakeup_sched_switch(void *ignore, bool preempt,
pc = preempt_count();
/* disable local data, not wakeup_cpu data */
- cpu = raw_smp_processor_id();
disabled = atomic_inc_return(&per_cpu_ptr(wakeup_trace->trace_buffer.data, cpu)->disabled);
if (likely(disabled != 1))
goto out;
@@ -473,7 +499,6 @@ probe_wakeup_sched_switch(void *ignore, bool preempt,
tracing_sched_switch_trace(wakeup_trace, prev, next, flags, pc);
T0 = data->preempt_timestamp;
- T1 = ftrace_now(cpu);
delta = T1-T0;
if (!report_latency(wakeup_trace, delta))
@@ -525,6 +550,10 @@ probe_wakeup(void *ignore, struct task_struct *p)
unsigned long flags;
long disabled;
int pc;
+ cycle_t T0;
+
+ T0 = ftrace_now(cpu);
+ latency_wakeup_start(p, (u64) T0);
if (likely(!tracer_enabled))
return;
@@ -580,7 +609,7 @@ probe_wakeup(void *ignore, struct task_struct *p)
local_save_flags(flags);
data = per_cpu_ptr(wakeup_trace->trace_buffer.data, wakeup_cpu);
- data->preempt_timestamp = ftrace_now(cpu);
+ data->preempt_timestamp = T0;
tracing_sched_wakeup_trace(wakeup_trace, p, current, flags, pc);
/*
These latencies usually occurs during the wakeup of a process. To determine this latency, the kernel stores the time stamp when a process is scheduled to be woken up, and determines the duration of the wakeup time shortly before control is passed over to this process. Note that the apparent latency in user space may be somewhat longer, since the process may be interrupted after control is passed over to it but before the execution in user space takes place. Simply measuring the interval between enqueuing and wakeup may also not appropriate in cases when a process is scheduled as a result of a timer expiration. The timer may have missed its deadline, e.g. due to disabled interrupts, but this latency would not be registered. Therefore, the offsets of missed hrtimers are recorded in the same histogram. The missed hrtimer offsets and the wakeup latency together contribute to the total latency. With the histogram triggers in place, the plots may be generated, with per-cpu breakdown of events captured and the latency measured in nanoseconds. The following histogram triggers may be used: 'hist:key=cpu,ccomm:val=wakeup_lat,total_lat:sort=cpu' 'hist:key=cpu,ccomm:val=timeroffset,total_lat:sort=cpu' 'hist:key=cpu,ccomm:val=total_lat:sort=cpu' 'hist:key=ccomm:val=total_lat if cpu==0' Enable the tracer 'wakeup' or 'wakeup_rt' to capture wakeup latencies of the respective processes. In '/sys/kernel/debug/tracing' echo wakeup > current_tracer [ Initial work and idea by Carsten Link: https://git.kernel.org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v3.14-rt-rebase&id=56d50cc34943bbba12b8c5942ee1ae3b29f73acb ] Cc: Carsten Emde <C.Emde@osadl.org> Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org> --- include/linux/sched.h | 3 +++ include/trace/events/sched.h | 34 ++++++++++++++++++++++++++++++++++ kernel/trace/Kconfig | 10 ++++++++++ kernel/trace/trace_sched_wakeup.c | 35 ++++++++++++++++++++++++++++++++--- 4 files changed, 79 insertions(+), 3 deletions(-) -- The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, a Linux Foundation Collaborative Project