arch/i386/kernel/traps.c | 41 ++++++++++- drivers/char/rtc.c | 173 +++++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 207 insertions(+), 7 deletions(-) diff -puN arch/i386/kernel/traps.c~rtc-debug arch/i386/kernel/traps.c --- 25/arch/i386/kernel/traps.c~rtc-debug 2003-10-19 02:00:15.000000000 -0700 +++ 25-akpm/arch/i386/kernel/traps.c 2003-10-19 02:00:15.000000000 -0700 @@ -176,14 +176,51 @@ void show_stack(struct task_struct *task for(i = 0; i < kstack_depth_to_print; i++) { if (kstack_end(stack)) break; - if (i && ((i % 8) == 0)) - printk("\n "); + if (i && ((i % 8) == 0)) { + printk("\n"); + printk(" "); + } printk("%08lx ", *stack++); } printk("\n"); show_trace(task, esp); } +static void show_trace_local(void) +{ + printk("CPU %d:\n", smp_processor_id()); + show_trace(0, 0); +} + +#ifdef CONFIG_SMP +static atomic_t trace_cpu; + +static void show_trace_one(void *dummy) +{ + while (atomic_read(&trace_cpu) != smp_processor_id()) + ; + show_trace_local(); + atomic_inc(&trace_cpu); + while (atomic_read(&trace_cpu) != num_online_cpus()) + ; +} + +void show_trace_smp(void) +{ + atomic_set(&trace_cpu, 0); + smp_call_function(show_trace_one, 0, 1, 0); + show_trace_one(0); +} + +#else + +void show_trace_smp(void) +{ + show_trace_local(); +} + +#endif + /* * The architecture-independent dump_stack generator */ diff -puN drivers/char/rtc.c~rtc-debug drivers/char/rtc.c --- 25/drivers/char/rtc.c~rtc-debug 2003-10-19 02:00:15.000000000 -0700 +++ 25-akpm/drivers/char/rtc.c 2003-10-19 02:00:15.000000000 -0700 @@ -86,6 +86,19 @@ #include #endif +static unsigned long long last_interrupt_time; + +#include + + +#define CPU_MHZ (cpu_khz / 1000) +#define HISTSIZE 1000 +#define HIST_USEC 10 /* Microseconds per slot */ +static int histogram[HISTSIZE]; + +int rtc_debug; +int rtc_running; + #ifdef __sparc__ #include #include @@ -187,6 +200,16 @@ static unsigned long epoch = 1900; /* ye static const unsigned char days_in_mo[] = {0, 31, 28, 31, 30, 31, 30, 31, 31, 30, 31, 30, 31}; +static int rtc_state; + +enum rtc_states { + S_IDLE, /* Waiting for an interrupt */ + S_WAITING_FOR_READ, /* Signal delivered. waiting for rtc_read() */ + S_READ_MISSED, /* Signal delivered, read() deadline missed */ +}; + +void show_trace_smp(void); + #if RTC_IRQ /* * A very tiny interrupt handler. It runs with SA_INTERRUPT set, @@ -206,7 +229,6 @@ irqreturn_t rtc_interrupt(int irq, void * low byte and the number of interrupts received since * the last read in the remainder of rtc_irq_data. */ - spin_lock (&rtc_lock); rtc_irq_data += 0x100; rtc_irq_data &= ~0xff; @@ -233,7 +255,36 @@ irqreturn_t rtc_interrupt(int irq, void spin_unlock(&rtc_task_lock); wake_up_interruptible(&rtc_wait); - kill_fasync (&rtc_async_queue, SIGIO, POLL_IN); + if (!(rtc_status & RTC_IS_OPEN)) + goto tata; + + switch (rtc_state) { + case S_IDLE: /* Waiting for an interrupt */ + rdtscll(last_interrupt_time); + kill_fasync (&rtc_async_queue, SIGIO, POLL_IN); + rtc_state = S_WAITING_FOR_READ; + break; + case S_WAITING_FOR_READ: /* Signal has been delivered. waiting for rtc_read() */ + /* + * Well foo. The usermode application didn't schedule and read in time. + */ + rtc_state = S_READ_MISSED; + if (strcmp(current->comm, "amlat") != 0) { + printk("`%s'[%d] is being piggy. " + "need_resched=%d, cpu=%d\n", + current->comm, current->pid, + need_resched(), smp_processor_id()); + show_trace_smp(); + } + break; + case S_READ_MISSED: /* Signal has been delivered, read() deadline was missed */ + /* + * Not much we can do here. We're waiting for the usermode + * application to read the rtc + */ + break; + } +tata: return IRQ_HANDLED; } @@ -293,8 +344,74 @@ static void __exit cleanup_sysctl(void) * Now all the various file operations that we export. */ -static ssize_t rtc_read(struct file *file, char *buf, - size_t count, loff_t *ppos) +static ssize_t ll_rtc_read(struct file *file, char *buf, + size_t count, loff_t *ppos) +{ + ssize_t retval; + unsigned long long now; + + rdtscll(now); + + switch (rtc_state) { + case S_IDLE: /* Waiting for an interrupt */ + /* + * err... This can't be happening + */ + printk("ll_rtc_read(): called in state S_IDLE!\n"); + break; + case S_WAITING_FOR_READ: /* + * Signal has been delivered. + * waiting for rtc_read() + */ + /* + * Well done + */ + case S_READ_MISSED: /* + * Signal has been delivered, read() + * deadline was missed + */ + /* + * So, you finally got here. + */ + if (last_interrupt_time == 0) + printk("ll_rtc_read(): we screwed up. " + "last_interrupt_time = 0\n"); + rtc_state = S_IDLE; + { + unsigned long long latency = now - last_interrupt_time; + unsigned long delta; /* Nocroseconds */ + + delta = latency; + delta /= CPU_MHZ; + if (delta > 1000 * 1000) { + printk("rtc: eek\n"); + } else { + unsigned long slot = delta / HIST_USEC; + if (slot >= HISTSIZE) + slot = HISTSIZE - 1; + histogram[slot]++; + if (delta > 2000) + printk("wow! That was a " + "%ld millisec bump\n", + delta / 1000); + } + } + rtc_state = S_IDLE; + break; + } + + if (count < sizeof(last_interrupt_time)) + return -EINVAL; + + retval = -EIO; + if (copy_to_user(buf, &last_interrupt_time, + sizeof(last_interrupt_time)) == 0) + retval = sizeof(last_interrupt_time); + return retval; +} + +static ssize_t orig_rtc_read(struct file *file, char *buf, + size_t count, loff_t *ppos) { #if !RTC_IRQ return -EIO; @@ -349,6 +466,19 @@ static ssize_t rtc_read(struct file *fil #endif } +/* + * If anyone reads this, please send me an email describing + * the superlative elegance of this conception + */ +static ssize_t rtc_read(struct file *file, char *buf, + size_t count, loff_t *ppos) +{ + if (strcmp(current->comm, "amlat") == 0) + return ll_rtc_read(file, buf, count, ppos); + else + return orig_rtc_read(file, buf, count, ppos); +} + static int rtc_do_ioctl(unsigned int cmd, unsigned long arg, int kernel) { struct rtc_time wtime; @@ -666,6 +796,8 @@ static int rtc_ioctl(struct inode *inode * needed here. Or anywhere else in this driver. */ static int rtc_open(struct inode *inode, struct file *file) { + int i; + spin_lock_irq (&rtc_lock); if(rtc_status & RTC_IS_OPEN) @@ -673,7 +805,16 @@ static int rtc_open(struct inode *inode, rtc_status |= RTC_IS_OPEN; - rtc_irq_data = 0; + if (strcmp(current->comm, "amlat") == 0) { + last_interrupt_time = 0; + rtc_state = S_IDLE; + rtc_irq_data = 0; + } + + rtc_running = 1; + for (i = 0; i < HISTSIZE; i++) + histogram[i] = 0; + spin_unlock_irq (&rtc_lock); return 0; @@ -726,6 +867,27 @@ no_irq: rtc_irq_data = 0; rtc_status &= ~RTC_IS_OPEN; spin_unlock_irq (&rtc_lock); + { + int i, col = 0; + unsigned long total = 0; + printk("rtc histogram:\n"); + for (i = 0; i < HISTSIZE; i++) { + if (histogram[i]) { + total += histogram[i]; + col++; + printk("%d:%d ", i * HIST_USEC, histogram[i]); + if (col == 5) { + printk("\n"); + col = 0; + } + } + } + printk("\nTotal samples: %lu\n", total); + rtc_running = 0; +#if LOWLATENCY_DEBUG + show_lolat_stats(); +#endif + } return 0; } @@ -1094,6 +1256,7 @@ static void rtc_dropped_irq(unsigned lon wake_up_interruptible(&rtc_wait); kill_fasync (&rtc_async_queue, SIGIO, POLL_IN); + return; } #endif _