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

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

[Mark_H_Johnson]

>* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
>
>> >- everything else should be SCHED_OTHER. Do latencies get any better if
>> >you do this?
>
>> I can, but that is not necessarily an "apples to apples" comparison.
>
>the goal now would be to simplify the test and work down the issues in
>isolation, instead of looking at a complex setup of mixed workloads and
>just seeing 'it sucks' without knowing which component causes what.

However based on the results of the last several weeks, it is apparent
to me that the simple tests are finding only a subset of the problems.
The stressful series of tests is finding a number of symptoms much
sooner and more repeatable than those simple tests.

I was thinking about this problem this morning and was wondering if
we could do something like an "end trigger" to help determine the cause
of some of these pauses. Something like:
 - start to fill / refresh the trace buffer (already doing this?)
 - run RT CPU loop & sample TSC every 100 iterations or so
 - if delta T exceeds 100 usec (or so), then set "end trigger" and
dump the data from /proc/latency_trace.
Repeat with some rate limit so we don't get too much data.
I can still run the stressful test cases to cause the situations and
get the "just in time" data for the analysis. Perhaps a variant of
the interface you provided before on tracing a specific path.

I may do a variant on this anyway. I think its important to see if
the symptom (> 100 usec CPU delay) is really:
 - lots of short delays
OR
 - relatively few long delays
and I have an idea of how to code that up and add to latencytrace.

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

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

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> I was thinking about this problem this morning and was wondering if
> we could do something like an "end trigger" to help determine the cause
> of some of these pauses. Something like:
>  - start to fill / refresh the trace buffer (already doing this?)
>  - run RT CPU loop & sample TSC every 100 iterations or so
>  - if delta T exceeds 100 usec (or so), then set "end trigger" and
> dump the data from /proc/latency_trace.
> Repeat with some rate limit so we don't get too much data.

we had most of this in the tracer already, just obscured a bit.

In the current tree i've separated all the functionality into the
following flags: trace_enabled, trace_user_triggered, trace_freerunning.
When user_triggered is enabled all the other timing related tracing
activities stops (wakeup & critical/irq timing), and userspace is the
master of when tracing starts and stops. The way to turn the tracer
on/off is still the gettimeofday API hack:

	gettimeofday(0,1);
	gettimeofday(0,0);

i enhanced this user-defined tracing with a timing mechanism: the kernel
measures the latency between on and off and does the usual max-latency
or threshold tracking and saves the latency trace into
/proc/latency_trace only if the latency condition triggers. So userspace 
only has to add the start/stop hooks and the kernel will deal with the 
rest.

the freerunning flag can be used to generate traces where there's no
natural 'start' event, only some well-defined "we have a latency
problem" point. The application can start tracing at startup (or you can
start it via a different app), and it's enough to stop tracing when
there's a problem - the last ~4000 trace entries will be copied into
/proc/latency_trace. (the timing mechanism is still present in this mode
as well.)

(Freerunning mode can also be used if for some reason the delays are too
long to be fully traced and if the 'interesting' stuff is at the end of
the delay.)

This stuff will show up in the next release, later today. It should
cover the needs that your tests have at the moment, correct? 

	Ingo

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

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 681 bytes --]


* Ingo Molnar <mingo@elte.hu> wrote:

> 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.

i've attached another update with a few more smaller details fixed:

 - only print the histogram if a /dev/rtc using application indeed used 
   it to get interrupts. This removes bogus printouts triggered by 
   hwclock.

 - skip the first RTC interrupt from the histogram - most of the
   /dev/rtc applications do not handle the first event very well,
   skewing the histogram.

	Ingo

[-- Attachment #2: rtc-hist-2.6.10-rc1-mm3-A1 --]
[-- Type: text/plain, Size: 5237 bytes --]

--- 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 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_STARTUP,		/* First round - let the application start */
+	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,144 @@ 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_STARTUP;
+	rtc_irq_data = 0;
+
+	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) {
+	/* Startup */
+	case S_STARTUP:
+		kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+		break;
+	/* Waiting for an interrupt */
+	case S_IDLE:
+		kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+		last_interrupt_time = get_cycles();
+		rtc_state = S_WAITING_FOR_READ;
+		break;
+
+	/* Signal has been delivered. waiting for rtc_read() */
+	case S_WAITING_FOR_READ:
+		/*
+		 * Well foo.  The usermode application didn't
+		 * schedule and read in time.
+		 */
+		rtc_state = S_READ_MISSED;
+		printk("`%s'[%d] is being piggy. need_resched=%d, cpu=%d\n",
+			current->comm, current->pid,
+				need_resched(), smp_processor_id());
+		printk("Read missed before next interrupt\n");
+		break;
+	/* Signal has been delivered, read() deadline was missed */
+	case S_READ_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) {
+	/* Startup */
+	case S_STARTUP:
+		rtc_state = S_IDLE;
+		break;
+		
+	/* Waiting for an interrupt */
+	case S_IDLE:
+		printk("bug in 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)
+			printk("bug in rtc_read(): last_interrupt_time = 0\n");
+		rtc_state = S_IDLE;
+		{
+			cycles_t latency = now - last_interrupt_time;
+			unsigned long delta;	/* Microseconds */
+
+			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;
+
+	for (i = 0; i < HISTSIZE; i++)
+		total += histogram[i];
+	if (!total)
+		return;
+
+	printk("\nrtc latency histogram of {%s/%d, %lu samples}:\n",
+		current->comm, current->pid, total);
+	for (i = 0; i < HISTSIZE; i++) {
+		if (histogram[i])
+			printk("%d %d\n", i, histogram[i]);
+	}
+#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 +410,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 +514,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
@@ -689,6 +857,7 @@ static int rtc_open(struct inode *inode,
 	if(rtc_status & RTC_IS_OPEN)
 		goto out_busy;
 
+	rtc_open_event();
 	rtc_status |= RTC_IS_OPEN;
 
 	rtc_irq_data = 0;
@@ -744,6 +913,7 @@ no_irq:
 	rtc_irq_data = 0;
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock_irq (&rtc_lock);
+	rtc_close_event();
 	return 0;
 }
 

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

[K.R. Foley]

Ingo Molnar wrote:
> * Ingo Molnar <mingo@elte.hu> wrote:
> 
> 
>>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.
> 
> 
> i've attached another update with a few more smaller details fixed:
> 
>  - only print the histogram if a /dev/rtc using application indeed used 
>    it to get interrupts. This removes bogus printouts triggered by 
>    hwclock.
> 
>  - skip the first RTC interrupt from the histogram - most of the
>    /dev/rtc applications do not handle the first event very well,
>    skewing the histogram.
> 
> 	Ingo

Very nicely done. Also much less of a hack now the way you took all of 
the code out of the normal codepaths and made it into inlines that 
pretty much compile out if not being used.

kr

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

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >you have to build another kernel for them. irqs-off and preempt-off
> >timing can be mixed freely (and both can be enabled in the same kernel),
> >but wakeup timing deserves its own .config space and since it's not
> >mixable with the other two methods i didnt see much point in enabling
> >all 3 at once with strange dependencies between them. Is this a big
> >issue? Normally i think the wakeup timing is more than enough to get a
> >feel of latencies, and if something specific is suspected the other ones
> >can be turned on.
> 
> Just that it takes an hour or so to rebuild the kernel plus the disk
> storage to keep two kernels instead of one.

ok, i added runtime configurability of the 3 options back, so that you
can build all 3 in and switch between them via the preempt_wakeup_timing
flag. Will be in the next release.

	Ingo

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

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 768 bytes --]


* K.R. Foley <kr@cybsft.com> 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

[-- Attachment #2: rtc-hist-2.6.10-rc1-mm3-A0 --]
[-- Type: text/plain, Size: 5121 bytes --]

--- 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;
 }
 

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

[Ingo Molnar]

* K.R. Foley <kr@cybsft.com> wrote:

> Ingo Molnar wrote:
> >i have released the -V0.7.23 Real-Time Preemption patch, which can be
> >downloaded from the usual place:
> >
> 
> 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. 

looks good - i've added this to my tree. (with minor portability fixes:
rdtscll -> get_cycles(), long long -> cycles_t)

	Ingo

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

[K.R. Foley]

[-- Attachment #1: Type: text/plain, Size: 601 bytes --]

Ingo Molnar wrote:
> i have released the -V0.7.23 Real-Time Preemption patch, which can be
> downloaded from the usual place:
> 

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.

kr

[-- Attachment #2: rtc-debug2.patch --]
[-- Type: text/x-patch, Size: 4504 bytes --]

--- linux-2.6.10-rc1-mm3/drivers/char/rtc.c.orig	2004-11-10 21:27:39.106900807 -0600
+++ linux-2.6.10-rc1-mm3/drivers/char/rtc.c	2004-11-10 20:45:39.000000000 -0600
@@ -86,6 +86,18 @@
 #include <asm/hpet.h>
 #endif
 
+static unsigned long long last_interrupt_time;
+
+#include <asm/timex.h>
+
+
+#define CPU_MHZ	(cpu_khz / 1000)
+#define HISTSIZE	10000
+static int histogram[HISTSIZE];
+
+int rtc_debug;
+int rtc_running;
+
 #ifdef __sparc__
 #include <linux/pci.h>
 #include <asm/ebus.h>
@@ -191,6 +203,14 @@
 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 */
+};
+
 /*
  * Returns true if a clock update is in progress
  */
@@ -259,7 +279,37 @@
 	spin_unlock_irqrestore(&rtc_task_lock, flags);
 	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(); */
+		}
+		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;
+	}
+tata:
 
 	return IRQ_HANDLED;
 }
@@ -328,6 +378,7 @@
 	DECLARE_WAITQUEUE(wait, current);
 	unsigned long data;
 	ssize_t retval;
+	unsigned long long now;
 	
 	if (rtc_has_irq == 0)
 		return -EIO;
@@ -363,6 +414,56 @@
 		schedule();
 	} while (1);
 
+	rdtscll(now);
+
+	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;
+		{
+			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;
+				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(unsigned long))
 		retval = put_user(data, (unsigned int __user *)buf) ?: sizeof(int); 
 	else
@@ -692,6 +793,8 @@
  * 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)
@@ -700,6 +803,14 @@
 	rtc_status |= RTC_IS_OPEN;
 
 	rtc_irq_data = 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;
 
@@ -753,6 +864,19 @@
 	rtc_irq_data = 0;
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock_irq (&rtc_lock);
+	{
+		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;
+	}
 	return 0;
 }
 
@@ -1127,6 +1251,7 @@
 	wake_up_interruptible(&rtc_wait);
 
 	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+	return;
 }
 #endif
 

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

[K.R. Foley]

Ingo Molnar wrote:
> i have released the -V0.7.23 Real-Time Preemption patch, which can be
> downloaded from the usual place:
> 
>     http://redhat.com/~mingo/realtime-preempt/
> 

I have found some test results that I find interesting with -V0.7.24. I 
modified the rtc-debug patch to work with any program that can use the 
rtc driver. It measures the latency between handling an interrupt and 
the actual read. The amlat program normally used with this patch sets up 
a signal handler that reads /dev/rtc when there is data available and 
then sleeps until it receives the signal. Realfeel just does a blocking 
read on /dev/rtc. Oh and both of them setup the rtc for periodic 
interrupts. I would probably expect the blocking read to be a bit faster 
but not dramatically. Here are the results of a couple of very short 
runs to illustrate the difference:

amlat results (sleep/sighandler):
Nov 10 21:10:39 daffy kernel: rtc histogram:
Nov 10 21:10:39 daffy kernel: 26 1
Nov 10 21:10:39 daffy kernel: 28 2152
Nov 10 21:10:39 daffy kernel: 29 4286
Nov 10 21:10:39 daffy kernel: 30 6857
Nov 10 21:10:39 daffy kernel: 31 408
Nov 10 21:10:39 daffy kernel: 32 9
Nov 10 21:10:39 daffy kernel: 33 32
Nov 10 21:10:39 daffy kernel: 34 217
Nov 10 21:10:39 daffy kernel: 35 145
Nov 10 21:10:39 daffy kernel: 36 26
Nov 10 21:10:39 daffy kernel: 40 2
Nov 10 21:10:39 daffy kernel: 41 9
Nov 10 21:10:39 daffy kernel: 42 100
Nov 10 21:10:39 daffy kernel: 43 180
Nov 10 21:10:39 daffy kernel: 44 113
Nov 10 21:10:39 daffy kernel: 45 30
Nov 10 21:10:39 daffy kernel: 46 2
Nov 10 21:10:39 daffy kernel: 47 4
Nov 10 21:10:39 daffy kernel: 48 15
Nov 10 21:10:39 daffy kernel: 49 4
Nov 10 21:10:39 daffy kernel: 50 5
Nov 10 21:10:39 daffy kernel:
Nov 10 21:10:39 daffy kernel: Total samples: 14597

realfeel results (blocking read):
Nov 10 21:11:32 daffy kernel: rtc histogram:
Nov 10 21:11:32 daffy kernel: 3 17844
Nov 10 21:11:32 daffy kernel: 4 859
Nov 10 21:11:32 daffy kernel: 5 34
Nov 10 21:11:32 daffy kernel: 6 1
Nov 10 21:11:32 daffy kernel: 8 1
Nov 10 21:11:32 daffy kernel: 12 19
Nov 10 21:11:32 daffy kernel: 13 41
Nov 10 21:11:32 daffy kernel: 14 7
Nov 10 21:11:32 daffy kernel:
Nov 10 21:11:32 daffy kernel: Total samples: 18806

Both of the above runs were with 'IRQ 8' running at SCHED_FF 99. Amlat 
and realfeel were both running at SCHED_FF 98. The updated  rtc-debug 
patch to follow in case anyone is interested.

kr

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

[Mark_H_Johnson]

>you have to build another kernel for them. irqs-off and preempt-off
>timing can be mixed freely (and both can be enabled in the same kernel),
>but wakeup timing deserves its own .config space and since it's not
>mixable with the other two methods i didnt see much point in enabling
>all 3 at once with strange dependencies between them. Is this a big
>issue? Normally i think the wakeup timing is more than enough to get a
>feel of latencies, and if something specific is suspected the other ones
>can be turned on.

Just that it takes an hour or so to rebuild the kernel plus the
disk storage to keep two kernels instead of one.

The wakeup latencies I am seeing are all quite small, but the overhead
I am seeing at the application level have been quite high. Only 40 wakeup
latencies > 50 usec in a half hour of testing. I guess I'll build a
.24 without wakeup timing to see what kind of problems I'm having.
I can send you the wakeup timing traces if you are interested but
they are all really short (< 100 usec) or appear to indicate a hardware
contention problem (one step at 100 usec or so).

 --Mark

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

[Mark_H_Johnson]

>I may do a variant on this anyway. I think its important to see if
>the symptom (> 100 usec CPU delay) is really:
>- lots of short delays
>OR
>- relatively few long delays
>and I have an idea of how to code that up and add to latencytrace.

A follow up on this message. My first test completed with the following
results. The new code indicates:

X     - Min delay was     0. Max delay was     3. Ave delay was  0.015295.
top   - Min delay was     0. Max delay was    23. Ave delay was  0.025659.
netO  - Min delay was     0. Max delay was    31. Ave delay was  1.169024.
netI  - Min delay was     1. Max delay was    35. Ave delay was  1.182864.
diskW - Min delay was     0. Max delay was    18. Ave delay was  1.166944.
diskC - Min delay was     0. Max delay was    18. Ave delay was  1.080036.
diskR - Min delay was     0. Max delay was     7. Ave delay was  0.803804.

A "delay" was counted if 1000 iterations of the CPU inner loop took
longer than 10 usec. For comparison, I moved this code to my 2.4 system
and got the following results:

X     - Min delay was     0. Max delay was    17. Ave delay was  1.277730.
top   - Min delay was     0. Max delay was    12. Ave delay was  1.452692.
netO  - Min delay was     0. Max delay was    12. Ave delay was  1.633742.
netI  - Min delay was     0. Max delay was    12. Ave delay was  1.626565.
diskW - Min delay was     0. Max delay was    14. Ave delay was  1.566188.
diskC - Min delay was     0. Max delay was    12. Ave delay was  1.701542.
diskR - Min delay was     0. Max delay was    12. Ave delay was  1.650909.

Looks pretty comparable at this level. The 2.4 results appear to be more
consistent.

Grr. The new code does have an impact on the application measurements
under 2.4. It appears the TSC accesses are being delayed while the disk
is active. The within 100 usec rate was only 77% (was 90%) but the peak
is still pretty close (2.60 vs. 2.38 msec).

I am also not sure this is the "right" measurement either. I probably
need to count the delays or divide the overall loop time by the number
of delays to see if that is a more meaningful value.

  --Mark

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

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> OK. So maybe I didn't understand what you said previously. Now, if I
> build to get maximum-latency wakeup values, I can't get the IRQ off or
> preempt off timing and traces? If that's not true, how do I switch
> between the different sampling methods?

you have to build another kernel for them. irqs-off and preempt-off
timing can be mixed freely (and both can be enabled in the same kernel),
but wakeup timing deserves its own .config space and since it's not
mixable with the other two methods i didnt see much point in enabling
all 3 at once with strange dependencies between them. Is this a big
issue? Normally i think the wakeup timing is more than enough to get a
feel of latencies, and if something specific is suspected the other ones
can be turned on.

	Ingo

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

[Mark_H_Johnson]

>> [...] I also noticed that /proc/sys/kernel/preempt_wakeup_timing was
>> removed at .20 but not sure if that was deliberate. [...]
>
>yeah, this was deliberate - it's a side-effect of separating it from the
>other timing options.

OK. So maybe I didn't understand what you said previously. Now, if I build
to get maximum-latency wakeup values, I can't get the IRQ off or
preempt off timing and traces? If that's not true, how do I switch
between the different sampling methods?

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

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

[Ingo Molnar]

* Karsten Wiese <annabellesgarden@yahoo.de> wrote:

> Yes, it always happens, when callling ./cvscompile script of a
> project, that is mounted via nfs. Haven't tried to do that
> ./cvscompile locally, should I?

very interesting, nfs is indeed one of the frequent BKL users.

a 'BKL leak' is an unbalanced lock, e.g.:

	lock_kernel();
	... do stuff ...
	if (error)
		return;
	... do more stuff ...
	unlock_kernel();

the BKL is a very special type of lock which fact has the side-effect
that in the stock kernel a 'BKL leak' can go unnoticed very easily: it
causes no problems other than hard-to-debug (but severe) scalability
regressions. The moment the BKL count leaked from the NFS code that
process has been 'scalability-poisoned' and will be handicapped until it
exits.

In the PREEMPT_RT patchset i added a strict locking checker to do_exit()
that found this apparent NFS bug. Unfortunately the deadlock detector
only reported a pretty common place where the BKL gets
dropped/reacquired frequently so we dont know where the NFS code has the
lock/unlock imbalance. Could you report this bug to the NFS maintainers
(along with the above and the previous analysis)?

	Ingo

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

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >- everything else should be SCHED_OTHER. Do latencies get any better if
> >you do this?

> I can, but that is not necessarily an "apples to apples" comparison.

the goal now would be to simplify the test and work down the issues in
isolation, instead of looking at a complex setup of mixed workloads and
just seeing 'it sucks' without knowing which component causes what. 
That's why e.g. rtc_wakeup is so useful - it's simple and dependable and
still it showed a good deal of problems and helped debug/fix them.

	Ingo

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

[Ingo Molnar]

* Karsten Wiese <annabellesgarden@yahoo.de> wrote:

> Hi
> 
> On SMP/HT/P4 I get:
>  BUG: lock held at task exit time!

> sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
> BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
> in_atomic():1 [00000003], irqs_disabled():0

hm, apparently something leaked a BKL count. Unfortunately we dont know
precisely what did it, only that it happened. Did this happen during
bootup, or during normal use. Can you trigger it arbitrarily?

	Ingo

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

[Karsten Wiese]

Am Mittwoch 10 November 2004 15:20 schrieb Karsten Wiese:
> Am Mittwoch 10 November 2004 16:01 schrieb Ingo Molnar:
> > 
> > * Karsten Wiese <annabellesgarden@yahoo.de> wrote:
> > 
> > > Hi
> > > 
> > > On SMP/HT/P4 I get:
> > >  BUG: lock held at task exit time!
> > 
> > > sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
> > > BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
> > > in_atomic():1 [00000003], irqs_disabled():0
> > 
> > hm, apparently something leaked a BKL count. Unfortunately we dont know
> > precisely what did it, only that it happened. Did this happen during
> > bootup, or during normal use. Can you trigger it arbitrarily?
> 
> Yes, it always happens, when callling ./cvscompile script of a project, that is mounted via nfs.
> Haven't tried to do that ./cvscompile locally, should I?

./cvscompile locally is ok.
Also if I disable HT in BIOS, the machine survives the crash "./cvscompile"ing via nfs 
and the next "./cvscompile"s over nfs are ok. Also if I unmount / mount the nfs share again.
So it always happens the first time calling this ./cvscompile via nfs.

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

[Karsten Wiese]

Am Mittwoch 10 November 2004 16:01 schrieb Ingo Molnar:
> 
> * Karsten Wiese <annabellesgarden@yahoo.de> wrote:
> 
> > Hi
> > 
> > On SMP/HT/P4 I get:
> >  BUG: lock held at task exit time!
> 
> > sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
> > BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
> > in_atomic():1 [00000003], irqs_disabled():0
> 
> hm, apparently something leaked a BKL count. Unfortunately we dont know
> precisely what did it, only that it happened. Did this happen during
> bootup, or during normal use. Can you trigger it arbitrarily?

Yes, it always happens, when callling ./cvscompile script of a project, that is mounted via nfs.
Haven't tried to do that ./cvscompile locally, should I?

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

[Mark_H_Johnson]

>* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
>
>> [3] I am not so sure that the latency tracing works. I do not get any
>> trace output, even if I set preempt_max_latency to zero.
>
>What is the value of preempt_thresh?
It was zero at boot time. Now that I check, set it somewhere to 200.
Setting it back to zero, I now see that I have some extremely
small reports, max so far is 63 usec. Will run my big test again
to see what turns up.

  --Mark

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

[Mark_H_Johnson]

>> [4] Application level latencies are OK but not great.
>>  X test - only 90% of CPU loops are within 100 usec of nominal value.
>> In previous RT kernels I got > 99% with 100 usec.
>
>this might be a side-effect of the chrt-ing of events/[0|1] and/or
>ksoftirqd (which we did to debug the 'freeze' problems) - are those
>still chrt-ed?
For reference:
# ps -eo pid,pri,rtprio,cmd | grep '\['
    1  23      - init [5]
    2 139     99 [migration/0]
    3  34      - [ksoftirqd/0]
    4  34      - [desched/0]
    5 139     99 [migration/1]
    6  34      - [ksoftirqd/1]
    7  34      - [desched/1]
    8  41      1 [events/0]
    9  41      1 [events/1]
   10  34      - [khelper]
   15  32      - [kthread]
   27  34      - [kblockd/0]
   28  34      - [kblockd/1]
   36  24      - [khubd]
  103  23      - [kswapd0]
  104  32      - [aio/0]
  105  33      - [aio/1]
  180 139     99 [IRQ 8]
  195  14      - [kseriod]
  201 139     99 [IRQ 12]
  237 139     99 [IRQ 14]
  239 139     99 [IRQ 15]
  278 139     99 [IRQ 1]
  310  24      - [kirqd]
  313 139     99 [IRQ 4]
  320  24      - [kjournald]
  605 139     99 [IRQ 10]
 1206  24      - [kjournald]
 1207  24      - [kjournald]
 1309 139     99 [IRQ 3]
 1323  31      - [IRQ 7]
 1494 139     99 [IRQ 6]
 1748 139     99 [IRQ 11]
14131  23      - [pdflush]
14242  24      - [pdflush]
17337  21      - grep \[

>Please review and double-check all SCHED_FIFO tasks in
>the system and keep only those that are absolutely necessary for
>latencytest's operation [i.e. the soundcard IRQ and latencytest itself]
>- everything else should be SCHED_OTHER. Do latencies get any better if
>you do this?
I can, but that is not necessarily an "apples to apples" comparison.
When I compare with 2.4 preempt + low latency kernels, the X stress
test had > 99% of the samples within 100 usec of the nominal value.
Don't forget - on a 2.4 kernel, the IRQ's are all unthreaded. On
the 2.4 kernel, heavy disk I/O is where I get the worst behavior
and even then, I get > 90% of samples within 100 usec.

I still maintain that a 2.6 RT kernel has to do as well or better
than a 2.4 RT kernel (or else, why would I step up??).

  --Mark

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

[Karsten Wiese]

Am Mittwoch 10 November 2004 14:52 schrieb Karsten Wiese:
> Am Dienstag 09 November 2004 17:05 schrieb Ingo Molnar:
> > 
> > i have released the -V0.7.23 Real-Time Preemption patch, which can be
> > downloaded from the usual place:
> > 
> >     http://redhat.com/~mingo/realtime-preempt/
> 
> Hi
> 
> On SMP/HT/P4 I get:
>  BUG: lock held at task exit time!

Forgot to write that this happened with V0.7.24.

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

[Karsten Wiese]

Am Dienstag 09 November 2004 17:05 schrieb Ingo Molnar:
> 
> i have released the -V0.7.23 Real-Time Preemption patch, which can be
> downloaded from the usual place:
> 
>     http://redhat.com/~mingo/realtime-preempt/

Hi

On SMP/HT/P4 I get:
 BUG: lock held at task exit time!

This was captured via netconsole:
<NETCONSOLELOG>
apm: disabled - APM is not SMP safe.
sh:5429 BUG: lock held at task exit time!
 [c03af1c4] {kernel_sem.lock}
.. held by:                sh/ 5429 [f4d2c420, 117]
... acquired at:  __reacquire_kernel_lock+0x2e/0x60
sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
in_atomic():1 [00000003], irqs_disabled():0
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c011d10b>] __might_sleep+0xbc/0xcf (36)
 [<c013a136>] __spin_lock+0x34/0x50 (24)
 [<c013a16f>] _spin_lock+0x1d/0x1f (16)
 [<c014e36b>] kmem_cache_alloc+0x37/0xf1 (32)
 [<c02c95d4>] alloc_skb+0x28/0xe6 (32)
 [<c02da818>] find_skb+0x31/0x9b (24)
 [<c02da97a>] netpoll_send_udp+0x40/0x25a (48)
 [<c028f246>] write_msg+0x56/0xfa (52)
 [<c0120e06>] __call_console_drivers+0x56/0x65 (32)
 [<c0120f49>] call_console_drivers+0xac/0x163 (36)
 [<c0121326>] release_console_sem+0x33/0xde (32)
 [<c012122c>] vprintk+0x134/0x16d (36)
 [<c01210f6>] printk+0x1d/0x1f (16)
 [<c01390ee>] __up_mutex+0x270/0x443 (68)
 [<c0139fc2>] up+0xe0/0xec (36)
 [<c0342e95>] __schedule+0x985/0xdb4 (124)
 [<c0123afc>] do_exit+0x331/0x59f (48)
 [<c0123e81>] do_group_exit+0x39/0xd1 (40)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000004 ]
| 4-level deep critical section nesting:
----------------------------------------
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c0142848>] ..   ( <= __do_IRQ+0xf6/0x16e)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c010b340>] ..   ( <= timer_interrupt+0xd3/0x10f)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c013b1c9>] ..   ( <= trace_start_sched_wakeup+0x22/0x7e)
.. [<c013b764>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)

 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c01390f3>] __up_mutex+0x275/0x443 (68)
 [<c0139fc2>] up+0xe0/0xec (36)
 [<c0342e95>] __schedule+0x985/0xdb4 (124)
 [<c0123afc>] do_exit+0x331/0x59f (48)
 [<c0123e81>] do_group_exit+0x39/0xd1 (40)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000004 ]
| 4-level deep critical section nesting:
----------------------------------------
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c0142848>] ..   ( <= __do_IRQ+0xf6/0x16e)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c010b340>] ..   ( <= timer_interrupt+0xd3/0x10f)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c013b1c9>] ..   ( <= trace_start_sched_wakeup+0x22/0x7e)
.. [<c013b764>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)

autom4te/5419: BUG in lock_new_owner at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:651
 [<c010704e>] dump_stack+0x23/0x25 (20)
BUG: scheduling while atomic: autom4te/0x00000001/5419
caller is schedule+0x38/0x12e
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c0342f06>] __schedule+0x9f6/0xdb4 (124)
 [<c03432fc>] schedule+0x38/0x12e (36)
 [<c0344758>] __down_mutex+0x225/0x30f (84)
 [<c013a148>] __spin_lock+0x46/0x50 (24)
 [<c013a1cc>] _spin_lock_irqsave+0x1d/0x21 (16)
 [<c028b31e>] e100_xmit_frame+0x13f/0x2d8 (60)
 [<c02da8a5>] netpoll_send_skb+0x23/0xb8 (28)
 [<c028f246>] write_msg+0x56/0xfa (52)
 [<c0120e06>] __call_console_drivers+0x56/0x65 (32)
 [<c0120f49>] call_console_drivers+0xac/0x163 (36)
 [<c0121326>] release_console_sem+0x33/0xde (32)
 [<c012122c>] vprintk+0x134/0x16d (36)
 [<c01210f6>] printk+0x1d/0x1f (16)
 [<c0106f4c>] show_trace+0x89/0xcd (36)
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c0138be0>] lock_new_owner+0xbe/0xe2 (40)
 [<c034462e>] __down_mutex+0xfb/0x30f (84)
 [<c013a148>] __spin_lock+0x46/0x50 (24)
 [<c013a1cc>] _spin_lock_irqsave+0x1d/0x21 (16)
 [<c012a6d8>] del_timer+0x2c/0xe4 (32)
 [<c012a7e1>] del_timer_sync+0x51/0x14b (104)
 [<c0330469>] __rpc_execute+0x8d/0x3db (112)
 [<c032bd4e>] rpc_call_sync+0x9b/0xc8 (40)
 [<c01b7b4d>] nfs3_rpc_wrapper+0x3d/0x82 (40)
 [<c01b7d31>] nfs3_proc_getattr+0x50/0x81 (40)
 [<c01aeeec>] __nfs_revalidate_inode+0xf3/0x3b7 (192)
 [<c01aac1c>] nfs_lookup_revalidate+0x37e/0x54c (352)
 [<c0173220>] do_lookup+0x53/0x8d (32)
 [<c01733da>] link_path_walk+0x180/0x1071 (108)
 [<c01745f2>] path_lookup+0xa5/0x1b0 (32)
 [<c017489f>] __user_walk+0x30/0x4d (32)
 [<c016ed2b>] vfs_stat+0x1f/0x5a (92)
 [<c016f3c4>] sys_stat64+0x1e/0x3d (100)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000002 ]
| 2-level deep critical section nesting:
----------------------------------------
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c0118894>] ..   ( <= task_rq_lock+0x32/0x5b)
.. [<c013b764>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)
</NETCONSOLELOG>

The "lock_new_owner" BUGs then repeated until the machine was restarted.

With HIGHMEM enabled, there were really weired things happening.
<HIGHMEMENABLEDLOG>
BUG at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/mm/highmem.c:191!
------------[ cut here ]------------
BUG: sleeping function called from invalid context init(1) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
in_atomic():1 [00000001], irqs_disabled():0
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c011d3db>] __might_sleep+0xbc/0xcf (36)
 [<c013a3e6>] __spin_lock+0x34/0x50 (24)
 [<c013a41f>] _spin_lock+0x1d/0x1f (16)
 [<c014e632>] kmem_cache_alloc+0x37/0xf1 (32)
 [<c02ca4f4>] alloc_skb+0x28/0xe6 (32)
 [<c02db938>] find_skb+0x31/0x9b (24)
 [<c02dba9a>] netpoll_send_udp+0x40/0x25a (48)
 [<c02900c6>] write_msg+0x56/0xfa (52)
 [<c01210d6>] __call_console_drivers+0x56/0x65 (32)
 [<c0121219>] call_console_drivers+0xac/0x163 (36)
 [<c01215f6>] release_console_sem+0x33/0xde (32)
 [<c01214fc>] vprintk+0x134/0x16d (36)
 [<c01213c6>] printk+0x1d/0x1f (16)
 [<c0107299>] handle_BUG+0x63/0x9e (28)
 [<c0107356>] die+0x82/0x195 (64)
 [<c01079ac>] do_invalid_op+0x127/0x129 (192)
 [<c0106c73>] error_code+0x2b/0x30 (76)
 [<c01541dc>] copy_pte_range+0xd8/0x1e3 (48)
 [<c015439b>] copy_pmd_range+0xb4/0xca (52)
 [<c015441e>] copy_pgd_range+0x6d/0x8c (48)
 [<c0154483>] copy_page_range+0x46/0x4e (48)
 [<c011e76c>] copy_mm+0x28a/0x3ac (76)
 [<c011f352>] copy_process+0x54a/0xf1b (76)
 [<c011fe2c>] do_fork+0x6e/0x1ce (132)
 [<c0104d08>] sys_fork+0x3d/0x3f (32)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000002 ]
| 2-level deep critical section nesting:
----------------------------------------
.. [<c0345fad>] .... _raw_spin_lock_irqsave+0x1b/0x70
.....[<c0107318>] ..   ( <= die+0x44/0x195)
.. [<c013ba14>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)

</HIGHMEMENABLEDLOG>

looks like some machinecode was undigestible for the cpu, no?

Best regards,
Karsten

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

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >i have released the -V0.7.23 Real-Time Preemption patch, which can be
> >downloaded from the usual place:
> >
> >    http://redhat.com/~mingo/realtime-preempt/
> 
> A few notes on results from running with this patch (well, actually
> -EA that Ingo provided separately).
> 
> [1] Build problems, separately reported to Ingo with CONFIG_PREEMPT_RT
> enabled on x86 and you have modules using kunmap_atomic. Fix by adding
> kunmap_virt and kmap_to_page to the list of exports.

these should be fixed in -V0.7.24 which i uploaded shortly after
-V0.7.23, based on your reports. In any case, the export problems
trigger with CONFIG_HIGHMEM and the affected subsystems compiled as
modules.

> [2] The live lock that I was having seems to have been killed based on
> an hour of testing (I could usually cause it in 5 minutes or less).

great!

> [4] Application level latencies are OK but not great.
>  X test - only 90% of CPU loops are within 100 usec of nominal value.
> In previous RT kernels I got > 99% with 100 usec.

this might be a side-effect of the chrt-ing of events/[0|1] and/or
ksoftirqd (which we did to debug the 'freeze' problems) - are those
still chrt-ed? Please review and double-check all SCHED_FIFO tasks in
the system and keep only those that are absolutely necessary for
latencytest's operation [i.e. the soundcard IRQ and latencytest itself]
- everything else should be SCHED_OTHER. Do latencies get any better if
you do this?

	Ingo

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

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> [3] I am not so sure that the latency tracing works. I do not get any
> trace output, even if I set preempt_max_latency to zero.

What is the value of preempt_thresh? If it's set then it overrides the
preempt_max_latency value. (previously the bogus timing values probably
triggered even a relatively high preempt-threshold, but now with a
correct tracer it's not possible anymore.)

> [...] I also noticed that /proc/sys/kernel/preempt_wakeup_timing was
> removed at .20 but not sure if that was deliberate. [...]

yeah, this was deliberate - it's a side-effect of separating it from the
other timing options.

	Ingo

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

[Mark_H_Johnson]

>i have released the -V0.7.23 Real-Time Preemption patch, which can be
>downloaded from the usual place:
>
>    http://redhat.com/~mingo/realtime-preempt/

A few notes on results from running with this patch (well, actually -EA
that Ingo provided separately).

[1] Build problems, separately reported to Ingo with CONFIG_PREEMPT_RT
enabled on x86 and you have modules using kunmap_atomic. Fix by adding
kunmap_virt and kmap_to_page to the list of exports.

[2] The live lock that I was having seems to have been killed based
on an hour of testing (I could usually cause it in 5 minutes or less).

[3] I am not so sure that the latency tracing works. I do not get any
trace output, even if I set preempt_max_latency to zero. I also noticed
that /proc/sys/kernel/preempt_wakeup_timing was removed at .20 but
not sure if that was deliberate. As a result, I have no reports from
the kernel tracing.

[4] Application level latencies are OK but not great.
 X test - only 90% of CPU loops are within 100 usec of nominal value.
In previous RT kernels I got > 99% with 100 usec.
 top test - looks much nicer than X test, but still have up to 30%
overhead on CPU loop.
 network I/O tests - smoothest of all test results, very nice
 disk write - very noisy, bursts of long delays with only 82% within
100 usec and worst case has over 100% overhead (2.5 msec vs 1.16 nominal)
 disk copy - fewer bursts, but worst case is similar to disk write.
About 95% within 100 usec.
 disk read - relatively clean with a pair of modest bursts early in
the test and then settled out a little worse than the network tests.
99.9% of samples within 100 usec and max of 1.65 msec.

[5] concurrent ping of system had over 13% lost packets (1089 out
of 10723 - plus I let this run after the tests had completed). The
2.4 RT kernel I use has no lost packets.

[6] I did a separate run of a script Ingo suggested that samples
the kernel profile data. It shows basically no CPU time for the
events/0 and events/1 tasks. I took 11 samples in about 1/2 hour
of testing but nothing seems to jump out of the data.

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

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

[Ingo Molnar]

i have released the -V0.7.23 Real-Time Preemption patch, which can be
downloaded from the usual place:

    http://redhat.com/~mingo/realtime-preempt/

this release includes fixes, development/debugging improvements and
latency improvements and other speedups.

the biggest change is the reworked timing/tracing framework. Wakeup
timing became a compile-time thing and can be selected independently of
the preemption mode - i.e. it can now be used on near-vanilla !PREEMPT
kernels too, providing good wakeup-latency comparison of the various
preemption models.

irqs-off and preempt-off critical section timing/tracing can be selected
if wakeup timing is disabled, the two options can be selected separately
or together as well.

another improvement is that wakeup-timing now works correctly on SMP too
- the tracer 'follows' the highest-priority task in the system as it
gets bounced between CPUs and always traces the CPU where the task is
pending.

other changes since -V0.7.22:

 - semaphore livelock fix: feedback from Mark H. Johnson pinpointed a 
   bug in the down_trylock() semaphore code: if preempted in the wrong
   moment a lower-prio task could cause a higher-prio task to livelock
   indefinitely. This fix could solve the 'keventd looping' problem 
   reported by Mark.

   the fix is to make the down_trylock() code a bit simpler, but this
   also introduces the potential for down_trylock() to get 'spurious' 
   locking-rejects. Hopefully this wont be a big problem - we dont 
   really guarantee that down_trylock() succeeds - but code using higher
   semaphore counts to track resources could be negatively impacted by
   this. We'll see.

 - console assert fix: implemented a different type of fbcon
   RT-preemption handling variant, this could solve the assert reported
   by Amit Shah.

 - debugging improvement: implemented a sequence counter for max latency 
   traces. This has the advantage of solving the 'slow console on SMP
   problem': the latency-timing code used to get confused by another CPU 
   printing a timing message to a slow console and thus delaying that 
   other CPU. Now any latency that gets generated while a maximum is 
   printed is skipped.

 - further shrunk the non-debug size of struct rt_mutex by moving the 
   save_state logic into the debug paths - size is now 4 machine-words.

 - fixed CONFIG_HIGHMEM latencies: all atomic-kmap APIs are now wrapped 
   seemlessly and in a preemptible way.

 - implemented an IO-APIC register cache to speed up the IRQ-redirection
   latency hotpath. Also, made the POST flush a bit faster.

 - disable KGDB if PREEMPT_RT - it's broken for now.

 - move some runtime checks to under DEBUG_PREEMPT - this speeds up 
   CRITICAL_PREEMPT_TIMING.

to create a -V0.7.23 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
   http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.10-rc1.bz2
   http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.10-rc1/2.6.10-rc1-mm3/2.6.10-rc1-mm3.bz2
   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.10-rc1-mm3-V0.7.23

	Ingo