Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

From: Ingo Molnar
Date: Thu Nov 11 2004 - 04:21:46 EST



* K.R. Foley <kr@xxxxxxxxxx> wrote:

> Here is the updated rtc-debug patch. This version unlike previous
> versions doesn't change the way the rtc driver works. The output of
> /dev/rtc is preserved also so it doesn't break the existing
> functionality of rtc. By the same token it won't produce output usable
> by amlat, but it works for measuring the latency from interrupt to
> read. It doesn't measure when a poll is satisfied yet because I
> didn't need that yet. It doesn't trigger the end until the read.

i've done some further cleanups: made it .config configurable
(CONFIG_RTC_HISTOGRAM), moved the latency-histogram construction code
into separate functions to make it more apparent that there is no impact
to the normal codepaths. Patch attached.

Ingo
--- linux/drivers/char/Kconfig.orig
+++ linux/drivers/char/Kconfig
@@ -729,6 +729,15 @@ config RTC
To compile this driver as a module, choose M here: the
module will be called rtc.

+config RTC_HISTOGRAM
+ tristate "Real Time Clock Histogram Support"
+ default y
+ depends on RTC
+ ---help---
+ If you say Y here then the kernel will track the delivery and
+ wakeup latency of /dev/rtc using tasks and will report a
+ histogram to the kernel log when the application closes /dev/rtc.
+
config SGI_DS1286
tristate "SGI DS1286 RTC support"
depends on SGI_IP22
--- linux/drivers/char/rtc.c.orig
+++ linux/drivers/char/rtc.c
@@ -86,6 +86,28 @@
#include <asm/hpet.h>
#endif

+#ifdef CONFIG_RTC_HISTOGRAM
+
+static int rtc_running;
+static cycles_t last_interrupt_time;
+
+#include <asm/timex.h>
+
+#define CPU_MHZ (cpu_khz / 1000)
+
+#define HISTSIZE 10000
+static int histogram[HISTSIZE];
+
+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 */
+};
+
+#endif
+
#ifdef __sparc__
#include <linux/pci.h>
#include <asm/ebus.h>
@@ -205,6 +227,132 @@ static inline unsigned char rtc_is_updat
}

#ifdef RTC_IRQ
+
+static inline void rtc_open_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+ int i;
+
+ last_interrupt_time = 0;
+ rtc_state = S_IDLE;
+ rtc_irq_data = 0;
+
+ rtc_running = 1;
+ for (i = 0; i < HISTSIZE; i++)
+ histogram[i] = 0;
+#endif
+}
+
+static inline void rtc_wake_event(void)
+{
+#ifndef CONFIG_RTC_HISTOGRAM
+ kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+#else
+ if (!(rtc_status & RTC_IS_OPEN))
+ return;
+
+ switch (rtc_state) {
+ case S_IDLE: /* Waiting for an interrupt */
+ last_interrupt_time = get_cycles();
+ 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(); */
+ }
+ printk("Read missed before next interrupt\n");
+ 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;
+ }
+#endif
+}
+
+static inline void rtc_read_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+ cycles_t now = get_cycles();
+
+ switch (rtc_state) {
+ case S_IDLE: /* Waiting for an interrupt */
+ /*
+ * err... This can't be happening
+ */
+ printk("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("rtc_read(): we screwed up. "
+ "last_interrupt_time = 0\n");
+ rtc_state = S_IDLE;
+ {
+ cycles_t 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;
+ 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;
+ }
+#endif
+}
+
+static inline void rtc_close_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+ int i = 0;
+ unsigned long total = 0;
+ printk("rtc histogram:\n");
+ for (i = 0; i < HISTSIZE; i++) {
+ if (histogram[i]) {
+ total += histogram[i];
+ printk("%d %d\n", i, histogram[i]);
+ }
+ }
+ printk("\nTotal samples: %lu\n", total);
+ rtc_running = 0;
+#endif
+}
+
/*
* A very tiny interrupt handler. It runs with SA_INTERRUPT set,
* but there is possibility of conflicting with the set_rtc_mmss()
@@ -250,7 +398,7 @@ 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);
+ rtc_wake_event();

return IRQ_HANDLED;
}
@@ -354,6 +502,8 @@ static ssize_t rtc_read(struct file *fil
schedule();
} while (1);

+ rtc_read_event();
+
if (count < sizeof(unsigned long))
retval = put_user(data, (unsigned int __user *)buf) ?: sizeof(int);
else
@@ -692,6 +848,7 @@ static int rtc_open(struct inode *inode,
rtc_status |= RTC_IS_OPEN;

rtc_irq_data = 0;
+ rtc_open_event();
spin_unlock_irq (&rtc_lock);
return 0;

@@ -744,6 +901,7 @@ no_irq:
rtc_irq_data = 0;
rtc_status &= ~RTC_IS_OPEN;
spin_unlock_irq (&rtc_lock);
+ rtc_close_event();
return 0;
}