| From 2b9e26d455e61248e467989b2d1cedb75c8e26fe Mon Sep 17 00:00:00 2001 |
| From: Carsten Emde <Carsten.Emde@osadl.org> |
| Date: Mon, 2 Nov 2009 00:59:47 +0100 |
| Subject: [PATCH] ftrace: Add latency histograms of missed timer offsets |
| |
| commit d2ac742de047029bb44d0f1b7d4b01c35678a19a in tip. |
| |
| A source of system latencies not yet considered in the histograms |
| of effective latencies are delayed timer interrupts. Such latencies |
| are mainly due to disabled interrupts. Recording of effective latencies |
| allows to continuously monitor a system's real-time capabilities |
| under real-world conditions. |
| |
| This patch adds latency histograms of missed timer offsets. If the |
| timer belongs to a sleeper that is about to wakeup a task and the |
| latency is higher than previous latencies of such timers, some data |
| of this task are recorded as well. |
| |
| Adapted and expanded Documentation/trace/histograms.txt. |
| |
| Signed-off-by: Carsten Emde <C.Emde@osadl.org> |
| Signed-off-by: Thomas Gleixner <tglx@linutronix.de> |
| Signed-off-by: Paul Gortmaker <paul.gortmaker@windriver.com> |
| |
| diff --git a/Documentation/trace/histograms.txt b/Documentation/trace/histograms.txt |
| index 3f6070a..2f17967 100644 |
| --- a/Documentation/trace/histograms.txt |
| +++ b/Documentation/trace/histograms.txt |
| @@ -26,24 +26,41 @@ 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 this latency or not. |
| - Configuration items (in the Kernel hacking/Tracers submenu) |
| - CONFIG_INTERRUPT_OFF_LATENCY |
| - CONFIG_PREEMPT_OFF_LATENCY |
| + CONFIG_INTERRUPT_OFF_HIST |
| + CONFIG_PREEMPT_OFF_HIST |
| |
| |
| * Effective latencies |
| - |
| -Effective latencies are actually occuring 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 considerably longer, |
| -since |
| -i) interrupts may be disabled preventing the scheduler from initiating |
| -the wakeup mechanism, and |
| +There are two types of effective latencies, wakeup latencies and missed |
| +timer latencies |
| + |
| +* Wakeup latencies |
| +Wakeup latencies may occur during wakeup of a process. To determine |
| +wakeup 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 considerably longer, since |
| +i) interrupts may be disabled preventing the timer from waking up a process |
| +in time |
| ii) the process may be interrupted after control is passed over to it |
| but before user space execution takes place. |
| +If a particular wakeup latency is highest so far, details of the task |
| +that is suffering from this latency are stored as well (see below). |
| +- Configuration item (in the Kernel hacking/Tracers submenu) |
| + CONFIG_WAKEUP_LATENCY_HIST |
| + |
| +* Missed timer latencies |
| + |
| +Missed timer latencies occur when a timer interrupt is serviced later |
| +than it should. This is mainly due to disabled interrupts. To determine |
| +the missed timer latency, the expected and the real execution time of a |
| +timer are compared. If the former precedes the latter, the difference is |
| +entered into the missed timer offsets histogram. If the timer is |
| +responsible to wakeup a sleeping process and the latency is highest so |
| +far among previous wakeup timers, details of the related task are stored |
| +as well (see below). |
| - Configuration item (in the Kernel hacking/Tracers submenu) |
| - CONFIG_WAKEUP_LATENCY |
| + CONFIG_MISSED_TIMER_OFFSETS_HIST |
| |
| |
| * Usage |
| @@ -59,19 +76,23 @@ 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 |
| +to the file /etc/fstab in order to implicitly mount the debug file |
| +system at every reboot. All latency histogram related files are |
| 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. The |
| -histogram data - one per CPU - are available in the files |
| +Select "preemptirqsoff" for histograms of potential sources of |
| +latencies, "wakeup" for histograms of wakeup latencies and |
| +"missed_timer_offsets" for histograms of missed timer offsets, |
| +respectively. |
| |
| +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. |
| |
| The histograms are reset by writing non-zero to the file "reset" in a |
| particular latency directory. To reset all latency data, use |
| @@ -94,19 +115,19 @@ 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, |
| +maximum latency is 10,240 microseconds. 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. |
| +#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 |
| +#There are 0 samples lower than 0 microseconds. |
| +#There are 0 samples greater or equal than 10240 microseconds. |
| #usecs samples |
| 0 2984486876 |
| 1 49843506 |
| @@ -140,11 +161,16 @@ grep -v " 0$" /sys/kernel/debug/tracing/latency_hist/preemptoff/CPU0 |
| Two different algorithms are used to determine the wakeup latency of a |
| process. One of them only considers processes that exclusively use the |
| highest priority of the system, the other one records the wakeup latency |
| -of a process even if it shares the highest systemm latency with other |
| -processes. The former is used to improve hardware and system software; |
| -the related histograms are located it the wakeup subdirectory. The |
| -latter is used to optimize the priority design of a given system; the |
| -related histograms are located in the wakeup/sharedprio subdirectory. |
| +of a process even if it shares the highest system latency with other |
| +processes. The former is used to determine the worst-case latency of a |
| +system; if higher than expected, the hardware and or system software |
| +(e.g. the Linux kernel) may need to be debugged and fixed. The latter |
| +reflects the priority design of a given system; if higher than expected, |
| +the system design may need to be re-evaluated - the hardware |
| +manufacturer or the kernel developers must not be blamed for such |
| +latencies. The exclusive-priority wakeup latency histograms are located |
| +in the "wakeup" subdirectory, the shared-priority histograms are located |
| +in the "wakeup/sharedprio" subdirectory. |
| |
| |
| * Wakeup latency of a selected process |
| @@ -157,20 +183,18 @@ PID of the requested process to |
| PIDs are not considered, if this variable is set to 0. |
| |
| |
| -* Details of the process with the highest wakeup latency so far |
| +* Details of processes with the highest wakeup or missed timer |
| +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 files |
| +Selected data of processes that suffered from the highest wakeup or |
| +missed timer latency that occurred on a particular CPU are available in |
| +the files |
| |
| /sys/kernel/debug/tracing/latency_hist/wakeup/max_latency-CPUx |
| - |
| -and |
| - |
| -/sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio/max_latency-CPUx, |
| - |
| -respectively. |
| +/sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio/max_latency-CPUx |
| +/sys/kernel/debug/tracing/latency_hist/missed_timer_offsets/max_latency-CPUx |
| |
| The format of the data is |
| <PID> <Priority> <Latency> <Command> |
| |
| -These data are also reset when the related wakeup histograms are reset. |
| +These data are also reset when the related histograms are reset. |
| diff --git a/include/trace/events/hist.h b/include/trace/events/hist.h |
| index 73b0454..2dc4c70 100644 |
| --- a/include/trace/events/hist.h |
| +++ b/include/trace/events/hist.h |
| @@ -17,8 +17,8 @@ TRACE_EVENT(preemptirqsoff_hist, |
| TP_ARGS(reason, starthist), |
| |
| TP_STRUCT__entry( |
| - __field( int, reason ) |
| - __field( int, starthist ) |
| + __field(int, reason ) |
| + __field(int, starthist ) |
| ), |
| |
| TP_fast_assign( |
| @@ -31,6 +31,31 @@ TRACE_EVENT(preemptirqsoff_hist, |
| ); |
| #endif |
| |
| +#ifndef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| +#define trace_hrtimer_interrupt(a,b,c) |
| +#else |
| +TRACE_EVENT(hrtimer_interrupt, |
| + |
| + TP_PROTO(int cpu, long long offset, struct task_struct *task), |
| + |
| + TP_ARGS(cpu, offset, task), |
| + |
| + TP_STRUCT__entry( |
| + __array(char, comm, TASK_COMM_LEN) |
| + __field(int, cpu ) |
| + __field(long long, offset ) |
| + ), |
| + |
| + TP_fast_assign( |
| + strncpy(__entry->comm, task != NULL ? task->comm : "", TASK_COMM_LEN); |
| + __entry->cpu = cpu; |
| + __entry->offset = offset; |
| + ), |
| + |
| + TP_printk("cpu=%d offset=%lld thread=%s", __entry->cpu, __entry->offset, __entry->comm) |
| +); |
| +#endif |
| + |
| #endif /* _TRACE_HIST_H */ |
| |
| /* This part must be outside protection */ |
| diff --git a/init/main.c b/init/main.c |
| index b90180a..4445c08 100644 |
| --- a/init/main.c |
| +++ b/init/main.c |
| @@ -899,7 +899,15 @@ static int __init kernel_init(void * unused) |
| WARN_ON(irqs_disabled()); |
| #endif |
| |
| -#define DEBUG_COUNT (defined(CONFIG_DEBUG_RT_MUTEXES) + defined(CONFIG_IRQSOFF_TRACER) + defined(CONFIG_PREEMPT_TRACER) + defined(CONFIG_STACK_TRACER) + defined(CONFIG_INTERRUPT_OFF_HIST) + defined(CONFIG_PREEMPT_OFF_HIST) + defined(CONFIG_WAKEUP_LATENCY_HIST) + defined(CONFIG_DEBUG_SLAB) + defined(CONFIG_DEBUG_PAGEALLOC) + defined(CONFIG_LOCKDEP) + (defined(CONFIG_FTRACE) - defined(CONFIG_FTRACE_MCOUNT_RECORD))) |
| +#define DEBUG_COUNT (defined(CONFIG_DEBUG_RT_MUTEXES) + \ |
| + defined(CONFIG_IRQSOFF_TRACER) + defined(CONFIG_PREEMPT_TRACER) + \ |
| + defined(CONFIG_STACK_TRACER) + defined(CONFIG_INTERRUPT_OFF_HIST) + \ |
| + defined(CONFIG_PREEMPT_OFF_HIST) + \ |
| + defined(CONFIG_WAKEUP_LATENCY_HIST) + \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) + \ |
| + defined(CONFIG_DEBUG_SLAB) + defined(CONFIG_DEBUG_PAGEALLOC) + \ |
| + defined(CONFIG_LOCKDEP) + \ |
| + (defined(CONFIG_FTRACE) - defined(CONFIG_FTRACE_MCOUNT_RECORD))) |
| |
| #if DEBUG_COUNT > 0 |
| printk(KERN_ERR "*****************************************************************************\n"); |
| @@ -931,6 +939,9 @@ static int __init kernel_init(void * unused) |
| #ifdef CONFIG_WAKEUP_LATENCY_HIST |
| printk(KERN_ERR "* CONFIG_WAKEUP_LATENCY_HIST *\n"); |
| #endif |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| + printk(KERN_ERR "* CONFIG_MISSED_TIMER_OFFSETS_HIST *\n"); |
| +#endif |
| #ifdef CONFIG_DEBUG_SLAB |
| printk(KERN_ERR "* CONFIG_DEBUG_SLAB *\n"); |
| #endif |
| diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c |
| index 720ceb5..e018333 100644 |
| --- a/kernel/hrtimer.c |
| +++ b/kernel/hrtimer.c |
| @@ -49,6 +49,7 @@ |
| #include <asm/uaccess.h> |
| |
| #include <trace/events/timer.h> |
| +#include <trace/events/hist.h> |
| |
| /* |
| * The timer bases: |
| @@ -1415,6 +1416,8 @@ static inline int hrtimer_rt_defer(struct hrtimer *timer) { return 0; } |
| |
| #ifdef CONFIG_HIGH_RES_TIMERS |
| |
| +static enum hrtimer_restart hrtimer_wakeup(struct hrtimer *timer); |
| + |
| /* |
| * High resolution timer interrupt |
| * Called with interrupts disabled |
| @@ -1457,6 +1460,14 @@ retry: |
| |
| timer = rb_entry(node, struct hrtimer, node); |
| |
| + trace_hrtimer_interrupt(raw_smp_processor_id(), |
| + ktime_to_ns(ktime_sub( |
| + 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 adc44b6..fb9ec61 100644 |
| --- a/kernel/trace/Kconfig |
| +++ b/kernel/trace/Kconfig |
| @@ -187,7 +187,10 @@ config INTERRUPT_OFF_HIST |
| |
| 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. |
| + 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" |
| @@ -224,7 +227,10 @@ config PREEMPT_OFF_HIST |
| |
| 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. |
| + 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" |
| @@ -251,7 +257,29 @@ config WAKEUP_LATENCY_HIST |
| 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. |
| + 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 |
| + |
| +config MISSED_TIMER_OFFSETS_HIST |
| + depends on GENERIC_TIME |
| + 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 |
| |
| config SYSPROF_TRACER |
| bool "Sysprof Tracer" |
| diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile |
| index 04e959d..5dddc4d 100644 |
| --- a/kernel/trace/Makefile |
| +++ b/kernel/trace/Makefile |
| @@ -38,6 +38,7 @@ 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 |
| index 6fe972e..83d8d2f 100644 |
| --- a/kernel/trace/latency_hist.c |
| +++ b/kernel/trace/latency_hist.c |
| @@ -35,6 +35,7 @@ enum { |
| PREEMPTIRQSOFF_LATENCY, |
| WAKEUP_LATENCY, |
| WAKEUP_LATENCY_SHAREDPRIO, |
| + MISSED_TIMER_OFFSETS, |
| MAX_LATENCY_TYPE, |
| }; |
| |
| @@ -42,9 +43,11 @@ enum { |
| |
| 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 */ |
| unsigned long min_lat; |
| unsigned long max_lat; |
| - unsigned long long beyond_hist_bound_samples; |
| + unsigned long long below_hist_bound_samples; |
| + unsigned long long above_hist_bound_samples; |
| unsigned long long accumulate_lat; |
| unsigned long long total_samples; |
| unsigned long long hist_array[MAX_ENTRY_NUM]; |
| @@ -60,16 +63,22 @@ static char *latency_hist_dir_root = "latency_hist"; |
| #ifdef CONFIG_INTERRUPT_OFF_HIST |
| static DEFINE_PER_CPU(struct hist_data, irqsoff_hist); |
| static char *irqsoff_hist_dir = "irqsoff"; |
| +static DEFINE_PER_CPU(cycles_t, hist_irqsoff_start); |
| +static DEFINE_PER_CPU(int, hist_irqsoff_counting); |
| #endif |
| |
| #ifdef CONFIG_PREEMPT_OFF_HIST |
| static DEFINE_PER_CPU(struct hist_data, preemptoff_hist); |
| static char *preemptoff_hist_dir = "preemptoff"; |
| +static DEFINE_PER_CPU(cycles_t, hist_preemptoff_start); |
| +static DEFINE_PER_CPU(int, hist_preemptoff_counting); |
| #endif |
| |
| #if defined(CONFIG_PREEMPT_OFF_HIST) && defined(CONFIG_INTERRUPT_OFF_HIST) |
| static DEFINE_PER_CPU(struct hist_data, preemptirqsoff_hist); |
| static char *preemptirqsoff_hist_dir = "preemptirqsoff"; |
| +static DEFINE_PER_CPU(cycles_t, hist_preemptirqsoff_start); |
| +static DEFINE_PER_CPU(int, hist_preemptirqsoff_counting); |
| #endif |
| |
| #if defined(CONFIG_PREEMPT_OFF_HIST) || defined(CONFIG_INTERRUPT_OFF_HIST) |
| @@ -80,6 +89,16 @@ static struct enable_data preemptirqsoff_enabled_data = { |
| }; |
| #endif |
| |
| +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) |
| +struct maxlatproc_data { |
| + char comm[FIELD_SIZEOF(struct task_struct, comm)]; |
| + unsigned int pid; |
| + unsigned int prio; |
| + unsigned long latency; |
| +}; |
| +#endif |
| + |
| #ifdef CONFIG_WAKEUP_LATENCY_HIST |
| static DEFINE_PER_CPU(struct hist_data, wakeup_latency_hist); |
| static DEFINE_PER_CPU(struct hist_data, wakeup_latency_hist_sharedprio); |
| @@ -93,13 +112,6 @@ static struct enable_data wakeup_latency_enabled_data = { |
| .latency_type = WAKEUP_LATENCY, |
| .enabled = 0, |
| }; |
| -static struct task_struct *ts; |
| -struct maxlatproc_data { |
| - char comm[sizeof(ts->comm)]; |
| - unsigned int pid; |
| - unsigned int prio; |
| - unsigned long latency; |
| -}; |
| static DEFINE_PER_CPU(struct maxlatproc_data, wakeup_maxlatproc); |
| static DEFINE_PER_CPU(struct maxlatproc_data, wakeup_maxlatproc_sharedprio); |
| static struct task_struct *wakeup_task; |
| @@ -107,11 +119,25 @@ static int wakeup_sharedprio; |
| static int wakeup_pid; |
| #endif |
| |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| +static DEFINE_PER_CPU(struct hist_data, missed_timer_offsets); |
| +static char *missed_timer_offsets_dir = "missed_timer_offsets"; |
| +static notrace void probe_hrtimer_interrupt(int cpu, |
| + long long offset, struct task_struct *task); |
| +static struct enable_data missed_timer_offsets_enabled_data = { |
| + .latency_type = MISSED_TIMER_OFFSETS, |
| + .enabled = 0, |
| +}; |
| +static DEFINE_PER_CPU(struct maxlatproc_data, |
| + missed_timer_offsets_maxlatproc); |
| +#endif |
| + |
| void notrace latency_hist(int latency_type, int cpu, unsigned long latency, |
| struct task_struct *p) |
| { |
| struct hist_data *my_hist; |
| -#ifdef CONFIG_WAKEUP_LATENCY_HIST |
| +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) |
| struct maxlatproc_data *mp = NULL; |
| #endif |
| |
| @@ -125,19 +151,16 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency, |
| my_hist = &per_cpu(irqsoff_hist, cpu); |
| break; |
| #endif |
| - |
| #ifdef CONFIG_PREEMPT_OFF_HIST |
| case PREEMPTOFF_LATENCY: |
| my_hist = &per_cpu(preemptoff_hist, cpu); |
| break; |
| #endif |
| - |
| #if defined(CONFIG_PREEMPT_OFF_HIST) && defined(CONFIG_INTERRUPT_OFF_HIST) |
| case PREEMPTIRQSOFF_LATENCY: |
| my_hist = &per_cpu(preemptirqsoff_hist, cpu); |
| break; |
| #endif |
| - |
| #ifdef CONFIG_WAKEUP_LATENCY_HIST |
| case WAKEUP_LATENCY: |
| my_hist = &per_cpu(wakeup_latency_hist, cpu); |
| @@ -148,6 +171,12 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency, |
| mp = &per_cpu(wakeup_maxlatproc_sharedprio, cpu); |
| break; |
| #endif |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| + case MISSED_TIMER_OFFSETS: |
| + my_hist = &per_cpu(missed_timer_offsets, cpu); |
| + mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu); |
| + break; |
| +#endif |
| default: |
| return; |
| } |
| @@ -155,15 +184,21 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency, |
| if (atomic_read(&my_hist->hist_mode) == 0) |
| return; |
| |
| - if (latency >= MAX_ENTRY_NUM) |
| - my_hist->beyond_hist_bound_samples++; |
| - else |
| + latency += my_hist->offset; |
| + |
| + 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 (latency < my_hist->min_lat) |
| my_hist->min_lat = latency; |
| else if (latency > my_hist->max_lat) { |
| -#ifdef CONFIG_WAKEUP_LATENCY_HIST |
| +#if defined (CONFIG_WAKEUP_LATENCY_HIST) || \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) |
| if (latency_type == WAKEUP_LATENCY || |
| latency_type == WAKEUP_LATENCY_SHAREDPRIO) { |
| strncpy(mp->comm, p->comm, sizeof(mp->comm)); |
| @@ -174,7 +209,15 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency, |
| #endif |
| my_hist->max_lat = latency; |
| } |
| - |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| + if (latency_type == MISSED_TIMER_OFFSETS && p != NULL && |
| + latency > mp->latency) { |
| + strncpy(mp->comm, p->comm, sizeof(mp->comm)); |
| + mp->pid = task_pid_nr(p); |
| + mp->prio = p->prio; |
| + mp->latency = latency; |
| + } |
| +#endif |
| my_hist->total_samples++; |
| my_hist->accumulate_lat += latency; |
| return; |
| @@ -190,30 +233,42 @@ static void *l_start(struct seq_file *m, loff_t *pos) |
| return NULL; |
| |
| if (index == 0) { |
| - char avgstr[32]; |
| + char minstr[32], avgstr[32], maxstr[32]; |
| |
| atomic_dec(&my_hist->hist_mode); |
| + |
| if (likely(my_hist->total_samples)) { |
| unsigned long avg = (unsigned long) |
| div64_u64(my_hist->accumulate_lat, |
| my_hist->total_samples); |
| - sprintf(avgstr, "%lu", avg); |
| - } else |
| - strcpy(avgstr, "<undef>"); |
| + snprintf(minstr, sizeof(minstr), "%ld", |
| + (long) my_hist->min_lat - my_hist->offset); |
| + snprintf(avgstr, sizeof(avgstr), "%ld", |
| + (long) avg - my_hist->offset); |
| + snprintf(maxstr, sizeof(minstr), "%ld", |
| + (long) my_hist->max_lat - my_hist->offset); |
| + } else { |
| + strcpy(minstr, "<undef>"); |
| + strcpy(avgstr, minstr); |
| + strcpy(maxstr, minstr); |
| + } |
| |
| - seq_printf(m, "#Minimum latency: %lu microseconds.\n" |
| - "#Average latency: %s microseconds.\n" |
| - "#Maximum latency: %lu microseconds.\n" |
| + 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 %d microseconds\n" |
| - "#usecs\t%16s\n" |
| - , my_hist->min_lat |
| - , avgstr |
| - , my_hist->max_lat |
| - , my_hist->total_samples |
| - , my_hist->beyond_hist_bound_samples |
| - , MAX_ENTRY_NUM, "samples"); |
| + " 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) |
| return NULL; |
| @@ -244,8 +299,15 @@ static int l_show(struct seq_file *m, void *p) |
| { |
| int index = *(loff_t *) p; |
| struct hist_data *my_hist = m->private; |
| + char *fmt; |
| + |
| + if (my_hist->offset) |
| + fmt = "%6d\t%16llu\n"; |
| + else |
| + fmt = "%5d\t%16llu\n"; |
| |
| - seq_printf(m, "%5d\t%16llu\n", index, my_hist->hist_array[index]); |
| + seq_printf(m, fmt, index - my_hist->offset, |
| + my_hist->hist_array[index]); |
| return 0; |
| } |
| |
| @@ -280,7 +342,8 @@ static void hist_reset(struct hist_data *hist) |
| atomic_dec(&hist->hist_mode); |
| |
| memset(hist->hist_array, 0, sizeof(hist->hist_array)); |
| - hist->beyond_hist_bound_samples = 0ULL; |
| + hist->below_hist_bound_samples = 0ULL; |
| + hist->above_hist_bound_samples = 0ULL; |
| hist->min_lat = 0xFFFFFFFFUL; |
| hist->max_lat = 0UL; |
| hist->total_samples = 0ULL; |
| @@ -295,13 +358,13 @@ latency_hist_reset(struct file *file, const char __user *a, |
| { |
| int cpu; |
| struct hist_data *hist; |
| -#ifdef CONFIG_WAKEUP_LATENCY_HIST |
| +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) |
| struct maxlatproc_data *mp = NULL; |
| #endif |
| int latency_type = (int) file->private_data; |
| |
| switch (latency_type) { |
| - |
| #ifdef CONFIG_PREEMPT_OFF_HIST |
| case PREEMPTOFF_LATENCY: |
| for_each_online_cpu(cpu) { |
| @@ -310,7 +373,6 @@ latency_hist_reset(struct file *file, const char __user *a, |
| } |
| break; |
| #endif |
| - |
| #ifdef CONFIG_INTERRUPT_OFF_HIST |
| case IRQSOFF_LATENCY: |
| for_each_online_cpu(cpu) { |
| @@ -319,7 +381,6 @@ latency_hist_reset(struct file *file, const char __user *a, |
| } |
| break; |
| #endif |
| - |
| #if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST) |
| case PREEMPTIRQSOFF_LATENCY: |
| for_each_online_cpu(cpu) { |
| @@ -328,7 +389,6 @@ latency_hist_reset(struct file *file, const char __user *a, |
| } |
| break; |
| #endif |
| - |
| #ifdef CONFIG_WAKEUP_LATENCY_HIST |
| case WAKEUP_LATENCY: |
| for_each_online_cpu(cpu) { |
| @@ -339,7 +399,6 @@ latency_hist_reset(struct file *file, const char __user *a, |
| mp->prio = mp->pid = mp->latency = 0; |
| } |
| break; |
| - |
| case WAKEUP_LATENCY_SHAREDPRIO: |
| for_each_online_cpu(cpu) { |
| hist = &per_cpu(wakeup_latency_hist_sharedprio, cpu); |
| @@ -350,6 +409,17 @@ latency_hist_reset(struct file *file, const char __user *a, |
| } |
| break; |
| #endif |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| + case MISSED_TIMER_OFFSETS: |
| + for_each_online_cpu(cpu) { |
| + hist = &per_cpu(missed_timer_offsets, cpu); |
| + hist_reset(hist); |
| + mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu); |
| + mp->comm[0] = '\0'; |
| + mp->prio = mp->pid = mp->latency = 0; |
| + } |
| + break; |
| +#endif |
| } |
| |
| return size; |
| @@ -388,7 +458,10 @@ latency_hist_pid(struct file *filp, const char __user *ubuf, |
| wakeup_pid = pid; |
| return cnt; |
| } |
| +#endif |
| |
| +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) |
| static ssize_t |
| latency_hist_show_maxlatproc(struct file *filp, char __user *ubuf, |
| size_t cnt, loff_t *ppos) |
| @@ -405,20 +478,6 @@ latency_hist_show_maxlatproc(struct file *filp, char __user *ubuf, |
| |
| #endif |
| |
| -#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST) |
| -#ifdef CONFIG_INTERRUPT_OFF_HIST |
| -static DEFINE_PER_CPU(cycles_t, hist_irqsoff_start); |
| -static DEFINE_PER_CPU(int, hist_irqsoff_counting); |
| -#endif |
| -#ifdef CONFIG_PREEMPT_OFF_HIST |
| -static DEFINE_PER_CPU(cycles_t, hist_preemptoff_start); |
| -static DEFINE_PER_CPU(int, hist_preemptoff_counting); |
| -#endif |
| -#if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST) |
| -static DEFINE_PER_CPU(cycles_t, hist_preemptirqsoff_start); |
| -static DEFINE_PER_CPU(int, hist_preemptirqsoff_counting); |
| -#endif |
| - |
| static ssize_t |
| latency_hist_show_enable(struct file *filp, char __user *ubuf, |
| size_t cnt, loff_t *ppos) |
| @@ -457,6 +516,19 @@ latency_hist_enable(struct file *filp, const char __user *ubuf, |
| int ret; |
| |
| switch (ed->latency_type) { |
| +#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST) |
| + case PREEMPTIRQSOFF_LATENCY: |
| + ret = register_trace_preemptirqsoff_hist( |
| + probe_preemptirqsoff_hist); |
| + if (ret) { |
| + pr_info("wakeup trace: Couldn't assign " |
| + "probe_preemptirqsoff_hist " |
| + "to trace_preemptirqsoff_hist\n"); |
| + return ret; |
| + } |
| + break; |
| +#endif |
| +#ifdef CONFIG_WAKEUP_LATENCY_HIST |
| case WAKEUP_LATENCY: |
| ret = register_trace_sched_wakeup( |
| probe_wakeup_latency_hist_start); |
| @@ -489,23 +561,49 @@ latency_hist_enable(struct file *filp, const char __user *ubuf, |
| return ret; |
| } |
| break; |
| - case PREEMPTIRQSOFF_LATENCY: |
| - ret = register_trace_preemptirqsoff_hist( |
| - probe_preemptirqsoff_hist); |
| +#endif |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| + case MISSED_TIMER_OFFSETS: |
| + ret = register_trace_hrtimer_interrupt( |
| + probe_hrtimer_interrupt); |
| if (ret) { |
| pr_info("wakeup trace: Couldn't assign " |
| - "probe_preemptirqsoff_hist " |
| - "to trace_preemptirqsoff_hist\n"); |
| + "probe_hrtimer_interrupt " |
| + "to trace_hrtimer_interrupt\n"); |
| return ret; |
| } |
| break; |
| +#endif |
| default: |
| break; |
| } |
| } else { |
| - int cpu; |
| - |
| switch (ed->latency_type) { |
| +#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST) |
| + case PREEMPTIRQSOFF_LATENCY: |
| + { |
| + int cpu; |
| + |
| + unregister_trace_preemptirqsoff_hist( |
| + probe_preemptirqsoff_hist); |
| + for_each_online_cpu(cpu) { |
| +#ifdef CONFIG_INTERRUPT_OFF_HIST |
| + per_cpu(hist_irqsoff_counting, |
| + cpu) = 0; |
| +#endif |
| +#ifdef CONFIG_PREEMPT_OFF_HIST |
| + per_cpu(hist_preemptoff_counting, |
| + cpu) = 0; |
| +#endif |
| +#if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST) |
| + per_cpu(hist_preemptirqsoff_counting, |
| + cpu) = 0; |
| +#endif |
| + } |
| + } |
| + break; |
| +#endif |
| +#ifdef CONFIG_WAKEUP_LATEHCY_HIST |
| case WAKEUP_LATENCY: |
| unregister_trace_sched_wakeup( |
| probe_wakeup_latency_hist_start); |
| @@ -516,21 +614,13 @@ latency_hist_enable(struct file *filp, const char __user *ubuf, |
| wakeup_task = NULL; |
| wakeup_sharedprio = 0; |
| break; |
| - case PREEMPTIRQSOFF_LATENCY: |
| - unregister_trace_preemptirqsoff_hist( |
| - probe_preemptirqsoff_hist); |
| - for_each_online_cpu(cpu) { |
| -#ifdef CONFIG_INTERRUPT_OFF_HIST |
| - per_cpu(hist_irqsoff_counting, cpu) = 0; |
| #endif |
| -#ifdef CONFIG_PREEMPT_OFF_HIST |
| - per_cpu(hist_preemptoff_counting, cpu) = 0; |
| -#endif |
| -#if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST) |
| - per_cpu(hist_preemptirqsoff_counting, cpu) = 0; |
| -#endif |
| - } |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| + case MISSED_TIMER_OFFSETS: |
| + unregister_trace_hrtimer_interrupt( |
| + probe_hrtimer_interrupt); |
| break; |
| +#endif |
| default: |
| break; |
| } |
| @@ -544,23 +634,29 @@ static const struct file_operations latency_hist_reset_fops = { |
| .write = latency_hist_reset, |
| }; |
| |
| +static const struct file_operations latency_hist_enable_fops = { |
| + .open = tracing_open_generic, |
| + .read = latency_hist_show_enable, |
| + .write = latency_hist_enable, |
| +}; |
| + |
| +#ifdef CONFIG_WAKEUP_LATENCY_HIST |
| static const struct file_operations latency_hist_pid_fops = { |
| .open = tracing_open_generic, |
| .read = latency_hist_show_pid, |
| .write = latency_hist_pid, |
| }; |
| +#endif |
| |
| +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) |
| static const struct file_operations latency_hist_maxlatproc_fops = { |
| .open = tracing_open_generic, |
| .read = latency_hist_show_maxlatproc, |
| }; |
| +#endif |
| |
| -static const struct file_operations latency_hist_enable_fops = { |
| - .open = tracing_open_generic, |
| - .read = latency_hist_show_enable, |
| - .write = latency_hist_enable, |
| -}; |
| - |
| +#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST) |
| notrace void probe_preemptirqsoff_hist(int reason, int starthist) |
| { |
| int cpu = raw_smp_processor_id(); |
| @@ -660,11 +756,9 @@ notrace void probe_preemptirqsoff_hist(int reason, int starthist) |
| #endif |
| } |
| } |
| - |
| #endif |
| |
| #ifdef CONFIG_WAKEUP_LATENCY_HIST |
| -static cycle_t wakeup_start; |
| static DEFINE_RAW_SPINLOCK(wakeup_lock); |
| |
| notrace void probe_wakeup_latency_hist_start(struct rq *rq, |
| @@ -694,8 +788,8 @@ notrace void probe_wakeup_latency_hist_start(struct rq *rq, |
| put_task_struct(wakeup_task); |
| get_task_struct(p); |
| wakeup_task = p; |
| - wakeup_start = ftrace_now(raw_smp_processor_id()); |
| - wakeup_task->preempt_timestamp_hist = wakeup_start; |
| + wakeup_task->preempt_timestamp_hist = |
| + ftrace_now(raw_smp_processor_id()); |
| raw_spin_unlock_irqrestore(&wakeup_lock, flags); |
| } |
| |
| @@ -714,30 +808,40 @@ notrace void probe_wakeup_latency_hist_stop(struct rq *rq, |
| stop = ftrace_now(cpu); |
| |
| raw_spin_lock_irqsave(&wakeup_lock, flags); |
| + |
| + latency = nsecs_to_usecs(stop - next->preempt_timestamp_hist); |
| if (next != wakeup_task) { |
| - if (wakeup_task && next->prio == wakeup_task->prio) { |
| - latency = nsecs_to_usecs( |
| - stop - next->preempt_timestamp_hist); |
| + if (wakeup_task && next->prio == wakeup_task->prio) |
| latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, |
| next); |
| - } |
| goto out; |
| } |
| |
| - latency = nsecs_to_usecs(stop - wakeup_start); |
| - if (!wakeup_sharedprio) |
| - latency_hist(WAKEUP_LATENCY, cpu, latency, next); |
| - else { |
| + if (wakeup_sharedprio) { |
| latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, next); |
| wakeup_sharedprio = 0; |
| - } |
| + } else |
| + latency_hist(WAKEUP_LATENCY, cpu, latency, next); |
| |
| put_task_struct(wakeup_task); |
| wakeup_task = NULL; |
| out: |
| raw_spin_unlock_irqrestore(&wakeup_lock, flags); |
| } |
| +#endif |
| + |
| +#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST |
| +notrace void probe_hrtimer_interrupt(int cpu, long long latency_ns, |
| + struct task_struct *task) |
| +{ |
| + if (latency_ns <= 0) { |
| + unsigned long latency; |
| |
| + latency = (unsigned long) div_s64(-latency_ns, 1000); |
| + |
| + latency_hist(MISSED_TIMER_OFFSETS, cpu, latency, task); |
| + } |
| +} |
| #endif |
| |
| static __init int latency_hist_init(void) |
| @@ -753,7 +857,10 @@ static __init int latency_hist_init(void) |
| struct hist_data *my_hist; |
| char name[64]; |
| char *cpufmt = "CPU%d"; |
| +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ |
| + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) |
| char *cpufmt_maxlatproc = "max_latency-CPU%d"; |
| +#endif |
| |
| dentry = tracing_init_dentry(); |
| |
| @@ -855,6 +962,30 @@ static __init int latency_hist_init(void) |
| latency_hist_enable_root, (void *)&wakeup_latency_enabled_data, |
| &latency_hist_enable_fops); |
| #endif |
| + |
| +#ifdef 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 = 0xFFFFFFFFUL; |
| + |
| + sprintf(name, cpufmt_maxlatproc, i); |
| + entry = debugfs_create_file(name, 0444, dentry, |
| + &per_cpu(missed_timer_offsets_maxlatproc, i), |
| + &latency_hist_maxlatproc_fops); |
| + } |
| + entry = debugfs_create_file("reset", 0644, dentry, |
| + (void *)MISSED_TIMER_OFFSETS, &latency_hist_reset_fops); |
| + entry = debugfs_create_file("missed_timer_offsets", 0644, |
| + latency_hist_enable_root, |
| + (void *)&missed_timer_offsets_enabled_data, |
| + &latency_hist_enable_fops); |
| +#endif |
| return 0; |
| } |
| |
| -- |
| 1.7.1.1 |
| |