| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Tue, 20 Sep 2016 19:21:57 +0530
From: Binoy Jayan <binoy.jayan@...aro.org>
To: "Steven Rostedt (Red Hat)" <rostedt@...dmis.org>,
Thomas Gleixner <tglx@...utronix.de>
Cc: Ingo Molnar <mingo@...hat.com>,
Daniel Wagner <daniel.wagner@...-carit.de>,
Arnd Bergmann <arnd@...db.de>, linux-kernel@...r.kernel.org,
Masami <masami.hiramatsu@...aro.org>,
Mark Brown <mark.brown@...aro.org>,
Binoy Jayan <binoy.jayan@...aro.org>,
Carsten Emde <C.Emde@...dl.org>
Subject: [RFC PATCH v7 5/5] tracing: wakeup latency events and histograms
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@...dl.org>
Signed-off-by: Binoy Jayan <binoy.jayan@...aro.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(-)
diff --git a/include/linux/sched.h b/include/linux/sched.h
index 7bf67f8..82f3b62 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -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;
diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index 9b90c57..c8b81d0 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -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 */
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index f4b86e8..20cf135 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -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
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index 9d4399b..ec9e5a8 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -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);
/*
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project
Powered by blists - more mailing lists