From d9ccd6f8336155d79573ac1c4eb616474ad58bd6 Mon Sep 17 00:00:00 2001 From: Paul Gortmaker Date: Sat, 22 Jan 2011 17:07:07 -0500 Subject: [PATCH] trace bundle uprev parts from merges. This is one of several extractions from the merge up to 33-rc8. See portions of it in a git tip repo with: git diff 5f854cfc024622e4aae14d7cf422f6ff86278688^ \ 5f854cfc024622e4aae14d7cf422f6ff86278688 You can find the origin of this change in the tip merge commit: commit 5f854cfc024622e4aae14d7cf422f6ff86278688 Merge: cc24da0 4ec62b2 Author: Thomas Gleixner Date: Sun Feb 21 20:17:22 2010 +0100 Forward to 2.6.33-rc8 Merge branch 'linus' into rt/head with a pile of conflicts. Signed-off-by: Thomas Gleixner Normally there are not significant changes/additions in a merge commit that are not from any other "normal" commit. But in this case there are, so break them out into separate explicit commits. Signed-off-by: Paul Gortmaker --- Documentation/trace/ftrace.txt | 9 +- Documentation/trace/histograms.txt | 112 ++++-------- include/trace/events/hist.h | 19 ++- kernel/trace/latency_hist.c | 385 ++++++++++++++++++++---------------- kernel/trace/ring_buffer.c | 21 ++- 5 files changed, 277 insertions(+), 269 deletions(-) diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt index 14cc034..03485bf 100644 --- a/Documentation/trace/ftrace.txt +++ b/Documentation/trace/ftrace.txt @@ -117,14 +117,9 @@ of ftrace. Here is a list of some of the key files: For example, the time interrupts are disabled. This time is saved in this file. The max trace will also be stored, and displayed by "trace". - A new max trace will only be recorded, if the + A new max trace will only be recorded if the latency is greater than the value in this - file (in microseconds). Note that the max latency - recorded by the wakeup and the wakeup_rt tracer - do not necessarily reflect the worst-case latency - of the system, but may be erroneously high in - case two or more processes share the maximum - priority of the system. + file. (in microseconds) buffer_size_kb: diff --git a/Documentation/trace/histograms.txt b/Documentation/trace/histograms.txt index 2f17967..6645057 100644 --- a/Documentation/trace/histograms.txt +++ b/Documentation/trace/histograms.txt @@ -24,43 +24,26 @@ 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 this latency or not. +running process is affected by latency or not. - Configuration items (in the Kernel hacking/Tracers submenu) - CONFIG_INTERRUPT_OFF_HIST - CONFIG_PREEMPT_OFF_HIST + CONFIG_INTERRUPT_OFF_LATENCY + CONFIG_PREEMPT_OFF_LATENCY * Effective latencies -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 + +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 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_MISSED_TIMER_OFFSETS_HIST + CONFIG_WAKEUP_LATENCY * Usage @@ -76,36 +59,30 @@ 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 in order to implicitly mount the debug file -system at every reboot. All latency histogram related files are +to the file /etc/fstab. 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 histograms of potential sources of -latencies, "wakeup" for histograms of wakeup latencies and -"missed_timer_offsets" for histograms of missed timer offsets, -respectively. +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 -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 -#!/bin/bash +#!/bin/sh -TRACINGDIR=/sys/kernel/debug/tracing -HISTDIR=$TRACINGDIR/latency_hist +HISTDIR=/sys/kernel/debug/tracing/latency_hist if test -d $HISTDIR then cd $HISTDIR - for i in `find . | grep /reset$` + for i in */reset do echo 1 >$i done @@ -115,19 +92,19 @@ fi * Data format Latency data are stored with a resolution of one microsecond. The -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, +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 +#Minimum latency: 0 microseconds. +#Average latency: 0 microseconds. +#Maximum latency: 25 microseconds. #Total samples: 3104770694 -#There are 0 samples lower than 0 microseconds. -#There are 0 samples greater or equal than 10240 microseconds. +#There are 0 samples greater or equal than 10240 microseconds #usecs samples 0 2984486876 1 49843506 @@ -156,23 +133,6 @@ grep -v " 0$" /sys/kernel/debug/tracing/latency_hist/preemptoff/CPU0 25 1 -* Two types of wakeup latency histograms - -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 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 To only collect wakeup latency data of a particular process, write the @@ -183,18 +143,14 @@ PID of the requested process to PIDs are not considered, if this variable is set to 0. -* Details of processes with the highest wakeup or missed timer -latency so far +* Details of the process with the highest wakeup latency so far -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 +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 -/sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio/max_latency-CPUx -/sys/kernel/debug/tracing/latency_hist/missed_timer_offsets/max_latency-CPUx +/sys/kernel/debug/tracing/latency_hist/wakeup/max_latency-CPUx. The format of the data is -These data are also reset when the related histograms are reset. +These data are also reset when the wakeup histogram ist reset. diff --git a/include/trace/events/hist.h b/include/trace/events/hist.h index 2dc4c70..28646db 100644 --- a/include/trace/events/hist.h +++ b/include/trace/events/hist.h @@ -32,27 +32,34 @@ TRACE_EVENT(preemptirqsoff_hist, #endif #ifndef CONFIG_MISSED_TIMER_OFFSETS_HIST -#define trace_hrtimer_interrupt(a,b,c) +#define trace_hrtimer_interrupt(a,b,c,d) #else TRACE_EVENT(hrtimer_interrupt, - TP_PROTO(int cpu, long long offset, struct task_struct *task), + TP_PROTO(int cpu, long long offset, struct task_struct *curr, struct task_struct *task), - TP_ARGS(cpu, offset, task), + TP_ARGS(cpu, offset, curr, task), TP_STRUCT__entry( - __array(char, comm, TASK_COMM_LEN) __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( - strncpy(__entry->comm, task != NULL ? task->comm : "", TASK_COMM_LEN); __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 : "", task != NULL ? TASK_COMM_LEN : 7); + __entry->tprio = task != NULL ? task->prio : -1; ), - TP_printk("cpu=%d offset=%lld thread=%s", __entry->cpu, __entry->offset, __entry->comm) + 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 diff --git a/kernel/trace/latency_hist.c b/kernel/trace/latency_hist.c index 83d8d2f..8300929 100644 --- a/kernel/trace/latency_hist.c +++ b/kernel/trace/latency_hist.c @@ -93,9 +93,9 @@ static struct enable_data preemptirqsoff_enabled_data = { 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; + int pid; + int prio; + long latency; }; #endif @@ -108,28 +108,30 @@ static notrace void probe_wakeup_latency_hist_start(struct rq *rq, struct task_struct *p, int success); static notrace void probe_wakeup_latency_hist_stop(struct rq *rq, struct task_struct *prev, struct task_struct *next); +static notrace void probe_sched_migrate_task(struct task_struct *task, + int cpu); static struct enable_data 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 struct task_struct *wakeup_task; -static int wakeup_sharedprio; -static int wakeup_pid; +static DEFINE_PER_CPU(struct task_struct *, wakeup_task); +static DEFINE_PER_CPU(int, wakeup_sharedprio); +static unsigned long 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); + long long offset, struct task_struct *curr, 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); +static DEFINE_PER_CPU(struct maxlatproc_data, missed_timer_offsets_maxlatproc); +static unsigned long missed_timer_offsets_pid; #endif void notrace latency_hist(int latency_type, int cpu, unsigned long latency, @@ -196,11 +198,12 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency, if (latency < my_hist->min_lat) my_hist->min_lat = latency; - else if (latency > my_hist->max_lat) { -#if defined (CONFIG_WAKEUP_LATENCY_HIST) || \ + if (latency > my_hist->max_lat) { +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) if (latency_type == WAKEUP_LATENCY || - latency_type == WAKEUP_LATENCY_SHAREDPRIO) { + latency_type == WAKEUP_LATENCY_SHAREDPRIO || + latency_type == MISSED_TIMER_OFFSETS) { strncpy(mp->comm, p->comm, sizeof(mp->comm)); mp->pid = task_pid_nr(p); mp->prio = p->prio; @@ -209,18 +212,8 @@ 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; } static void *l_start(struct seq_file *m, loff_t *pos) @@ -245,7 +238,7 @@ static void *l_start(struct seq_file *m, loff_t *pos) (long) my_hist->min_lat - my_hist->offset); snprintf(avgstr, sizeof(avgstr), "%ld", (long) avg - my_hist->offset); - snprintf(maxstr, sizeof(minstr), "%ld", + snprintf(maxstr, sizeof(maxstr), "%ld", (long) my_hist->max_lat - my_hist->offset); } else { strcpy(minstr, ""); @@ -299,14 +292,8 @@ 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, fmt, index - my_hist->offset, + seq_printf(m, "%6ld\t%16llu\n", index - my_hist->offset, my_hist->hist_array[index]); return 0; } @@ -354,71 +341,61 @@ static void hist_reset(struct hist_data *hist) static ssize_t latency_hist_reset(struct file *file, const char __user *a, - size_t size, loff_t *off) + size_t size, loff_t *off) { int cpu; - struct hist_data *hist; + struct hist_data *hist = NULL; #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; + off_t latency_type = (off_t) file->private_data; - switch (latency_type) { + for_each_online_cpu(cpu) { + + switch (latency_type) { #ifdef CONFIG_PREEMPT_OFF_HIST - case PREEMPTOFF_LATENCY: - for_each_online_cpu(cpu) { + case PREEMPTOFF_LATENCY: hist = &per_cpu(preemptoff_hist, cpu); - hist_reset(hist); - } - break; + break; #endif #ifdef CONFIG_INTERRUPT_OFF_HIST - case IRQSOFF_LATENCY: - for_each_online_cpu(cpu) { + case IRQSOFF_LATENCY: hist = &per_cpu(irqsoff_hist, cpu); - hist_reset(hist); - } - break; + break; #endif #if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST) - case PREEMPTIRQSOFF_LATENCY: - for_each_online_cpu(cpu) { + case PREEMPTIRQSOFF_LATENCY: hist = &per_cpu(preemptirqsoff_hist, cpu); - hist_reset(hist); - } - break; + break; #endif #ifdef CONFIG_WAKEUP_LATENCY_HIST - case WAKEUP_LATENCY: - for_each_online_cpu(cpu) { + case WAKEUP_LATENCY: hist = &per_cpu(wakeup_latency_hist, cpu); - hist_reset(hist); mp = &per_cpu(wakeup_maxlatproc, cpu); - mp->comm[0] = '\0'; - mp->prio = mp->pid = mp->latency = 0; - } - break; - case WAKEUP_LATENCY_SHAREDPRIO: - for_each_online_cpu(cpu) { + break; + case WAKEUP_LATENCY_SHAREDPRIO: hist = &per_cpu(wakeup_latency_hist_sharedprio, cpu); - hist_reset(hist); mp = &per_cpu(wakeup_maxlatproc_sharedprio, cpu); - mp->comm[0] = '\0'; - mp->prio = mp->pid = mp->latency = 0; - } - break; + break; #endif #ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST - case MISSED_TIMER_OFFSETS: - for_each_online_cpu(cpu) { + case MISSED_TIMER_OFFSETS: hist = &per_cpu(missed_timer_offsets, cpu); - hist_reset(hist); mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu); + break; +#endif + } + + hist_reset(hist); +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) + if (latency_type == WAKEUP_LATENCY || + latency_type == WAKEUP_LATENCY_SHAREDPRIO || + latency_type == MISSED_TIMER_OFFSETS) { mp->comm[0] = '\0'; - mp->prio = mp->pid = mp->latency = 0; + mp->prio = mp->pid = mp->latency = -1; } - break; #endif } @@ -427,22 +404,22 @@ latency_hist_reset(struct file *file, const char __user *a, #ifdef CONFIG_WAKEUP_LATENCY_HIST static ssize_t -latency_hist_show_pid(struct file *filp, char __user *ubuf, - size_t cnt, loff_t *ppos) +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), "%u\n", wakeup_pid); + r = snprintf(buf, sizeof(buf), "%lu\n", *this_pid); return simple_read_from_buffer(ubuf, cnt, ppos, buf, r); } -static ssize_t -latency_hist_pid(struct file *filp, const char __user *ubuf, - size_t cnt, loff_t *ppos) +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; @@ -455,7 +432,8 @@ latency_hist_pid(struct file *filp, const char __user *ubuf, if (strict_strtoul(buf, 10, &pid)) return(-EINVAL); - wakeup_pid = pid; + *this_pid = pid; + return cnt; } #endif @@ -463,27 +441,23 @@ latency_hist_pid(struct file *filp, const char __user *ubuf, #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) +show_maxlatproc(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos) { char buf[1024]; int r; - struct maxlatproc_data *mp = (struct maxlatproc_data *) - filp->private_data; + struct maxlatproc_data *mp = file->private_data; - r = snprintf(buf, sizeof(buf), "%5d %3d %ld %s\n", - mp->pid, mp->prio, mp->latency, mp->comm); + r = snprintf(buf, sizeof(buf), "%d %d %ld %s\n", + mp->pid, MAX_RT_PRIO-1 - mp->prio, mp->latency, mp->comm); return simple_read_from_buffer(ubuf, cnt, ppos, buf, r); } - #endif static ssize_t -latency_hist_show_enable(struct file *filp, char __user *ubuf, - size_t cnt, loff_t *ppos) +show_enable(struct file *file, char __user *ubuf, size_t cnt, loff_t *ppos) { char buf[64]; - struct enable_data *ed = (struct enable_data *) filp->private_data; + struct enable_data *ed = file->private_data; int r; r = snprintf(buf, sizeof(buf), "%d\n", ed->enabled); @@ -491,12 +465,11 @@ latency_hist_show_enable(struct file *filp, char __user *ubuf, } static ssize_t -latency_hist_enable(struct file *filp, const char __user *ubuf, - size_t cnt, loff_t *ppos) +do_enable(struct file *file, const char __user *ubuf, size_t cnt, loff_t *ppos) { char buf[64]; long enable; - struct enable_data *ed = (struct enable_data *) filp->private_data; + struct enable_data *ed = file->private_data; if (cnt >= sizeof(buf)) return -EINVAL; @@ -556,6 +529,20 @@ latency_hist_enable(struct file *filp, const char __user *ubuf, "to trace_sched_switch\n"); unregister_trace_sched_wakeup( probe_wakeup_latency_hist_start); + unregister_trace_sched_wakeup_new( + probe_wakeup_latency_hist_start); + return ret; + } + ret = register_trace_sched_migrate_task( + probe_sched_migrate_task); + 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); + unregister_trace_sched_wakeup_new( + probe_wakeup_latency_hist_start); unregister_trace_sched_switch( probe_wakeup_latency_hist_stop); return ret; @@ -603,16 +590,25 @@ latency_hist_enable(struct file *filp, const char __user *ubuf, } break; #endif -#ifdef CONFIG_WAKEUP_LATEHCY_HIST +#ifdef CONFIG_WAKEUP_LATENCY_HIST case WAKEUP_LATENCY: - unregister_trace_sched_wakeup( - probe_wakeup_latency_hist_start); - unregister_trace_sched_wakeup_new( - probe_wakeup_latency_hist_start); - unregister_trace_sched_switch( - probe_wakeup_latency_hist_stop); - wakeup_task = NULL; - wakeup_sharedprio = 0; + { + int cpu; + + unregister_trace_sched_wakeup( + probe_wakeup_latency_hist_start); + unregister_trace_sched_wakeup_new( + probe_wakeup_latency_hist_start); + unregister_trace_sched_switch( + probe_wakeup_latency_hist_stop); + unregister_trace_sched_migrate_task( + probe_sched_migrate_task); + + for_each_online_cpu(cpu) { + per_cpu(wakeup_task, cpu) = NULL; + per_cpu(wakeup_sharedprio, cpu) = 0; + } + } break; #endif #ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST @@ -634,30 +630,28 @@ static const struct file_operations latency_hist_reset_fops = { .write = latency_hist_reset, }; -static const struct file_operations latency_hist_enable_fops = { +static const struct file_operations enable_fops = { .open = tracing_open_generic, - .read = latency_hist_show_enable, - .write = latency_hist_enable, + .read = show_enable, + .write = do_enable, }; -#ifdef CONFIG_WAKEUP_LATENCY_HIST -static const struct file_operations latency_hist_pid_fops = { +#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ + defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) +static const struct file_operations pid_fops = { .open = tracing_open_generic, - .read = latency_hist_show_pid, - .write = latency_hist_pid, + .read = show_pid, + .write = do_pid, }; -#endif -#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ - defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) -static const struct file_operations latency_hist_maxlatproc_fops = { +static const struct file_operations maxlatproc_fops = { .open = tracing_open_generic, - .read = latency_hist_show_maxlatproc, + .read = show_maxlatproc, }; #endif #if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST) -notrace void probe_preemptirqsoff_hist(int reason, int starthist) +static notrace void probe_preemptirqsoff_hist(int reason, int starthist) { int cpu = raw_smp_processor_id(); int time_set = 0; @@ -760,85 +754,133 @@ notrace void probe_preemptirqsoff_hist(int reason, int starthist) #ifdef CONFIG_WAKEUP_LATENCY_HIST static DEFINE_RAW_SPINLOCK(wakeup_lock); +static notrace void probe_sched_migrate_task(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; -notrace void probe_wakeup_latency_hist_start(struct rq *rq, + 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); + } +} + +static notrace void probe_wakeup_latency_hist_start(struct rq *rq, struct task_struct *p, int success) { unsigned long flags; struct task_struct *curr = rq_curr(rq); + 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 ((wakeup_task && p->prio == wakeup_task->prio) || + if ((cpu_wakeup_task && p->prio == cpu_wakeup_task->prio) || p->prio == curr->prio) - wakeup_sharedprio = 1; + per_cpu(wakeup_sharedprio, cpu) = 1; if (likely(wakeup_pid != task_pid_nr(p))) - return; + goto out; } else { if (likely(!rt_task(p)) || - (wakeup_task && p->prio > wakeup_task->prio) || + (cpu_wakeup_task && p->prio > cpu_wakeup_task->prio) || p->prio > curr->prio) - return; - if ((wakeup_task && p->prio == wakeup_task->prio) || + goto out; + if ((cpu_wakeup_task && p->prio == cpu_wakeup_task->prio) || p->prio == curr->prio) - wakeup_sharedprio = 1; + per_cpu(wakeup_sharedprio, cpu) = 1; } - raw_spin_lock_irqsave(&wakeup_lock, flags); - if (wakeup_task) - put_task_struct(wakeup_task); - get_task_struct(p); - wakeup_task = p; - wakeup_task->preempt_timestamp_hist = - ftrace_now(raw_smp_processor_id()); + 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(struct rq *rq, +static notrace void probe_wakeup_latency_hist_stop(struct rq *rq, struct task_struct *prev, struct task_struct *next) { unsigned long flags; - int cpu; + int cpu = task_cpu(next); unsigned long latency; cycle_t stop; + struct task_struct *cpu_wakeup_task; - if (next != wakeup_task) - return; + raw_spin_lock_irqsave(&wakeup_lock, flags); - cpu = raw_smp_processor_id(); - stop = ftrace_now(cpu); + cpu_wakeup_task = per_cpu(wakeup_task, cpu); - raw_spin_lock_irqsave(&wakeup_lock, flags); + 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; - latency = nsecs_to_usecs(stop - next->preempt_timestamp_hist); - if (next != wakeup_task) { - if (wakeup_task && next->prio == wakeup_task->prio) - latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, - next); goto out; } - if (wakeup_sharedprio) { + /* + * 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 = nsecs_to_usecs(stop - next->preempt_timestamp_hist); + + if (per_cpu(wakeup_sharedprio, cpu)) { latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, next); - wakeup_sharedprio = 0; + per_cpu(wakeup_sharedprio, cpu) = 0; } else latency_hist(WAKEUP_LATENCY, cpu, latency, next); - put_task_struct(wakeup_task); - wakeup_task = NULL; +out_reset: + put_task_struct(cpu_wakeup_task); + per_cpu(wakeup_task, cpu) = 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) +static notrace void probe_hrtimer_interrupt(int cpu, long long latency_ns, + struct task_struct *curr, struct task_struct *task) { - if (latency_ns <= 0) { + if (latency_ns <= 0 && task != NULL && rt_task(task) && + task->prio < curr->prio) { unsigned long latency; - latency = (unsigned long) div_s64(-latency_ns, 1000); + if (missed_timer_offsets_pid) { + if (likely(missed_timer_offsets_pid != + task_pid_nr(task))) + return; + } + latency = (unsigned long) div_s64(-latency_ns, 1000); latency_hist(MISSED_TIMER_OFFSETS, cpu, latency, task); } } @@ -852,7 +894,7 @@ static __init int latency_hist_init(void) struct dentry *dentry_sharedprio; #endif struct dentry *entry; - struct dentry *latency_hist_enable_root; + struct dentry *enable_root; int i = 0; struct hist_data *my_hist; char name[64]; @@ -860,15 +902,12 @@ static __init int latency_hist_init(void) #if defined(CONFIG_WAKEUP_LATENCY_HIST) || \ defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) char *cpufmt_maxlatproc = "max_latency-CPU%d"; + struct maxlatproc_data *mp = NULL; #endif dentry = tracing_init_dentry(); - - latency_hist_root = - debugfs_create_dir(latency_hist_dir_root, dentry); - - latency_hist_enable_root = - debugfs_create_dir("enable", latency_hist_root); + latency_hist_root = debugfs_create_dir(latency_hist_dir_root, dentry); + enable_root = debugfs_create_dir("enable", latency_hist_root); #ifdef CONFIG_INTERRUPT_OFF_HIST dentry = debugfs_create_dir(irqsoff_hist_dir, latency_hist_root); @@ -916,8 +955,8 @@ static __init int latency_hist_init(void) #if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST) entry = debugfs_create_file("preemptirqsoff", 0644, - latency_hist_enable_root, (void *)&preemptirqsoff_enabled_data, - &latency_hist_enable_fops); + enable_root, (void *)&preemptirqsoff_enabled_data, + &enable_fops); #endif #ifdef CONFIG_WAKEUP_LATENCY_HIST @@ -927,6 +966,7 @@ static __init int latency_hist_init(void) 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); @@ -934,7 +974,6 @@ static __init int latency_hist_init(void) atomic_set(&my_hist->hist_mode, 1); my_hist->min_lat = 0xFFFFFFFFUL; - sprintf(name, cpufmt, i); entry = debugfs_create_file(name, 0444, dentry_sharedprio, &per_cpu(wakeup_latency_hist_sharedprio, i), &latency_hist_fops); @@ -943,24 +982,26 @@ static __init int latency_hist_init(void) my_hist->min_lat = 0xFFFFFFFFUL; sprintf(name, cpufmt_maxlatproc, i); - entry = debugfs_create_file(name, 0444, dentry, - &per_cpu(wakeup_maxlatproc, i), - &latency_hist_maxlatproc_fops); - sprintf(name, cpufmt_maxlatproc, i); - entry = debugfs_create_file(name, 0444, dentry_sharedprio, - &per_cpu(wakeup_maxlatproc_sharedprio, i), - &latency_hist_maxlatproc_fops); + mp = &per_cpu(wakeup_maxlatproc, i); + entry = debugfs_create_file(name, 0444, dentry, mp, + &maxlatproc_fops); + mp->prio = mp->pid = mp->latency = -1; + + mp = &per_cpu(wakeup_maxlatproc_sharedprio, i); + entry = debugfs_create_file(name, 0444, dentry_sharedprio, mp, + &maxlatproc_fops); + mp->prio = mp->pid = mp->latency = -1; } entry = debugfs_create_file("pid", 0644, dentry, - (void *)&wakeup_pid, &latency_hist_pid_fops); + (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, - latency_hist_enable_root, (void *)&wakeup_latency_enabled_data, - &latency_hist_enable_fops); + enable_root, (void *)&wakeup_latency_enabled_data, + &enable_fops); #endif #ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST @@ -975,16 +1016,18 @@ static __init int latency_hist_init(void) 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); + mp = &per_cpu(missed_timer_offsets_maxlatproc, i); + entry = debugfs_create_file(name, 0444, dentry, mp, + &maxlatproc_fops); + mp->prio = mp->pid = mp->latency = -1; } + 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, - latency_hist_enable_root, - (void *)&missed_timer_offsets_enabled_data, - &latency_hist_enable_fops); + enable_root, (void *)&missed_timer_offsets_enabled_data, + &enable_fops); #endif return 0; } diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c index 30cd3c9..f96c9ec 100644 --- a/kernel/trace/ring_buffer.c +++ b/kernel/trace/ring_buffer.c @@ -1201,11 +1201,12 @@ static void rb_reset_cpu(struct ring_buffer_per_cpu *cpu_buffer); static void rb_remove_pages(struct ring_buffer_per_cpu *cpu_buffer, unsigned nr_pages) { - struct buffer_page *bpage; + struct buffer_page *bpage, *tmp; struct list_head *p; + LIST_HEAD(tofree); unsigned i; - spin_lock_irq(&cpu_buffer->reader_lock); + raw_spin_lock_irq(&cpu_buffer->reader_lock); rb_head_page_deactivate(cpu_buffer); for (i = 0; i < nr_pages; i++) { @@ -1213,8 +1214,8 @@ rb_remove_pages(struct ring_buffer_per_cpu *cpu_buffer, unsigned nr_pages) goto out; p = cpu_buffer->pages->next; bpage = list_entry(p, struct buffer_page, list); - list_del_init(&bpage->list); - free_buffer_page(bpage); + list_del(&bpage->list); + list_add(&bpage->list, &tofree); } if (RB_WARN_ON(cpu_buffer, list_empty(cpu_buffer->pages))) goto out; @@ -1223,7 +1224,13 @@ rb_remove_pages(struct ring_buffer_per_cpu *cpu_buffer, unsigned nr_pages) rb_check_pages(cpu_buffer); out: - spin_unlock_irq(&cpu_buffer->reader_lock); + raw_spin_unlock_irq(&cpu_buffer->reader_lock); + + list_for_each_entry_safe(bpage, tmp, &tofree, list) { + list_del_init(&bpage->list); + free_buffer_page(bpage); + } + } static void @@ -1234,7 +1241,7 @@ rb_insert_pages(struct ring_buffer_per_cpu *cpu_buffer, struct list_head *p; unsigned i; - spin_lock_irq(&cpu_buffer->reader_lock); + raw_spin_lock_irq(&cpu_buffer->reader_lock); rb_head_page_deactivate(cpu_buffer); for (i = 0; i < nr_pages; i++) { @@ -1249,7 +1256,7 @@ rb_insert_pages(struct ring_buffer_per_cpu *cpu_buffer, rb_check_pages(cpu_buffer); out: - spin_unlock_irq(&cpu_buffer->reader_lock); + raw_spin_unlock_irq(&cpu_buffer->reader_lock); } /** -- 1.7.0.4