Hi, Ingo
This patch can record interrupt-off latency, preemption-off latency and
wakeup latency in a big history array, in the meanwhile, it dummies up
printks produced
by these latency timing.
This patch adds three options: "Log interrupts-off critical section
latency", "Log non-preemptible critical section latency" and "Log wakeup
latency", they may be selected together, but just enabling one of them
will be better.
All the latency history can be viewed via /proc interface:
(Note, * presents CPU ID)
###interrupt-off latency history
cat /proc/latency_log/interrupt_off_latency/CPU*
###preemption-off latency history
cat /proc/latency_log/preemption_off_latency/CPU*
###wakeup latency history
cat /proc/latency_log/wakeup_latency/CPU*
Latency tracing will trace the maximum sample of three options, so
/proc/latency_trace can provide the detailed tracing for maximum sample.
diffstat:
kernel/Makefile | 1
kernel/latency.c | 96 ++++++++++++++++
kernel/latency_log.c | 292
+++++++++++++++++++++++++++++++++++++++++++++++++++
lib/Kconfig.debug | 59 ++++++++++
4 files changed, 445 insertions(+), 3 deletions(-)
--- /dev/null 2003-01-30 18:24:37.000000000 +0800
+++ linux-2.6.12/kernel/latency_log.c 2005-07-15 17:45:53.000000000
+0800
@@ -0,0 +1,292 @@
+/*
+ * kernel/latency_log.c
+ *
+ * Add support for history logs of preemption-off latency and
+ * interrupt-off latency and wakeup latency, it depends on
+ * Real-Time Preemption Support.
+ *
+ * Copyright (C) 2005, 2007 MontaVista Software, Inc.
+ * Yi Yang <[EMAIL PROTECTED]>
+ *
+ */
+#include <linux/config.h>
+#include <linux/module.h>
+#include <linux/proc_fs.h>
+#include <linux/seq_file.h>
+#include <linux/percpu.h>
+#include <asm/atomic.h>
+
+#define MAX_ENTRY_NUM 10240
+#define LATENCY_TYPE_NUM 3
+
+typedef struct log_data_struct {
+ atomic_t log_mode; /* 0 log, 1 don't log */
+ unsigned long min_lat;
+ unsigned long avg_lat;
+ unsigned long max_lat;
+ unsigned long long beyond_log_bound_samples;
+ unsigned long long accumulate_lat;
+ unsigned long long total_samples;
+ unsigned long long log_array[MAX_ENTRY_NUM];
+} log_data_t;
+
+enum {
+ INTERRUPT_LATENCY = 0,
+ PREEMPT_LATENCY,
+ WAKEUP_LATENCY
+};
+
+static struct proc_dir_entry * latency_log_root = NULL;
+static char * latency_log_proc_dir_root = "latency_log";
+
+static char * percpu_proc_name = "CPU";
+
+#ifdef CONFIG_INTERRUPT_OFF_LOG
+static DEFINE_PER_CPU(log_data_t, interrupt_off_log);
+static char * interrupt_off_log_proc_dir = "interrupt_off_latency";
+#endif
+
+#ifdef CONFIG_PREEMPT_OFF_LOG
+static DEFINE_PER_CPU(log_data_t, preempt_off_log);
+static char * preempt_off_log_proc_dir = "preempt_off_latency";
+#endif
+
+#ifdef CONFIG_WAKEUP_LATENCY_LOG
+static DEFINE_PER_CPU(log_data_t, wakeup_latency_log);
+static char * wakeup_latency_log_proc_dir = "wakeup_latency";
+#endif
+
+static struct proc_dir_entry *entry[LATENCY_TYPE_NUM][NR_CPUS];
+
+static inline u64 u64_div(u64 x, u64 y)
+{
+ do_div(x, y);
+ return x;
+}
+
+void latency_log(int latency_type, int cpu, unsigned long latency)
+{
+ log_data_t * my_log;
+
+
+ if ((cpu < 0) || (cpu >= NR_CPUS) || (latency_type <
INTERRUPT_LATENCY)
+ || (latency_type > WAKEUP_LATENCY) || (latency < 0)) {
+ return;
+ }
+
+ switch(latency_type) {
+#ifdef CONFIG_INTERRUPT_OFF_LOG
+ case INTERRUPT_LATENCY:
+ my_log = (log_data_t *)&per_cpu(interrupt_off_log, cpu);
+ if (atomic_read(&my_log->log_mode) == 0) {
+ return;
+ }
+ break;
+#endif
+
+#ifdef CONFIG_PREEMPT_OFF_LOG
+ case PREEMPT_LATENCY:
+ my_log = (log_data_t *)&per_cpu(preempt_off_log, cpu);
+ if (atomic_read(&my_log->log_mode) == 0) {
+ return;
+ }
+ break;
+#endif
+
+#ifdef CONFIG_WAKEUP_LATENCY_LOG
+ case WAKEUP_LATENCY:
+ my_log = (log_data_t *)&per_cpu(wakeup_latency_log, cpu);
+ if (atomic_read(&my_log->log_mode) == 0) {
+ return;
+ }
+ break;
+#endif
+ default:
+ return;
+ }
+
+ if (latency >= MAX_ENTRY_NUM) {
+ my_log->beyond_log_bound_samples++;
+ }
+ else {
+ my_log->log_array[latency]++;
+ }
+
+ if (latency < my_log->min_lat) {
+ my_log->min_lat = latency;
+ }
+ else if (latency > my_log->max_lat) {
+ my_log->max_lat = latency;
+ }
+
+ my_log->total_samples++;
+ my_log->accumulate_lat += latency;
+ my_log->avg_lat = (unsigned long)u64_div(my_log->accumulate_lat,
my_log->total_samples);
+ return;
+}
+
+static void *l_start(struct seq_file *m, loff_t * pos)
+{
+ loff_t *index_ptr = kmalloc(sizeof(loff_t), GFP_KERNEL);
+ loff_t index = *pos;
+ log_data_t *my_log = (log_data_t *) m->private;
+
+ if (index_ptr == NULL) {
+ return NULL;
+ }
+
+ if (index == 0) {
+ atomic_dec(&my_log->log_mode);
+ seq_printf(m, "#Minimum latency: %lu microseconds.\n"
+ "#Average latency: %lu microseconds.\n"
+ "#Maximum latency: %lu microseconds.\n"
+ "#Total samples: %llu\n"
+ "#There are %llu samples greater or equal than %d
microseconds\n"
+ "#usecs\t%16s\n"
+ , my_log->min_lat
+ , my_log->avg_lat
+ , my_log->max_lat
+ , my_log->total_samples
+ , my_log->beyond_log_bound_samples
+ , MAX_ENTRY_NUM, "samples");
+ }
+ if (index >= MAX_ENTRY_NUM) {
+ return NULL;
+ }
+
+ *index_ptr = index;
+ return index_ptr;
+}
+
+static void *l_next(struct seq_file *m, void *p, loff_t * pos)
+{
+ loff_t *index_ptr = p;
+ log_data_t *my_log = (log_data_t *) m->private;
+
+ if (++*pos >= MAX_ENTRY_NUM) {
+ atomic_inc(&my_log->log_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;
+ log_data_t *my_log = (log_data_t *) m->private;
+
+ seq_printf(m, "%5d\t%16llu\n", index
+ , my_log->log_array[index]);
+ return 0;
+}
+
+static struct seq_operations latency_log_seq_op = {
+ .start = l_start,
+ .next = l_next,
+ .stop = l_stop,
+ .show = l_show
+};
+
+static int latency_log_seq_open(struct inode *inode, struct file *file)
+{
+ int ret;
+ struct proc_dir_entry *entry_ptr = NULL;
+ int i, j;
+ struct seq_file *seq;
+ int break_flags = 0;
+
+ entry_ptr = PDE(file->f_dentry->d_inode);
+ for (i = 0; i < LATENCY_TYPE_NUM; i++) {
+ for (j = 0; j < NR_CPUS; j++) {
+ if (entry[i][j] == NULL) {
+ continue;
+ }
+ if (entry_ptr->low_ino == entry[i][j]->low_ino) {
+ break_flags = 1;
+ break;
+ }
+ }
+ if (break_flags == 1) {
+ break;
+ }
+ }
+ ret = seq_open(file, &latency_log_seq_op);
+ if (break_flags == 1) {
+ seq = (struct seq_file *)file->private_data;
+ seq->private = entry[i][j]->data;
+ }
+ return ret;
+}
+static struct file_operations latency_log_seq_fops = {
+ .open = latency_log_seq_open,
+ .read = seq_read,
+ .llseek = seq_lseek,
+ .release = seq_release,
+};
+
+static __init int latency_log_init(void)
+{
+ struct proc_dir_entry *tmp_parent_proc_dir;
+ char procname[64];
+ int len = 0;
+ int i = 0;
+ log_data_t *my_log;
+
+ latency_log_root = proc_mkdir(latency_log_proc_dir_root, NULL);
+
+
+#ifdef CONFIG_INTERRUPT_OFF_LOG
+ tmp_parent_proc_dir = proc_mkdir(interrupt_off_log_proc_dir,
latency_log_root);
+ for (i = 0; i < NR_CPUS; i++) {
+ len = sprintf(procname, "%s%d", percpu_proc_name, i);
+ procname[len] = '\0';
+ entry[INTERRUPT_LATENCY][i] =
+ create_proc_entry(procname, 0, tmp_parent_proc_dir);
+ entry[INTERRUPT_LATENCY][i]->data = (void
*)&per_cpu(interrupt_off_log, i);
+ entry[INTERRUPT_LATENCY][i]->proc_fops = &latency_log_seq_fops;
+ my_log = (log_data_t *) entry[INTERRUPT_LATENCY][i]->data;
+ atomic_set(&my_log->log_mode,1);
+ my_log->min_lat = 0xFFFFFFFFUL;
+ }
+#endif
+
+#ifdef CONFIG_PREEMPT_OFF_LOG
+ tmp_parent_proc_dir = proc_mkdir(preempt_off_log_proc_dir,
latency_log_root);
+ for (i = 0; i < NR_CPUS; i++) {
+ len = sprintf(procname, "%s%d", percpu_proc_name, i);
+ procname[len] = '\0';
+ entry[PREEMPT_LATENCY][i] =
+ create_proc_entry(procname, 0, tmp_parent_proc_dir);
+ entry[PREEMPT_LATENCY][i]->data = (void
*)&per_cpu(preempt_off_log,
i);
+ entry[PREEMPT_LATENCY][i]->proc_fops =
&latency_log_seq_fops;
+ my_log = (log_data_t *) entry[PREEMPT_LATENCY][i]->data;
+ atomic_set(&my_log->log_mode,1);
+ my_log->min_lat = 0xFFFFFFFFUL;
+ }
+#endif
+
+#ifdef CONFIG_WAKEUP_LATENCY_LOG
+ tmp_parent_proc_dir = proc_mkdir(wakeup_latency_log_proc_dir,
latency_log_root);
+ for (i = 0; i < NR_CPUS; i++) {
+ len = sprintf(procname, "%s%d", percpu_proc_name, i);
+ procname[len] = '\0';
+ entry[WAKEUP_LATENCY][i] =
+ create_proc_entry(procname, 0, tmp_parent_proc_dir);
+ entry[WAKEUP_LATENCY][i]->data = (void
*)&per_cpu(wakeup_latency_log, i);
+ entry[WAKEUP_LATENCY][i]->proc_fops =
&latency_log_seq_fops;
+ my_log = (log_data_t *) entry[WAKEUP_LATENCY][i]->data;
+ atomic_set(&my_log->log_mode,1);
+ my_log->min_lat = 0xFFFFFFFFUL;
+ }
+#endif
+ return 0;
+
+}
+
+__initcall(latency_log_init);
--- linux-2.6.12/kernel/latency.c.orig 2005-07-15 17:45:10.000000000
+0800
+++ linux-2.6.12/kernel/latency.c 2005-07-15 17:45:53.000000000 +0800
@@ -23,6 +23,20 @@
#include <asm/uaccess.h>
#include <asm/unistd.h>
+#ifdef CONFIG_LATENCY_LOG
+enum {
+ INTERRUPT_LATENCY = 0,
+ PREEMPT_LATENCY,
+ WAKEUP_LATENCY
+};
+extern void latency_log(int latency_type, int cpu, unsigned long
latency);
+
+#ifdef CONFIG_INTERRUPT_OFF_LOG
+static inline int is_interrupt_off_timing(void);
+#endif
+
+#endif
+
#ifdef CONFIG_PPC
#include <asm/time.h>
#endif
@@ -60,7 +74,12 @@ int wakeup_timing = 1;
* Maximum preemption latency measured. Initialize to maximum,
* we clear it after bootup.
*/
+#ifdef CONFIG_LATENCY_LOG
+static cycles_t preempt_max_latency = (cycles_t)0UL;
+#else
static cycles_t preempt_max_latency = (cycles_t)ULONG_MAX;
+#endif
+
static cycles_t preempt_thresh;
/*
@@ -1220,6 +1239,9 @@ check_critical_timing(int cpu, struct cp
{
unsigned long latency, t0, t1;
cycles_t T0, T1, T2, delta;
+#ifdef CONFIG_CRITICAL_LATENCY_LOG
+ int latency_type;
+#endif
if (trace_user_triggered)
return;
@@ -1231,8 +1253,10 @@ check_critical_timing(int cpu, struct cp
T1 = cycles();
delta = T1-T0;
+#ifndef CONFIG_CRITICAL_LATENCY_LOG
if (!report_latency(delta))
goto out;
+#endif
____trace(cpu, TRACE_FN, tr, CALLER_ADDR0, parent_eip, 0, 0, 0);
/*
* Update the timestamp, because the trace entry above
@@ -1247,21 +1271,29 @@ check_critical_timing(int cpu, struct cp
if (tr->critical_sequence != max_sequence || down_trylock(&max_mutex))
goto out;
+
+#ifndef CONFIG_CRITICAL_LATENCY_LOG
if (!preempt_thresh && preempt_max_latency > delta) {
printk("bug: updating %016Lx > %016Lx?\n",
preempt_max_latency, delta);
printk(" [%016Lx %016Lx %016Lx]\n", T0, T1, T2);
}
+#endif
+ latency = cycles_to_usecs(delta);
+
+#ifdef CONFIG_CRITICAL_LATENCY_LOG
+if (preempt_max_latency < delta) {
+#endif
preempt_max_latency = delta;
t0 = cycles_to_usecs(T0);
t1 = cycles_to_usecs(T1);
- latency = cycles_to_usecs(delta);
tr->critical_end = parent_eip;
update_max_tr(tr);
+#ifndef CONFIG_CRITICAL_LATENCY_LOG
if (preempt_thresh)
printk("(%16s-%-5d|#%d): %lu us critical section "
"violates %lu us threshold.\n"
@@ -1282,10 +1314,35 @@ check_critical_timing(int cpu, struct cp
dump_stack();
t1 = cycles_to_usecs(cycles());
printk(" => dump-end timestamp %lu\n\n", t1);
+#endif
max_sequence++;
+#ifdef CONFIG_CRITICAL_LATENCY_LOG
+}
+#endif
+
up(&max_mutex);
+
+#ifdef CONFIG_CRITICAL_LATENCY_LOG
+ latency_type = WAKEUP_LATENCY + 1;
+#ifdef CONFIG_INTERRUPT_OFF_LOG
+ if (is_interrupt_off_timing()) {
+ latency_type = INTERRUPT_LATENCY;
+ }
+#ifdef CONFIG_PREEMPT_OFF_LOG
+ else {
+ latency_type = PREEMPT_LATENCY;
+ }
+#endif /* CONFIG_PREEMPT_OFF_LOG */
+#else
+#ifdef CONFIG_PREEMPT_OFF_LOG
+ latency_type = PREEMPT_LATENCY;
+#endif /* CONFIG_PREEMPT_OFF_LOG */
+#endif /* CONFIG_INTERRUPT_OFF_LOG */
+ latency_log(latency_type, cpu, latency);
+#endif /* CONFIG_CRITICAL_LATENCY_LOG */
+
out:
tr->critical_sequence = max_sequence;
tr->preempt_timestamp = cycles();
@@ -1293,6 +1350,7 @@ out:
tr->trace_idx = 0;
_trace_cmdline(cpu, tr);
____trace(cpu, TRACE_FN, tr, CALLER_ADDR0, parent_eip, 0, 0, 0);
+
}
void notrace touch_critical_timing(void)
@@ -1371,6 +1429,17 @@ __stop_critical_timing(unsigned long eip
# define irqs_off_preempt_count() 0
#endif
+#ifdef CONFIG_INTERRUPT_OFF_LOG
+static inline int is_interrupt_off_timing(void)
+{
+ unsigned long flags;
+
+ raw_local_save_flags(flags);
+
+ return (!irqs_off_preempt_count() && raw_irqs_disabled_flags(flags));
+}
+#endif
+
void notrace trace_irqs_off_lowlevel(void)
{
unsigned long flags;
@@ -1575,6 +1644,9 @@ check_wakeup_timing(struct cpu_trace *tr
unsigned long latency;
unsigned long t0, t1;
cycles_t T0, T1, T2, delta;
+#ifdef CONFIG_WAKEUP_LATENCY_LOG
+ int cpu = _smp_processor_id();
+#endif
if (trace_user_triggered)
return;
@@ -1593,8 +1665,10 @@ check_wakeup_timing(struct cpu_trace *tr
T0 = T1;
delta = T1-T0;
+#ifndef CONFIG_WAKEUP_LATENCY_LOG
if (!report_latency(delta))
goto out;
+#endif
____trace(smp_processor_id(), TRACE_FN, tr, CALLER_ADDR0, parent_eip,
0, 0, 0);
T2 = cycles();
@@ -1605,21 +1679,27 @@ check_wakeup_timing(struct cpu_trace *tr
if (tr->critical_sequence != max_sequence || down_trylock(&max_mutex))
goto out;
+#ifndef CONFIG_WAKEUP_LATENCY_LOG
if (!preempt_thresh && preempt_max_latency > delta) {
printk("bug2: updating %016Lx > %016Lx?\n",
preempt_max_latency, delta);
printk(" [%016Lx %016Lx %016Lx]\n", T0, T1, T2);
}
+#endif
+ latency = cycles_to_usecs(delta);
+
+#ifdef CONFIG_WAKEUP_LATENCY_LOG
+if (preempt_max_latency < delta) {
+#endif
preempt_max_latency = delta;
t0 = cycles_to_usecs(T0);
t1 = cycles_to_usecs(T1);
- latency = cycles_to_usecs(delta);
-
tr->critical_end = parent_eip;
update_max_tr(tr);
+#ifndef CONFIG_WAKEUP_LATENCY_LOG
if (preempt_thresh)
printk("(%16s-%-5d|#%d): %lu us wakeup latency "
"violates %lu us threshold.\n",
@@ -1630,12 +1710,22 @@ check_wakeup_timing(struct cpu_trace *tr
printk("(%16s-%-5d|#%d): new %lu us maximum-latency "
"wakeup.\n", current->comm, current->pid,
_smp_processor_id(), latency);
+#endif
max_sequence++;
+#ifdef CONFIG_WAKEUP_LATENCY_LOG
+}
+#endif
up(&max_mutex);
+
+#ifdef CONFIG_WAKEUP_LATENCY_LOG
+ latency_log(WAKEUP_LATENCY, cpu, latency);
+#endif
+
out:
atomic_dec(&tr->disabled);
+
}
/*
--- linux-2.6.12/kernel/Makefile.orig 2005-07-15 17:44:56.000000000
+0800
+++ linux-2.6.12/kernel/Makefile 2005-07-15 17:45:53.000000000 +0800
@@ -13,6 +13,7 @@ obj-$(CONFIG_PREEMPT_RT) += rt.o
obj-$(CONFIG_DEBUG_PREEMPT) += latency.o
obj-$(CONFIG_LATENCY_TIMING) += latency.o
+obj-$(CONFIG_LATENCY_LOG) += latency_log.o
obj-$(CONFIG_FUTEX) += futex.o
obj-$(CONFIG_GENERIC_ISA_DMA) += dma.o
--- linux-2.6.12/lib/Kconfig.debug.orig 2005-07-15 17:45:34.000000000
+0800
+++ linux-2.6.12/lib/Kconfig.debug 2005-07-15 18:07:15.000000000 +0800
@@ -143,6 +143,21 @@ config WAKEUP_TIMING
echo 0 > /proc/sys/kernel/preempt_max_latency
+config WAKEUP_LATENCY_LOG
+ bool "Log wakeup latency"
+ default n
+ depends on WAKEUP_TIMING
+ help
+ This option logs all the wakeup latency timing to a big histogram
+ bucket, in the meanwhile, it also dummies up printk produced by
+ wakeup latency timing.
+
+ The wakeup latency timing histogram can be viewed via:
+
+ cat /proc/latency_log/wakeup_latency/CPU*
+
+ (Note: * presents CPU ID.)
+
config PREEMPT_TRACE
bool
default y
@@ -165,6 +180,23 @@ config CRITICAL_PREEMPT_TIMING
enabled. This option and the irqs-off timing option can be
used together or separately.)
+config PREEMPT_OFF_LOG
+ bool "Log non-preemptible critical section latency"
+ default n
+ depends on CRITICAL_PREEMPT_TIMING
+ help
+ This option logs all the non-preemptible critical section
latency
+ timing to a big histogram bucket, in the meanwhile, it also
+ dummies up printk produced by non-preemptible critical section
+ latency timing.
+
+ The non-preemptible critical section latency timing histogram
can
+ be viewed via:
+
+ cat /proc/latency_log/preempt_off_latency/CPU*
+
+ (Note: * presents CPU ID.)
+
config CRITICAL_IRQSOFF_TIMING
bool "Interrupts-off critical section latency timing"
default n
@@ -181,6 +213,23 @@ config CRITICAL_IRQSOFF_TIMING
enabled. This option and the preempt-off timing option can be
used together or separately.)
+config INTERRUPT_OFF_LOG
+ bool "Log interrupts-off critical section latency"
+ default n
+ depends on CRITICAL_IRQSOFF_TIMING
+ help
+ This option logs all the interrupts-off critical section
latency
+ timing to a big histogram bucket, in the meanwhile, it also
+ dummies up printk produced by interrupts-off critical section
+ latency timing.
+
+ The interrupts-off critical section latency timing histogram
can
+ be viewed via:
+
+ cat /proc/latency_log/interrupt_off_latency/CPU*
+
+ (Note: * presents CPU ID.)
+
config CRITICAL_TIMING
bool
default y
@@ -191,6 +240,16 @@ config LATENCY_TIMING
default y
depends on WAKEUP_TIMING || CRITICAL_TIMING
+config CRITICAL_LATENCY_LOG
+ bool
+ default y
+ depends on PREEMPT_OFF_LOG || INTERRUPT_OFF_LOG
+
+config LATENCY_LOG
+ bool
+ default y
+ depends on WAKEUP_LATENCY_LOG || CRITICAL_LATENCY_LOG
+
config LATENCY_TRACE
bool "Latency tracing"
default n
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
