* [PATCH 0/2] *** Latency Histogram ***
@ 2016-07-28 4:52 Binoy Jayan
2016-07-28 4:52 ` [PATCH 1/2] tracing: Add latency histograms Binoy Jayan
` (2 more replies)
0 siblings, 3 replies; 6+ messages in thread
From: Binoy Jayan @ 2016-07-28 4:52 UTC (permalink / raw)
To: Steven Rostedt; +Cc: linux-kernel, Binoy Jayan
Hi,
I was looking at these RT kernel patches and was wondering why it has
not been upstreamed yet. I have made a few changes to these patches to
make it compliant with upstream submission process. Also did a minimal
testing on my msm board. Can some one from rt kernel team shed some
light on why this is not upstreamed yet? Also if there some way to test
this throroughly on a board with a high resolution timer running mainline
(and not rt) kernel.
Binoy
Carsten Emde (1):
tracing: Add latency histograms
Yang Shi (1):
trace: Add missing tracer macros
Documentation/trace/histograms.txt | 186 ++++++
include/linux/hrtimer.h | 3 +
include/linux/sched.h | 6 +
include/trace/events/hist.h | 74 +++
include/trace/events/latency_hist.h | 136 +++++
kernel/time/hrtimer.c | 20 +
kernel/trace/Kconfig | 104 ++++
kernel/trace/Makefile | 4 +
kernel/trace/latency_hist.c | 1091 +++++++++++++++++++++++++++++++++++
kernel/trace/trace_irqsoff.c | 9 +
10 files changed, 1633 insertions(+)
create mode 100644 Documentation/trace/histograms.txt
create mode 100644 include/trace/events/hist.h
create mode 100644 include/trace/events/latency_hist.h
create mode 100644 kernel/trace/latency_hist.c
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project
^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH 1/2] tracing: Add latency histograms
2016-07-28 4:52 [PATCH 0/2] *** Latency Histogram *** Binoy Jayan
@ 2016-07-28 4:52 ` Binoy Jayan
2016-07-28 18:51 ` Carsten Emde
2016-07-28 4:52 ` [PATCH 2/2] trace: Add missing tracer macros Binoy Jayan
2016-07-28 13:10 ` [PATCH 0/2] *** Latency Histogram *** Steven Rostedt
2 siblings, 1 reply; 6+ messages in thread
From: Binoy Jayan @ 2016-07-28 4:52 UTC (permalink / raw)
To: Steven Rostedt; +Cc: linux-kernel, Carsten Emde, Thomas Gleixner, Binoy Jayan
From: Carsten Emde <C.Emde@osadl.org>
This patch provides a recording mechanism to store data of potential
sources of system latencies. The recordings separately determine the
latency caused by a delayed timer expiration, by a delayed wakeup of the
related user space program and by the sum of both. The histograms can be
enabled and reset individually. The data are accessible via the debug
filesystem. The patch is adapted from the rt kernel and restructured to
avoid unwanted macros from source files. For details please consult
Documentation/trace/histograms.txt.
Signed-off-by: Carsten Emde <C.Emde@osadl.org>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org>
---
Documentation/trace/histograms.txt | 186 ++++++
include/linux/hrtimer.h | 3 +
include/linux/sched.h | 6 +
include/trace/events/hist.h | 72 +++
include/trace/events/latency_hist.h | 136 +++++
kernel/time/hrtimer.c | 20 +
kernel/trace/Kconfig | 104 ++++
kernel/trace/Makefile | 4 +
kernel/trace/latency_hist.c | 1091 +++++++++++++++++++++++++++++++++++
kernel/trace/trace_irqsoff.c | 9 +
10 files changed, 1631 insertions(+)
create mode 100644 Documentation/trace/histograms.txt
create mode 100644 include/trace/events/hist.h
create mode 100644 include/trace/events/latency_hist.h
create mode 100644 kernel/trace/latency_hist.c
diff --git a/Documentation/trace/histograms.txt b/Documentation/trace/histograms.txt
new file mode 100644
index 0000000..60644ff
--- /dev/null
+++ b/Documentation/trace/histograms.txt
@@ -0,0 +1,186 @@
+ Using the Linux Kernel Latency Histograms
+
+
+This document gives a short explanation how to enable, configure and use
+latency histograms. Latency histograms are primarily relevant in the
+context of real-time enabled kernels (CONFIG_PREEMPT/CONFIG_PREEMPT_RT)
+and are used in the quality management of the Linux real-time
+capabilities.
+
+
+* Purpose of latency histograms
+
+A latency histogram continuously accumulates the frequencies of latency
+data. There are two types of histograms
+- potential sources of latencies
+- effective latencies
+
+
+* Potential sources of latencies
+
+Potential sources of latencies are code segments where interrupts,
+preemption or both are disabled (aka critical sections). To create
+histograms of potential sources of latency, the kernel stores the time
+stamp at the start of a critical section, determines the time elapsed
+when the end of the section is reached, and increments the frequency
+counter of that latency value - irrespective of whether any concurrently
+running process is affected by latency or not.
+- Configuration items (in the Kernel hacking/Tracers submenu)
+ CONFIG_INTERRUPT_OFF_LATENCY
+ CONFIG_PREEMPT_OFF_LATENCY
+
+
+* Effective latencies
+
+Effective latencies are actually occurring during wakeup of a process. To
+determine effective latencies, 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 timers are
+recorded in a separate histogram. If both wakeup latency and missed timer
+offsets are configured and enabled, a third histogram may be enabled that
+records the overall latency as a sum of the timer latency, if any, and the
+wakeup latency. This histogram is called "timerandwakeup".
+- Configuration items (in the Kernel hacking/Tracers submenu)
+ CONFIG_WAKEUP_LATENCY
+ CONFIG_MISSED_TIMER_OFSETS
+
+
+* Usage
+
+The interface to the administration of the latency histograms is located
+in the debugfs file system. To mount it, either enter
+
+mount -t sysfs nodev /sys
+mount -t debugfs nodev /sys/kernel/debug
+
+from shell command line level, or add
+
+nodev /sys sysfs defaults 0 0
+nodev /sys/kernel/debug debugfs defaults 0 0
+
+to the file /etc/fstab. All latency histogram related files are then
+available in the directory /sys/kernel/debug/tracing/latency_hist. A
+particular histogram type is enabled by writing non-zero to the related
+variable in the /sys/kernel/debug/tracing/latency_hist/enable directory.
+Select "preemptirqsoff" for the histograms of potential sources of
+latencies and "wakeup" for histograms of effective latencies etc. The
+histogram data - one per CPU - are available in the files
+
+/sys/kernel/debug/tracing/latency_hist/preemptoff/CPUx
+/sys/kernel/debug/tracing/latency_hist/irqsoff/CPUx
+/sys/kernel/debug/tracing/latency_hist/preemptirqsoff/CPUx
+/sys/kernel/debug/tracing/latency_hist/wakeup/CPUx
+/sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio/CPUx
+/sys/kernel/debug/tracing/latency_hist/missed_timer_offsets/CPUx
+/sys/kernel/debug/tracing/latency_hist/timerandwakeup/CPUx
+
+The histograms are reset by writing non-zero to the file "reset" in a
+particular latency directory. To reset all latency data, use
+
+#!/bin/sh
+
+TRACINGDIR=/sys/kernel/debug/tracing
+HISTDIR=$TRACINGDIR/latency_hist
+
+if test -d $HISTDIR
+then
+ cd $HISTDIR
+ for i in `find . | grep /reset$`
+ do
+ echo 1 >$i
+ done
+fi
+
+
+* Data format
+
+Latency data are stored with a resolution of one microsecond. The
+maximum latency is 10,240 microseconds. The data are only valid, if the
+overflow register is empty. Every output line contains the latency in
+microseconds in the first row and the number of samples in the second
+row. To display only lines with a positive latency count, use, for
+example,
+
+grep -v " 0$" /sys/kernel/debug/tracing/latency_hist/preemptoff/CPU0
+
+#Minimum latency: 0 microseconds.
+#Average latency: 0 microseconds.
+#Maximum latency: 25 microseconds.
+#Total samples: 3104770694
+#There are 0 samples greater or equal than 10240 microseconds
+#usecs samples
+ 0 2984486876
+ 1 49843506
+ 2 58219047
+ 3 5348126
+ 4 2187960
+ 5 3388262
+ 6 959289
+ 7 208294
+ 8 40420
+ 9 4485
+ 10 14918
+ 11 18340
+ 12 25052
+ 13 19455
+ 14 5602
+ 15 969
+ 16 47
+ 17 18
+ 18 14
+ 19 1
+ 20 3
+ 21 2
+ 22 5
+ 23 2
+ 25 1
+
+
+* Wakeup latency of a selected process
+
+To only collect wakeup latency data of a particular process, write the
+PID of the requested process to
+
+/sys/kernel/debug/tracing/latency_hist/wakeup/pid
+
+PIDs are not considered, if this variable is set to 0.
+
+
+* Details of the process with the highest wakeup latency so far
+
+Selected data of the process that suffered from the highest wakeup
+latency that occurred in a particular CPU are available in the file
+
+/sys/kernel/debug/tracing/latency_hist/wakeup/max_latency-CPUx.
+
+In addition, other relevant system data at the time when the
+latency occurred are given.
+
+The format of the data is (all in one line):
+<PID> <Priority> <Latency> (<Timeroffset>) <Command> \
+<- <PID> <Priority> <Command> <Timestamp>
+
+The value of <Timeroffset> is only relevant in the combined timer
+and wakeup latency recording. In the wakeup recording, it is
+always 0, in the missed_timer_offsets recording, it is the same
+as <Latency>.
+
+When retrospectively searching for the origin of a latency and
+tracing was not enabled, it may be helpful to know the name and
+some basic data of the task that (finally) was switching to the
+late real-tlme task. In addition to the victim's data, also the
+data of the possible culprit are therefore displayed after the
+"<-" symbol.
+
+Finally, the timestamp of the time when the latency occurred
+in <seconds>.<microseconds> after the most recent system boot
+is provided.
+
+These data are also reset when the wakeup histogram is reset.
diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h
index c98c653..f73935b 100644
--- a/include/linux/hrtimer.h
+++ b/include/linux/hrtimer.h
@@ -104,6 +104,9 @@ struct hrtimer {
struct hrtimer_clock_base *base;
u8 state;
u8 is_rel;
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+ ktime_t praecox;
+#endif
#ifdef CONFIG_TIMER_STATS
int start_pid;
void *start_site;
diff --git a/include/linux/sched.h b/include/linux/sched.h
index 253538f..a96735b 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -1885,6 +1885,12 @@ struct task_struct {
unsigned long trace;
/* bitmask and counter of trace recursion */
unsigned long trace_recursion;
+#ifdef CONFIG_WAKEUP_LATENCY_HIST
+ u64 preempt_timestamp_hist;
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+ long timer_offset;
+#endif
+#endif
#endif /* CONFIG_TRACING */
#ifdef CONFIG_KCOV
/* Coverage collection mode enabled for this task (0 if disabled). */
diff --git a/include/trace/events/hist.h b/include/trace/events/hist.h
new file mode 100644
index 0000000..6122e42
--- /dev/null
+++ b/include/trace/events/hist.h
@@ -0,0 +1,72 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM hist
+
+#if !defined(_TRACE_HIST_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_HIST_H
+
+#include "latency_hist.h"
+#include <linux/tracepoint.h>
+
+#if !defined(CONFIG_PREEMPT_OFF_HIST) && !defined(CONFIG_INTERRUPT_OFF_HIST)
+#define trace_preemptirqsoff_hist(a, b)
+#else
+TRACE_EVENT(preemptirqsoff_hist,
+
+ TP_PROTO(int reason, int starthist),
+
+ TP_ARGS(reason, starthist),
+
+ TP_STRUCT__entry(
+ __field(int, reason)
+ __field(int, starthist)
+ ),
+
+ TP_fast_assign(
+ __entry->reason = reason;
+ __entry->starthist = starthist;
+ ),
+
+ TP_printk("reason=%s starthist=%s", getaction(__entry->reason),
+ __entry->starthist ? "start" : "stop")
+);
+#endif
+
+#ifndef CONFIG_MISSED_TIMER_OFFSETS_HIST
+#define trace_hrtimer_interrupt(a, b, c, d)
+#else
+TRACE_EVENT(hrtimer_interrupt,
+
+ TP_PROTO(int cpu, long long offset, struct task_struct *curr,
+ struct task_struct *task),
+
+ TP_ARGS(cpu, offset, curr, task),
+
+ TP_STRUCT__entry(
+ __field(int, cpu)
+ __field(long long, offset)
+ __array(char, ccomm, TASK_COMM_LEN)
+ __field(int, cprio)
+ __array(char, tcomm, TASK_COMM_LEN)
+ __field(int, tprio)
+ ),
+
+ TP_fast_assign(
+ __entry->cpu = cpu;
+ __entry->offset = offset;
+ memcpy(__entry->ccomm, curr->comm, TASK_COMM_LEN);
+ __entry->cprio = curr->prio;
+ memcpy(__entry->tcomm, task != NULL ? task->comm : "<none>",
+ task != NULL ? TASK_COMM_LEN : 7);
+ __entry->tprio = task != NULL ? task->prio : -1;
+ ),
+
+ TP_printk("cpu=%d offset=%lld curr=%s[%d] thread=%s[%d]",
+ __entry->cpu, __entry->offset, __entry->ccomm,
+ __entry->cprio, __entry->tcomm, __entry->tprio)
+);
+#endif
+
+#endif /* _TRACE_HIST_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/include/trace/events/latency_hist.h b/include/trace/events/latency_hist.h
new file mode 100644
index 0000000..6478496
--- /dev/null
+++ b/include/trace/events/latency_hist.h
@@ -0,0 +1,136 @@
+#ifndef _LATENCY_HIST_H
+#define _LATENCY_HIST_H
+
+enum hist_action {
+ IRQS_ON,
+ PREEMPT_ON,
+ TRACE_STOP,
+ IRQS_OFF,
+ PREEMPT_OFF,
+ TRACE_START,
+};
+
+static char *actions[] = {
+ "IRQS_ON",
+ "PREEMPT_ON",
+ "TRACE_STOP",
+ "IRQS_OFF",
+ "PREEMPT_OFF",
+ "TRACE_START",
+};
+
+enum {
+ IRQSOFF_LATENCY = 0,
+ PREEMPTOFF_LATENCY,
+ PREEMPTIRQSOFF_LATENCY,
+ WAKEUP_LATENCY,
+ WAKEUP_LATENCY_SHAREDPRIO,
+ MISSED_TIMER_OFFSETS,
+ TIMERANDWAKEUP_LATENCY,
+ MAX_LATENCY_TYPE,
+};
+
+#define MAX_ENTRY_NUM 10240
+
+struct hist_data {
+ atomic_t hist_mode; /* 0 log, 1 don't log */
+ long offset; /* set it to MAX_ENTRY_NUM/2 for a bipolar scale */
+ long min_lat;
+ long max_lat;
+ unsigned long long below_hist_bound_samples;
+ unsigned long long above_hist_bound_samples;
+ long long accumulate_lat;
+ unsigned long long total_samples;
+ unsigned long long hist_array[MAX_ENTRY_NUM];
+};
+
+struct enable_data {
+ int latency_type;
+ int enabled;
+};
+
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+struct maxlatproc_data {
+ char comm[FIELD_SIZEOF(struct task_struct, comm)];
+ char current_comm[FIELD_SIZEOF(struct task_struct, comm)];
+ int pid;
+ int current_pid;
+ int prio;
+ int current_prio;
+ long latency;
+ long timeroffset;
+ cycle_t timestamp;
+};
+extern void clear_maxlatprocdata(struct maxlatproc_data *mp);
+extern ssize_t
+show_pid(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos);
+extern ssize_t
+show_maxlatproc(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos);
+#else
+void clear_maxlatprocdata(struct maxlatproc_data *mp)
+{
+}
+static ssize_t
+show_pid(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+}
+static ssize_t
+show_maxlatproc(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+}
+#endif
+
+#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST)
+extern notrace void probe_preemptirqsoff_hist(void *v, int reason,
+ int starthist);
+#else
+static notrace void probe_preemptirqsoff_hist(void *v, int reason,
+ int starthist)
+{
+}
+#endif
+
+#ifdef CONFIG_WAKEUP_LATENCY_HIST
+extern notrace void probe_sched_migrate_task(void *v, struct task_struct *task,
+ int cpu);
+extern notrace void probe_wakeup_latency_hist_start(void *v,
+ struct task_struct *p);
+extern notrace void probe_wakeup_latency_hist_stop(void *v, bool preempt,
+ struct task_struct *prev, struct task_struct *next);
+#else
+static notrace void probe_sched_migrate_task(void *v, struct task_struct *task,
+ int cpu)
+{
+}
+static notrace void probe_wakeup_latency_hist_start(void *v,
+ struct task_struct *p)
+{
+}
+static notrace void probe_wakeup_latency_hist_stop(void *v, bool preempt,
+ struct task_struct *prev, struct task_struct *next)
+{
+}
+#endif
+
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+extern notrace void probe_hrtimer_interrupt(void *v, int cpu,
+ long long latency_ns, struct task_struct *curr,
+ struct task_struct *task);
+#else
+static notrace void probe_hrtimer_interrupt(void *v, int cpu,
+ long long latency_ns, struct task_struct *curr,
+ struct task_struct *task)
+{
+}
+#endif
+
+static inline char *getaction(int action)
+{
+ if (action >= 0 && action <= ARRAY_SIZE(actions))
+ return actions[action];
+ return "unknown";
+}
+
+#endif /* _LATENCY_HIST_H */
+
diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
index e99df0f..0a0ca23 100644
--- a/kernel/time/hrtimer.c
+++ b/kernel/time/hrtimer.c
@@ -53,6 +53,7 @@
#include <asm/uaccess.h>
#include <trace/events/timer.h>
+#include <trace/events/hist.h>
#include "tick-internal.h"
@@ -991,6 +992,14 @@ void hrtimer_start_range_ns(struct hrtimer *timer, ktime_t tim,
new_base = switch_hrtimer_base(timer, base, mode & HRTIMER_MODE_PINNED);
timer_stats_hrtimer_set_start_info(timer);
+ if (IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ ktime_t now = new_base->get_time();
+
+ if (ktime_to_ns(tim) < ktime_to_ns(now))
+ timer->praecox = now;
+ else
+ timer->praecox = ktime_set(0, 0);
+ }
leftmost = enqueue_hrtimer(timer, new_base);
if (!leftmost)
@@ -1265,6 +1274,8 @@ static void __run_hrtimer(struct hrtimer_cpu_base *cpu_base,
cpu_base->running = NULL;
}
+static enum hrtimer_restart hrtimer_wakeup(struct hrtimer *timer);
+
static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
{
struct hrtimer_clock_base *base = cpu_base->clock_base;
@@ -1284,6 +1295,15 @@ static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
timer = container_of(node, struct hrtimer, node);
+ trace_hrtimer_interrupt(raw_smp_processor_id(),
+ ktime_to_ns(ktime_sub(ktime_to_ns(timer->praecox) ?
+ timer->praecox : hrtimer_get_expires(timer),
+ basenow)),
+ current,
+ timer->function == hrtimer_wakeup ?
+ container_of(timer, struct hrtimer_sleeper,
+ timer)->task : NULL);
+
/*
* The immediate goal for using the softexpires is
* minimizing wakeups, not running timers at the
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index fafeaf8..ae80502 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -187,6 +187,24 @@ config IRQSOFF_TRACER
enabled. This option and the preempt-off timing option can be
used together or separately.)
+config INTERRUPT_OFF_HIST
+ bool "Interrupts-off Latency Histogram"
+ depends on IRQSOFF_TRACER
+ help
+ This option generates continuously updated histograms (one per cpu)
+ of the duration of time periods with interrupts disabled. The
+ histograms are disabled by default. To enable them, write a non-zero
+ number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/preemptirqsoff
+
+ If PREEMPT_OFF_HIST is also selected, additional histograms (one
+ per cpu) are generated that accumulate the duration of time periods
+ when both interrupts and preemption are disabled. The histogram data
+ will be located in the debug file system at
+
+ /sys/kernel/debug/tracing/latency_hist/irqsoff
+
config PREEMPT_TRACER
bool "Preemption-off Latency Tracer"
default n
@@ -211,6 +229,24 @@ config PREEMPT_TRACER
enabled. This option and the irqs-off timing option can be
used together or separately.)
+config PREEMPT_OFF_HIST
+ bool "Preemption-off Latency Histogram"
+ depends on PREEMPT_TRACER
+ help
+ This option generates continuously updated histograms (one per cpu)
+ of the duration of time periods with preemption disabled. The
+ histograms are disabled by default. To enable them, write a non-zero
+ number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/preemptirqsoff
+
+ If INTERRUPT_OFF_HIST is also selected, additional histograms (one
+ per cpu) are generated that accumulate the duration of time periods
+ when both interrupts and preemption are disabled. The histogram data
+ will be located in the debug file system at
+
+ /sys/kernel/debug/tracing/latency_hist/preemptoff
+
config SCHED_TRACER
bool "Scheduling Latency Tracer"
select GENERIC_TRACER
@@ -221,6 +257,74 @@ config SCHED_TRACER
This tracer tracks the latency of the highest priority task
to be scheduled in, starting from the point it has woken up.
+config WAKEUP_LATENCY_HIST
+ bool "Scheduling Latency Histogram"
+ depends on SCHED_TRACER
+ help
+ This option generates continuously updated histograms (one per cpu)
+ of the scheduling latency of the highest priority task.
+ The histograms are disabled by default. To enable them, write a
+ non-zero number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/wakeup
+
+ Two different algorithms are used, one to determine the latency of
+ processes that exclusively use the highest priority of the system and
+ another one to determine the latency of processes that share the
+ highest system priority with other processes. The former is used to
+ improve hardware and system software, the latter to optimize the
+ priority design of a given system. The histogram data will be
+ located in the debug file system at
+
+ /sys/kernel/debug/tracing/latency_hist/wakeup
+
+ and
+
+ /sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio
+
+ If both Scheduling Latency Histogram and Missed Timer Offsets
+ Histogram are selected, additional histogram data will be collected
+ that contain, in addition to the wakeup latency, the timer latency, in
+ case the wakeup was triggered by an expired timer. These histograms
+ are available in the
+
+ /sys/kernel/debug/tracing/latency_hist/timerandwakeup
+
+ directory. They reflect the apparent interrupt and scheduling latency
+ and are best suitable to determine the worst-case latency of a given
+ system. To enable these histograms, write a non-zero number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/timerandwakeup
+
+config MISSED_TIMER_OFFSETS_HIST
+ depends on HIGH_RES_TIMERS
+ select GENERIC_TRACER
+ bool "Missed Timer Offsets Histogram"
+ help
+ Generate a histogram of missed timer offsets in microseconds. The
+ histograms are disabled by default. To enable them, write a non-zero
+ number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/missed_timer_offsets
+
+ The histogram data will be located in the debug file system at
+
+ /sys/kernel/debug/tracing/latency_hist/missed_timer_offsets
+
+ If both Scheduling Latency Histogram and Missed Timer Offsets
+ Histogram are selected, additional histogram data will be collected
+ that contain, in addition to the wakeup latency, the timer latency, in
+ case the wakeup was triggered by an expired timer. These histograms
+ are available in the
+
+ /sys/kernel/debug/tracing/latency_hist/timerandwakeup
+
+ directory. They reflect the apparent interrupt and scheduling latency
+ and are best suitable to determine the worst-case latency of a given
+ system. To enable these histograms, write a non-zero number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/timerandwakeup
+
config ENABLE_DEFAULT_TRACERS
bool "Trace process context switches and events"
depends on !GENERIC_TRACER
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 979e7bf..1a27aad 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -37,6 +37,10 @@ obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o
obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
obj-$(CONFIG_PREEMPT_TRACER) += trace_irqsoff.o
obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o
+obj-$(CONFIG_INTERRUPT_OFF_HIST) += latency_hist.o
+obj-$(CONFIG_PREEMPT_OFF_HIST) += latency_hist.o
+obj-$(CONFIG_WAKEUP_LATENCY_HIST) += latency_hist.o
+obj-$(CONFIG_MISSED_TIMER_OFFSETS_HIST) += latency_hist.o
obj-$(CONFIG_NOP_TRACER) += trace_nop.o
obj-$(CONFIG_STACK_TRACER) += trace_stack.o
obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o
diff --git a/kernel/trace/latency_hist.c b/kernel/trace/latency_hist.c
new file mode 100644
index 0000000..45a6b9f
--- /dev/null
+++ b/kernel/trace/latency_hist.c
@@ -0,0 +1,1091 @@
+/*
+ * kernel/trace/latency_hist.c
+ *
+ * Add support for histograms of preemption-off latency and
+ * interrupt-off latency and wakeup latency, it depends on
+ * Real-Time Preemption Support.
+ *
+ * Copyright (C) 2005 MontaVista Software, Inc.
+ * Yi Yang <yyang@ch.mvista.com>
+ *
+ * Converted to work with the new latency tracer.
+ * Copyright (C) 2008 Red Hat, Inc.
+ * Steven Rostedt <srostedt@redhat.com>
+ *
+ */
+#include <linux/module.h>
+#include <linux/debugfs.h>
+#include <linux/seq_file.h>
+#include <linux/percpu.h>
+#include <linux/kallsyms.h>
+#include <linux/uaccess.h>
+#include <linux/sched.h>
+#include <linux/sched/rt.h>
+#include <linux/slab.h>
+#include <linux/atomic.h>
+#include <asm/div64.h>
+
+#include "trace.h"
+#include <trace/events/sched.h>
+
+#define NSECS_PER_USECS 1000L
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/hist.h>
+
+static char *latency_hist_dir_root = "latency_hist";
+
+static int __maybe_unused one = 1;
+
+static DEFINE_PER_CPU(struct __maybe_unused hist_data, irqsoff_hist);
+static char *irqsoff_hist_dir __maybe_unused = "irqsoff";
+static DEFINE_PER_CPU(cycles_t __maybe_unused, hist_irqsoff_start);
+static DEFINE_PER_CPU(int __maybe_unused, hist_irqsoff_counting);
+
+static DEFINE_PER_CPU(struct __maybe_unused hist_data, preemptoff_hist);
+static char *preemptoff_hist_dir __maybe_unused = "preemptoff";
+static DEFINE_PER_CPU(cycles_t __maybe_unused, hist_preemptoff_start);
+static DEFINE_PER_CPU(int __maybe_unused, hist_preemptoff_counting);
+
+static DEFINE_PER_CPU(struct __maybe_unused hist_data, preemptirqsoff_hist);
+static char *preemptirqsoff_hist_dir __maybe_unused = "preemptirqsoff";
+static DEFINE_PER_CPU(cycles_t __maybe_unused, hist_preemptirqsoff_start);
+static DEFINE_PER_CPU(int __maybe_unused, hist_preemptirqsoff_counting);
+
+static struct enable_data __maybe_unused preemptirqsoff_enabled_data = {
+ .latency_type = PREEMPTIRQSOFF_LATENCY,
+ .enabled = 0,
+};
+
+static DEFINE_PER_CPU(struct __maybe_unused hist_data, wakeup_latency_hist);
+static DEFINE_PER_CPU(struct __maybe_unused hist_data,
+ wakeup_latency_hist_sharedprio);
+static char *wakeup_latency_hist_dir __maybe_unused = "wakeup";
+static char *wakeup_latency_hist_dir_sharedprio __maybe_unused = "sharedprio";
+static struct enable_data __maybe_unused wakeup_latency_enabled_data = {
+ .latency_type = WAKEUP_LATENCY,
+ .enabled = 0,
+};
+
+static DEFINE_PER_CPU(struct maxlatproc_data, wakeup_maxlatproc);
+static DEFINE_PER_CPU(struct maxlatproc_data, wakeup_maxlatproc_sharedprio);
+static DEFINE_PER_CPU(struct task_struct *, wakeup_task);
+static DEFINE_PER_CPU(int, wakeup_sharedprio);
+static unsigned long wakeup_pid;
+
+static DEFINE_PER_CPU(struct __maybe_unused hist_data, missed_timer_offsets);
+static char *missed_timer_offsets_dir __maybe_unused = "missed_timer_offsets";
+static struct enable_data __maybe_unused missed_timer_offsets_enabled_data = {
+ .latency_type = MISSED_TIMER_OFFSETS,
+ .enabled = 0,
+};
+static DEFINE_PER_CPU(struct __maybe_unused maxlatproc_data,
+ missed_timer_offsets_maxlatproc);
+static unsigned long __maybe_unused missed_timer_offsets_pid;
+
+static DEFINE_PER_CPU(struct __maybe_unused hist_data,
+ timerandwakeup_latency_hist);
+static char *timerandwakeup_latency_hist_dir __maybe_unused = "timerandwakeup";
+static struct enable_data __maybe_unused timerandwakeup_enabled_data = {
+ .latency_type = TIMERANDWAKEUP_LATENCY,
+ .enabled = 0,
+};
+static DEFINE_PER_CPU(struct __maybe_unused maxlatproc_data,
+ timerandwakeup_maxlatproc);
+
+void notrace latency_hist(int latency_type, int cpu, long latency,
+ long timeroffset, cycle_t stop,
+ struct task_struct *p)
+{
+ struct hist_data *my_hist;
+ struct maxlatproc_data *mp __maybe_unused = NULL;
+
+ if (!cpu_possible(cpu) || latency_type < 0 ||
+ latency_type >= MAX_LATENCY_TYPE)
+ return;
+
+ switch (latency_type) {
+ case IRQSOFF_LATENCY:
+ my_hist = &per_cpu(irqsoff_hist, cpu);
+ break;
+ case PREEMPTOFF_LATENCY:
+ my_hist = &per_cpu(preemptoff_hist, cpu);
+ break;
+ case PREEMPTIRQSOFF_LATENCY:
+ my_hist = &per_cpu(preemptirqsoff_hist, cpu);
+ break;
+ case WAKEUP_LATENCY:
+ my_hist = &per_cpu(wakeup_latency_hist, cpu);
+ mp = &per_cpu(wakeup_maxlatproc, cpu);
+ break;
+ case WAKEUP_LATENCY_SHAREDPRIO:
+ my_hist = &per_cpu(wakeup_latency_hist_sharedprio, cpu);
+ mp = &per_cpu(wakeup_maxlatproc_sharedprio, cpu);
+ break;
+ case MISSED_TIMER_OFFSETS:
+ my_hist = &per_cpu(missed_timer_offsets, cpu);
+ mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu);
+ break;
+ case TIMERANDWAKEUP_LATENCY:
+ my_hist = &per_cpu(timerandwakeup_latency_hist, cpu);
+ mp = &per_cpu(timerandwakeup_maxlatproc, cpu);
+ break;
+ default:
+ return;
+ }
+
+ latency += my_hist->offset;
+
+ if (atomic_read(&my_hist->hist_mode) == 0)
+ return;
+
+ if (latency < 0 || latency >= MAX_ENTRY_NUM) {
+ if (latency < 0)
+ my_hist->below_hist_bound_samples++;
+ else
+ my_hist->above_hist_bound_samples++;
+ } else
+ my_hist->hist_array[latency]++;
+
+ if (unlikely(latency > my_hist->max_lat ||
+ my_hist->min_lat == LONG_MAX)) {
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST) ||
+ IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ if (latency_type == WAKEUP_LATENCY ||
+ latency_type == WAKEUP_LATENCY_SHAREDPRIO ||
+ latency_type == MISSED_TIMER_OFFSETS ||
+ latency_type == TIMERANDWAKEUP_LATENCY) {
+ strncpy(mp->comm, p->comm, sizeof(mp->comm));
+ strncpy(mp->current_comm, current->comm,
+ sizeof(mp->current_comm));
+ mp->pid = task_pid_nr(p);
+ mp->current_pid = task_pid_nr(current);
+ mp->prio = p->prio;
+ mp->current_prio = current->prio;
+ mp->latency = latency;
+ mp->timeroffset = timeroffset;
+ mp->timestamp = stop;
+ }
+ }
+ my_hist->max_lat = latency;
+ }
+ if (unlikely(latency < my_hist->min_lat))
+ my_hist->min_lat = latency;
+ my_hist->total_samples++;
+ my_hist->accumulate_lat += latency;
+}
+
+static void *l_start(struct seq_file *m, loff_t *pos)
+{
+ loff_t *index_ptr = NULL;
+ loff_t index = *pos;
+ struct hist_data *my_hist = m->private;
+
+ if (index == 0) {
+ char minstr[32], avgstr[32], maxstr[32];
+
+ atomic_dec(&my_hist->hist_mode);
+
+ if (likely(my_hist->total_samples)) {
+ long avg = (long) div64_s64(my_hist->accumulate_lat,
+ my_hist->total_samples);
+ snprintf(minstr, sizeof(minstr), "%ld",
+ my_hist->min_lat - my_hist->offset);
+ snprintf(avgstr, sizeof(avgstr), "%ld",
+ avg - my_hist->offset);
+ snprintf(maxstr, sizeof(maxstr), "%ld",
+ my_hist->max_lat - my_hist->offset);
+ } else {
+ strcpy(minstr, "<undef>");
+ strcpy(avgstr, minstr);
+ strcpy(maxstr, minstr);
+ }
+
+ seq_printf(m, "#Minimum latency: %s microseconds\n"
+ "#Average latency: %s microseconds\n"
+ "#Maximum latency: %s microseconds\n"
+ "#Total samples: %llu\n"
+ "#There are %llu samples lower than %ld"
+ " microseconds.\n"
+ "#There are %llu samples greater or equal"
+ " than %ld microseconds.\n"
+ "#usecs\t%16s\n",
+ minstr, avgstr, maxstr,
+ my_hist->total_samples,
+ my_hist->below_hist_bound_samples,
+ -my_hist->offset,
+ my_hist->above_hist_bound_samples,
+ MAX_ENTRY_NUM - my_hist->offset,
+ "samples");
+ }
+ if (index < MAX_ENTRY_NUM) {
+ index_ptr = kmalloc(sizeof(loff_t), GFP_KERNEL);
+ if (index_ptr)
+ *index_ptr = index;
+ }
+
+ return index_ptr;
+}
+
+static void *l_next(struct seq_file *m, void *p, loff_t *pos)
+{
+ loff_t *index_ptr = p;
+ struct hist_data *my_hist = m->private;
+
+ if (++*pos >= MAX_ENTRY_NUM) {
+ atomic_inc(&my_hist->hist_mode);
+ return NULL;
+ }
+ *index_ptr = *pos;
+ return index_ptr;
+}
+
+static void l_stop(struct seq_file *m, void *p)
+{
+ kfree(p);
+}
+
+static int l_show(struct seq_file *m, void *p)
+{
+ int index = *(loff_t *) p;
+ struct hist_data *my_hist = m->private;
+
+ seq_printf(m, "%6ld\t%16llu\n", index - my_hist->offset,
+ my_hist->hist_array[index]);
+ return 0;
+}
+
+static const struct seq_operations latency_hist_seq_op = {
+ .start = l_start,
+ .next = l_next,
+ .stop = l_stop,
+ .show = l_show
+};
+
+static int latency_hist_open(struct inode *inode, struct file *file)
+{
+ int ret;
+
+ ret = seq_open(file, &latency_hist_seq_op);
+ if (!ret) {
+ struct seq_file *seq = file->private_data;
+
+ seq->private = inode->i_private;
+ }
+ return ret;
+}
+
+static const struct file_operations latency_hist_fops = {
+ .open = latency_hist_open,
+ .read = seq_read,
+ .llseek = seq_lseek,
+ .release = seq_release,
+};
+
+void clear_maxlatprocdata(struct maxlatproc_data *mp)
+{
+ mp->comm[0] = mp->current_comm[0] = '\0';
+ mp->prio = mp->current_prio = mp->pid = mp->current_pid =
+ mp->latency = mp->timeroffset = -1;
+ mp->timestamp = 0;
+}
+
+static void hist_reset(struct hist_data *hist)
+{
+ atomic_dec(&hist->hist_mode);
+
+ memset(hist->hist_array, 0, sizeof(hist->hist_array));
+ hist->below_hist_bound_samples = 0ULL;
+ hist->above_hist_bound_samples = 0ULL;
+ hist->min_lat = LONG_MAX;
+ hist->max_lat = LONG_MIN;
+ hist->total_samples = 0ULL;
+ hist->accumulate_lat = 0LL;
+
+ atomic_inc(&hist->hist_mode);
+}
+
+static ssize_t
+latency_hist_reset(struct file *file, const char __user *a,
+ size_t size, loff_t *off)
+{
+ int cpu;
+ struct hist_data *hist = NULL;
+ struct maxlatproc_data *mp __maybe_unused = NULL;
+ off_t latency_type = (off_t) file->private_data;
+
+ for_each_online_cpu(cpu) {
+
+ switch (latency_type) {
+ case PREEMPTOFF_LATENCY:
+ hist = &per_cpu(preemptoff_hist, cpu);
+ break;
+ case IRQSOFF_LATENCY:
+ hist = &per_cpu(irqsoff_hist, cpu);
+ break;
+ case PREEMPTIRQSOFF_LATENCY:
+ hist = &per_cpu(preemptirqsoff_hist, cpu);
+ break;
+ case WAKEUP_LATENCY:
+ hist = &per_cpu(wakeup_latency_hist, cpu);
+ mp = &per_cpu(wakeup_maxlatproc, cpu);
+ break;
+ case WAKEUP_LATENCY_SHAREDPRIO:
+ hist = &per_cpu(wakeup_latency_hist_sharedprio, cpu);
+ mp = &per_cpu(wakeup_maxlatproc_sharedprio, cpu);
+ break;
+ case MISSED_TIMER_OFFSETS:
+ hist = &per_cpu(missed_timer_offsets, cpu);
+ mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu);
+ break;
+ case TIMERANDWAKEUP_LATENCY:
+ hist = &per_cpu(timerandwakeup_latency_hist, cpu);
+ mp = &per_cpu(timerandwakeup_maxlatproc, cpu);
+ break;
+ }
+
+ hist_reset(hist);
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST) ||
+ IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ if (latency_type == WAKEUP_LATENCY ||
+ latency_type == WAKEUP_LATENCY_SHAREDPRIO ||
+ latency_type == MISSED_TIMER_OFFSETS ||
+ latency_type == TIMERANDWAKEUP_LATENCY)
+ clear_maxlatprocdata(mp);
+ }
+ }
+ return size;
+}
+
+ssize_t
+show_pid(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+ char buf[64];
+ int r;
+ unsigned long *this_pid = file->private_data;
+
+ r = snprintf(buf, sizeof(buf), "%lu\n", *this_pid);
+ return simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
+}
+
+static ssize_t do_pid(struct file *file, const char __user *ubuf,
+ size_t cnt, loff_t *ppos)
+{
+ char buf[64];
+ unsigned long pid;
+ unsigned long *this_pid = file->private_data;
+
+ if (cnt >= sizeof(buf))
+ return -EINVAL;
+
+ if (copy_from_user(&buf, ubuf, cnt))
+ return -EFAULT;
+
+ buf[cnt] = '\0';
+
+ if (kstrtoul(buf, 10, &pid))
+ return -EINVAL;
+
+ *this_pid = pid;
+
+ return cnt;
+}
+
+ssize_t
+show_maxlatproc(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+ int r;
+ struct maxlatproc_data *mp = file->private_data;
+ int strmaxlen = (TASK_COMM_LEN * 2) + (8 * 8);
+ unsigned long long t;
+ unsigned long usecs, secs;
+ char *buf;
+
+ if (mp->pid == -1 || mp->current_pid == -1) {
+ buf = "(none)\n";
+ return simple_read_from_buffer(ubuf, cnt, ppos, buf,
+ strlen(buf));
+ }
+
+ buf = kmalloc(strmaxlen, GFP_KERNEL);
+ if (buf == NULL)
+ return -ENOMEM;
+
+ t = ns2usecs(mp->timestamp);
+ usecs = do_div(t, USEC_PER_SEC);
+ secs = (unsigned long) t;
+ r = snprintf(buf, strmaxlen,
+ "%d %d %ld (%ld) %s <- %d %d %s %lu.%06lu\n", mp->pid,
+ MAX_RT_PRIO-1 - mp->prio, mp->latency, mp->timeroffset, mp->comm,
+ mp->current_pid, MAX_RT_PRIO-1 - mp->current_prio, mp->current_comm,
+ secs, usecs);
+ r = simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
+ kfree(buf);
+ return r;
+}
+
+static ssize_t
+show_enable(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+ char buf[64];
+ struct enable_data *ed = file->private_data;
+ int r;
+
+ r = snprintf(buf, sizeof(buf), "%d\n", ed->enabled);
+ return simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
+}
+
+static ssize_t __maybe_unused enable_trace_events(struct enable_data *ed)
+{
+ int ret = 0;
+
+ switch (ed->latency_type) {
+ case PREEMPTIRQSOFF_LATENCY:
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST) ||
+ IS_ENABLED(CONFIG_PREEMPT_OFF_HIST)) {
+ ret = register_trace_preemptirqsoff_hist(
+ probe_preemptirqsoff_hist, NULL);
+ if (ret) {
+ pr_info("wakeup trace: Couldn't assign"
+ " probe_preemptirqsoff_hist"
+ " to trace_preemptirqsoff_hist\n");
+ return ret;
+ }
+ }
+ break;
+
+ case WAKEUP_LATENCY:
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST)) {
+ ret = register_trace_sched_wakeup(
+ probe_wakeup_latency_hist_start, NULL);
+ if (ret) {
+ pr_info("wakeup trace: Couldn't assign"
+ " probe_wakeup_latency_hist_start"
+ " to trace_sched_wakeup\n");
+ return ret;
+ }
+ ret = register_trace_sched_wakeup_new(
+ probe_wakeup_latency_hist_start, NULL);
+ if (ret) {
+ pr_info("wakeup trace: Couldn't assign"
+ " probe_wakeup_latency_hist_start "
+ " to trace_sched_wakeup_new\n");
+ unregister_trace_sched_wakeup(
+ probe_wakeup_latency_hist_start,
+ NULL);
+ return ret;
+ }
+ ret = register_trace_sched_switch(
+ probe_wakeup_latency_hist_stop, NULL);
+ if (ret) {
+ pr_info("wakeup trace: Couldn't assign"
+ " probe_wakeup_latency_hist_stop"
+ " to trace_sched_switch\n");
+ unregister_trace_sched_wakeup(
+ probe_wakeup_latency_hist_start,
+ NULL);
+ unregister_trace_sched_wakeup_new(
+ probe_wakeup_latency_hist_start,
+ NULL);
+ return ret;
+ }
+ ret = register_trace_sched_migrate_task(
+ probe_sched_migrate_task, NULL);
+ if (ret) {
+ pr_info("wakeup trace: Couldn't assign"
+ " probe_sched_migrate_task"
+ " to trace_sched_migrate_task\n");
+ unregister_trace_sched_wakeup(
+ probe_wakeup_latency_hist_start,
+ NULL);
+ unregister_trace_sched_wakeup_new(
+ probe_wakeup_latency_hist_start,
+ NULL);
+ unregister_trace_sched_switch(
+ probe_wakeup_latency_hist_stop,
+ NULL);
+ return ret;
+ }
+ }
+ break;
+ case MISSED_TIMER_OFFSETS:
+ if (IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ ret = register_trace_hrtimer_interrupt(
+ probe_hrtimer_interrupt, NULL);
+ if (ret) {
+ pr_info("wakeup trace: Couldn't assign "
+ "probe_hrtimer_interrupt "
+ "to trace_hrtimer_interrupt\n");
+ return ret;
+ }
+ }
+ break;
+ case TIMERANDWAKEUP_LATENCY:
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST) &&
+ IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ if (!wakeup_latency_enabled_data.enabled ||
+ !missed_timer_offsets_enabled_data.enabled)
+ return -EINVAL;
+ }
+ break;
+ default:
+ break;
+ }
+ return ret;
+}
+
+static void __maybe_unused disable_trace_events(struct enable_data *ed)
+{
+ switch (ed->latency_type) {
+ case PREEMPTIRQSOFF_LATENCY:
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST) ||
+ IS_ENABLED(CONFIG_PREEMPT_OFF_HIST)) {
+ int cpu;
+
+ unregister_trace_preemptirqsoff_hist(
+ probe_preemptirqsoff_hist, NULL);
+ for_each_online_cpu(cpu) {
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST))
+ per_cpu(hist_irqsoff_counting,
+ cpu) = 0;
+ if (IS_ENABLED(CONFIG_PREEMPT_OFF_HIST))
+ per_cpu(hist_preemptoff_counting,
+ cpu) = 0;
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST) &&
+ IS_ENABLED(CONFIG_PREEMPT_OFF_HIST))
+ per_cpu(hist_preemptirqsoff_counting,
+ cpu) = 0;
+ }
+ }
+ break;
+
+ case WAKEUP_LATENCY:
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST)) {
+ int cpu;
+
+ unregister_trace_sched_wakeup(
+ probe_wakeup_latency_hist_start, NULL);
+ unregister_trace_sched_wakeup_new(
+ probe_wakeup_latency_hist_start, NULL);
+ unregister_trace_sched_switch(
+ probe_wakeup_latency_hist_stop, NULL);
+ unregister_trace_sched_migrate_task(
+ probe_sched_migrate_task, NULL);
+
+ for_each_online_cpu(cpu) {
+ per_cpu(wakeup_task, cpu) = NULL;
+ per_cpu(wakeup_sharedprio, cpu) = 0;
+ }
+ if (IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST))
+ timerandwakeup_enabled_data.enabled = 0;
+ }
+ break;
+
+ case MISSED_TIMER_OFFSETS:
+ if (IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ unregister_trace_hrtimer_interrupt(
+ probe_hrtimer_interrupt, NULL);
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST))
+ timerandwakeup_enabled_data.enabled = 0;
+ }
+ break;
+ default:
+ break;
+ }
+}
+
+static ssize_t __maybe_unused
+do_enable(struct file *file, const char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+ char buf[64];
+ long enable;
+ int ret;
+ struct enable_data *ed = file->private_data;
+
+ if (cnt >= sizeof(buf))
+ return -EINVAL;
+
+ if (copy_from_user(&buf, ubuf, cnt))
+ return -EFAULT;
+
+ buf[cnt] = 0;
+
+ if (kstrtoul(buf, 10, &enable))
+ return -EINVAL;
+
+ if ((enable && ed->enabled) || (!enable && !ed->enabled))
+ return cnt;
+
+ if (enable) {
+ ret = enable_trace_events(ed);
+ if (ret)
+ return ret;
+ } else {
+ disable_trace_events(ed);
+ }
+ ed->enabled = enable;
+ return cnt;
+}
+
+static const struct file_operations latency_hist_reset_fops = {
+ .open = tracing_open_generic,
+ .write = latency_hist_reset,
+};
+
+static const struct file_operations enable_fops = {
+ .open = tracing_open_generic,
+ .read = show_enable,
+ .write = do_enable,
+};
+
+static const struct file_operations __maybe_unused pid_fops = {
+ .open = tracing_open_generic,
+ .read = show_pid,
+ .write = do_pid,
+};
+
+static const struct file_operations __maybe_unused maxlatproc_fops = {
+ .open = tracing_open_generic,
+ .read = show_maxlatproc,
+};
+
+notrace void probe_preemptirqsoff_hist(void *v, int reason,
+ int starthist)
+{
+ int cpu = raw_smp_processor_id();
+ int time_set = 0;
+
+ if (starthist) {
+ cycle_t uninitialized_var(start);
+
+ if (!preempt_count() && !irqs_disabled())
+ return;
+
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST)) {
+ if ((reason == IRQS_OFF || reason == TRACE_START) &&
+ !per_cpu(hist_irqsoff_counting, cpu)) {
+ per_cpu(hist_irqsoff_counting, cpu) = 1;
+ start = ftrace_now(cpu);
+ time_set++;
+ per_cpu(hist_irqsoff_start, cpu) = start;
+ }
+ }
+
+ if (IS_ENABLED(CONFIG_PREEMPT_OFF_HIST)) {
+ if ((reason == PREEMPT_OFF || reason == TRACE_START) &&
+ !per_cpu(hist_preemptoff_counting, cpu)) {
+ per_cpu(hist_preemptoff_counting, cpu) = 1;
+ if (!(time_set++))
+ start = ftrace_now(cpu);
+ per_cpu(hist_preemptoff_start, cpu) = start;
+ }
+ }
+
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST) &&
+ IS_ENABLED(CONFIG_PREEMPT_OFF_HIST)) {
+ if (per_cpu(hist_irqsoff_counting, cpu) &&
+ per_cpu(hist_preemptoff_counting, cpu) &&
+ !per_cpu(hist_preemptirqsoff_counting, cpu)) {
+ per_cpu(hist_preemptirqsoff_counting, cpu) = 1;
+ if (!time_set)
+ start = ftrace_now(cpu);
+ per_cpu(hist_preemptirqsoff_start, cpu) = start;
+ }
+ }
+ } else {
+ cycle_t uninitialized_var(stop);
+
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST)) {
+ if ((reason == IRQS_ON || reason == TRACE_STOP) &&
+ per_cpu(hist_irqsoff_counting, cpu)) {
+ cycle_t start = per_cpu(hist_irqsoff_start,
+ cpu);
+
+ stop = ftrace_now(cpu);
+ time_set++;
+ if (start) {
+ long latency = ((long) (stop - start))
+ / NSECS_PER_USECS;
+
+ latency_hist(IRQSOFF_LATENCY, cpu,
+ latency, 0, stop, NULL);
+ }
+ per_cpu(hist_irqsoff_counting, cpu) = 0;
+ }
+ }
+
+ if (IS_ENABLED(CONFIG_PREEMPT_OFF_HIST)) {
+ if ((reason == PREEMPT_ON || reason == TRACE_STOP) &&
+ per_cpu(hist_preemptoff_counting, cpu)) {
+ cycle_t start = per_cpu(hist_preemptoff_start,
+ cpu);
+
+ if (!(time_set++))
+ stop = ftrace_now(cpu);
+ if (start) {
+ long latency = ((long) (stop - start))
+ / NSECS_PER_USECS;
+
+ latency_hist(PREEMPTOFF_LATENCY, cpu,
+ latency, 0, stop, NULL);
+ }
+ per_cpu(hist_preemptoff_counting, cpu) = 0;
+ }
+ }
+
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST) &&
+ IS_ENABLED(CONFIG_PREEMPT_OFF_HIST)) {
+ if ((!per_cpu(hist_irqsoff_counting, cpu) ||
+ !per_cpu(hist_preemptoff_counting, cpu)) &&
+ per_cpu(hist_preemptirqsoff_counting, cpu)) {
+ cycle_t start = per_cpu(
+ hist_preemptirqsoff_start,
+ cpu);
+
+ if (!time_set)
+ stop = ftrace_now(cpu);
+ if (start) {
+ long latency = ((long) (stop - start)) /
+ NSECS_PER_USECS;
+
+ latency_hist(PREEMPTIRQSOFF_LATENCY,
+ cpu, latency, 0, stop, NULL);
+ }
+ per_cpu(hist_preemptirqsoff_counting, cpu) = 0;
+ }
+ }
+ }
+}
+
+static DEFINE_RAW_SPINLOCK(wakeup_lock);
+notrace void probe_sched_migrate_task(void *v, struct task_struct *task,
+ int cpu)
+{
+ int old_cpu = task_cpu(task);
+
+ if (cpu != old_cpu) {
+ unsigned long flags;
+ struct task_struct *cpu_wakeup_task;
+
+ raw_spin_lock_irqsave(&wakeup_lock, flags);
+
+ cpu_wakeup_task = per_cpu(wakeup_task, old_cpu);
+ if (task == cpu_wakeup_task) {
+ put_task_struct(cpu_wakeup_task);
+ per_cpu(wakeup_task, old_cpu) = NULL;
+ cpu_wakeup_task = per_cpu(wakeup_task, cpu) = task;
+ get_task_struct(cpu_wakeup_task);
+ }
+
+ raw_spin_unlock_irqrestore(&wakeup_lock, flags);
+ }
+}
+
+notrace void probe_wakeup_latency_hist_start(void *v, struct task_struct *p)
+{
+ unsigned long flags;
+ struct task_struct *curr = current;
+ int cpu = task_cpu(p);
+ struct task_struct *cpu_wakeup_task;
+
+ raw_spin_lock_irqsave(&wakeup_lock, flags);
+
+ cpu_wakeup_task = per_cpu(wakeup_task, cpu);
+
+ if (wakeup_pid) {
+ if ((cpu_wakeup_task && p->prio == cpu_wakeup_task->prio) ||
+ p->prio == curr->prio)
+ per_cpu(wakeup_sharedprio, cpu) = 1;
+ if (likely(wakeup_pid != task_pid_nr(p)))
+ goto out;
+ } else {
+ if (likely(!rt_task(p)) ||
+ (cpu_wakeup_task && p->prio > cpu_wakeup_task->prio) ||
+ p->prio > curr->prio)
+ goto out;
+ if ((cpu_wakeup_task && p->prio == cpu_wakeup_task->prio) ||
+ p->prio == curr->prio)
+ per_cpu(wakeup_sharedprio, cpu) = 1;
+ }
+
+ if (cpu_wakeup_task)
+ put_task_struct(cpu_wakeup_task);
+ cpu_wakeup_task = per_cpu(wakeup_task, cpu) = p;
+ get_task_struct(cpu_wakeup_task);
+ cpu_wakeup_task->preempt_timestamp_hist =
+ ftrace_now(raw_smp_processor_id());
+out:
+ raw_spin_unlock_irqrestore(&wakeup_lock, flags);
+}
+
+notrace void probe_wakeup_latency_hist_stop(void *v, bool preempt,
+ struct task_struct *prev, struct task_struct *next)
+{
+ unsigned long flags;
+ int cpu = task_cpu(next);
+ long latency;
+ cycle_t stop;
+ struct task_struct *cpu_wakeup_task;
+
+ raw_spin_lock_irqsave(&wakeup_lock, flags);
+
+ cpu_wakeup_task = per_cpu(wakeup_task, cpu);
+
+ if (cpu_wakeup_task == NULL)
+ goto out;
+
+ /* Already running? */
+ if (unlikely(current == cpu_wakeup_task))
+ goto out_reset;
+
+ if (next != cpu_wakeup_task) {
+ if (next->prio < cpu_wakeup_task->prio)
+ goto out_reset;
+
+ if (next->prio == cpu_wakeup_task->prio)
+ per_cpu(wakeup_sharedprio, cpu) = 1;
+
+ goto out;
+ }
+
+ if (current->prio == cpu_wakeup_task->prio)
+ per_cpu(wakeup_sharedprio, cpu) = 1;
+
+ /*
+ * The task we are waiting for is about to be switched to.
+ * Calculate latency and store it in histogram.
+ */
+ stop = ftrace_now(raw_smp_processor_id());
+
+ latency = ((long) (stop - next->preempt_timestamp_hist)) /
+ NSECS_PER_USECS;
+
+ if (per_cpu(wakeup_sharedprio, cpu)) {
+ latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, 0, stop,
+ next);
+ per_cpu(wakeup_sharedprio, cpu) = 0;
+ } else {
+ latency_hist(WAKEUP_LATENCY, cpu, latency, 0, stop, next);
+ if (IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ if (timerandwakeup_enabled_data.enabled) {
+ latency_hist(TIMERANDWAKEUP_LATENCY, cpu,
+ next->timer_offset + latency,
+ next->timer_offset,
+ stop, next);
+ }
+ }
+ }
+
+out_reset:
+ if (IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST))
+ next->timer_offset = 0;
+ put_task_struct(cpu_wakeup_task);
+ per_cpu(wakeup_task, cpu) = NULL;
+out:
+ raw_spin_unlock_irqrestore(&wakeup_lock, flags);
+}
+
+notrace void probe_hrtimer_interrupt(void *v, int cpu,
+ long long latency_ns, struct task_struct *curr,
+ struct task_struct *task)
+{
+ if (latency_ns <= 0 && task != NULL && rt_task(task) &&
+ (task->prio < curr->prio ||
+ (task->prio == curr->prio &&
+ !cpumask_test_cpu(cpu, &task->cpus_allowed)))) {
+ long latency;
+ cycle_t now;
+
+ if (missed_timer_offsets_pid) {
+ if (likely(missed_timer_offsets_pid !=
+ task_pid_nr(task)))
+ return;
+ }
+
+ now = ftrace_now(cpu);
+ latency = (long) div_s64(-latency_ns, NSECS_PER_USECS);
+ latency_hist(MISSED_TIMER_OFFSETS, cpu, latency, latency, now,
+ task);
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST))
+ task->timer_offset = latency;
+ }
+}
+
+static __init int latency_hist_init(void)
+{
+ struct dentry *latency_hist_root = NULL;
+ struct dentry *dentry;
+ struct dentry *dentry_sharedprio __maybe_unused;
+ struct dentry *entry;
+ struct dentry *enable_root;
+ int i = 0;
+ struct hist_data *my_hist;
+ char name[64];
+ char *cpufmt = "CPU%d";
+ char *cpufmt_maxlatproc __maybe_unused = "max_latency-CPU%d";
+ struct maxlatproc_data *mp __maybe_unused = NULL;
+
+ dentry = tracing_init_dentry();
+ latency_hist_root = debugfs_create_dir(latency_hist_dir_root, dentry);
+ enable_root = debugfs_create_dir("enable", latency_hist_root);
+
+
+ if (IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST)) {
+ dentry = debugfs_create_dir(irqsoff_hist_dir,
+ latency_hist_root);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(irqsoff_hist, i), &latency_hist_fops);
+ my_hist = &per_cpu(irqsoff_hist, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+ }
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)IRQSOFF_LATENCY, &latency_hist_reset_fops);
+ }
+
+ if (IS_ENABLED(CONFIG_PREEMPT_OFF_HIST)) {
+ dentry = debugfs_create_dir(preemptoff_hist_dir,
+ latency_hist_root);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(preemptoff_hist, i), &latency_hist_fops);
+ my_hist = &per_cpu(preemptoff_hist, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+ }
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)PREEMPTOFF_LATENCY, &latency_hist_reset_fops);
+ }
+
+ if (IS_ENABLED(CONFIG_PREEMPT_OFF_HIST) &&
+ IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST)) {
+ dentry = debugfs_create_dir(preemptirqsoff_hist_dir,
+ latency_hist_root);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(preemptirqsoff_hist, i),
+ &latency_hist_fops);
+ my_hist = &per_cpu(preemptirqsoff_hist, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+ }
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)PREEMPTIRQSOFF_LATENCY, &latency_hist_reset_fops);
+
+ }
+
+ if (IS_ENABLED(CONFIG_PREEMPT_OFF_HIST) ||
+ IS_ENABLED(CONFIG_INTERRUPT_OFF_HIST)) {
+ entry = debugfs_create_file("preemptirqsoff", 0644,
+ enable_root, (void *)&preemptirqsoff_enabled_data,
+ &enable_fops);
+ }
+
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST)) {
+ dentry = debugfs_create_dir(wakeup_latency_hist_dir,
+ latency_hist_root);
+ dentry_sharedprio = debugfs_create_dir(
+ wakeup_latency_hist_dir_sharedprio, dentry);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(wakeup_latency_hist, i),
+ &latency_hist_fops);
+ my_hist = &per_cpu(wakeup_latency_hist, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+
+ entry = debugfs_create_file(name, 0444,
+ dentry_sharedprio,
+ &per_cpu(wakeup_latency_hist_sharedprio, i),
+ &latency_hist_fops);
+ my_hist = &per_cpu(wakeup_latency_hist_sharedprio, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+
+ sprintf(name, cpufmt_maxlatproc, i);
+
+ mp = &per_cpu(wakeup_maxlatproc, i);
+ entry = debugfs_create_file(name, 0444, dentry, mp,
+ &maxlatproc_fops);
+ clear_maxlatprocdata(mp);
+
+ mp = &per_cpu(wakeup_maxlatproc_sharedprio, i);
+ entry = debugfs_create_file(name, 0444,
+ dentry_sharedprio, mp, &maxlatproc_fops);
+ clear_maxlatprocdata(mp);
+ }
+ entry = debugfs_create_file("pid", 0644, dentry,
+ (void *)&wakeup_pid, &pid_fops);
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)WAKEUP_LATENCY, &latency_hist_reset_fops);
+ entry = debugfs_create_file("reset", 0644, dentry_sharedprio,
+ (void *)WAKEUP_LATENCY_SHAREDPRIO,
+ &latency_hist_reset_fops);
+ entry = debugfs_create_file("wakeup", 0644,
+ enable_root, (void *)&wakeup_latency_enabled_data,
+ &enable_fops);
+ }
+
+ if (IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ dentry = debugfs_create_dir(missed_timer_offsets_dir,
+ latency_hist_root);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(missed_timer_offsets, i),
+ &latency_hist_fops);
+ my_hist = &per_cpu(missed_timer_offsets, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+
+ sprintf(name, cpufmt_maxlatproc, i);
+ mp = &per_cpu(missed_timer_offsets_maxlatproc, i);
+ entry = debugfs_create_file(name, 0444, dentry, mp,
+ &maxlatproc_fops);
+ clear_maxlatprocdata(mp);
+ }
+ entry = debugfs_create_file("pid", 0644, dentry,
+ (void *)&missed_timer_offsets_pid, &pid_fops);
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)MISSED_TIMER_OFFSETS, &latency_hist_reset_fops);
+ entry = debugfs_create_file("missed_timer_offsets", 0644,
+ enable_root, (void *)&missed_timer_offsets_enabled_data,
+ &enable_fops);
+ }
+
+ if (IS_ENABLED(CONFIG_WAKEUP_LATENCY_HIST) ||
+ IS_ENABLED(CONFIG_MISSED_TIMER_OFFSETS_HIST)) {
+ dentry = debugfs_create_dir(timerandwakeup_latency_hist_dir,
+ latency_hist_root);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(timerandwakeup_latency_hist, i),
+ &latency_hist_fops);
+ my_hist = &per_cpu(timerandwakeup_latency_hist, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+
+ sprintf(name, cpufmt_maxlatproc, i);
+ mp = &per_cpu(timerandwakeup_maxlatproc, i);
+ entry = debugfs_create_file(name, 0444, dentry, mp,
+ &maxlatproc_fops);
+ clear_maxlatprocdata(mp);
+ }
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)TIMERANDWAKEUP_LATENCY, &latency_hist_reset_fops);
+ entry = debugfs_create_file("timerandwakeup", 0644,
+ enable_root, (void *)&timerandwakeup_enabled_data,
+ &enable_fops);
+ }
+ return 0;
+}
+
+device_initcall(latency_hist_init);
+
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 03cdff8..e138d69 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -13,6 +13,7 @@
#include <linux/uaccess.h>
#include <linux/module.h>
#include <linux/ftrace.h>
+#include <trace/events/hist.h>
#include "trace.h"
@@ -424,11 +425,13 @@ void start_critical_timings(void)
{
if (preempt_trace() || irq_trace())
start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ trace_preemptirqsoff_hist(TRACE_START, 1);
}
EXPORT_SYMBOL_GPL(start_critical_timings);
void stop_critical_timings(void)
{
+ trace_preemptirqsoff_hist(TRACE_STOP, 0);
if (preempt_trace() || irq_trace())
stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
}
@@ -438,6 +441,7 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
#ifdef CONFIG_PROVE_LOCKING
void time_hardirqs_on(unsigned long a0, unsigned long a1)
{
+ trace_preemptirqsoff_hist(IRQS_ON, 0);
if (!preempt_trace() && irq_trace())
stop_critical_timing(a0, a1);
}
@@ -446,6 +450,7 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1)
{
if (!preempt_trace() && irq_trace())
start_critical_timing(a0, a1);
+ trace_preemptirqsoff_hist(IRQS_OFF, 1);
}
#else /* !CONFIG_PROVE_LOCKING */
@@ -485,6 +490,7 @@ EXPORT_SYMBOL(trace_hardirqs_off);
__visible void trace_hardirqs_on_caller(unsigned long caller_addr)
{
+ trace_preemptirqsoff_hist(IRQS_ON, 0);
if (!preempt_trace() && irq_trace())
stop_critical_timing(CALLER_ADDR0, caller_addr);
}
@@ -494,6 +500,7 @@ __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
{
if (!preempt_trace() && irq_trace())
start_critical_timing(CALLER_ADDR0, caller_addr);
+ trace_preemptirqsoff_hist(IRQS_OFF, 1);
}
EXPORT_SYMBOL(trace_hardirqs_off_caller);
@@ -503,12 +510,14 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller);
#ifdef CONFIG_PREEMPT_TRACER
void trace_preempt_on(unsigned long a0, unsigned long a1)
{
+ trace_preemptirqsoff_hist(PREEMPT_ON, 0);
if (preempt_trace() && !irq_trace())
stop_critical_timing(a0, a1);
}
void trace_preempt_off(unsigned long a0, unsigned long a1)
{
+ trace_preemptirqsoff_hist(PREEMPT_ON, 1);
if (preempt_trace() && !irq_trace())
start_critical_timing(a0, a1);
}
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [PATCH 2/2] trace: Add missing tracer macros
2016-07-28 4:52 [PATCH 0/2] *** Latency Histogram *** Binoy Jayan
2016-07-28 4:52 ` [PATCH 1/2] tracing: Add latency histograms Binoy Jayan
@ 2016-07-28 4:52 ` Binoy Jayan
2016-07-28 13:10 ` [PATCH 0/2] *** Latency Histogram *** Steven Rostedt
2 siblings, 0 replies; 6+ messages in thread
From: Binoy Jayan @ 2016-07-28 4:52 UTC (permalink / raw)
To: Steven Rostedt
Cc: linux-kernel, Yang Shi, linaro-kernel, bigeasy, rostedt,
stable-rt, Thomas Gleixner
From: Yang Shi <yang.shi@linaro.org>
When building rt kernel with IRQSOFF_TRACER enabled but INTERRUPT_OFF_HIST
or PREEMPT_OFF_HIST disabled, the below build failure will be triggered:
| kernel/trace/trace_irqsoff.c: In function 'time_hardirqs_on':
| kernel/trace/trace_irqsoff.c:453:2: error: implicit declaration of
| function 'trace_preemptirqsoff_hist_rcuidle'
| [-Werror=implicit-function-declaration]
| trace_preemptirqsoff_hist_rcuidle(IRQS_ON, 0);
| ^
| cc1: some warnings being treated as errors
| scripts/Makefile.build:258: recipe for target
| 'kernel/trace/trace_irqsoff.o' failed
| make[4]: *** [kernel/trace/trace_irqsoff.o] Error 1
| make[4]: *** Waiting for unfinished jobs....
| scripts/Makefile.build:403: recipe for target 'kernel/trace' failed
These macros are only defined when both PREEMPT_OFF_HIST and
PREEMPT_OFF_HIST are enabled, otherwise just trace_preemptirqsoff_hist
is defined as a preprocessor macro.
Signed-off-by: Yang Shi <yang.shi@linaro.org>
Cc: linaro-kernel@lists.linaro.org
Cc: bigeasy@linutronix.de
Cc: rostedt@goodmis.org
Cc: stable-rt@vger.kernel.org
Link: http://lkml.kernel.org/r/1445280008-8456-1-git-send-email-yang.shi@linaro.org
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
---
include/trace/events/hist.h | 2 ++
1 file changed, 2 insertions(+)
diff --git a/include/trace/events/hist.h b/include/trace/events/hist.h
index 6122e42..37f6eb8 100644
--- a/include/trace/events/hist.h
+++ b/include/trace/events/hist.h
@@ -9,6 +9,7 @@
#if !defined(CONFIG_PREEMPT_OFF_HIST) && !defined(CONFIG_INTERRUPT_OFF_HIST)
#define trace_preemptirqsoff_hist(a, b)
+#define trace_preemptirqsoff_hist_rcuidle(a, b)
#else
TRACE_EVENT(preemptirqsoff_hist,
@@ -33,6 +34,7 @@ TRACE_EVENT(preemptirqsoff_hist,
#ifndef CONFIG_MISSED_TIMER_OFFSETS_HIST
#define trace_hrtimer_interrupt(a, b, c, d)
+#define trace_hrtimer_interrupt_rcuidle(a, b, c, d)
#else
TRACE_EVENT(hrtimer_interrupt,
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH 0/2] *** Latency Histogram ***
2016-07-28 4:52 [PATCH 0/2] *** Latency Histogram *** Binoy Jayan
2016-07-28 4:52 ` [PATCH 1/2] tracing: Add latency histograms Binoy Jayan
2016-07-28 4:52 ` [PATCH 2/2] trace: Add missing tracer macros Binoy Jayan
@ 2016-07-28 13:10 ` Steven Rostedt
2016-07-28 13:25 ` Daniel Wagner
2 siblings, 1 reply; 6+ messages in thread
From: Steven Rostedt @ 2016-07-28 13:10 UTC (permalink / raw)
To: Binoy Jayan; +Cc: linux-kernel, Daniel Wagner, Thomas Gleixner
On Thu, Jul 28, 2016 at 10:22:12AM +0530, Binoy Jayan wrote:
> Hi,
>
> I was looking at these RT kernel patches and was wondering why it has
> not been upstreamed yet. I have made a few changes to these patches to
> make it compliant with upstream submission process. Also did a minimal
> testing on my msm board. Can some one from rt kernel team shed some
> light on why this is not upstreamed yet? Also if there some way to test
Note, Daniel did start work on upstreaming this previously:
http://lkml.kernel.org/r/1430388385-29558-1-git-send-email-daniel.wagner@bmw-carit.de
There are a few things that do need to be cleaned up before this can go
upstream. Please coordinate any effort with Daniel, if you want to get this
rolling again. I'm not sure why the effort died last time. Could be because
something more important came up.
-- Steve
> this throroughly on a board with a high resolution timer running mainline
> (and not rt) kernel.
>
> Binoy
>
> Carsten Emde (1):
> tracing: Add latency histograms
>
> Yang Shi (1):
> trace: Add missing tracer macros
>
> Documentation/trace/histograms.txt | 186 ++++++
> include/linux/hrtimer.h | 3 +
> include/linux/sched.h | 6 +
> include/trace/events/hist.h | 74 +++
> include/trace/events/latency_hist.h | 136 +++++
> kernel/time/hrtimer.c | 20 +
> kernel/trace/Kconfig | 104 ++++
> kernel/trace/Makefile | 4 +
> kernel/trace/latency_hist.c | 1091 +++++++++++++++++++++++++++++++++++
> kernel/trace/trace_irqsoff.c | 9 +
> 10 files changed, 1633 insertions(+)
> create mode 100644 Documentation/trace/histograms.txt
> create mode 100644 include/trace/events/hist.h
> create mode 100644 include/trace/events/latency_hist.h
> create mode 100644 kernel/trace/latency_hist.c
>
> --
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH 0/2] *** Latency Histogram ***
2016-07-28 13:10 ` [PATCH 0/2] *** Latency Histogram *** Steven Rostedt
@ 2016-07-28 13:25 ` Daniel Wagner
0 siblings, 0 replies; 6+ messages in thread
From: Daniel Wagner @ 2016-07-28 13:25 UTC (permalink / raw)
To: Steven Rostedt, Binoy Jayan; +Cc: linux-kernel, Thomas Gleixner
On 07/28/2016 03:10 PM, Steven Rostedt wrote:
> Note, Daniel did start work on upstreaming this previously:
>
> http://lkml.kernel.org/r/1430388385-29558-1-git-send-email-daniel.wagner@bmw-carit.de
>
> There are a few things that do need to be cleaned up before this can go
> upstream. Please coordinate any effort with Daniel, if you want to get this
> rolling again. I'm not sure why the effort died last time. Could be because
> something more important came up.
I was in the impression that the hist patches were about to be merged
very soon. So I postponed the activities until they are in. Which is now :)
Binoy if you like to work on this be free to pick it up. If not I will
do it but it is not right now.
cheers,
daniel
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH 1/2] tracing: Add latency histograms
2016-07-28 4:52 ` [PATCH 1/2] tracing: Add latency histograms Binoy Jayan
@ 2016-07-28 18:51 ` Carsten Emde
0 siblings, 0 replies; 6+ messages in thread
From: Carsten Emde @ 2016-07-28 18:51 UTC (permalink / raw)
To: Binoy Jayan, Steven Rostedt; +Cc: linux-kernel, Thomas Gleixner
Binoy,
> [..]
> This patch provides a recording mechanism to store data of potential
> sources of system latencies. [..]
Thanks a lot! I would be more than happy and certainly will help and test as much
as I can to get this functionality upstream.
Some time ago, I provided a patch to add a context switch time histogram.
Unfortunately, this patch did not make it into the RT patch by some reason.
However, the context switch time is needed to completely elucidate any latency
that is seen from user space. The below patch only applies to the original
version of the histogram patch - not to your version. I am appending it just
for your information. I would be more than happy to convert the patch so it
applies on top of yours. However, I would not do it, if there were no chance
that it ever gets considered. Please let me know.
Thanks,
-Carsten.
--
From: Carsten Emde <C.Emde@osadl.org>
Date: Fri, 3 Oct 2014 22:14:55 +0100
Subject: Add trace latency histogram to monitor context switch time
The existing two on-line methods to record system latency (timer and
wakeup latency) do not completely reflect the user-space wakeup time,
since the duration of the context switch is not taken into account. This
patch adds two new histograms - one that records the duration of the
context switch and another one that records the sum of the timer delay,
the wakeup latency and the newly available duration of the context
switch. The latter histogram probably is best suitable to determine the
worst-case total preemption latency of a given system.
Signed-off-by: Carsten Emde <C.Emde@osadl.org>
---
include/linux/sched.h | 8
kernel/trace/Kconfig | 32 +++
kernel/trace/latency_hist.c | 427 ++++++++++++++++++++++++++++++++++++++------
3 files changed, 411 insertions(+), 56 deletions(-)
Index: linux-4.4.9-rt17/include/linux/sched.h
===================================================================
--- linux-4.4.9-rt17.orig/include/linux/sched.h
+++ linux-4.4.9-rt17/include/linux/sched.h
@@ -1828,7 +1828,15 @@ struct task_struct {
#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
long timer_offset;
#endif
+#endif /* CONFIG_WAKEUP_LATENCY_HIST */
+#ifdef CONFIG_SWITCHTIME_HIST
+ u64 switchtime_timestamp_hist;
+ struct task_struct *switchtime_prev;
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+ unsigned long wakeup_latency;
#endif
+#endif /* CONFIG_SWITCHTIME_HIST */
#endif /* CONFIG_TRACING */
#ifdef CONFIG_MEMCG
struct mem_cgroup *memcg_in_oom;
Index: linux-4.4.9-rt17/kernel/trace/Kconfig
===================================================================
--- linux-4.4.9-rt17.orig/kernel/trace/Kconfig
+++ linux-4.4.9-rt17/kernel/trace/Kconfig
@@ -325,6 +325,38 @@ config MISSED_TIMER_OFFSETS_HIST
/sys/kernel/debug/tracing/latency_hist/enable/timerandwakeup
+config SWITCHTIME_HIST
+ depends on HIGH_RES_TIMERS
+ depends on HAVE_SYSCALL_TRACEPOINTS
+ depends on WAKEUP_LATENCY_HIST
+ select GENERIC_TRACER
+ select FTRACE_SYSCALLS
+ bool "Context Switch Time Histogram"
+ help
+ Generate a histogram of the context switch duration per CPU. The
+ histograms are disabled by default. To enable them, write a non-zero
+ number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/switchtime
+
+ The histogram data will be located in the debug file system at
+
+ /sys/kernel/debug/tracing/latency_hist/switchtime
+
+ If both Scheduling Latency Histogram, Missed Timer Offsets and the
+ newly provided Context Switch Time Histogram are selected, additional
+ histogram data will be collected from the sum of the wakeup latency,
+ the timer latency, if available, and the switch time per CPU. These
+ histograms are available in the
+
+ /sys/kernel/debug/tracing/latency_hist/timerwakeupswitch
+
+ directory. They reflect the apparent interrupt and scheduling latency
+ and are best suitable to determine the worst-case latency of a given
+ system. To enable these histograms, write a non-zero number to
+
+ /sys/kernel/debug/tracing/latency_hist/enable/timerwakeupswitch
+
config ENABLE_DEFAULT_TRACERS
bool "Trace process context switches and events"
depends on !GENERIC_TRACER
Index: linux-4.4.9-rt17/kernel/trace/latency_hist.c
===================================================================
--- linux-4.4.9-rt17.orig/kernel/trace/latency_hist.c
+++ linux-4.4.9-rt17/kernel/trace/latency_hist.c
@@ -23,11 +23,15 @@
#include <linux/sched/rt.h>
#include <linux/slab.h>
#include <linux/atomic.h>
+#include <trace/syscall.h>
#include <asm/div64.h>
+#include <asm/syscall.h>
#include "trace.h"
#include <trace/events/sched.h>
+extern struct tracepoint __tracepoint_sys_exit;
+
#define NSECS_PER_USECS 1000L
#define CREATE_TRACE_POINTS
@@ -41,6 +45,8 @@ enum {
WAKEUP_LATENCY_SHAREDPRIO,
MISSED_TIMER_OFFSETS,
TIMERANDWAKEUP_LATENCY,
+ SWITCHTIME,
+ TIMERWAKEUPSWITCH_LATENCY,
MAX_LATENCY_TYPE,
};
@@ -104,8 +110,10 @@ struct maxlatproc_data {
int prio;
int current_prio;
long latency;
- long timeroffset;
+ unsigned long timer_offset;
+ long wakeup_latency;
cycle_t timestamp;
+ int nr;
};
#endif
@@ -144,6 +152,19 @@ static DEFINE_PER_CPU(struct maxlatproc_
static unsigned long missed_timer_offsets_pid;
#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+static DEFINE_PER_CPU(struct hist_data, switchtime);
+static char *switchtime_dir = "switchtime";
+static notrace void probe_syscall_exit(void *v, struct pt_regs *regs, long ret);
+static struct enable_data switchtime_enabled_data = {
+ .latency_type = SWITCHTIME,
+ .enabled = 0,
+};
+static DEFINE_PER_CPU(struct maxlatproc_data, switchtime_maxlatproc);
+static DEFINE_PER_CPU(struct task_struct *, switchtime_task);
+static unsigned long switchtime_pid;
+#endif
+
#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
static DEFINE_PER_CPU(struct hist_data, timerandwakeup_latency_hist);
@@ -155,13 +176,26 @@ static struct enable_data timerandwakeup
static DEFINE_PER_CPU(struct maxlatproc_data, timerandwakeup_maxlatproc);
#endif
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) && \
+ defined(CONFIG_SWITCHTIME_HIST)
+static DEFINE_PER_CPU(struct hist_data, timerwakeupswitch_latency_hist);
+static char *timerwakeupswitch_latency_hist_dir = "timerwakeupswitch";
+static struct enable_data timerwakeupswitch_enabled_data = {
+ .latency_type = TIMERWAKEUPSWITCH_LATENCY,
+ .enabled = 0,
+};
+static DEFINE_PER_CPU(struct maxlatproc_data, timerwakeupswitch_maxlatproc);
+#endif
+
void notrace latency_hist(int latency_type, int cpu, long latency,
- long timeroffset, cycle_t stop,
- struct task_struct *p)
+ unsigned long timer_offset, long wakeup_latency,
+ cycle_t stop, struct task_struct *p, int nr)
{
struct hist_data *my_hist;
#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
- defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) || \
+ defined(CONFIG_SWITCHTIME_HIST)
struct maxlatproc_data *mp = NULL;
#endif
@@ -201,6 +235,12 @@ void notrace latency_hist(int latency_ty
mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu);
break;
#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+ case SWITCHTIME:
+ my_hist = &per_cpu(switchtime, cpu);
+ mp = &per_cpu(switchtime_maxlatproc, cpu);
+ break;
+#endif
#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
case TIMERANDWAKEUP_LATENCY:
@@ -208,6 +248,14 @@ void notrace latency_hist(int latency_ty
mp = &per_cpu(timerandwakeup_maxlatproc, cpu);
break;
#endif
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) && \
+ defined(CONFIG_SWITCHTIME_HIST)
+ case TIMERWAKEUPSWITCH_LATENCY:
+ my_hist = &per_cpu(timerwakeupswitch_latency_hist, cpu);
+ mp = &per_cpu(timerwakeupswitch_maxlatproc, cpu);
+ break;
+#endif
default:
return;
@@ -229,21 +277,38 @@ void notrace latency_hist(int latency_ty
if (unlikely(latency > my_hist->max_lat ||
my_hist->min_lat == LONG_MAX)) {
#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
- defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) || \
+ defined(CONFIG_SWITCHTIME_HIST)
if (latency_type == WAKEUP_LATENCY ||
latency_type == WAKEUP_LATENCY_SHAREDPRIO ||
latency_type == MISSED_TIMER_OFFSETS ||
- latency_type == TIMERANDWAKEUP_LATENCY) {
- strncpy(mp->comm, p->comm, sizeof(mp->comm));
- strncpy(mp->current_comm, current->comm,
- sizeof(mp->current_comm));
- mp->pid = task_pid_nr(p);
- mp->current_pid = task_pid_nr(current);
- mp->prio = p->prio;
- mp->current_prio = current->prio;
+ latency_type == TIMERANDWAKEUP_LATENCY ||
+ latency_type == SWITCHTIME ||
+ latency_type == TIMERWAKEUPSWITCH_LATENCY) {
+ if (latency_type == SWITCHTIME ||
+ latency_type == TIMERWAKEUPSWITCH_LATENCY) {
+ strncpy(mp->current_comm, p->comm,
+ sizeof(mp->current_comm));
+ strncpy(mp->comm, current->comm,
+ sizeof(mp->comm));
+ mp->current_pid = task_pid_nr(p);
+ mp->pid = task_pid_nr(current);
+ mp->current_prio = p->prio;
+ mp->prio = current->prio;
+ } else {
+ strncpy(mp->comm, p->comm, sizeof(mp->comm));
+ strncpy(mp->current_comm, current->comm,
+ sizeof(mp->current_comm));
+ mp->pid = task_pid_nr(p);
+ mp->current_pid = task_pid_nr(current);
+ mp->prio = p->prio;
+ mp->current_prio = current->prio;
+ }
mp->latency = latency;
- mp->timeroffset = timeroffset;
+ mp->timer_offset = timer_offset;
+ mp->wakeup_latency = wakeup_latency;
mp->timestamp = stop;
+ mp->nr = nr;
}
#endif
my_hist->max_lat = latency;
@@ -366,8 +431,9 @@ static void clear_maxlatprocdata(struct
{
mp->comm[0] = mp->current_comm[0] = '\0';
mp->prio = mp->current_prio = mp->pid = mp->current_pid =
- mp->latency = mp->timeroffset = -1;
+ mp->latency = mp->timer_offset = mp->wakeup_latency = -1;
mp->timestamp = 0;
+ mp->nr = 0;
}
#endif
@@ -426,6 +492,12 @@ latency_hist_reset(struct file *file, co
mp = &per_cpu(wakeup_maxlatproc_sharedprio, cpu);
break;
#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+ case SWITCHTIME:
+ hist = &per_cpu(switchtime, cpu);
+ mp = &per_cpu(switchtime_maxlatproc, cpu);
+ break;
+#endif
#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
case MISSED_TIMER_OFFSETS:
hist = &per_cpu(missed_timer_offsets, cpu);
@@ -439,15 +511,26 @@ latency_hist_reset(struct file *file, co
mp = &per_cpu(timerandwakeup_maxlatproc, cpu);
break;
#endif
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) && \
+ defined(CONFIG_SWITCHTIME_HIST)
+ case TIMERWAKEUPSWITCH_LATENCY:
+ hist = &per_cpu(timerwakeupswitch_latency_hist, cpu);
+ mp = &per_cpu(timerwakeupswitch_maxlatproc, cpu);
+ break;
+#endif
}
hist_reset(hist);
#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
- defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) || \
+ defined(CONFIG_SWITCHTIME_HIST)
if (latency_type == WAKEUP_LATENCY ||
latency_type == WAKEUP_LATENCY_SHAREDPRIO ||
latency_type == MISSED_TIMER_OFFSETS ||
- latency_type == TIMERANDWAKEUP_LATENCY)
+ latency_type == TIMERANDWAKEUP_LATENCY ||
+ latency_type == SWITCHTIME ||
+ latency_type == TIMERWAKEUPSWITCH_LATENCY)
clear_maxlatprocdata(mp);
#endif
}
@@ -456,7 +539,8 @@ latency_hist_reset(struct file *file, co
}
#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
- defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) || \
+ defined(CONFIG_SWITCHTIME_HIST)
static ssize_t
show_pid(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos)
{
@@ -499,7 +583,7 @@ show_maxlatproc(struct file *file, char
{
int r;
struct maxlatproc_data *mp = file->private_data;
- int strmaxlen = (TASK_COMM_LEN * 2) + (8 * 8);
+ int strmaxlen = (TASK_COMM_LEN * 2) + 32 + (8 * 8);
unsigned long long t;
unsigned long usecs, secs;
char *buf;
@@ -518,10 +602,18 @@ show_maxlatproc(struct file *file, char
usecs = do_div(t, USEC_PER_SEC);
secs = (unsigned long) t;
r = snprintf(buf, strmaxlen,
- "%d %d %ld (%ld) %s <- %d %d %s %lu.%06lu\n", mp->pid,
- MAX_RT_PRIO-1 - mp->prio, mp->latency, mp->timeroffset, mp->comm,
- mp->current_pid, MAX_RT_PRIO-1 - mp->current_prio, mp->current_comm,
+ "%d %d %ld (%ld,%ld) %s <- %d %d %s %lu.%06lu", mp->pid,
+ MAX_RT_PRIO-1 - mp->prio, mp->latency, mp->timer_offset,
+ mp->wakeup_latency, mp->comm, mp->current_pid,
+ MAX_RT_PRIO-1 - mp->current_prio, mp->current_comm,
secs, usecs);
+#ifdef CONFIG_SWITCHTIME_HIST
+ if (mp->nr >= 0 && mp->nr < NR_syscalls)
+ r += snprintf(buf + r, strmaxlen - r, " %pf",
+ sys_call_table[mp->nr]);
+#endif
+ r += snprintf(buf + r, strmaxlen - r, "\n");
+
r = simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
kfree(buf);
return r;
@@ -569,9 +661,7 @@ do_enable(struct file *file, const char
ret = register_trace_preemptirqsoff_hist(
probe_preemptirqsoff_hist, NULL);
if (ret) {
- pr_info("wakeup trace: Couldn't assign "
- "probe_preemptirqsoff_hist "
- "to trace_preemptirqsoff_hist\n");
+ pr_info("Couldn't register preemptirqsoff_hist probe\n");
return ret;
}
break;
@@ -581,17 +671,13 @@ do_enable(struct file *file, const char
ret = register_trace_sched_wakeup(
probe_wakeup_latency_hist_start, NULL);
if (ret) {
- pr_info("wakeup trace: Couldn't assign "
- "probe_wakeup_latency_hist_start "
- "to trace_sched_wakeup\n");
+ pr_info("Couldn't register sched_wakeup probe\n");
return ret;
}
ret = register_trace_sched_wakeup_new(
probe_wakeup_latency_hist_start, NULL);
if (ret) {
- pr_info("wakeup trace: Couldn't assign "
- "probe_wakeup_latency_hist_start "
- "to trace_sched_wakeup_new\n");
+ pr_info("Couldn't register sched_wakeup_new probe\n");
unregister_trace_sched_wakeup(
probe_wakeup_latency_hist_start, NULL);
return ret;
@@ -599,9 +685,7 @@ do_enable(struct file *file, const char
ret = register_trace_sched_switch(
probe_wakeup_latency_hist_stop, NULL);
if (ret) {
- pr_info("wakeup trace: Couldn't assign "
- "probe_wakeup_latency_hist_stop "
- "to trace_sched_switch\n");
+ pr_info("Couldn't register sched_switch probe\n");
unregister_trace_sched_wakeup(
probe_wakeup_latency_hist_start, NULL);
unregister_trace_sched_wakeup_new(
@@ -611,9 +695,7 @@ do_enable(struct file *file, const char
ret = register_trace_sched_migrate_task(
probe_sched_migrate_task, NULL);
if (ret) {
- pr_info("wakeup trace: Couldn't assign "
- "probe_sched_migrate_task "
- "to trace_sched_migrate_task\n");
+ pr_info("Couldn't register sched_migrate_task probe\n");
unregister_trace_sched_wakeup(
probe_wakeup_latency_hist_start, NULL);
unregister_trace_sched_wakeup_new(
@@ -629,9 +711,19 @@ do_enable(struct file *file, const char
ret = register_trace_hrtimer_interrupt(
probe_hrtimer_interrupt, NULL);
if (ret) {
- pr_info("wakeup trace: Couldn't assign "
- "probe_hrtimer_interrupt "
- "to trace_hrtimer_interrupt\n");
+ pr_info("Couldn't register hrtimer IRQ probe\n");
+ return ret;
+ }
+ break;
+#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+ case SWITCHTIME:
+ if (!wakeup_latency_enabled_data.enabled)
+ return -EINVAL;
+ ret = tracepoint_probe_register(&__tracepoint_sys_exit,
+ probe_syscall_exit, NULL);
+ if (ret) {
+ pr_info("Couldn't register sys_exit probe\n");
return ret;
}
break;
@@ -644,6 +736,16 @@ do_enable(struct file *file, const char
return -EINVAL;
break;
#endif
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) && \
+ defined(CONFIG_SWITCHTIME_HIST)
+ case TIMERWAKEUPSWITCH_LATENCY:
+ if (!wakeup_latency_enabled_data.enabled ||
+ !missed_timer_offsets_enabled_data.enabled ||
+ !switchtime_enabled_data.enabled)
+ return -EINVAL;
+ break;
+#endif
default:
break;
}
@@ -695,6 +797,12 @@ do_enable(struct file *file, const char
#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
timerandwakeup_enabled_data.enabled = 0;
#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+ switchtime_enabled_data.enabled = 0;
+#endif
+#ifdef CONFIG_TIMERWAKEUPSWITCH_LATENCY_HIST
+ timerwakeupswitch_enabled_data.enabled = 0;
+#endif
break;
#endif
#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
@@ -704,6 +812,25 @@ do_enable(struct file *file, const char
#ifdef CONFIG_WAKEUP_LATENCY_HIST
timerandwakeup_enabled_data.enabled = 0;
#endif
+#ifdef CONFIG_TIMERWAKEUPSWITCH_LATENCY_HIST
+ timerwakeupswitch_enabled_data.enabled = 0;
+#endif
+ break;
+#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+ case SWITCHTIME:
+ {
+ int cpu;
+
+ tracepoint_probe_unregister(&__tracepoint_sys_exit,
+ probe_syscall_exit, NULL);
+
+ for_each_online_cpu(cpu)
+ per_cpu(switchtime_task, cpu) = NULL;
+ }
+#ifdef CONFIG_TIMERWAKEUPSWITCH_LATENCY_HIST
+ timerwakeupswitch_enabled_data.enabled = 0;
+#endif
break;
#endif
default:
@@ -797,7 +924,7 @@ static notrace void probe_preemptirqsoff
NSECS_PER_USECS;
latency_hist(IRQSOFF_LATENCY, cpu, latency, 0,
- stop, NULL);
+ 0, stop, NULL, -1);
}
per_cpu(hist_irqsoff_counting, cpu) = 0;
}
@@ -815,7 +942,7 @@ static notrace void probe_preemptirqsoff
NSECS_PER_USECS;
latency_hist(PREEMPTOFF_LATENCY, cpu, latency,
- 0, stop, NULL);
+ 0, 0, stop, NULL, -1);
}
per_cpu(hist_preemptoff_counting, cpu) = 0;
}
@@ -834,7 +961,7 @@ static notrace void probe_preemptirqsoff
NSECS_PER_USECS;
latency_hist(PREEMPTIRQSOFF_LATENCY, cpu,
- latency, 0, stop, NULL);
+ latency, 0, 0, stop, NULL, -1);
}
per_cpu(hist_preemptirqsoff_counting, cpu) = 0;
}
@@ -845,6 +972,9 @@ static notrace void probe_preemptirqsoff
#ifdef CONFIG_WAKEUP_LATENCY_HIST
static DEFINE_RAW_SPINLOCK(wakeup_lock);
+#ifdef CONFIG_SWITCHTIME_HIST
+static DEFINE_RAW_SPINLOCK(switchtime_lock);
+#endif
static notrace void probe_sched_migrate_task(void *v, struct task_struct *task,
int cpu)
{
@@ -855,7 +985,6 @@ static notrace void probe_sched_migrate_
struct task_struct *cpu_wakeup_task;
raw_spin_lock_irqsave(&wakeup_lock, flags);
-
cpu_wakeup_task = per_cpu(wakeup_task, old_cpu);
if (task == cpu_wakeup_task) {
put_task_struct(cpu_wakeup_task);
@@ -863,8 +992,24 @@ static notrace void probe_sched_migrate_
cpu_wakeup_task = per_cpu(wakeup_task, cpu) = task;
get_task_struct(cpu_wakeup_task);
}
-
raw_spin_unlock_irqrestore(&wakeup_lock, flags);
+
+#ifdef CONFIG_SWITCHTIME_HIST
+ {
+ struct task_struct *cpu_switchtime_task;
+
+ raw_spin_lock_irqsave(&switchtime_lock, flags);
+ cpu_switchtime_task = per_cpu(switchtime_task, old_cpu);
+ if (task == cpu_switchtime_task) {
+ put_task_struct(cpu_switchtime_task);
+ per_cpu(switchtime_task, old_cpu) = NULL;
+ cpu_switchtime_task =
+ per_cpu(switchtime_task, cpu) = task;
+ get_task_struct(cpu_switchtime_task);
+ }
+ raw_spin_unlock_irqrestore(&switchtime_lock, flags);
+ }
+#endif
}
}
@@ -876,8 +1021,23 @@ static notrace void probe_wakeup_latency
int cpu = task_cpu(p);
struct task_struct *cpu_wakeup_task;
- raw_spin_lock_irqsave(&wakeup_lock, flags);
+#ifdef CONFIG_SWITCHTIME_HIST
+ struct task_struct *cpu_switchtime_task;
+
+ if (!switchtime_pid) {
+ raw_spin_lock_irqsave(&switchtime_lock, flags);
+ cpu_switchtime_task = per_cpu(switchtime_task, cpu);
+ if (cpu_switchtime_task &&
+ p->prio < cpu_switchtime_task->prio) {
+ cpu_switchtime_task->switchtime_timestamp_hist = 0;
+ put_task_struct(cpu_switchtime_task);
+ per_cpu(switchtime_task, cpu) = NULL;
+ }
+ raw_spin_unlock_irqrestore(&switchtime_lock, flags);
+ }
+#endif
+ raw_spin_lock_irqsave(&wakeup_lock, flags);
cpu_wakeup_task = per_cpu(wakeup_task, cpu);
if (wakeup_pid) {
@@ -914,6 +1074,7 @@ static notrace void probe_wakeup_latency
long latency;
cycle_t stop;
struct task_struct *cpu_wakeup_task;
+ int hit = 0;
raw_spin_lock_irqsave(&wakeup_lock, flags);
@@ -949,28 +1110,52 @@ static notrace void probe_wakeup_latency
NSECS_PER_USECS;
if (per_cpu(wakeup_sharedprio, cpu)) {
- latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, 0, stop,
- next);
+ latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, 0, 0,
+ stop, next, -1);
per_cpu(wakeup_sharedprio, cpu) = 0;
} else {
- latency_hist(WAKEUP_LATENCY, cpu, latency, 0, stop, next);
+ latency_hist(WAKEUP_LATENCY, cpu, latency, 0, 0, stop, next,
+ -1);
#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
if (timerandwakeup_enabled_data.enabled) {
latency_hist(TIMERANDWAKEUP_LATENCY, cpu,
- next->timer_offset + latency, next->timer_offset,
- stop, next);
+ next->timer_offset + latency, next->timer_offset, 0,
+ stop, next, -1);
}
+ hit = 1;
#endif
}
out_reset:
-#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
- next->timer_offset = 0;
-#endif
put_task_struct(cpu_wakeup_task);
per_cpu(wakeup_task, cpu) = NULL;
out:
raw_spin_unlock_irqrestore(&wakeup_lock, flags);
+
+#ifdef CONFIG_SWITCHTIME_HIST
+ if (hit && switchtime_enabled_data.enabled &&
+ (switchtime_pid == 0 || task_pid_nr(next) == switchtime_pid)) {
+ unsigned long flags;
+ struct task_struct *cpu_switchtime_task;
+
+ raw_spin_lock_irqsave(&switchtime_lock, flags);
+
+ cpu_switchtime_task = per_cpu(switchtime_task, cpu) =
+ next;
+ get_task_struct(cpu_switchtime_task);
+
+ raw_spin_unlock_irqrestore(&switchtime_lock, flags);
+
+ next->switchtime_timestamp_hist = stop;
+ next->wakeup_latency = latency;
+ next->switchtime_prev = current;
+ }
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+ else
+ next->timer_offset = 0;
+#endif
+
+#endif
}
#endif
@@ -992,10 +1177,28 @@ static notrace void probe_hrtimer_interr
return;
}
+#ifdef CONFIG_SWITCHTIME_HIST
+ if (!switchtime_pid) {
+ unsigned long flags;
+ struct task_struct *cpu_switchtime_task;
+
+ raw_spin_lock_irqsave(&switchtime_lock, flags);
+ cpu_switchtime_task = per_cpu(switchtime_task, cpu);
+ if (cpu_switchtime_task &&
+ task->prio < cpu_switchtime_task->prio) {
+ cpu_switchtime_task->switchtime_timestamp_hist =
+ 0;
+ put_task_struct(cpu_switchtime_task);
+ per_cpu(switchtime_task, cpu) = NULL;
+ }
+ raw_spin_unlock_irqrestore(&switchtime_lock, flags);
+ }
+#endif
+
now = ftrace_now(cpu);
latency = (long) div_s64(-latency_ns, NSECS_PER_USECS);
- latency_hist(MISSED_TIMER_OFFSETS, cpu, latency, latency, now,
- task);
+ latency_hist(MISSED_TIMER_OFFSETS, cpu, latency, 0, 0, now,
+ task, -1);
#ifdef CONFIG_WAKEUP_LATENCY_HIST
task->timer_offset = latency;
#endif
@@ -1003,6 +1206,66 @@ static notrace void probe_hrtimer_interr
}
#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+static notrace void probe_syscall_exit(void *v, struct pt_regs *regs, long ret)
+{
+ unsigned long flags;
+ int cpu = task_cpu(current);
+ struct task_struct *cpu_switchtime_task;
+
+ raw_spin_lock_irqsave(&switchtime_lock, flags);
+
+ cpu_switchtime_task = per_cpu(switchtime_task, cpu);
+ if (cpu_switchtime_task == NULL)
+ goto out;
+
+ if (current == cpu_switchtime_task) {
+ unsigned long latency;
+ cycle_t stop;
+ int syscall_nr;
+
+ if (switchtime_pid) {
+ if (likely(switchtime_pid !=
+ task_pid_nr(current)))
+ goto out;
+ }
+
+ /*
+ * The task we are waiting for exited from sytem call.
+ * Calculate latency since start of context switch and store it
+ * in histogram.
+ */
+ stop = ftrace_now(raw_smp_processor_id());
+
+ latency = ((long) (stop - current->switchtime_timestamp_hist)) /
+ NSECS_PER_USECS;
+
+ syscall_nr = syscall_get_nr(current, regs);
+
+ current->switchtime_timestamp_hist = 0;
+
+ latency_hist(SWITCHTIME, cpu, latency, 0, 0, stop,
+ current->switchtime_prev, syscall_nr);
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+ if (timerwakeupswitch_enabled_data.enabled) {
+ latency_hist(TIMERWAKEUPSWITCH_LATENCY, cpu,
+ current->timer_offset + current->wakeup_latency +
+ latency, current->timer_offset,
+ current->wakeup_latency, stop,
+ current->switchtime_prev, syscall_nr);
+ }
+ current->timer_offset = current->wakeup_latency = 0;
+#endif
+ }
+ put_task_struct(cpu_switchtime_task);
+ per_cpu(switchtime_task, cpu) = NULL;
+
+out:
+ raw_spin_unlock_irqrestore(&switchtime_lock, flags);
+}
+#endif
+
static __init int latency_hist_init(void)
{
struct dentry *latency_hist_root = NULL;
@@ -1147,6 +1410,32 @@ static __init int latency_hist_init(void
&enable_fops);
#endif
+#ifdef CONFIG_SWITCHTIME_HIST
+ dentry = debugfs_create_dir(switchtime_dir,
+ latency_hist_root);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(switchtime, i), &latency_hist_fops);
+ my_hist = &per_cpu(switchtime, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+
+ sprintf(name, cpufmt_maxlatproc, i);
+ mp = &per_cpu(switchtime_maxlatproc, i);
+ entry = debugfs_create_file(name, 0444, dentry, mp,
+ &maxlatproc_fops);
+ clear_maxlatprocdata(mp);
+ }
+ entry = debugfs_create_file("pid", 0644, dentry,
+ (void *)&switchtime_pid, &pid_fops);
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)SWITCHTIME, &latency_hist_reset_fops);
+ entry = debugfs_create_file("switchtime", 0644,
+ enable_root, (void *)&switchtime_enabled_data,
+ &enable_fops);
+#endif
+
#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
dentry = debugfs_create_dir(timerandwakeup_latency_hist_dir,
@@ -1172,6 +1461,32 @@ static __init int latency_hist_init(void
enable_root, (void *)&timerandwakeup_enabled_data,
&enable_fops);
#endif
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) && \
+ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) && \
+ defined(CONFIG_SWITCHTIME_HIST)
+ dentry = debugfs_create_dir(timerwakeupswitch_latency_hist_dir,
+ latency_hist_root);
+ for_each_possible_cpu(i) {
+ sprintf(name, cpufmt, i);
+ entry = debugfs_create_file(name, 0444, dentry,
+ &per_cpu(timerwakeupswitch_latency_hist, i),
+ &latency_hist_fops);
+ my_hist = &per_cpu(timerwakeupswitch_latency_hist, i);
+ atomic_set(&my_hist->hist_mode, 1);
+ my_hist->min_lat = LONG_MAX;
+
+ sprintf(name, cpufmt_maxlatproc, i);
+ mp = &per_cpu(timerwakeupswitch_maxlatproc, i);
+ entry = debugfs_create_file(name, 0444, dentry, mp,
+ &maxlatproc_fops);
+ clear_maxlatprocdata(mp);
+ }
+ entry = debugfs_create_file("reset", 0644, dentry,
+ (void *)TIMERWAKEUPSWITCH_LATENCY, &latency_hist_reset_fops);
+ entry = debugfs_create_file("timerwakeupswitch", 0644,
+ enable_root, (void *)&timerwakeupswitch_enabled_data,
+ &enable_fops);
+#endif
return 0;
}
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2016-07-28 20:02 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-07-28 4:52 [PATCH 0/2] *** Latency Histogram *** Binoy Jayan
2016-07-28 4:52 ` [PATCH 1/2] tracing: Add latency histograms Binoy Jayan
2016-07-28 18:51 ` Carsten Emde
2016-07-28 4:52 ` [PATCH 2/2] trace: Add missing tracer macros Binoy Jayan
2016-07-28 13:10 ` [PATCH 0/2] *** Latency Histogram *** Steven Rostedt
2016-07-28 13:25 ` Daniel Wagner
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.