preempt-timing-2.6.8-rc1

This patch uses the preemption counter increments and decrements to time non-preemptible critical sections.

This is an instrumentation patch intended to help determine the causes of scheduling latency related to long non-preemptible critical sections.

Changes from 2.6.7-based patch:
(1) fix unmap_vmas() check correctly this time
(2) add touch_preempt_timing() to cond_resched_lock()
(3) depend on preempt until it's worked out wtf goes wrong without it

-- wli

Index: timing-2.6.8-rc1/include/linux/preempt.h
===================================================================
@@ -9,17 +9,17 @@
 #include <linux/config.h>
 #include <linux/linkage.h>
 
-#define preempt_count()	(current_thread_info()->preempt_count)
-
-#define inc_preempt_count() \
-do { \
-	preempt_count()++; \
-} while (0)
+#ifdef CONFIG_PREEMPT_TIMING
+void inc_preempt_count(void);
+void dec_preempt_count(void);
+void touch_preempt_timing(void);
+#else
+#define touch_preempt_timing()	do { } while (0)
+#define inc_preempt_count()	do { preempt_count()++; } while (0)
+#define dec_preempt_count()	do { preempt_count()--; } while (0)
+#endif
 
-#define dec_preempt_count() \
-do { \
-	preempt_count()--; \
-} while (0)
+#define preempt_count()	(current_thread_info()->preempt_count)
 
 #ifdef CONFIG_PREEMPT
 

@@ -51,9 +51,15 @@
 
 #else
 
+#ifdef CONFIG_PREEMPT_TIMING
+#define preempt_disable()		inc_preempt_count()
+#define preempt_enable_no_resched()	dec_preempt_count()
+#define preempt_enable()		dec_preempt_count()
+#else
 #define preempt_disable()		do { } while (0)
 #define preempt_enable_no_resched()	do { } while (0)
 #define preempt_enable()		do { } while (0)
+#endif
 #define preempt_check_resched()		do { } while (0)
 
 #endif

Index: timing-2.6.8-rc1/include/linux/sched.h
===================================================================
@@ -1021,6 +1021,7 @@
 extern void __cond_resched(void);
 static inline void cond_resched(void)
 {
+	touch_preempt_timing();
 	if (need_resched())
 		__cond_resched();
 }

@@ -1040,7 +1041,8 @@
 		preempt_enable_no_resched();
 		__cond_resched();
 		spin_lock(lock);
-	}
+	} else
+		touch_preempt_timing();
 }
 
 /* Reevaluate whether the task has signals pending delivery.

Index: timing-2.6.8-rc1/init/Kconfig
===================================================================
@@ -279,6 +279,15 @@
 	  Disabling this option will cause the kernel to be built without
 	  support for epoll family of system calls.
 
+config PREEMPT_TIMING
+	bool "Non-preemptible critical section timing"
+	default n
+	depends on PREEMPT
+	help
+	  This option measures the time spent in non-preemptible critical
+	  sections and reports warnings when a boot-time configurable
+	  latency threshold is exceeded.
+
 source "drivers/block/Kconfig.iosched"
 
 config CC_OPTIMIZE_FOR_SIZE

Index: timing-2.6.8-rc1/kernel/printk.c
===================================================================
@@ -650,10 +650,8 @@
  */
 void console_conditional_schedule(void)
 {
-	if (console_may_schedule && need_resched()) {
-		set_current_state(TASK_RUNNING);
-		schedule();
-	}
+	if (console_may_schedule)
+		cond_resched();
 }
 EXPORT_SYMBOL(console_conditional_schedule);
 

Index: timing-2.6.8-rc1/mm/memory.c
===================================================================
@@ -567,14 +567,17 @@
 			zap_bytes -= block;
 			if ((long)zap_bytes > 0)
 				continue;
-			if (!atomic && need_resched()) {
+			zap_bytes = ZAP_BLOCK_SIZE;
+			if (atomic)
+				continue;
+			if (need_resched()) {
 				int fullmm = tlb_is_full_mm(*tlbp);
 				tlb_finish_mmu(*tlbp, tlb_start, start);
 				cond_resched_lock(&mm->page_table_lock);
 				*tlbp = tlb_gather_mmu(mm, fullmm);
 				tlb_start_valid = 0;
-			}
-			zap_bytes = ZAP_BLOCK_SIZE;
+			} else
+				touch_preempt_timing();
 		}
 	}
 	return ret;

AFAICT this is nothing more than rounding up.

-- wli

But you want to round down by definition of preempt_thresh, don't you?

preempt_thresh = 1ms = 1000000us
ie. warn me if the lock hold goes _to or above_ 1000000us

The semantics I implemented are warning for strictly above the preempt_thresh. Whether those semantics are ideal is irrelevant; it's faithful to those semantics. Given that people are asking for sub- millisecond latencies, maybe I should increase the precision.

-- wli

You are right - I misread it, sorry.

Would soon be useful I think.

Let me spin up the CONFIG_PREEMPT=n fix and then I'll move on that.

-- wli

smp_lock.h and hardirq.h for all arches -- some of which may not have CONFIG_PREEMPT. -EWONTFIX. So the "workaround" stays.

-- wli

Hi,

My first results with 2.6.8-rc1 + preempt-timing:

Boot-time:

2ms non-preemptible critical section violated 1 ms preempt threshold starting at kmap_atomic+0x13/0x70 and ending at kunmap_atomic+0x5/0x20
2ms non-preemptible critical section violated 1 ms preempt threshold starting at buffered_rmqueue+0xea/0x190 and ending at buffered_rmqueue+0x144/0x190 2ms non-preemptible critical section violated 1 ms preempt threshold starting at search_by_key+0xe3/0xf70 and ending at do_IRQ+0xec/0x130
2ms non-preemptible critical section violated 1 ms preempt threshold starting at copy_mm+0x2e6/0x3b0 and ending at copy_mm+0x331/0x3b0
11ms non-preemptible critical section violated 1 ms preempt threshold starting at ohci_hub_resume+0x3c/0x350 [ohci_hcd] and ending at ohci_hub_resume+0x79/0x350 [ohci_hcd] 14ms non-preemptible critical section violated 1 ms preempt threshold starting at schedule+0x36/0x480 and ending at schedule+0x291/0x480
2ms non-preemptible critical section violated 1 ms preempt threshold starting at new_inode+0x1a/0x80 and ending at new_inode+0x58/0x80
2ms non-preemptible critical section violated 1 ms preempt threshold starting at kmap_atomic+0x13/0x70 and ending at kunmap_atomic+0x5/0x20
2ms non-preemptible critical section violated 1 ms preempt threshold starting at kmap_atomic+0x13/0x70 and ending at kunmap_atomic+0x5/0x20

Normal use (logging in, browsing, playing video with mplayer, moving windows around, etc):

2ms non-preemptible critical section violated 1 ms preempt threshold starting at search_by_key+0xe3/0xf70 and ending at smp_apic_timer_interrupt+0x9a/0xe0 2ms non-preemptible critical section violated 1 ms preempt threshold starting at do_munmap+0xd2/0x140 and ending at do_munmap+0xeb/0x140
2ms non-preemptible critical section violated 1 ms preempt threshold starting at kmap_atomic+0x13/0x70 and ending at kunmap_atomic+0x5/0x20
2ms non-preemptible critical section violated 1 ms preempt threshold starting at __d_lookup+0x66/0x170 and ending at __d_lookup+0x9c/0x170
2ms non-preemptible critical section violated 1 ms preempt threshold starting at kmap_atomic+0x13/0x70 and ending at kunmap_atomic+0x5/0x20
2ms non-preemptible critical section violated 1 ms preempt threshold starting at copy_mm+0x2e6/0x3b0 and ending at copy_mm+0x331/0x3b0
2ms non-preemptible critical section violated 1 ms preempt threshold starting at find_get_page+0x14/0x60 and ending at find_get_page+0x2f/0x60
2ms non-preemptible critical section violated 1 ms preempt threshold starting at dev_queue_xmit+0x7f/0x320 and ending at dev_queue_xmit+0x27f/0x320
2ms non-preemptible critical section violated 1 ms preempt threshold starting at dev_queue_xmit+0x7f/0x320 and ending at dev_queue_xmit+0x27f/0x320
49ms non-preemptible critical section violated 1 ms preempt threshold starting at snd_pcm_action_lock_irq+0x1b/0x1d0 [snd_pcm] and ending at snd_pcm_action_lock_irq+0x65/0x1d0 [snd_pcm] 2ms non-preemptible critical section violated 1 ms preempt threshold starting at do_no_page+0xd5/0x310 and ending at do_no_page+0x178/0x310
2ms non-preemptible critical section violated 1 ms preempt threshold starting at fget+0x28/0x70 and ending at fget+0x41/0x70
2ms non-preemptible critical section violated 1 ms preempt threshold starting at sys_ioctl+0x42/0x270 and ending at do_IRQ+0xec/0x130
2ms non-preemptible critical section violated 1 ms preempt threshold starting at dnotify_parent+0x27/0xc0 and ending at dnotify_parent+0x85/0xc0
2ms non-preemptible critical section violated 1 ms preempt threshold starting at buffered_rmqueue+0xea/0x190 and ending at buffered_rmqueue+0x144/0x190

What I've excluded (happens all the time):

1) 2ms non-preemptible critical section violated 1 ms preempt threshold starting at schedule+0x36/0x480 and ending at do_IRQ+0xec/0x130 it's 2ms 98%. This really happens all the time. Bogus?

2) 49ms non-preemptible critical section violated 1 ms preempt threshold starting at sys_ioctl+0x42/0x270 and ending at sys_ioctl+0xbd/0x270 40-50 ms most of the time, 12 ms couple of times.

Let me now if you need those traces for some of these (I've built kernel with 8K stacks).

Lenar

Boot-time stuff is unlikely to have much done about it. I highly suspect this is the kmap_atomic() trick for pagecache writes. 1ms is probably more than your box can handle if so.

If you're getting these in find_get_page() and buffered_rmqueue() either your box is definitely too slow to handle 1ms or sched_clock()'s results are questionable on your machine. cpufreq?

Wild guess is that you took an IRQ in dec_preempt_count() and that threw your results off. Let me know if the patch below helps at all. My guess is it'll cause more apparent problems than it solves.

ioctl() is typically grossly inefficient and even involves the BKL.

-- wli

Index: timing-2.6.8-rc1/kernel/sched.c
===================================================================
@@ -4069,22 +4069,33 @@
 
 void touch_preempt_timing(void)
 {
+	unsigned long flags;
+
+	local_irq_save(flags);
 	if (preempt_count() > 0 && system_state == SYSTEM_RUNNING &&
 						__get_cpu_var(preempt_entry))
 		__touch_preempt_timing(__builtin_return_address(0));
+	local_irq_restore(flags);
 }
 EXPORT_SYMBOL(touch_preempt_timing);
 
 void inc_preempt_count(void)
 {
+	unsigned long flags;
+
+	local_irq_save(flags);
 	preempt_count()++;
 	if (preempt_count() == 1 && system_state == SYSTEM_RUNNING)
 		__touch_preempt_timing(__builtin_return_address(0));
+	local_irq_restore(flags);
 }
 EXPORT_SYMBOL(inc_preempt_count);
 
 void dec_preempt_count(void)
 {
+	unsigned long flags;
+
+	local_irq_save(flags);
 	if (preempt_count() == 1 && system_state == SYSTEM_RUNNING &&
 					__get_cpu_var(preempt_entry)) {
 		u64 hold;

@@ -4108,6 +4119,7 @@
 		__get_cpu_var(preempt_entry) = 0;
 	}
 	preempt_count()--;
+	local_irq_restore(flags);
 }
 EXPORT_SYMBOL(dec_preempt_count);
 #endif

woa

Indeed - but 49ms is stunning and worthy of investigation. The interesting thing is that sys_ioctl blankly locks the kernel, even if the systems below it don't need it. Would be a big change to fix.

In this case, how about adding

	printk(KERN_DEBUG "ioctl cmd=%d\n", cmd);

here in fs/ioctl.c:

	unlock_kernel();
	fput(filp);

out:

		return error;
}

Or something else to instrument ioctl?

http://www.PowerDNS.com      Open source, database driven DNS Software 
http://lartc.org           Linux Advanced Routing & Traffic Control HOWTO

Machine in question is [email protected] (it was [email protected] during last test, now running at official speed). Is this really slow for 1ms?

Applied your patch. Booted.

With preempt_thresh=1 I still got tons of those violations at schedule().

With preempt_thresh=2 I do not get those anymore. Apart from sys_ioctl() violation, getting now these:

16ms non-preemptible critical section violated 2 ms preempt threshold starting at exit_notify+0x1d/0x7b0 and ending at schedule+0x291/0x480 7ms non-preemptible critical section violated 2 ms preempt threshold starting at kmap_atomic+0x13/0x70 and ending at kunmap_atomic+0x5/0x20 6ms non-preemptible critical section violated 2 ms preempt threshold starting at fget+0x28/0x70 and ending at fget+0x41/0x70

No apparent side-effects noticed.

As before, when running mplayer I'm getting many sys_ioctl() things coupled with messages:
rtc: lost some interrupts at 1024Hz.
It happens when madly seeking around in video.

Lenar

It should actually be fast enough. I suspect something else, maybe some slow devices. What's /proc/interrupts look like?

exit_notify() isn't a huge surprise unless you're not doing things with lots of processes. Actually, it probably is a surprise, since it should only hurt when you're doing forkbombs and/or threadbombs.

The kmap_atomic() stuff is too consistent. Maybe you're taking an interrupt during the copy operation.

fget() is mind-bogglingly O(1) and very short. Only plausible guess is we're seeing interrupts taken there because it's so frequently called.

Not surprised either. There's probably enough time spent with interrupts off the local_irq_save() hurt, and it didn't make your schedule() things go away, so my wild guesswork thus far is it made things worse with no tangible benefit, so best to drop that local_irq_save() change.

-- wli

CPU0

 0:   60521505    IO-APIC-edge  timer
 1:      11445    IO-APIC-edge  i8042
 8:      33269    IO-APIC-edge  rtc
 9:          0   IO-APIC-level  acpi
14:     523202    IO-APIC-edge  ide0
15:      61761    IO-APIC-edge  ide1
16:   10376547   IO-APIC-level  eth0
19:     522859   IO-APIC-level  ide2
20:     131904   IO-APIC-level  NVidia nForce2, ehci_hcd
21:      66209   IO-APIC-level  ohci_hcd
22:    9165291   IO-APIC-level  ohci_hcd, eth1
NMI:          0
LOC:   60351703
ERR:          0
MIS:          2

It probably happened when users where simultaneously logging in (many kdeinit processes created at that time).

Yeah, ok.

In the meantime couple of these found their way to logs during the night:
3ms non-preemptible critical section violated 2 ms preempt threshold starting at search_by_key+0xe3/0xf70 and ending at do_IRQ+0xec/0x130

And this still seems to be very long and real:
50ms non-preemptible critical section violated 2 ms preempt threshold starting at snd_pcm_action_lock_irq+0x1b/0x1d0 [snd_pcm] and ending at snd_pcm_action_lock_irq+0x65/0x1d0 [snd_pcm] Trace has this:
[<f9239b09>] snd_pcm_playback_ioctl1+0x49/0x2f0 [snd_pcm]
So maybe this too is ioctl related (non-educated guess)?

Lenar

At Wed, 14 Jul 2004 10:59:53 +0300,

If it's SNDRV_PCM_IOCTL_PREPARE, I'm modifying the relevant code with rwsem instead of rwlock. But it's still in BKL of ioctl. Do we need to unlock internally?

Takashi

Yes, otherwise it'll be non-preemptible.

-- wli

I applied the patch to 2.6.8-rc2 + voluntary-preempt-I4, and am constantly getting these:

2ms non-preemptible critical section violated 1 ms preempt threshold starting at schedule+0x65/0x5b0 and ending at do_IRQ+0x101/0x170

 [<c01066e7>] dump_stack+0x17/0x20
 [<c011426e>] dec_preempt_count+0x10e/0x120
 [<c0107cb1>] do_IRQ+0x101/0x170
 [<c01062a8>] common_interrupt+0x18/0x20
 [<c010421d>] cpu_idle+0x2d/0x40
 [<c030a782>] start_kernel+0x1a2/0x1f0
 [<c010019f>] 0xc010019f
printk: 1 messages suppressed.
2ms non-preemptible critical section violated 1 ms preempt threshold starting at schedule+0x65/0x5b0 and ending at do_IRQ+0x101/0x170
 [<c01066e7>] dump_stack+0x17/0x20
 [<c011426e>] dec_preempt_count+0x10e/0x120
 [<c0107cb1>] do_IRQ+0x101/0x170
 [<c01062a8>] common_interrupt+0x18/0x20
 [<c010421d>] cpu_idle+0x2d/0x40
 [<c030a782>] start_kernel+0x1a2/0x1f0
 [<c010019f>] 0xc010019f
printk: 1 messages suppressed.
2ms non-preemptible critical section violated 1 ms preempt threshold starting at schedule+0x65/0x5b0 and ending at do_IRQ+0x101/0x170
 [<c01066e7>] dump_stack+0x17/0x20
 [<c011426e>] dec_preempt_count+0x10e/0x120
 [<c0107cb1>] do_IRQ+0x101/0x170
 [<c01062a8>] common_interrupt+0x18/0x20
 [<c010421d>] cpu_idle+0x2d/0x40
 [<c030a782>] start_kernel+0x1a2/0x1f0
 [<c010019f>] 0xc010019f

This seems related to keyboard input; if I keep a key pressed down they happen regularly.

These are similar to the XRUN traces I get from ALSA, so I think there is a real problem here.

Lee

Here is another one:

Jul 25 18:46:18 mindpipe kernel: 11ms non-preemptible critical section violated 1 ms preempt threshold starting at kmap_atomic+0x10/0x60 and ending at kunmap_atomic+0x8/0x20
Jul 25 18:46:18 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 18:46:18 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 18:46:18 mindpipe kernel:  [kunmap_atomic+8/32] kunmap_atomic+0x8/0x20
Jul 25 18:46:18 mindpipe kernel:  [do_anonymous_page+139/400] do_anonymous_page+0x8b/0x190
Jul 25 18:46:18 mindpipe kernel:  [do_no_page+78/784] do_no_page+0x4e/0x310
Jul 25 18:46:18 mindpipe kernel:  [handle_mm_fault+193/368] handle_mm_fault+0xc1/0x170
Jul 25 18:46:18 mindpipe kernel:  [get_user_pages+288/944] get_user_pages+0x120/0x3b0
Jul 25 18:46:18 mindpipe kernel:  [make_pages_present+104/144] make_pages_present+0x68/0x90
Jul 25 18:46:18 mindpipe kernel:  [do_mmap_pgoff+998/1568] do_mmap_pgoff+0x3e6/0x620
Jul 25 18:46:18 mindpipe kernel:  [sys_mmap2+118/176] sys_mmap2+0x76/0xb0
Jul 25 18:46:18 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb

Lee

is this an mmap(MAP_LOCKED) instance [or a process doing an mmap() after having done an mlockall()]? I'll take a look.

Ingo

Yes, jackd does exactly this, mlockall then opens the ALSA driver with mmap.

Lee

ok, i fixed this in -J3:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc2-J3

-J3 also includes a number of softirq latency fixes for the networking layer.

Ingo

OK, I will try this. I have not seen any latency issues with softirqs with -I4. Other than the few remaining hot spots, the only thing that triggers latencies over 100 usecs during normal operation is the IDE I/O completion, which can be easily controlled by lowering the max SG size.

Here is one that I think happens when deleting a large number of files, or a directory that had a large number of files. Specifically, this happens when bonnie exits.

Jul 25 20:25:36 mindpipe kernel: 16ms non-preemptible critical section violated 1 ms preempt threshold starting at select_parent+0x18/0xd0 and ending at select_parent+0x94/0xd0
Jul 25 20:25:36 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 20:25:36 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 20:25:36 mindpipe kernel:  [select_parent+148/208] select_parent+0x94/0xd0
Jul 25 20:25:36 mindpipe kernel:  [shrink_dcache_parent+22/48] shrink_dcache_parent+0x16/0x30
Jul 25 20:25:36 mindpipe kernel:  [d_unhash+60/176] d_unhash+0x3c/0xb0
Jul 25 20:25:36 mindpipe kernel:  [vfs_rmdir+108/432] vfs_rmdir+0x6c/0x1b0
Jul 25 20:25:36 mindpipe kernel:  [sys_rmdir+207/240] sys_rmdir+0xcf/0xf0
Jul 25 20:25:36 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 25 20:27:45 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D2c
Jul 25 20:27:45 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 20:27:45 mindpipe kernel:  [__crc_totalram_pages+1165/3197748] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 25 20:27:45 mindpipe kernel:  [__crc_totalram_pages+65879/3197748] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 25 20:27:45 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 25 20:27:45 mindpipe kernel:  [do_IRQ+167/368] do_IRQ+0xa7/0x170
Jul 25 20:27:45 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 25 20:27:45 mindpipe kernel:  [shrink_dcache_parent+22/48] shrink_dcache_parent+0x16/0x30
Jul 25 20:27:45 mindpipe kernel:  [d_unhash+60/176] d_unhash+0x3c/0xb0
Jul 25 20:27:45 mindpipe kernel:  [vfs_rmdir+108/432] vfs_rmdir+0x6c/0x1b0
Jul 25 20:27:45 mindpipe kernel:  [sys_rmdir+207/240] sys_rmdir+0xcf/0xf0
Jul 25 20:27:45 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb

I am also seeing a lot of shorter timing violations that involve unmap_vmas. Not sure what triggers this one.

Jul 25 21:05:04 mindpipe kernel: 2ms non-preemptible critical section violated 1 ms preempt threshold starting at unmap_vmas+0x1ff/0x210 and ending at unmap_vmas+0x1f5/0x210
Jul 25 21:05:04 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 21:05:04 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 21:05:04 mindpipe kernel:  [unmap_vmas+501/528] unmap_vmas+0x1f5/0x210
Jul 25 21:05:04 mindpipe kernel:  [exit_mmap+94/336] exit_mmap+0x5e/0x150
Jul 25 21:05:04 mindpipe kernel:  [mmput+114/160] mmput+0x72/0xa0
Jul 25 21:05:04 mindpipe kernel:  [do_exit+251/1072] do_exit+0xfb/0x430
Jul 25 21:05:04 mindpipe kernel:  [do_group_exit+50/192] do_group_exit+0x32/0xc0
Jul 25 21:05:04 mindpipe kernel:  [get_signal_to_deliver+605/880] get_signal_to_deliver+0x25d/0x370
Jul 25 21:05:04 mindpipe kernel:  [do_signal+86/208] do_signal+0x56/0xd0
Jul 25 21:05:04 mindpipe kernel:  [do_notify_resume+71/80] do_notify_resume+0x47/0x50
Jul 25 21:05:04 mindpipe kernel:  [work_notifysig+19/21] work_notifysig+0x13/0x15
Jul 25 21:05:04 mindpipe kernel: 2ms non-preemptible critical section violated 1 ms preempt threshold starting at unmap_vmas+0x1ff/0x210 and ending at unmap_vmas+0x1f5/0x210
Jul 25 21:05:04 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 21:05:04 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 21:05:04 mindpipe kernel:  [unmap_vmas+501/528] unmap_vmas+0x1f5/0x210
Jul 25 21:05:04 mindpipe kernel:  [exit_mmap+94/336] exit_mmap+0x5e/0x150
Jul 25 21:05:04 mindpipe kernel:  [mmput+114/160] mmput+0x72/0xa0
Jul 25 21:05:04 mindpipe kernel:  [do_exit+251/1072] do_exit+0xfb/0x430
Jul 25 21:05:04 mindpipe kernel:  [do_group_exit+50/192] do_group_exit+0x32/0xc0
Jul 25 21:05:04 mindpipe kernel:  [get_signal_to_deliver+605/880] get_signal_to_deliver+0x25d/0x370
Jul 25 21:05:04 mindpipe kernel:  [do_signal+86/208] do_signal+0x56/0xd0
Jul 25 21:05:04 mindpipe kernel:  [do_notify_resume+71/80] do_notify_resume+0x47/0x50
Jul 25 21:05:04 mindpipe kernel:  [work_notifysig+19/21] work_notifysig+0x13/0x15
Jul 25 21:05:17 mindpipe kernel: 2ms non-preemptible critical section violated 1 ms preempt threshold starting at unmap_vmas+0x1ff/0x210 and ending at unmap_vmas+0x1f5/0x210
Jul 25 21:05:17 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 21:05:17 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 21:05:17 mindpipe kernel:  [unmap_vmas+501/528] unmap_vmas+0x1f5/0x210
Jul 25 21:05:17 mindpipe kernel:  [exit_mmap+94/336] exit_mmap+0x5e/0x150
Jul 25 21:05:17 mindpipe kernel:  [mmput+114/160] mmput+0x72/0xa0
Jul 25 21:05:17 mindpipe kernel:  [do_exit+251/1072] do_exit+0xfb/0x430
Jul 25 21:05:17 mindpipe kernel:  [do_group_exit+50/192] do_group_exit+0x32/0xc0
Jul 25 21:05:17 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb

Lee

i'm going through the subsystems systematically and i'm stressing them beyond normal use. These networking latencies need a high number of in flight packets, multiple TCP sockets, and a 100 mbit link or faster. (this is a more common workload on a corporate desktop, but not typical on a home desktop.)

ok, i'll take a look whether there's a way to control this without having to artificially impact the IO patterns.

ok, this should be the dcache/icache zapping. I've done some latency reduction in this area but apparently not enough.

it might just be a common operation, being hit by the IDE hardirq latency. (which thus is added to the 'scheduling' latency.) Although none of the traces show IDE hardirq leftovers [but they might be cleared from the stack by the time we notice the latency.]

Can you see these 1-2 msec latencies even if you reduce the IDE sg-size drastically via the max_sectors tunable? (just for testing purposes, to eliminate hardirq latencies as much as possible)

Ingo

i've uploaded -J7:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc2-J7

Changes since -J4:

- fix the latency that occurs when a large number of files are deleted:
the guilty one is select_parent() - this should fix the Bonnie latency reported by Lee Revell.

[ the ones below add conditional reschedule points that dont affect
users who have kernel_preemption turned on:]

- fix /proc/PID/maps latencies

- fix latencies triggered by 'df' on a large filesystem

- fix exec() latency when dealing with large environments

- add might_sleep() to lock_buffer()

Ingo

i've uploaded -L2:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc2-L2

the big change in the -L2 release is a new latency-reduction feature:
the redirection of hardirqs to irqd. This enables lock-break methods that make hardirqs preemptable.

I've done the lock-break of the IDE driver's completion path and i now cannot trigger larger than 100 usecs hardirq latencies via the IDE driver anymore, on a 2GHz x86 box - even if max_sectors is kept at the default 1024K value. (!)

the hardirq-redirection feature is activated via voluntary-preemption=3 (default). All irqs except the timer irq are redirected. (the timer irq needs to run from irq context - but it has constant latency and constant frequency so it's not an issue. Soft timers are executed from the timer softirq which is redirected and hence preemptable.)

this means that with this patch applied the 2.6 UP kernel is quite close to being hard-RT capable (using controlled drivers and workloads). All unbound-latency asynchronous workloads have been unloaded into synchronous, schedulable process contexts - so nothing can delay a high-prio RT task. (assuming we caught all the latencies. Any remaining latency can be fixed with the existing methods.)

other changes in -L2:

i've done a softirq lock-break in the atkbd and ps2mouse drivers - this should fix the big latencies triggered by NumLock/CapsLock, reported by Lee Revell.

BIG WARNING: the hardirq-redirection feature is quite intrusive to drivers so it's possible that some drivers will break under it. The changes done to the IDE driver might also endanger stability. Be careful when applying this patch to production systems. If your system doesnt boot then please try the voluntary-preempt=2 boot-option to turn off hardirq redirection.

I've done some stresstesting on a desktop-style IDE-based system and everything seems to work fine. YMMV.

Ingo

I've seen an oops on my P4 machine when booting with voluntary- preempt=3, but not with voluntary-preempt<3. I think it's related to the serial controller (IRQ3 and IRQ4). Please, see attached dmesg.

Linux version 2.6.8-rc2-bk6-ck6 ([email protected]) (gcc version 3.4.1 20040714 (Red Hat 3.4.1-5)) #1 Wed Jul 28 00:00:29 CEST 2004 BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
BIOS-e820: 0000000000100000 - 000000001fff0000 (usable)
BIOS-e820: 000000001fff0000 - 000000001fff3000 (ACPI NVS)
BIOS-e820: 000000001fff3000 - 0000000020000000 (ACPI data)
BIOS-e820: 00000000fec00000 - 0000000100000000 (reserved)
511MB LOWMEM available.
found SMP MP-table at 000f5610
On node 0 totalpages: 131056
DMA zone: 4096 pages, LIFO batch:1
Normal zone: 126960 pages, LIFO batch:16
HighMem zone: 0 pages, LIFO batch:1
DMI 2.3 present.
ACPI: RSDP (v000 IntelR ) @ 0x000f6fe0
ACPI: RSDT (v001 IntelR AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x1fff3000
ACPI: FADT (v001 IntelR AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x1fff3040
ACPI: MADT (v001 IntelR AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x1fff6dc0
ACPI: DSDT (v001 INTELR AWRDACPI 0x00001000 MSFT 0x0100000c) @ 0x00000000
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Processor #0 15:2 APIC version 20
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] disabled)
ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
IOAPIC[0]: Assigned apic_id 2
IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
ACPI: IRQ0 used by override.
ACPI: IRQ2 used by override.
ACPI: IRQ9 used by override.
Enabling APIC mode: Flat. Using 1 I/O APICs
Using ACPI (MADT) for SMP configuration information
Built 1 zonelists
Kernel command line: ro root=/dev/hda2
Initializing CPU#0
CPU 0 irqstacks, hard=c039f000 soft=c039e000
PID hash table entries: 2048 (order 11: 16384 bytes)
Detected 2004.916 MHz processor.
Using tsc for high-res timesource
Console: colour VGA+ 80x25
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 515648k/524224k available (1779k kernel code, 7816k reserved, 759k data, 128k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay loop... 3956.73 BogoMIPS
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
CPU: After generic identify, caps: 3febfbff 00000000 00000000 00000000
CPU: After vendor identify, caps: 3febfbff 00000000 00000000 00000000
CPU: Trace cache: 12K uops, L1 D cache: 8K
CPU: L2 cache: 512K
CPU: After all inits, caps: 3febfbff 00000000 00000000 00000080
CPU: Intel(R) Pentium(R) 4 CPU 2.00GHz stepping 04
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
enabled ExtINT on CPU#0
ESR value before enabling vector: 00000000
ESR value after enabling vector: 00000000
ENABLING IO-APIC IRQs
init IO_APIC IRQs
IO-APIC (apicid-pin) 2-0, 2-16, 2-17, 2-18, 2-19, 2-20, 2-21, 2-22, 2-23 not connected.
..TIMER: vector=0x31 pin1=2 pin2=-1
Using local APIC timer interrupts.
calibrating APIC timer ...
..... CPU clock speed is 2004.0312 MHz.
..... host bus clock speed is 100.0215 MHz.
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xfb0a0, last bus=2
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
ACPI: Subsystem revision 20040326
ACPI: Interpreter enabled
ACPI: Using IOAPIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (00:00)
PCI: Probing PCI hardware (bus 00)
PCI: Transparent bridge - 0000:00:1e.0
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.HUB0._PRT]
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 *5 6 7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 9 10 11 *12 14 15)
ACPI: PCI Interrupt Link [LNK0] (IRQs 3 4 5 6 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNK1] (IRQs 3 4 5 6 7 *9 10 11 12 14 15)
PCI: Using ACPI for IRQ routing
ACPI: PCI interrupt 0000:00:1f.2[D] -> GSI 19 (level, low) -> IRQ 19
ACPI: PCI interrupt 0000:00:1f.4[C] -> GSI 23 (level, low) -> IRQ 23
ACPI: PCI interrupt 0000:00:1f.5[B] -> GSI 17 (level, low) -> IRQ 17
ACPI: PCI interrupt 0000:02:0c.0[A] -> GSI 20 (level, low) -> IRQ 20
ACPI: PCI interrupt 0000:02:0d.0[A] -> GSI 21 (level, low) -> IRQ 21
number of MP IRQ sources: 15.
number of IO-APIC #2 registers: 24.
testing the IO APIC.......................
IO APIC #2......
.... register #00: 02000000

.......    : physical APIC id: 02
.......    : Delivery Type: 0
.......    : LTS          : 0
.... register #01: 00178020
.......     : max redirection entries: 0017
.......     : PRQ implemented: 1
.......     : IO APIC version: 0020

.... register #02: 00000000
....... : arbitration: 00
.... register #03: 00000001
....... : Boot DT : 1
.... IRQ redirection table:
NR Log Phy Mask Trig IRR Pol Stat Dest Deli Vect:

 00 000 00  1    0    0   0   0    0    0    00
 01 001 01  0    0    0   0   0    1    1    39
 02 001 01  0    0    0   0   0    1    1    31
 03 001 01  0    0    0   0   0    1    1    41
 04 001 01  0    0    0   0   0    1    1    49
 05 001 01  0    0    0   0   0    1    1    51
 06 001 01  0    0    0   0   0    1    1    59
 07 001 01  0    0    0   0   0    1    1    61
 08 001 01  0    0    0   0   0    1    1    69
 09 001 01  0    1    0   0   0    1    1    71
 0a 001 01  0    0    0   0   0    1    1    79
 0b 001 01  0    0    0   0   0    1    1    81
 0c 001 01  0    0    0   0   0    1    1    89
 0d 001 01  0    0    0   0   0    1    1    91
 0e 001 01  0    0    0   0   0    1    1    99
 0f 001 01  0    0    0   0   0    1    1    A1
 10 000 00  1    0    0   0   0    0    0    00
 11 001 01  1    1    0   1   0    1    1    B9
 12 000 00  1    0    0   0   0    0    0    00
 13 001 01  1    1    0   1   0    1    1    A9
 14 001 01  1    1    0   1   0    1    1    C1
 15 001 01  1    1    0   1   0    1    1    C9
 16 000 00  1    0    0   0   0    0    0    00
 17 001 01  1    1    0   1   0    1    1    B1

IRQ to pin mappings:
IRQ0 -> 0:2
IRQ1 -> 0:1
IRQ3 -> 0:3
IRQ4 -> 0:4
IRQ5 -> 0:5
IRQ6 -> 0:6
IRQ7 -> 0:7
IRQ8 -> 0:8
IRQ9 -> 0:9
IRQ10 -> 0:10
IRQ11 -> 0:11
IRQ12 -> 0:12
IRQ13 -> 0:13
IRQ14 -> 0:14
IRQ15 -> 0:15
IRQ17 -> 0:17
IRQ19 -> 0:19
IRQ20 -> 0:20
IRQ21 -> 0:21
IRQ23 -> 0:23
.................................... done.
TC classifier action (bugs to [email protected] cc [email protected])
audit: initializing netlink socket (disabled)
audit(1090974113.678:0): initialized
Total HugeTLB memory allocated, 0
Initializing Cryptographic API
ACPI: Power Button (FF) [PWRF]
ACPI: Sleep Button (CM) [SLPB]
ACPI: Fan [FAN] (on)
ACPI: Processor [CPU0] (supports C1)
ACPI: Thermal Zone [THRM] (55 C)
Real Time Clock Driver v1.12
Linux agpgart interface v0.100 (c) Dave Jones
agpgart: Detected an Intel i845 Chipset.
agpgart: Maximum main memory to use for agp memory: 439M
agpgart: AGP aperture is 64M @ 0xe8000000
[drm] Initialized radeon 1.11.0 20020828 on minor 0: ATI Technologies Inc Radeon RV100 QY [Radeon 7000/VE]
Serial: 8250/16550 driver $Revision: 1.90 $ 8 ports, IRQ sharing disabled
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
ICH2: IDE controller at PCI slot 0000:00:1f.1
ICH2: chipset revision 5
ICH2: not 100% native mode: will probe irqs later

    ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:DMA, hdb:DMA
    ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:DMA, hdd:DMA

hda: ST3120022A, ATA DISK drive
hdb: ST380021A, ATA DISK drive
Using cfq io scheduler
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
hdc: HL-DT-STDVD-ROM GDR8161B, ATAPI CD/DVD-ROM drive
hdd: PLEXTOR CD-R PX-W4824A, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
hda: max request size: 1024KiB
hda: 234441648 sectors (120034 MB) w/2048KiB Cache, CHS=16383/255/63, UDMA(100)
hda: hda1 hda2
hdb: max request size: 128KiB
hdb: 156301488 sectors (80026 MB) w/2048KiB Cache, CHS=65535/16/63, UDMA(100)
hdb: hdb1
mice: PS/2 mouse device common for all mice
input: PC Speaker
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
input: AT Translated Set 2 keyboard on isa0060/serio0
NET: Registered protocol family 2
IP: routing cache hash table of 4096 buckets, 32Kbytes
TCP: Hash tables configured (established 32768 bind 65536)
Initializing IPsec netlink socket
NET: Registered protocol family 1
NET: Registered protocol family 10
IPv6 over IPv4 tunneling driver
NET: Registered protocol family 17
NET: Registered protocol family 15
p4-clockmod: P4/Xeon(TM) CPU On-Demand Clock Modulation available
ACPI: (supports S0 S1 S3 S4bios S5)
BIOS EDD facility v0.16 2004-Jun-25, 2 devices found
kjournald starting. Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 128k freed
usbcore: registered new driver usbfs
usbcore: registered new driver hub
USB Universal Host Controller Interface driver v2.2
ACPI: PCI interrupt 0000:00:1f.2[D] -> GSI 19 (level, low) -> IRQ 19
uhci_hcd 0000:00:1f.2: Intel Corp. 82801BA/BAM USB (Hub #1)
PCI: Setting latency timer of device 0000:00:1f.2 to 64
uhci_hcd 0000:00:1f.2: irq 19, io base 0000b000
uhci_hcd 0000:00:1f.2: new USB bus registered, assigned bus number 1
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
ACPI: PCI interrupt 0000:00:1f.4[C] -> GSI 23 (level, low) -> IRQ 23
uhci_hcd 0000:00:1f.4: Intel Corp. 82801BA/BAM USB (Hub #2)
PCI: Setting latency timer of device 0000:00:1f.4 to 64
uhci_hcd 0000:00:1f.4: irq 23, io base 0000b800
uhci_hcd 0000:00:1f.4: new USB bus registered, assigned bus number 2
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 2 ports detected
EXT3 FS on hda2, internal journal
usb 1-2: new low speed USB device using address 2
usbcore: registered new driver hiddev
input: USB HID v1.00 Mouse [Microsoft Microsoft IntelliMouse� Explorer] on usb-0000:00:1f.2-2
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.0:USB HID core driver
Adding 262136k swap on /swap. Priority:-1 extents:67
kjournald starting. Commit interval 5 seconds
EXT3 FS on hda1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting. Commit interval 5 seconds
EXT3 FS on hdb1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
hdc: ATAPI 48X DVD-ROM drive, 256kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
hdd: ATAPI 40X CD-ROM CD-R/RW drive, 4096kB Cache, UDMA(33)
ip_tables: (C) 2000-2002 Netfilter core team
ip_tables: (C) 2000-2002 Netfilter core team
ACPI: PCI interrupt 0000:02:0c.0[A] -> GSI 20 (level, low) -> IRQ 20
3c59x: Donald Becker and others. www.scyld.com/network/vortex.html 0000:02:0c.0: 3Com PCI 3c905C Tornado at 0xa000. Vers LK1.1.19
ACPI: PCI interrupt 0000:02:0d.0[A] -> GSI 21 (level, low) -> IRQ 21 0000:02:0d.0: 3Com PCI 3c905C Tornado at 0xa400. Vers LK1.1.19
ip_tables: (C) 2000-2002 Netfilter core team
irq event 4: bogus return value ffffffff

 [<c0105b7e>] __report_bad_irq+0x24/0x7d
 [<c0105c3e>] note_interrupt+0x49/0x88
 [<c02bb3c2>] schedule+0x222/0x48d
 [<c0105f05>] do_hardirq+0x10f/0x191
 [<c0123cb5>] irqd+0x0/0xad
 [<c0123d55>] irqd+0xa0/0xad
 [<c0130010>] kthread+0x7c/0xa4
 [<c012ff94>] kthread+0x0/0xa4
 [<c0102249>] kernel_thread_helper+0x5/0xb
handlers:
irq event 3: bogus return value ffffffff
 [<c0105b7e>] __report_bad_irq+0x24/0x7d
 [<c0105c3e>] note_interrupt+0x49/0x88
 [<c02bb3c2>] schedule+0x222/0x48d
 [<c0105f05>] do_hardirq+0x10f/0x191
 [<c0123cb5>] irqd+0x0/0xad
 [<c0123d55>] irqd+0xa0/0xad
 [<c0130010>] kthread+0x7c/0xa4
 [<c012ff94>] kthread+0x0/0xa4
 [<c0102249>] kernel_thread_helper+0x5/0xb

handlers:
agpgart: Found an AGP 2.0 compliant device at 0000:00:00.0.
agpgart: Putting AGP V2 device at 0000:00:00.0 into 1x mode
agpgart: Putting AGP V2 device at 0000:01:01.0 into 1x mode

do you mean this one:

this isnt an oops, it is essentially just a warning. I am too getting this a couple of times during bootup when using the serial console.

irqd changes timings and apparently in this case the serial IRQ line gets deregistered for some amount of time while the hw still produces an interrupt. (it might also be an irqd bug, but all seems to be functional and i have no problems using the serial console.)

so unless you see some instability later on (or see a large flood of such messages), you can disregard this warning.

Ingo

L2 does not fix this problem. Previously, toggling CapsLock would trigger a single large XRUN. Now it seems to actually prevent the soundcard interrupt handler from executing in time, as well as triggering smaller XRUNs. This is with preempt=1, voluntary-preempt=3.

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:211: Unexpected hw_pointer value [1] (stream = 0, delta: -12, max jitter = 32): wrong interrupt acknowledge?

 [<c01066a7>] dump_stack+0x17/0x20
 [<de936497>] snd_pcm_period_elapsed+0x1c7/0x3e0 [snd_pcm]
 [<de956477>] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107c2f>] do_hardirq+0xaf/0x180
 [<c0113cbf>] cond_resched_softirq+0x4f/0x90
 [<c0211245>] atkbd_sendbyte+0x45/0x90
 [<c021144f>] atkbd_command+0x1bf/0x200
 [<c02115fb>] atkbd_event+0x16b/0x200
 [<c020e775>] input_event+0x115/0x3d0
 [<c01e7d9b>] kbd_bh+0xbb/0x160
 [<c011a7d4>] tasklet_action+0x44/0x70
 [<c011a593>] ___do_softirq+0x73/0x80
 [<c011a5e9>] _do_softirq+0x9/0x10
 [<c011a975>] irqd+0x75/0xc0
 [<c01284f4>] kthread+0xa4/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107c2f>] do_hardirq+0xaf/0x180
 [<c0113cbf>] cond_resched_softirq+0x4f/0x90
 [<c0211245>] atkbd_sendbyte+0x45/0x90
 [<c021144f>] atkbd_command+0x1bf/0x200
 [<c02115fb>] atkbd_event+0x16b/0x200
 [<c020e775>] input_event+0x115/0x3d0
 [<c01e7d9b>] kbd_bh+0xbb/0x160
 [<c011a7d4>] tasklet_action+0x44/0x70
 [<c011a593>] ___do_softirq+0x73/0x80
 [<c011a5e9>] _do_softirq+0x9/0x10
 [<c011a975>] irqd+0x75/0xc0
 [<c01284f4>] kthread+0xa4/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:211: Unexpected hw_pointer value [1] (stream = 0, delta: -7, max jitter = 32): wrong interrupt acknowledge?
 [<c01066a7>] dump_stack+0x17/0x20
 [<de936497>] snd_pcm_period_elapsed+0x1c7/0x3e0 [snd_pcm]
 [<de956477>] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107c2f>] do_hardirq+0xaf/0x180
 [<c011a99b>] irqd+0x9b/0xc0
 [<c01284f4>] kthread+0xa4/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10

Lee

yeah, this is because right now irqd lacks any configurability: it is executing all hardirqs (and all softirqs) in one context without any particular prioritization.

if your soundcard doesnt share the irq line with any other 'heavy' interrupt then you can make the irq 'direct' via a simple change to arch/i386/kernel/irq.c, change this line from:

#define redirectable_irq(irq) ((irq) != 0)

to:

#define redirectable_irq(irq) (((irq) != 0) && ((irq) != 10))

(if the soundcard is on IRQ 10).

does such a change combined with v=3 fix the latencies you are seeing?

Ingo

Testing with -L2 and the redirectable_irq change, the xruns triggered by the keyboard on 8.079 secs boundaries are still here (but the CAPS_LOCK one is gone since the the redirectable change). I ran some latency tests with vp:3 kp:0, progressively rising the rtc freqency (2048, 4096), and I realized that those latency spikes every 8.079 seconds are here even if I don't touch the keyboard. Here's the typical showtrace output for those spikes :

T=1.14231 diff=0.978288
rtc_interrupt (+bd)
handle_IRQ_event (+50)
do_hardirq (+bc)
irqd (+ac)
kthread (+aa)
irqd (+0)
kthread (+0)
kernel_thread_helper (+5)

The pattern is very similar to the previous one I reported on those regular xruns :

XRUN: pcmC2D0c

 [<c0105f6e>] dump_stack+0x1e/0x30
 [<c03673b1>] snd_pcm_period_elapsed+0x2e1/0x420
 [<c039d3d4>] snd_hdsp_interrupt+0x174/0x180
 [<c01073bb>] handle_IRQ_event+0x3b/0x70
 [<c0107746>] do_IRQ+0x96/0x150
 [<c0105b14>] common_interrupt+0x18/0x20
 [<c0107746>] do_IRQ+0x96/0x150
 [<c0105b14>] common_interrupt+0x18/0x20
 [<c01030f4>] cpu_idle+0x34/0x40
 [<c054880d>] start_kernel+0x16d/0x190
 [<c010019f>] 0xc010019f

The other source of xrun was seen during the disk write tests, once the memory runs out (spikes up to 14 ms, but more generally 6 ms)

Thomas

which particular filesystem and disk driver are you using? (ext3/IDE?) The 'disk write tests' are those of latencytest-0.5.4?

Ingo

It's an IDE reiserfs disk.
Those are indeed the disk write tests from latencytest-0.5.4 My mistake about the spikes, they are more 3 ms than 6. You can see the results here :
http://www.undata.org/~thomas/latencytest-0.5.4/rtc_freq_2048/
http://www.undata.org/~thomas/latencytest-0.5.4/rtc_freq_4096/
http://www.undata.org/~thomas/latencytest-0.5.4/rtc_freq_8192/

The traces always look the same :

T=29.6014 diff=14.4758
rtc_interrupt (+bd)
handle_IRQ_event (+50)
do_hardirq (+bc)
irqd (+ac)
kthread (+aa)
irqd (+0)
kthread (+0)
kernel_thread_helper (+5)

Thomas

This fixes the PS/2 problem, but running iozone still produces these (very small, ~0.1ms) XRUNs:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c

 [<c01066a7>] dump_stack+0x17/0x20
 [<de93d54b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de979211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078d7>] handle_IRQ_event+0x47/0x90
 [<c0107e93>] do_IRQ+0xe3/0x1b0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c020793c>] ide_dma_intr+0x7c/0xa0
 [<c02014a9>] ide_intr+0xf9/0x1a0
 [<c01078d7>] handle_IRQ_event+0x47/0x90
 [<c0107c3f>] do_hardirq+0xaf/0x180
 [<c011a9bb>] irqd+0x9b/0xc0
 [<c0128514>] kthread+0xa4/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10

This is with the default max_sectors_kb of 1024. If I turn this down to 512, I do not get these, but I did get this one, only once:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c

 [<c01066a7>] dump_stack+0x17/0x20
 [<de93d54b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de979211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078d7>] handle_IRQ_event+0x47/0x90
 [<c0107e93>] do_IRQ+0xe3/0x1b0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0262957>] schedule+0x2c7/0x580
 [<c02630d7>] schedule_timeout+0x57/0xa0
 [<c015df61>] do_poll+0xa1/0xc0
 [<c015e0b1>] sys_poll+0x131/0x220
 [<c0106047>] syscall_call+0x7/0xb

If I turn max_sectors_kb down to 256, I do not get any XRUNs at all, and the maximum delay reported by running JACK for 5 minutes (several million soundcard IRQs) is only 42 usecs! Previously, with 1:2, I could only get this down to ~120 usecs, and this required setting max_sectors_kb to 32-64. Going any lower than this did not reduce latency any more, it seems like some other code path is responsible.

I am not seeing the latency spikes at ~8 second intervals that Thomas reported. Could this be a bug in latencytest?

Lee

With L2, 1:3, max_sectors_kb=256, and the above change, the performance is truly amazing. Over 20 million interrupts, on a 600Mhz machine, the worst latency I was able to trigger was 46 usecs. There does not seem to be any adverse affect on any aspect of the system.

This looks like the perfect setup for a DAW.

Lee

And as a musician into the notion of owning tons of pro-audio gear (I don't at this time), I encourage you and the ALSA folks to go with it. :)

bill

Here are some more results. I am up to 56 million interrupts and I have yet to trigger a latency higher than 46 usecs. It looks like this is a hard upper limit.

I did get a couple XRUNs, some of which I have never seen before. One seemed to be caused by apt-get update/upgrade or exiting dselect.

The 'rtc: lost some interrupts' message is also new. I believe mplayer is using the RTC for timing.

Jul 28 20:23:17 mindpipe kernel: rtc: lost some interrupts at 1024Hz.
Jul 28 20:23:40 mindpipe kernel: rtc: lost some interrupts at 1024Hz.
Jul 28 20:23:54 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
Jul 28 20:23:54 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 28 20:23:54 mindpipe kernel:  [__crc_totalram_pages+29841/2369476] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
Jul 28 20:23:54 mindpipe kernel:  [__crc_totalram_pages+274775/2369476] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 28 20:23:54 mindpipe kernel:  [handle_IRQ_event+71/144] handle_IRQ_event+0x47/0x90
Jul 28 20:23:54 mindpipe kernel:  [do_IRQ+227/432] do_IRQ+0xe3/0x1b0
Jul 28 20:23:54 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 28 20:23:54 mindpipe kernel:  [set_page_dirty+70/96] set_page_dirty+0x46/0x60
Jul 28 20:23:54 mindpipe kernel:  [filemap_sync_pte+92/112] filemap_sync_pte+0x5c/0x70
Jul 28 20:23:54 mindpipe kernel:  [filemap_sync_pte_range+159/192] filemap_sync_pte_range+0x9f/0xc0
Jul 28 20:23:54 mindpipe kernel:  [filemap_sync+144/272] filemap_sync+0x90/0x110
Jul 28 20:23:54 mindpipe kernel:  [msync_interval+75/224] msync_interval+0x4b/0xe0
Jul 28 20:23:54 mindpipe kernel:  [sys_msync+292/310] sys_msync+0x124/0x136
Jul 28 20:23:54 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 28 20:30:24 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
Jul 28 20:30:24 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 28 20:30:24 mindpipe kernel:  [__crc_totalram_pages+29841/2369476] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
Jul 28 20:30:24 mindpipe kernel:  [__crc_totalram_pages+274775/2369476] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 28 20:30:24 mindpipe kernel:  [handle_IRQ_event+71/144] handle_IRQ_event+0x47/0x90
Jul 28 20:30:24 mindpipe kernel:  [do_IRQ+227/432] do_IRQ+0xe3/0x1b0
Jul 28 20:30:24 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 28 20:30:26 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
Jul 28 20:30:26 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 28 20:30:26 mindpipe kernel:  [__crc_totalram_pages+29841/2369476] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
Jul 28 20:30:26 mindpipe kernel:  [__crc_totalram_pages+274775/2369476] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 28 20:30:26 mindpipe kernel:  [handle_IRQ_event+71/144] handle_IRQ_event+0x47/0x90
Jul 28 20:30:26 mindpipe kernel:  [do_IRQ+227/432] do_IRQ+0xe3/0x1b0
Jul 28 20:30:26 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 28 20:30:26 mindpipe kernel:  [do_anonymous_page+124/384] do_anonymous_page+0x7c/0x180
Jul 28 20:30:26 mindpipe kernel:  [do_no_page+78/784] do_no_page+0x4e/0x310
Jul 28 20:30:26 mindpipe kernel:  [handle_mm_fault+193/368] handle_mm_fault+0xc1/0x170
Jul 28 20:30:26 mindpipe kernel:  [get_user_pages+258/880] get_user_pages+0x102/0x370
Jul 28 20:30:26 mindpipe kernel:  [make_pages_present+104/144] make_pages_present+0x68/0x90
Jul 28 20:30:26 mindpipe kernel:  [do_mmap_pgoff+998/1568] do_mmap_pgoff+0x3e6/0x620
Jul 28 20:30:26 mindpipe kernel:  [sys_mmap2+118/176] sys_mmap2+0x76/0xb0
Jul 28 20:30:26 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 28 20:32:18 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
Jul 28 20:32:18 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 28 20:32:18 mindpipe kernel:  [__crc_totalram_pages+29841/2369476] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
Jul 28 20:32:18 mindpipe kernel:  [__crc_totalram_pages+274775/2369476] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 28 20:32:18 mindpipe kernel:  [handle_IRQ_event+71/144] handle_IRQ_event+0x47/0x90
Jul 28 20:32:18 mindpipe kernel:  [do_IRQ+227/432] do_IRQ+0xe3/0x1b0
Jul 28 20:32:18 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 28 20:32:18 mindpipe kernel:  [set_page_dirty+70/96] set_page_dirty+0x46/0x60
Jul 28 20:32:18 mindpipe kernel:  [filemap_sync_pte+92/112] filemap_sync_pte+0x5c/0x70
Jul 28 20:32:18 mindpipe kernel:  [filemap_sync_pte_range+159/192] filemap_sync_pte_range+0x9f/0xc0
Jul 28 20:32:18 mindpipe kernel:  [filemap_sync+144/272] filemap_sync+0x90/0x110
Jul 28 20:32:18 mindpipe kernel:  [msync_interval+75/224] msync_interval+0x4b/0xe0
Jul 28 20:32:18 mindpipe kernel:  [sys_msync+292/310] sys_msync+0x124/0x136
Jul 28 20:32:18 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb

Lee

I have also found that if I stress the VM subsystem severely using sysbench --threads=128 --test=memory, jackd will not start, eventually its watchdog thread will kill it before it opens the audio ports. It seems likely that under pressure the mlockall() would never return. I can add some debugging code to jackd if you need to see which system call is timing out.

Lee

nice - what is the average (and minimum?) latency reported by jackd? I'd say 46 usecs on a 600 MHz box is quite close to what it takes to handle an interrupt and schedule to the cache-cold jackd task. It should definitely be well below the latency required for jackd to do its job reliably.

Ingo

Yes, I am quite impressed with these results. The jitter is about 5-10% of the total available time at the very lowest latency settings. This is an order of magnitude better than 2.4 + ll. It went as high as 50 usecs, but this took about 100 million interrupts. I have not hacked jackd yet to keep track of the average and minimum value, but eyeballing it I would say 7-8 usecs is the minimum and 25-30 the average. The distribution seems very normal.

I am going to try making the RTC irq non-redirectable as well, as I got a few 'rtc: lost some interrupts at 1024 Hz' messages, and the RTC is important for MIDI timing.

Other than the few outliers I reported earlier, this is very close to being ready for general pro audio use. I did notice that the msync() XRUN can be reliably reproduced by 'apt-get update && apt-get upgrade'.

I think I can speak on behalf of all Linux audio users when I say:
thanks a million, to all kernel developers.

Lee

The Caps Lock problem goes away with voluntary-preempt=2. It makes sense that 3 would be problematic, as for audio work you don't want the soundcard interrupt redirected.

The obvious next feature to add would be to make certain IRQs non-schedulable, like you would for an RT system. For an audio system this would be just the soundcard interrupt (and timer as stated above). Then, while it still might not be hard-RT, it would blow away anything achievable on the other OS'es people do audio work with.

Lee

yes, this is the next step. Does v=3 work on your system? (even if the delaying of the soundcard irq causes latencies.)

Ingo

Yes, it works well, except for this behavior which is as expected. I will test making this interrupt 'direct' tomorrow, it is not shared with anything too heavy.

Lee

Much better. With 2:1 Bonnie produced a single XRUN:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c

 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c01413ef>] filemap_sync_pte_range+0x9f/0xc0
 [<c01414a0>] filemap_sync+0x90/0x110
 [<c014156b>] msync_interval+0x4b/0xe0
 [<c0141724>] sys_msync+0x124/0x136
 [<c0106047>] syscall_call+0x7/0xb

And the mlockall/mmap2 problem is not completely solved. Starting a jackd while another is running still produces XRUNs:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D0p

 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956477>] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c013d89e>] do_no_page+0x4e/0x310
 [<c013dd21>] handle_mm_fault+0xc1/0x170
 [<c013c712>] get_user_pages+0x102/0x370
 [<c013de68>] make_pages_present+0x68/0x90
 [<c013f5d6>] do_mmap_pgoff+0x3e6/0x620
 [<c010be66>] sys_mmap2+0x76/0xb0
 [<c0106047>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D0p
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956477>] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c013de68>] make_pages_present+0x68/0x90
 [<c013e2bd>] mlock_fixup+0x8d/0xb0
 [<c013e5a0>] do_mlockall+0x70/0x90
 [<c013e659>] sys_mlockall+0x99/0xa0
 [<c0106047>] syscall_call+0x7/0xb

Works great otherwise.

Lee

Actually the following seems to be working on my laptop and I was thinking about pushing it to Vojtech. Any reason why this should not be done?

(The patch is on top of Vojtech's tee + my other changes so it won't apply to anything.)

===== drivers/input/keyboard/atkbd.c 1.66 vs edited =====

@@ -209,10 +209,25 @@
 	unsigned int last;
 	unsigned long time;
 
+	/* Ensures that only one command is executing at a time */
+	struct semaphore cmd_sem;
+
+	/* Used to signal completion from interrupt handler */
+	wait_queue_head_t wait;
+
 	/* Flags */
 	unsigned long flags;
 };
 
+/* Work structure to schedule execution of a command */
+struct atkbd_work {
+	struct work_struct work;
+	struct atkbd *atkbd;
+	int command;
+	unsigned char param[0];
+};
+
+
 static void atkbd_report_key(struct input_dev *dev, struct pt_regs *regs, int code, int value)
 {
 	input_regs(dev, regs);

@@ -262,10 +277,12 @@
 					set_bit(ATKBD_FLAG_CMD1, &atkbd->flags);
 				}
 				clear_bit(ATKBD_FLAG_ACK, &atkbd->flags);
+				wake_up_interruptible(&atkbd->wait);
 				break;
 			case ATKBD_RET_NAK:
 				atkbd->nak = 1;
 				clear_bit(ATKBD_FLAG_ACK, &atkbd->flags);
+				wake_up_interruptible(&atkbd->wait);
 				break;
 		}
 		goto out;

@@ -276,10 +293,13 @@
 		if (atkbd->cmdcnt)
 			atkbd->cmdbuf[--atkbd->cmdcnt] = code;
 
-		clear_bit(ATKBD_FLAG_CMD1, &atkbd->flags);
-		if (!atkbd->cmdcnt)
-			clear_bit(ATKBD_FLAG_CMD, &atkbd->flags);
+		if (test_and_clear_bit(ATKBD_FLAG_CMD1, &atkbd->flags) && atkbd->cmdcnt)
+			wake_up_interruptible(&atkbd->wait);
 
+		if (!atkbd->cmdcnt) {
+			clear_bit(ATKBD_FLAG_CMD, &atkbd->flags);
+			wake_up_interruptible(&atkbd->wait);
+		}
 		goto out;
 	}
 

@@ -412,12 +432,12 @@
  * acknowledge. It doesn't handle resends according to the keyboard
  * protocol specs, because if these are needed, the keyboard needs
  * replacement anyway, and they only make a mess in the protocol.
+ *
+ * atkbd_sendbyte() can only be called from a process context
  */
 
 static int atkbd_sendbyte(struct atkbd *atkbd, unsigned char byte)
 {
-	int timeout = 200000; /* 200 msec */
-
 #ifdef ATKBD_DEBUG
 	printk(KERN_DEBUG "atkbd.c: Sent: %02x\n", byte);
 #endif

@@ -425,8 +445,9 @@
 	set_bit(ATKBD_FLAG_ACK, &atkbd->flags);
 
 	if (serio_write(atkbd->serio, byte) == 0)
-		while (test_bit(ATKBD_FLAG_ACK, &atkbd->flags) && timeout--)
-			udelay(1);
+		wait_event_interruptible_timeout(atkbd->wait,
+				!test_bit(ATKBD_FLAG_ACK, &atkbd->flags),
+				msecs_to_jiffies(200));
 
 	clear_bit(ATKBD_FLAG_ACK, &atkbd->flags);
 	return -atkbd->nak;

@@ -435,19 +456,21 @@
 /*
  * atkbd_command() sends a command, and its parameters to the keyboard,
  * then waits for the response and puts it in the param array.
+ *
+ * atkbd_command() can only be called from a process context
  */
 
 static int atkbd_command(struct atkbd *atkbd, unsigned char *param, int command)
 {
-	int timeout = 500000; /* 500 msec */
+	int timeout;
 	int send = (command >> 12) & 0xf;
 	int receive = (command >> 8) & 0xf;
 	int rc = -1;
 	int i;
 
-	if (command == ATKBD_CMD_RESET_BAT)
-		timeout = 4000000; /* 4 sec */
+	timeout = msecs_to_jiffies(command == ATKBD_CMD_RESET_BAT ? 4000 : 500);
 
+	down(&atkbd->cmd_sem);
 	clear_bit(ATKBD_FLAG_CMD, &atkbd->flags);
 
 	if (receive && param)

@@ -464,27 +487,26 @@
 		if (atkbd_sendbyte(atkbd, param[i]))
 			goto out;
 
-	while (test_bit(ATKBD_FLAG_CMD, &atkbd->flags) && timeout--) {
-
-		if (!test_bit(ATKBD_FLAG_CMD1, &atkbd->flags)) {
-
-			if (command == ATKBD_CMD_RESET_BAT && timeout > 100000)
-				timeout = 100000;
+	timeout = wait_event_interruptible_timeout(atkbd->wait,
+				!test_bit(ATKBD_FLAG_CMD1, &atkbd->flags), timeout);
 
-			if (command == ATKBD_CMD_GETID &&
-			    atkbd->cmdbuf[receive - 1] != 0xab && atkbd->cmdbuf[receive - 1] != 0xac) {
-				/*
-				 * Device behind the port is not a keyboard
-				 * so we don't need to wait for the 2nd byte
-				 * of ID response.
-				 */
-				clear_bit(ATKBD_FLAG_CMD, &atkbd->flags);
-				atkbd->cmdcnt = 0;
-				break;
-			}
+	if (atkbd->cmdcnt && timeout > 0) {
+		if (command == ATKBD_CMD_RESET_BAT && jiffies_to_msecs(timeout) > 100)
+			timeout = msecs_to_jiffies(100);
+
+		if (command == ATKBD_CMD_GETID &&
+		    atkbd->cmdbuf[receive - 1] != 0xab && atkbd->cmdbuf[receive - 1] != 0xac) {
+			/*
+			 * Device behind the port is not a keyboard
+			 * so we don't need to wait for the 2nd byte
+			 * of ID response.
+			 */
+			clear_bit(ATKBD_FLAG_CMD, &atkbd->flags);
+			atkbd->cmdcnt = 0;
 		}
 
-		udelay(1);
+		wait_event_interruptible_timeout(atkbd->wait,
+				!test_bit(ATKBD_FLAG_CMD, &atkbd->flags), timeout);
 	}
 
 	if (param)

@@ -499,11 +521,59 @@
 out:
 	clear_bit(ATKBD_FLAG_CMD, &atkbd->flags);
 	clear_bit(ATKBD_FLAG_CMD1, &atkbd->flags);
+	up(&atkbd->cmd_sem);
 
 	return rc;
 }
 
 /*
+ * atkbd_execute_scheduled_command() sends a command, previously scheduled by
+ * atkbd_schedule_command(), to the keyboard.
+ */
+
+static void atkbd_execute_scheduled_command(void *data)
+{
+	struct atkbd_work *atkbd_work = data;
+
+	atkbd_command(atkbd_work->atkbd, atkbd_work->param, atkbd_work->command);
+
+	kfree(atkbd_work);
+}
+
+/*
+ * atkbd_schedule_command() allows to schedule delayed execution of a keyboard
+ * command and can be used to issue a command from an interrupt or softirq
+ * context.
+ */
+
+static int atkbd_schedule_command(struct atkbd *atkbd, unsigned char *param, int command)
+{
+	struct atkbd_work *atkbd_work;
+	int send = (command >> 12) & 0xf;
+	int receive = (command >> 8) & 0xf;
+
+	if (!test_bit(ATKBD_FLAG_ENABLED, &atkbd->flags))
+		return -1;
+
+	if (!(atkbd_work = kmalloc(sizeof(struct atkbd_work) + max(send, receive), GFP_ATOMIC)))
+		return -1;
+
+	memset(atkbd_work, 0, sizeof(struct atkbd_work));
+	atkbd_work->atkbd = atkbd;
+	atkbd_work->command = command;
+	memcpy(atkbd_work->param, param, send);
+	INIT_WORK(&atkbd_work->work, atkbd_execute_scheduled_command, atkbd_work);
+
+	if (!schedule_work(&atkbd_work->work)) {
+		kfree(atkbd_work);
+		return -1;
+	}
+
+	return 0;
+}
+
+
+/*
  * Event callback from the input module. Events that change the state of
  * the hardware are processed here.
  */

@@ -529,7 +599,7 @@
 			param[0] = (test_bit(LED_SCROLLL, dev->led) ? 1 : 0)
 			         | (test_bit(LED_NUML,    dev->led) ? 2 : 0)
 			         | (test_bit(LED_CAPSL,   dev->led) ? 4 : 0);
-		        atkbd_command(atkbd, param, ATKBD_CMD_SETLEDS);
+		        atkbd_schedule_command(atkbd, param, ATKBD_CMD_SETLEDS);
 
 			if (atkbd->extra) {
 				param[0] = 0;

@@ -538,7 +608,7 @@
 					 | (test_bit(LED_SUSPEND, dev->led) ? 0x04 : 0)
 				         | (test_bit(LED_MISC,    dev->led) ? 0x10 : 0)
 				         | (test_bit(LED_MUTE,    dev->led) ? 0x20 : 0);
-				atkbd_command(atkbd, param, ATKBD_CMD_EX_SETLEDS);
+				atkbd_schedule_command(atkbd, param, ATKBD_CMD_EX_SETLEDS);
 			}
 
 			return 0;

@@ -554,7 +624,7 @@
 			dev->rep[REP_PERIOD] = period[i];
 			dev->rep[REP_DELAY] = delay[j];
 			param[0] = i | (j << 5);
-			atkbd_command(atkbd, param, ATKBD_CMD_SETREP);
+			atkbd_schedule_command(atkbd, param, ATKBD_CMD_SETREP);
 
 			return 0;
 	}

@@ -726,7 +796,11 @@
 static void atkbd_disconnect(struct serio *serio)
 {
 	struct atkbd *atkbd = serio->private;
+
 	clear_bit(ATKBD_FLAG_ENABLED, &atkbd->flags);
+	synchronize_kernel();
+	flush_scheduled_work();
+
 	input_unregister_device(&atkbd->dev);
 	serio_close(serio);
 	kfree(atkbd);

@@ -747,6 +821,9 @@
 	if (!(atkbd = kmalloc(sizeof(struct atkbd), GFP_KERNEL)))
 		return;
 	memset(atkbd, 0, sizeof(struct atkbd));
+
+	init_MUTEX(&atkbd->cmd_sem);
+	init_waitqueue_head(&atkbd->wait);
 
 	switch (serio->type & SERIO_TYPE) {
 

your solution of pushing completion work into a workqueue is of course the right approach! My change was just papering over this artificial softirq latency. Please push it to Vojtech ASAP.

Ingo

Some more results:

I can no longer trigger XRUNs with bonnie, so I switched to iozone. Here is what I got:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c

 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c015deff>] do_poll+0x5f/0xc0
 [<c015e091>] sys_poll+0x131/0x220
 [<c0106047>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a197>] shrink_caches+0x57/0x60
 [<c013a238>] try_to_free_pages+0x98/0x170
 [<c0132707>] __alloc_pages+0x137/0x340
 [<c01302c5>] generic_file_aio_write_nolock+0x355/0xb80
 [<c0130bd2>] generic_file_aio_write+0x62/0x90
 [<c01a9458>] ext3_file_write+0x28/0xc0
 [<c014b01a>] do_sync_write+0x6a/0xa0
 [<c014b10c>] vfs_write+0xbc/0x110
 [<c014b1de>] sys_write+0x2e/0x50
 [<c0106047>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a197>] shrink_caches+0x57/0x60
 [<c013a238>] try_to_free_pages+0x98/0x170
 [<c0132707>] __alloc_pages+0x137/0x340
 [<c01302c5>] generic_file_aio_write_nolock+0x355/0xb80
 [<c0130bd2>] generic_file_aio_write+0x62/0x90
 [<c01a9458>] ext3_file_write+0x28/0xc0
 [<c014b01a>] do_sync_write+0x6a/0xa0
 [<c014b10c>] vfs_write+0xbc/0x110
 [<c014b1de>] sys_write+0x2e/0x50
 [<c0106047>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a197>] shrink_caches+0x57/0x60
 [<c013a238>] try_to_free_pages+0x98/0x170
 [<c0132707>] __alloc_pages+0x137/0x340
 [<c01302c5>] generic_file_aio_write_nolock+0x355/0xb80
 [<c0130bd2>] generic_file_aio_write+0x62/0x90
 [<c01a9458>] ext3_file_write+0x28/0xc0
 [<c014b01a>] do_sync_write+0x6a/0xa0
 [<c014b10c>] vfs_write+0xbc/0x110
 [<c014b1de>] sys_write+0x2e/0x50
 [<c0106047>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c01066a7>] dump_stack+0x17/0x20
 [<de93654b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de956211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c8>] handle_IRQ_event+0x38/0x80
 [<c0107e5d>] do_IRQ+0xbd/0x1a0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146751>] add_to_swap+0x21/0xc0
 [<c0139426>] shrink_list+0x156/0x4b0
 [<c01398cd>] shrink_cache+0x14d/0x370
 [<c013a0f8>] shrink_zone+0xa8/0xf0
 [<c013a4ce>] balance_pgdat+0x1be/0x220
 [<c013a5d9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10

Lee

i've uploaded the latest version of the voluntary-preempt patch:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc2-M5

the biggest change is that i've integrated the irq threads code from Scott Wood. I've done a number of usability enhancements:

added a new mechanism for finegrained configuration of threadedness / nonthreadedness at the handler level: there are new:

/proc/irq/<N>/<handler>/threaded

entries that control this behavior. Writing 0 to such an entry makes that particular handler 'directly executed', writing 1 to it turns it back to be handled by its own IRQ kernel thread.

E.g. the following command changes the serial line interrupt back to non-threaded:

echo 0 > /proc/irq/*/serial/threaded

the IRQ threads show up at low PID numbers (typically between 100 and
200) and their RT priority can be set via the 'chrt' utility (part of schedutils). E.g. setting IRQ 10's irq thread priority back to the non-RT SCHED_OTHER class can be done via:

  chrt --other --pid 0 `pidof 'IRQ 10'`

and to change IRQ 4's thread to SCHED_FIFO and the highest RT priority:

  chrt --fifo --pid 99 `pidof 'IRQ 4'`

to get good audio latencies i'd suggest to set the the audio driver's and the RT-clock driver's IRQ handler to be non-threaded, and to set jackd's RT priority to higher than 50 (which is the default of the IRQ threads).

But it would also be interesting to see how the maximum latencies look like if both the RT-clock and the audio handlers are threaded, and the two affected IRQ threads are set to SCHED_FIFO 99 priority - they should preempt everything. The latency increase compared to the 'direct' setup should show us the real-life overhead of hardirq redirection.

the patch also changes the way the IDE latencies are avoided: based on suggestions from Jens the latency-critical portion of the driver is now done without holding ide_lock - and this makes the driver preemptable if the handler is running in a thread.

if booting with voluntary-preempt=2/0/1 (the default is 3) then all interrupts default to being non-threaded. Note that the /proc entries can be used to turn threadedness back on even in this case - this can be used to debug problematic drivers.

i made the irq-threads code work on SMP too: the IRQ threads now bind themselves according to the value of /proc/irq/<N>/smp_affinity and change the binding of that value is modified. IRQ threads only migrate when it's safe - there will be no migration to another CPU while executing a hardirq.

Ingo

After running jackd with L2 all night, the only repeated XRUN was this one:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c

 [<c01066a7>] dump_stack+0x17/0x20
 [<de93d54b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de979211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078d7>] handle_IRQ_event+0x47/0x90
 [<c0107e93>] do_IRQ+0xe3/0x1b0
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0146771>] add_to_swap+0x21/0xc0
 [<c0139446>] shrink_list+0x156/0x4b0
 [<c01398ed>] shrink_cache+0x14d/0x370
 [<c013a118>] shrink_zone+0xa8/0xf0
 [<c013a4ee>] balance_pgdat+0x1be/0x220
 [<c013a5f9>] kswapd+0xa9/0xb0
 [<c0104395>] kernel_thread_helper+0x5/0x10

This produced a few ~2ms XRUNs. The shrink_zone -> shrink_cache -> shrink_list is a recurring motif.

Is this addressed in M2?

Lee

not yet. I havent seen this latency yet, nor are there any immediately clear clues in the xrun logs you sent. (it would still be nice to check out -M2, to see whether with all those configurability changes it matches the latencies of L2+your-irq.c-hack.)

shrink_list() itself is preemptable once every iteration so that function alone shouldnt be able to generate a 2msec latency.

a strong suspect is add_to_swap(), it could be looping. Could you do a 'echo m > /proc/sysrq-trigger' and send me the results? In particular are there any significant 'race' counts in the 'Swap cache:' stats?

the other possible suspect is get_swap_page() - it's called from add_to_swap() and has the potential to introduce latencies (it does bitmap scans, etc.) - but it never shows up in your xrun logs, which is a bit weird.

(could you perhaps also try wli's latency printing patch? That prints out latencies closer to where they really happen.)

plus it seems the latency is related to certain VM activities - you still cannot name any particular reproducer workload - it just happens occasionally, right?

Ingo

I think iozone -a or one of the sysbench tests triggers this one. But it also happened a few times overnight. I will try to reproduce it today. You are referring to wli's 'preempt timing' patch, correct?

Also, I sent another report of XRUNS related to msync(). I have narrowed this down a bit. This one happens whenever 'apt-get update' replaces its package lists. Presumably it mmaps the files in /var/lib/apt/lists and then calls msync at the end to write them out, which triggers the XRUN.

Here are the results of 'echo m > /proc/sysrq-trigger':

SysRq : Show Memory
Mem-info:
DMA per-cpu:
cpu 0 hot: low 2, high 6, batch 1
cpu 0 cold: low 0, high 2, batch 1
Normal per-cpu:
cpu 0 hot: low 32, high 96, batch 16
cpu 0 cold: low 0, high 32, batch 16
HighMem per-cpu: empty

Free pages: 12064kB (0kB HighMem)
Active:70285 inactive:41081 dirty:24 writeback:0 unstable:0 free:3016 slab:5405 mapped:34481 pagetables:233 DMA free:3352kB min:20kB low:40kB high:60kB active:5288kB inactive:2128kB present:16384kB protections[]: 10 348 348
Normal free:8712kB min:676kB low:1352kB high:2028kB active:275852kB inactive:162196kB present:475072kB protections[]: 0 338 338
HighMem free:0kB min:128kB low:256kB high:384kB active:0kB inactive:0kB present:0kB protections[]: 0 0 0
DMA: 382*4kB 52*8kB 2*16kB 1*32kB 1*64kB 0*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 3352kB
Normal: 188*4kB 159*8kB 82*16kB 100*32kB 8*64kB 3*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 8712kB
HighMem: empty
Swap cache: add 3, delete 1, find 0/0, race 0+0
Free swap: 499916kB
122864 pages of RAM
0 pages of HIGHMEM
2054 reserved pages
96028 pages shared
2 pages swap cached

Looks like no significant races.

Lee

I discovered that a few of the XRUN traces were spurious - jackd apparently does something while stopping and starting that produces an XRUN trace but that jackd does not consider an error. I will fix this in jackd. The msync() related XRUN triggered by apt-get is definitely real.

Here are my results with 2.6.8-rc2-mm1-M5.

max usecs
All IRQs threaded 349
Soundcard IRQ not threaded 227
Soundcard IRQ not threaded + max_sectors_kb -> 64 119

I will test next with 2.6.8-rc2-M5.

Lee

Results with 2.6.8-rc2-M5:

Configuration max usecs
-----------------------------------------------------------------
All IRQs threaded 370
Soundcard IRQ not threaded 335
Soundcard IRQ not threaded + max_sectors_kb -> 64 161

So, it looks like the added configurability does add some overhead - 161 usecs vs. 50. mm1 is significantly better than the stock kernel. The above results imply that 2.6.8-rc2-mm1 with the irq.c hack would be frighteningly good.

Lee

+110 usecs is too much to be explained by redirection and configurability overhead. The configurability overhead is near zero.

could you try to repeat the '50 usecs' test with -L2 [that was the one you used?] to make sure it's repeatable? The latencies of -L2 and -M5 should be near identical. The configurability should at most cause a 1-2 usecs overhead - definitely not two orders of magnitude higher. So if there's a difference then i must have degraded one of the latency reduction changes between L2 and M5.

Ingo

The above numbers really do not tell you much, I have some better ones. Here is the histogram for a 5,000,000 sample run with M5:

Delay Count

-----   -----
6       98189
7       2013275
8       51025
9       120465
10      93339
11      72087
12      116165
13      106433
14      85930
15      57178
16      59835
17      51096
18      71671
19      106738
20      109491
21      84906
22      2215
23      946
24      1755
25      1977
26      1589
27      1117
28      1889
29      1616
30      1858
31      2926
32      3111
33      2558
34      400
35      1366
36      2172
37      2840
38      1088
39      1042
40      172
41      26
42      32
43      43
44      41
45      10
46      8
47      36
48      109
49      125
50      83
51      45
52      36
53      7
55      1
56      1
58      1
61      1
62      1
68      1
75      1
77      1
79      1
89      1
97      1

So if you discard the highest ~10 of 5,000,000, it's the same as L2. Maybe a corner case, or a new race condition? I will run the above test with L2.

I wonder if the multiple spikes represent different code paths, or the same but with a hot/warm/cold cache?

Lee

Results with L2, soundcard + RTC interrupts 'direct', N=1,000,000:

Delay   Count
-----   -----
6       24330
7       429668
8       34474
9       26184
10      12210
11      9060
12      9104
13      8460
14      11011
15      13615
16      14584
17      13371
18      12169
19      10864
20      11936
21      7974
22      6256
23      4888
24      2385
25      640
26      164
27      113
28      86
29      105
30      90
31      86
32      103
33      140
34      149
35      183
36      160
37      141
38      147
39      146
40      172
41      140
42      131
43      89
44      54
45      10
46      3
47      2
49      3

It's as I expected - same as M5, minus the outliers. Any idea what caused these? I will try O2 next, I would expect it to be similar.

Lee

The above histogram was generated with normal desktop activity going on. Another run under the same conditions produced the same three "humps". Here are the results with an idle system:

Delay   Count
-----   -----
6       8460
7       481093
8       66311
9       43167
10      23021
11      5536
12      3883
13      3370
14      3635
15      3923
16      3419
17      2892
18      2615
19      2659
20      5239
21      3607
22      1289
23      662
24      237
25      59
26      28
27      15
28      17
29      24
30      29
31      50
32      65
33      34
34      34
35      23
36      29
37      19
38      25
39      36
40      42
41      22
42      18
43      8
44      5

The second hump centered at 20-21 usecs is still present, but smaller. The third hump centered at 31-32 is barely detectable, but present, repeating the test showed the same thing.

So the first hump is the fast path, interrupt -> scheduler -> jackd with the fewest possible context switches, and a hot or warm cache. The third would have to be the worst case scenario (relatively speaking), where we preempt another process in one of the longer common critical sections.

The second hump seems like either the same situation as the fast path, except with a cold cache, or where we have to preempt another process that is not in a critical section at all, or a short one.

If we have any suspects for the code paths involved, couldn't this be verified by adding a udelay(10) to the path, and verifying that the hump moves by 10? This technique could also be used to distinguish different code paths with similar execution times. It looks like they are finite and few in number.

At this point there are no latency problems I can see, all that remains is to understand the causes of the observed latencies. Then assuming any "direct-irq" drivers and anything you run SCHED_FIFO is realtime safe, what else remains to be done in order to make hard realtime guarantees?

Lee

Lee

i believe wli's latency-timing patch gives a pretty good indication of the code path(s) involved - i'm using something quite similar to that. The printout triggers immediately at the end of a high latency, so the stack contains a number of clues about what went on before.

what remains i believe is to improve wli's patch and to observe (and fix) the maximum latencies. Also, your workload is a subset of what other people might be running so wider testing is obviously needed as well.

btw., with what max_sectors setting were you testing during these tests? In -O2 the hardirqs are not preemptable (yet) so with 1024 sectors you should see quite high latencies due to the completion activity.

Ingo

256. It will be a few days before I can do any more testing.

Lee

Can you post this patch, or add it to the voluntary preempt series? The one posted several weeks ago worked for me but had to be applied manually and has probably been improved since.

Just to clarify the last numbers I posted were for O2.

Lee

i've uploaded the preempt-timing patch (relative to -O2):

http://redhat.com/~mingo/voluntary-preempt/preempt-timing-on-2.6.8-rc2-O2

QuickStart for those who havent used it yet: enable PREEMPT_TIMING in .config and add preempt_thresh=1000 [== 1000 usec threshold] to the kernel's boot options.

i changed the original patch to make it a bit more usable - the threshold can be changed runtime via /proc/sys/kernel/preempt_thresh, and the units are microseconds not milliseconds.

the timings should be pretty accurate in vp=0,1,2,3 modes as well.

Note that this patch only measures latencies of critical sections (preempt-off sections), not other latencies that occur when running !CONFIG_PREEMPT or with kernel_preemption=0.

Ingo

i've uploaded a new version of the patch, this solves a problem when using a smaller than 1000 usecs threshold: idle time got accounted as delay too which flooded the log. The new patch makes idle=poll the default and that function calls touch_preempt_timing().

Ingo

Sorry about not updating things, but there's also another bug, which is that touch_preempt_timing() forgets to check if the threshold has been violated in the interim.

-- wli

i've re-uploaded the -O2 patch with this fixed:

http://redhat.com/~mingo/voluntary-preempt/preempt-timing-on-2.6.8-rc2-O2

but i'm still seeing some latencies:

(kjournald/189): 997us non-preemptible critical section violated 100 us preempt threshold starting at journal_commit_transaction+0x642/0x2b10 and ending at journal_commit_transaction+0x24ce/0x2b10

  [<c0105d7e>] dump_stack+0x1e/0x30
  [<c011ad0f>] dec_preempt_count+0x3f/0x50
  [<c01dfd3e>] journal_commit_transaction+0x24ce/0x2b10
  [<c01e3bf4>] kjournald+0x1a4/0x710
  [<c0102765>] kernel_thread_helper+0x5/0x10

these should not happen with vp=3 and max_sectors=16. Could you double-check the patch above, does it have any other timing thinko?

Ingo

ok, found it - it's a false positive in commit.c due to need_resched() not doing a touch_preempt_timing(). Newest patch at:

http://redhat.com/~mingo/voluntary-preempt/preempt-timing-on-2.6.8-rc2-O2

i changed need_resched() to do a touch_preempt_timing() - this also got rid of some other changes. All code i checked really takes need_resched() seriously if it looks at it - any reason why you didnt add this to need_resched() before?

Ingo

Great, thanks for fixing this up.

I was less sure of this as I hadn't audited need_resched() callers to be sure they did cond_resched() or similar. As you've carried out the audit of need_resched() callers, you have the certainty I didn't.

-- wli

I get a *lot* of these:

(swapper/0): 996us non-preemptible critical section violated 100 us preempt threshold starting at schedule+0x55/0x5a0 and ending at

do_IRQ+0x110/0x180
 [<c0106717>] dump_stack+0x17/0x20
 [<c0113eec>] dec_preempt_count+0x3c/0x50
 [<c0107a20>] do_IRQ+0x110/0x180
 [<c01062d8>] common_interrupt+0x18/0x20
 [<c0104222>] cpu_idle+0x32/0x50
 [<c030a782>] start_kernel+0x1a2/0x1f0
 [<c010019f>] 0xc010019f

This has to be a false positive, because if there were really ~1ms non-preemptible critical sections all over the place I would be getting xruns.

Lee

This seems to be 996us spent in do_IRQ() when it interrupts idle tasks.

-- wli

I am not sure I understand how preemption can be disabled for 996us and not cause an xrun.

Lee

You were idling at the time, so the latency affected nothing, except perhaps task migration on SMP.

-- wli

Would it be possible to detect this situation and treat it like a preemptible section, just so the sheer volume of printks does not cause a problem?

Lee

It's probably actually a false positive. What I was explaining was why, if it were in fact a non-preemptible critical section, it wouldn't cause xruns.

-- wli

These two seem to be real. It looks like get_user_pages is still problematic in 2.6.8-rc2.

(jackd/6219): 10943us non-preemptible critical section violated 1000 us preempt threshold starting at kmap_atomic+0x10/0x60 and ending at kunmap_atomic+0x8/0x20

 [<c0106717>] dump_stack+0x17/0x20
 [<c0113eec>] dec_preempt_count+0x3c/0x50
 [<c0111ce8>] kunmap_atomic+0x8/0x20
 [<c013e2cb>] do_anonymous_page+0x8b/0x190
 [<c013e41e>] do_no_page+0x4e/0x310
 [<c013e8a1>] handle_mm_fault+0xc1/0x170
 [<c013d280>] get_user_pages+0x110/0x380
 [<c013e9f8>] make_pages_present+0x68/0x90
 [<c0140196>] do_mmap_pgoff+0x3e6/0x620
 [<c010b656>] sys_mmap2+0x76/0xb0
 [<c01060b7>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c0106717>] dump_stack+0x17/0x20
 [<de93d64b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de9791d1>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c011a7d3>] generic_handle_IRQ_event+0x33/0x60
 [<c01079c2>] do_IRQ+0xb2/0x180
 [<c01062d8>] common_interrupt+0x18/0x20
 [<c0113e18>] __touch_preempt_timing+0x8/0x20
 [<c0113ea2>] inc_preempt_count+0x32/0x40
 [<c014cb8e>] fget+0x1e/0x60
 [<c015ecdd>] do_pollfd+0x2d/0xa0
 [<c015edaf>] do_poll+0x5f/0xc0
 [<c015ef41>] sys_poll+0x131/0x220
 [<c01060b7>] syscall_call+0x7/0xb
(gnome-terminal/914): 10738us non-preemptible critical section violated 1000 us preempt threshold starting at fget+0x1e/0x60 and ending at fget+0x3d/0x60
 [<c0106717>] dump_stack+0x17/0x20
 [<c0113eec>] dec_preempt_count+0x3c/0x50
 [<c014cbad>] fget+0x3d/0x60
 [<c015ecdd>] do_pollfd+0x2d/0xa0
 [<c015edaf>] do_poll+0x5f/0xc0
 [<c015ef41>] sys_poll+0x131/0x220
 [<c01060b7>] syscall_call+0x7/0xb

Lee

The false negative I mentioned was the last unresolved issue I knew of. A brief examination of your updated patch didn't help me to spot any false positives that haven't been reported yet.

It may help to find the line numbers corresponding to the above (actually, the way the macros are hooked, the files, functions, line numbers could be reported directly by the implementation) so we can get a better idea if this is a false positive or a real 997us long non- preemptible critical section.

-- wli

At Fri, 30 Jul 2004 18:54:39 -0400,

Yes. There is a bogus report at stopping (snd_pcm_drain is called). It was fixed in the recent ALSA cvs tree, but seems not propagated to bk yet...

Takashi

It also seems to produce an xrun at startup. This is with the latest ALSA CVS. Is this behavior by design?

Lee

Hi,

(sorry for late reply, just back from vacation)

At Fri, 06 Aug 2004 22:54:26 -0400,

No, this is not. It should be a real XRUN, I believe.

Takashi

This one has still defied explanation. The working theory was that it was the same bug causing an xrun if an unrelated process called mlockall, but now that bug has been fixed, and this xrun at startup still happens.

Lee

does the first xrun happen right during startup, or only when the first jack application uses jackd to do audio?

if the former then does jackd set itself up (does an mlockall, etc.) before it opens the audio device? If the audio device has an event for jackd the moment the device is opened, and jackd opens the audio device early during startup, then jackd might not be able to process this event until it has started up (which can take milliseconds).

Ingo

It happens when the jackd server starts up, before any clients connect.

This is probably what is happening, the kernel-side issue seems fixed, but I will have to test some more and look at the source tomorrow, it's getting late.

Lee

It looks like this is what happens - jackd calls snd_pcm_start, then does several other thinks like malloc'ing memory for the array of fd's to poll() before entering the polling loop, by which time there has been data ready for a while. This may or may not be worth fixing, I am adding jackit-devel to the cc: list.

Lee

Yep. This looks like a bug to me. While jackd, itself, seems to allocate everything before calling driver->start(), the ALSA driver internally calls malloc() *after* calling snd_pcm_start(). I doubt anyone has ever made a concerted effort to clean up this path for realtime safety.

I think it should be fixed (I need to study the code in more detail). There's probably nothing to prevent us moving the free() and malloc() calls up nearer the top of alsa_driver_start(). That will probably require an extra error test and free in case snd_pcm_start() fails.

  joq

I made this change and it seems to work fine, snd_pcm_start is now the very last thing that happens in alsa_driver_start, and we free() if snd_pcm_start fails.

I still get the xruns at startup, but they were ~100ms before, now they are more like 20ms. Unfortunately the OO-ness of the code makes it hard for me to figure out where alsa_driver_start gets called from, so I'm not sure what else happens before we enter the polling loop.

Lee

Upon popular request i've merged the latest voluntary-preempt patch to the latest -mm kernel:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc2-mm1-M5

Ingo

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc2-mm1-M5

Works fairly nicely for me (nice job!), except the mouse does not work in both console (gpm) and X. This is on a thinkpad T21, 2.6.8-rc2-mm2 with the M5 patch. Doing 'echo 0 > /proc/irq/{1|12}/i8042/threaded' does not work. This trivial workaround fixes it for me:

@@ -302,8 +302,9 @@
 		if (i8042_mux_open++)
 			return 0;
 
+	printk(KERN_INFO "i8042 requesting IRQ %d\n", values->irq);
 	if (request_irq(values->irq, i8042_interrupt,
-			SA_SHIRQ, "i8042", i8042_request_irq_cookie)) {
+			SA_SHIRQ | SA_NOTHREAD, "i8042", i8042_request_irq_cookie)) {
 		printk(KERN_ERR "i8042.c: Can't get irq %d for %s, unregistering the port.\n", values->irq, values->name);
 		goto irq_fail;
 	}

Other things that might be relevant

- both with and without the workaround, I get this:
"Jul 30 08:42:40 hydra kernel: atkbd.c: Spurious ACK on isa0060/serio0. Some program, like XFree86, might be trying access hardware directly."

- both with and without the workaround, I get this:

Jul 30 08:42:27 hydra kernel: Badness in free_irq at arch/i386/kernel/irq.c:721
Jul 30 08:42:27 hydra kernel:  [<c010895d>] free_irq+0x190/0x1aa
Jul 30 08:42:27 hydra kernel:  [<c02632d6>] floppy_release_irq_and_dma+0x259/0x272
Jul 30 08:42:27 hydra kernel:  [<c025cb48>] set_dor+0xe0/0x16f
Jul 30 08:42:27 hydra kernel:  [<c025ceac>] motor_off_callback+0x0/0x36
Jul 30 08:42:27 hydra kernel:  [<c025cede>] motor_off_callback+0x32/0x36
Jul 30 08:42:27 hydra kernel:  [<c0128a42>] run_timer_softirq+0xee/0x1e4
Jul 30 08:42:27 hydra kernel:  [<c0124884>] ksoftirqd+0x0/0xd7
Jul 30 08:42:27 hydra kernel:  [<c0124481>] ___do_softirq+0x83/0x8a
Jul 30 08:42:27 hydra kernel:  [<c01244b9>] _do_softirq+0x6/0x8
Jul 30 08:42:27 hydra kernel:  [<c012490c>] ksoftirqd+0x88/0xd7
Jul 30 08:42:27 hydra kernel:  [<c01341cd>] kthread+0xb7/0xbd
Jul 30 08:42:27 hydra kernel:  [<c0134116>] kthread+0x0/0xbd
Jul 30 08:42:27 hydra kernel:  [<c0103e41>] kernel_thread_helper+0x5/0xb

- with the workaround, I see this
"Jul 30 08:42:33 hydra kernel: psmouse.c: Mouse at isa0060/serio1/input0 lost synchronization, throwing 1 bytes away."

Cheers,
Muli

Muli Ben-Yehuda
http://www.mulix.org | http://mulix.livejournal.com/

If you have an old Xorg or run XFree86 this may well be a real report. Old X tries to bang the controller directly for some things. It also turns up in some normal situations unfortunately and is very confusing for end users. Really this printk should die ASAP.

This patch doesn't solve the latency spikes I see every ~8 seconds on my system. They still appear in latencytest when the rtc interrupt is the only non threaded interrupt on the system, and they still produce xruns in jack in conjunction with the keyboard even if the the sound card's interrupt is the only non threaded irq and jack's SCHED_FIFO priority is higher than the irq threads. I suspected a clock issue and switched from tsc to pmtmr without success. I now suspect a hardware issue (the machine is a laptop with a PIII M 1GHz cpu) or a scheduler corner case. Running jack at 96000Hz with 2 periods of 64 samples, I can see regular bursts of cpu usage every 2 or 3 seconds. Oprofile reveals that schedule is then the second most CPU intensive function on the system.

Thomas

here's the latest version of the voluntary-preempt patch:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc2-O2

this patch is mainly a stabilization effort. I dropped the irq-threads code added in -M5 and rewrote it from scratch based on -L2 - it is simpler and should be more robust.

The same /proc/irq/* configuration switches are still present, but i added the following additional rule: if _any_ handler of a given IRQ is marked as non-threaded then all handlers will be executed non-threaded as well.

E.g. if you have the following handlers on IRQ 10:

10: 11584 IO-APIC-level eth0, eth1, eth2

and you change /proc/irq/16/eth1/threaded from 1 to 0 then the eth0 and eth2 handlers will be executed non-threaded as well. (This rule only enforces what the hardware enforces anyway, none of the previous patches allowed true separation of these handlers.)

i also changed the IO-APIC level-triggered code to be robust when redirection is done. The noapic workaround should not be necessary anymore.

the keyboard lockups are now hopefully all gone too - i've tested IO-APIC and non-IO-APIC setups as well and NumLock/ScrollLock works fine in all sorts of workloads.

Let me know if you still have any problems.

Ingo

I'll be away on vacations for about two weeks, but before leaving, I wanted to test run 2.6.8-rc2-bk11 plus voluntary-preempt-O2 on my P4 box with both ACPI and IO/APIC enabled, voluntary-preempt=3 and preempt=1 and it seems to be working fine (I still haven't seen any hard locks).

# cat /proc/interrupts
           CPU0
  0:     114044    IO-APIC-edge  timer
  1:        497    IO-APIC-edge  i8042
  8:          1    IO-APIC-edge  rtc
  9:          0   IO-APIC-level  acpi
 14:       9289    IO-APIC-edge  ide0
 15:         54    IO-APIC-edge  ide1
 17:       1299   IO-APIC-level  Intel 82801BA-ICH2
 19:      13408   IO-APIC-level  uhci_hcd
 20:        279   IO-APIC-level  eth0
 23:          0   IO-APIC-level  uhci_hcd
NMI:          0
LOC:     113967
ERR:          0
MIS:          0

# grep . /proc/irq/*/*/threaded
/proc/irq/14/ide0/threaded:1
/proc/irq/15/ide1/threaded:1
/proc/irq/17/Intel 82801BA-ICH2/threaded:1
/proc/irq/19/uhci_hcd/threaded:1
/proc/irq/1/i8042/threaded:1
/proc/irq/20/eth0/threaded:1
/proc/irq/23/uhci_hcd/threaded:1
/proc/irq/8/rtc/threaded:1
/proc/irq/9/acpi/threaded:1

One minor problem: this crashes hard (in interrupt context, stack pointer is bogus) during early boot iff CONFIG_REGPARM is set. With the earlier patches, this didn't happen. No ill effects so far with the default ABI; performance (apart from the usual reiserfs problems) is flawless.

Context: plain 2.6.8-rc2 + O2, gcc (GCC) 3.3.4 20040623 (Gentoo Linux 3.3.4-r1, ssp-3.3.2-2, pie-8.7.6), EPoX 8RDA3+ (nForce2) motherboard. If you need more information, let me know.

Ciao,

Daniel.

Hmmm... I have CONFIG_REGPARM enabled and it didn't crash for me at all.

Ingo,

I get the following error below on with your patch applied on stock 2.6.8-rc2 ...

CC kernel/softirq.o
CC kernel/hardirq.o
kernel/hardirq.c:51: error: conflicting types for 'generic_handle_IRQ_event' include/linux/irq.h:78: error: previous declaration of 'generic_handle_IRQ_event' was here
kernel/hardirq.c:51: error: conflicting types for 'generic_handle_IRQ_event' include/linux/irq.h:78: error: previous declaration of 'generic_handle_IRQ_event' was here
make[1]: *** [kernel/hardirq.o] Error 1
make: *** [kernel] Error 2

Matt H.

Try removing the "asmlinkage" from the definition of "generic_handle_IRQ_event" in file "kernel/hardirq.c".

i solved it by adding asmlinkage to irq.h - i've updated the -O2 patch to include this fix. It needs to stay asmlinkage because e.g. the 4K stacks code calls it from within an assembly section which assumes the function follows the normal calling convention (and not e.g. regparm).

Ingo

This works as well as L2, possibly better, because the 42 usec result was with the rtc irq threaded, it is now direct. I will post numbers soon.

Lee

I will be out of town for a few days, so this is the last batch. On my hardware at least, all the latency problems have been resolved.

Delay   Count
-----   -----
6       2880
7       173347
8       311550
9       51870
10      16382
11      12687
12      11757
13      16355
14      14338
15      10980
16      8152
17      6837
18      5331
19      6593
20      5175
21      4181
22      2189
23      1280
24      622
25      461
26      327
27      230
28      195
29      183
30      277
31      271
32      263
33      224
34      143
35      78
36      62
37      78
38      66
39      60
40      55
41      39
42      25
43      14
44      7
45      6
46      5
47      4
48      1
49      5
50      6
51      3
52      1
54      1
55      2
56      2

Lee

nice. I'd not worry about the identity of the -M5 latencies too much if they are gone in -O2.

Ingo

This didn't link:

 CC      arch/i386/lib/usercopy.o
 AR      arch/i386/lib/lib.a
 GEN     .version
 CHK     include/linux/compile.h
 UPD     include/linux/compile.h
 CC      init/version.o
 LD      init/built-in.o
 LD      .tmp_vmlinux1

init/built-in.o(.text+0x1be): In function `init':
init/main.c:708: undefined reference to `spawn_irq_threads'
make: *** [.tmp_vmlinux1] Error 1

Helge Hafting

hm, the -O2 patch doesnt have any spawn_irq_threads() function. Are you sure your build is correct?

Ingo

Rediff against 2.6.8-rc2-mm2 would be nice if possible (there are some rejects right now).

Lenar

here's the latest version of the voluntary-preempt patch:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc3-O4

(it should apply to -rc2 cleanly too.)

-O4 fixes a two more latency sources:

- mlockall() triggering latencies (reported by Thomas Charbonnel, Lee Revell and Florian Schmidt)

- CDROM umount triggering latencies (reported by Florian Schmidt)

there's also a fix for the CONFIG_PCI_MSI compilation bug reported by Edouard Gomez.

(the APIC bug has not been found yet so either turn off all APIC options in .config or use noapic if you intend to use voluntary_preempt=3.)

the preempt-timing-on-2.6.8-rc2-O2 patch applies cleanly to -O4.

Ingo

but it would be nice if those experiencing APIC lockups could test the
following: does the lockup still occur with -O4 if kernel_preemption=0? (while keeping voluntary_preemption=3)

Ingo

I don't use APIC, since it never worked good for me.. But i wanted to report that the mlockall latency still seems to be there.. I can easily trigger it with mlockall'ing > ~10000kb. Need to recompile with the preempt-timing patch, but here's an xrun trace that happened when mlockall'ing 20000kb:

Aug  9 18:53:51 mango kernel: ALSA sound/core/pcm_lib.c:169: XRUN:
pcmC0D0p
Aug  9 18:53:51 mango kernel:  [<c010636e>] dump_stack+0x1e/0x20
Aug  9 18:53:51 mango kernel:  [<f08befae>]
snd_pcm_period_elapsed+0x2ee/0x460 [snd_pcm]
Aug  9 18:53:51 mango kernel:  [<f08e1b84>]
snd_cs46xx_interrupt+0x1b4/0x1f0 [snd_cs46xx]
Aug  9 18:53:51 mango kernel:  [<c011a5db>]
generic_handle_IRQ_event+0x3b/0x70
Aug  9 18:53:51 mango kernel:  [<c0107725>] do_IRQ+0xa5/0x150
Aug  9 18:53:51 mango kernel:  [<c0105f88>] common_interrupt+0x18/0x20
Aug  9 18:53:51 mango kernel:  [<c013cc4a>] get_user_pages+0xca/0x380
Aug  9 18:53:51 mango kernel:  [<c013e33d>] make_pages_present+0x8d/0xb0
Aug  9 18:53:51 mango kernel:  [<c013e7e6>] mlock_fixup+0xa6/0xc0
Aug  9 18:53:51 mango kernel:  [<c013eadb>] do_mlockall+0x7b/0x90
Aug  9 18:53:51 mango kernel:  [<c013eb8e>] sys_mlockall+0x9e/0xb0
Aug  9 18:53:51 mango kernel:  [<c0105e1b>] syscall_call+0x7/0xb

I can also see some of these [sparse they are though]:

Aug  9 18:58:08 mango kernel: ALSA sound/core/pcm_lib.c:199: Unexpected
hw_pointer value [1] (stream = 0, delta: -32, max jitter = 64): wrong
interrupt acknowledge?
Aug  9 18:58:08 mango kernel:  [<c010636e>] dump_stack+0x1e/0x20
Aug  9 18:58:08 mango kernel:  [<f08bee8d>]
snd_pcm_period_elapsed+0x1cd/0x460 [snd_pcm]
Aug  9 18:58:08 mango kernel:  [<f08e1b84>]
snd_cs46xx_interrupt+0x1b4/0x1f0 [snd_cs46xx]
Aug  9 18:58:08 mango kernel:  [<c011a5db>]
generic_handle_IRQ_event+0x3b/0x70
Aug  9 18:58:08 mango kernel:  [<c0107725>] do_IRQ+0xa5/0x150
Aug  9 18:58:08 mango kernel:  [<c0105f88>] common_interrupt+0x18/0x20

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

Ingo, do you plan to maintain the voluntary preempt patch against the -mm series? From looking at Andrew's announcement yesterday it looks like many latency issues fixed in the voluntary preemption patches are also fixed in -mm, so it seems like the patch would be much smaller. One thing that might be useful is breaking out the irq threading code as a patch against -mm. Judging from all the -mm latency fixes it seems like this would work as well as the vanilla kernel+voluntary preempt.

This would also make it easier to identify which are the important latency fixes from -mm enabling them to be pushed into mainline sooner. On some of my tests I got 10-20% better results using vol-preempt+mm vs vol-preempt+vanilla, it would be nice to identify what changes are responsible.

Lee

yeah, and in addition we've already pushed 99% of our might_sleep() additions to -mm too so that reduces the patch size too, quite significantly.

time is the only limiting factor. Due to these partial merges (we are trying to get all uncontroversial bits into -mm, hence into upstream) the merge to -mm is hard. Especially for lock-breaks that i've done differently than Andrew. I sent a consolidation patch yesterday but this is still work in progress. So i'll do an -mm merge very time i get to do it, but the primary testing still remains on the vanilla kernel (which most people use).

both softirq threading and hardirq threading will be done separately, yes. Also, most of the switches and source-level distinctions between cond_resched and voluntary_resched variants can go away too. The '-clean' patch in the voluntary-preempt directory shows how it would look like in the end.

the plan right now is to push all the known-good stuff into 2.6.9 once 2.6.8 is out. That will unify all the improvements in a natural way. The latest update kernel of FC2 also includes an earlier version of the voluntary-preempt patch (sans any irq threading bits) - and it worked out fine so far.

Ingo

Rather than having to maintain the voluntary preempt patch for the -mm series, after the next -mm merge, maybe you could just post or send me an incremental diff against the last voluntary preempt patch for the vanilla kernel when you update it, and I or someone else from the Linux audio community could maintain the patch against the -mm series. It seems that lately the changes from one version of the patch to the next are small and easy enough to comprehend. We could also filter the bug reports a bit. Maybe a voluntary preemption mailing list is in order, if this gets to be a constant source of huge log postings to LKML.

This would also improve the ability of the Linux audio community to influence the direction of the kernel, by separately analyzing the impact of different changes, especially if the -mm series is going to function as 2.7 for the time being.

Lee

Same results here, the mlockall problem is not fixed by -O4:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139:
XRUN: pcmC0D2c

 [<c0106717>] dump_stack+0x17/0x20
 [<de93664b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de9571d1>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c011a7d3>] generic_handle_IRQ_event+0x33/0x60
 [<c01079c2>] do_IRQ+0xb2/0x180
 [<c01062d8>] common_interrupt+0x18/0x20
 [<c013e2ee>] do_anonymous_page+0x7e/0x190
 [<c013e44e>] do_no_page+0x4e/0x310
 [<c013e8d1>] handle_mm_fault+0xc1/0x170
 [<c013d2a0>] get_user_pages+0x130/0x3b0
 [<c013ea28>] make_pages_present+0x68/0x90
 [<c01401d8>] do_mmap_pgoff+0x3f8/0x640
 [<c010b656>] sys_mmap2+0x76/0xb0
 [<c01060b7>] syscall_call+0x7/0xb
(jackd/778): 10984us non-preemptible critical section violated 1100 us
preempt threshold starting at kmap_atomic+0x10/0x60 and ending at
kunmap_atomic+0x8/0x20
 [<c0106717>] dump_stack+0x17/0x20
 [<c0113eec>] dec_preempt_count+0x3c/0x50
 [<c0111ce8>] kunmap_atomic+0x8/0x20
 [<c013e2fb>] do_anonymous_page+0x8b/0x190
 [<c013e44e>] do_no_page+0x4e/0x310
 [<c013e8d1>] handle_mm_fault+0xc1/0x170
 [<c013d2a0>] get_user_pages+0x130/0x3b0
 [<c013ea28>] make_pages_present+0x68/0x90
 [<c01401d8>] do_mmap_pgoff+0x3f8/0x640
 [<c010b656>] sys_mmap2+0x76/0xb0
 [<c01060b7>] syscall_call+0x7/0xb

Lee

Correction, those traces did not involve mlockall at all, but kmap_atomic and get_user_pages.

Here is another one I got starting jackd. Never seen it before today.

(jackd/778): 14583us non-preemptible critical section violated 1100 us preempt threshold starting at schedule+0x55/0x5a0 and ending at schedule+0x2ed/0x5a0

 [<c0106717>] dump_stack+0x17/0x20
 [<c0113eec>] dec_preempt_count+0x3c/0x50
 [<c0264d4d>] schedule+0x2ed/0x5a0
 [<c026554e>] schedule_timeout+0x9e/0xa0
 [<c0121dcf>] sys_rt_sigtimedwait+0x1df/0x2e0
 [<c01060b7>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c0106717>] dump_stack+0x17/0x20
 [<de93664b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de9571d1>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c011a7d3>] generic_handle_IRQ_event+0x33/0x60
 [<c01079c2>] do_IRQ+0xb2/0x180
 [<c01062d8>] common_interrupt+0x18/0x20

Lee

just to make sure this is not a false positive - is this accompanied by ALSA-detected xruns as well? (i suspect it is.)

Ingo

Yes, here it is:

Aug  9 22:12:48 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
Aug  9 22:12:48 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Aug  9 22:12:48 mindpipe kernel:  [__crc_totalram_pages+1425/2369476] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
Aug  9 22:12:48 mindpipe kernel:  [__crc_totalram_pages+135447/2369476] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Aug  9 22:12:48 mindpipe kernel:  [generic_handle_IRQ_event+51/96] generic_handle_IRQ_event+0x33/0x60
Aug  9 22:12:48 mindpipe kernel:  [do_IRQ+178/384] do_IRQ+0xb2/0x180
Aug  9 22:12:48 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Aug  9 22:12:48 mindpipe kernel:  [schedule+727/1440] schedule+0x2d7/0x5a0
Aug  9 22:12:48 mindpipe kernel:  [schedule_timeout+158/160] schedule_timeout+0x9e/0xa0
Aug  9 22:12:48 mindpipe kernel:  [sys_rt_sigtimedwait+479/736] sys_rt_sigtimedwait+0x1df/0x2e0
Aug  9 22:12:48 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb

I do not seem to get false positives anymore, IOW, all the traces I send you are accompanied by an ALSA xrun. I suspect that with a lower threshold (100us), the overhead from all the printks and stack dumps was causing one violation to lead to a domino effect.

Lee

i've uploaded a new version of the preempt-timing patch:

http://redhat.com/~mingo/voluntary-preempt/preempt-timing-on-2.6.8-rc3-O4.patch

this patch fixes a number of false positives and false negatives. In particular it fixes the idle-task false positives, and it now correctly measures preemption delays in softirq and hardirq contexts and in bh-disabled process contexts. Maybe this sheds a light on some of the more mysterious delays that we've seen. (and which were never directly measured before.)

(the patch also got alot simpler, which should help portability.)

Ingo

Looks really good, this thing is really starting to look slick from all the time you've put in on it.

The adding in of the FOOIRQ_OFFSET bits were a rather major oversisght on my part! Very good catch.

-- wli

Feh, there has to be a way to say "this is a good patch" without sounding like I'm reviewing freshman code. This is a good patch.

-- wli

can you trigger similar latencies via the attached mlock testcode? (written by Florian. Run it as root.)

Ingo

// here is the code i used to test the mlockall caused xruns #include <sys/mman.h>
#include <iostream>
#include <sstream>
#include <unistd.h>

int main (int argc, char *argv[]) {

        if (argc < 2) {
                std::cout << "how many kbytes you want allocated and mlockall'ed?" << std::endl;
        }

        std::stringstream stream(argv[1]);
        int kbytes;
        stream >> kbytes;
        char *mem = new char[kbytes*1024];
        std::cout << "filling with 0's" << std::endl;
        for (int i = 0; i < kbytes*1024; ++i) {
                mem[i] = 0;
        }

        std::cout << "ok, you want " << kbytes << "kb of memory mlocked.  going for it.." << std::endl;
        int error = mlockall(MCL_CURRENT);
        if (error != 0) { std::cout << "mlock error" << std::endl; }
        else { std::cout << "mlock successfull" << std::endl;}
}

Yup, using only 100000 bytes, I get a bunch of these:

(mlockall-test/6561): 10353us non-preemptible critical section violated 1100 us preempt threshold starting at get_user_pages+0xa6/0x3b0 and ending at get_user_pages+0x2c5/0x3b0

 [<c0106717>] dump_stack+0x17/0x20
 [<c0113eec>] dec_preempt_count+0x3c/0x50
 [<c013d435>] get_user_pages+0x2c5/0x3b0
 [<c013ea28>] make_pages_present+0x68/0x90
 [<c013ee8d>] mlock_fixup+0x8d/0xb0
 [<c013f170>] do_mlockall+0x70/0x90
 [<c013f229>] sys_mlockall+0x99/0xa0
 [<c01060b7>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c0106717>] dump_stack+0x17/0x20
 [<de93d64b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de9791d1>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c011a7d3>] generic_handle_IRQ_event+0x33/0x60
 [<c01079c2>] do_IRQ+0xb2/0x180
 [<c01062d8>] common_interrupt+0x18/0x20
 [<c0113d31>] check_preempt_timing+0x11/0xf0
 [<c0113e62>] touch_preempt_timing+0x32/0x40
 [<c013d216>] get_user_pages+0xa6/0x3b0
 [<c013ea28>] make_pages_present+0x68/0x90
 [<c013ee8d>] mlock_fixup+0x8d/0xb0
(mlockall-test/6561): 9168us non-preemptible critical section violated 1100 us preempt threshold starting at get_user_pages+0x2cf/0x3b0 and ending at get_user_pages+0xa6/0x3b0
 [<c0106717>] dump_stack+0x17/0x20
 [<c0113e62>] touch_preempt_timing+0x32/0x40
 [<c013d216>] get_user_pages+0xa6/0x3b0
 [<c013ea28>] make_pages_present+0x68/0x90
 [<c013ee8d>] mlock_fixup+0x8d/0xb0
 [<c013f170>] do_mlockall+0x70/0x90
 [<c013f229>] sys_mlockall+0x99/0xa0
 [<c01060b7>] syscall_call+0x7/0xb

Lee

Hi, just to make sure: Those weren't 100000 kbytes actually?

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

Oops, 100000KB.

Lee

could you turn off CONFIG_HIGHMEM altogether? Can you still reproduce this mlockall() latency?

Ingo

another idea: you are running this on a C3, using CONFIG_MCYRIXIII, correct? That is one of the rare configs that triggers X86_USE_3DNOW and MMX ops. If 3dnow is in any way handicapped in that CPU then that could cause trouble. Could you compile for e.g. CONFIG_M586TSC? [that option should be fully compatible with a C3.] - this will exclude the MMX page clearing ops.

what makes me suspicious is this entry in your call-trace:

this is the next instruction after:

call c01d1910 <mmx_clear_page>

but it's all a bit weird - the ALSA interrupt should have hit the fast_clear_page() function but it didnt. Maybe it doesnt show up because the call to fast_clear_page() within mmx_clear_page() is tail-optimized and possibly the stack entry is lost. But still ...

Ingo

another (more remote) possibility is that the timestamp counter gets somehow messed up during MMX ops. Does the ALSA detector use the timestamp counter, or does it only use jiffies? (if it only used jiffies that would give us some robustness since it's an independent time-source.) I suspect 'music indeed skips' isnt a good enough test for this case, given that jackd starts up ...

Ingo

The standard VIA EPIA boards are 133Mhz SDRAM or 266Mhz DDR, which is shared with video and the graphics engine. Could the MMX copier simply be eating all the remaining memory bandwidth so that its in fact memory not latency ?

it's a 10 msec latency that got measured, for a single page copy (!) - if it's memory latency then it must be something really bad...

Ingo

Here's another one that I have seen a few times.

(gnome-terminal/850): 15487us non-preemptible critical section violated 1100 us preempt threshold starting at add_wait_queue+0x15/0x50 and ending at add_wait_queue+0x2c/0x50

 [<c0106717>] dump_stack+0x17/0x20
 [<c0113eec>] dec_preempt_count+0x3c/0x50
 [<c011406c>] add_wait_queue+0x2c/0x50
 [<c01e334d>] normal_poll+0x3d/0x177
 [<c01df281>] tty_poll+0x61/0x80
 [<c015f0a1>] do_pollfd+0x91/0xa0
 [<c015f10f>] do_poll+0x5f/0xc0
 [<c015f2a1>] sys_poll+0x131/0x220
 [<c01060b7>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c0106717>] dump_stack+0x17/0x20
 [<de93d64b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de9791d1>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c011a7d3>] generic_handle_IRQ_event+0x33/0x60
 [<c01079c2>] do_IRQ+0xb2/0x180
 [<c01062d8>] common_interrupt+0x18/0x20
 [<c015f0a1>] do_pollfd+0x91/0xa0
 [<c015f10f>] do_poll+0x5f/0xc0
 [<c015f2a1>] sys_poll+0x131/0x220
 [<c01060b7>] syscall_call+0x7/0xb

Lee

At Tue, 10 Aug 2004 11:22:49 +0200,

No, neither of them. It checks the DMA buffer position, so the accuracy of the latency measurement depends on the size of DMA buffer fragment (called "period" in ALSA).

The only thing related with the time in the pcm layer is the call of do_gettimeofday() when status ioctl is called (or at each DMA interrupt, depending on the running mode).

Takashi

OK, with CONFIG_M586TSC, I am getting a lot of lockups. A few happened during normal desktop use, and it locks up hard when starting jackd. Could this have anything to do with the ALSA drivers (which I am compiling seperately from ALSA cvs) detecting my build system as i686? I have read that the C3 is more like a 486 (with MMX & 3DNow) than a 686.

Lee

well, could you try M486 then?

Ingo

Sure, I want to try recompiling alsa-lib as well, there was a version mismatch that may be the problem.

Lee

Still does not work. Starting jackd hangs the system.

Lee

Results with CONFIG_M586TSC are basically the same as CONFIG_MCYRIXIII. I have posted my latest results here:

http://www.members.dca.net/rlrevell/testresults/testresults.html

There are graphs (linear and logarithmic scale) for each of 5 trials, followed by all the XRUN traces and preempt violations I got around the time of the test.

iozone -a was running also.

Lee

The C3 is a full 686 instruction set. The kernel is different because the GNU tool people couldn't read manuals and once the error was made it was a bit too late to fix it.

Thus ALSA deciding its 686 is fine.

Depends which C3. If OP's C3 lacks cmov, it definitly is not ok. Any cmov ending up in that module will blow up.

Dave

Argh, never mind, this was an ALSA bug, reverting to CVS from two days ago fixed it.

Lee

Not that it helps at all, but the conditional move instruction was marked as optional by Intel, hence the 'cmov' capability flag (in the flags part of /proc/cpuinfo). As you say, the earlier C3 chips (like the one in my firewall) lack support for this instruction:

model name : VIA Samuel 2
cpu MHz : 533.365
flags : fpu de tsc msr cx8 mtrr pge mmx 3dnow

So, strictly speaking, you shouldn't use cmov for something that's simply "i686" compatible. Of course, gcc etc. uses it because it's very nice from the point of view of avoiding having to do branches and the associated malarky and someone failed to spot that it was optional. So, yes, it's not OK to use -march=i686 on these chips. Modern gccs know about -march=c3, which ought to be a good bet for these chips (one would hope).

Tim

Tim Wright <[email protected]>
Splhi

If you have an early C3 (ie, pre Nehemiah model), then you will lack the cmov instruction that gcc assumes is in 686's. If the ALSA scripts aren't aware of this, they will generate code which your CPU cannot run.

It's 686, just lacking various extensions. The current models have all the same optional features you could find on a Pentium Pro, plus a bunch of extra exclusive bits.

Dave

This is what I have, the first of their fanless models I believe, 600Mhz C3.

However ALSA always detected the CPU as a 686 and I never had problems, it's definitely the change from CONFIG_MCYRIXIII to CONFIG_M586TSC that started the lockups.

I recompiled all the ALSA libs and jackd, same problem - starting jackd causes immediate lockup. Now building with M486.

Lee

[snip]

[snip]

Hi,

i just applied the new preempt-timing patch and i made the observation that if jackd is not running then mlocking 500megs of ram doesn't cause the preempt-timing [thresh = 1000] to report anything.

But when jackd is running i can easily cause an xrun by mlocking even only 50megs. In this case also a critical section report is printed by the preempt-timing:

Aug 10 13:13:05 mango kernel: ALSA sound/core/pcm_lib.c:169: XRUN:
pcmC0D0p
Aug 10 13:13:05 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 10 13:13:05 mango kernel:  [<f08c2431>]
snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
Aug 10 13:13:05 mango kernel:  [<f089ebce>]
snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
Aug 10 13:13:05 mango kernel:  [<c011b55b>]
generic_handle_IRQ_event+0x3b/0x70
Aug 10 13:13:05 mango kernel:  [<c01078c6>] do_IRQ+0xb6/0x170
Aug 10 13:13:05 mango kernel:  [<c0106098>] common_interrupt+0x18/0x20
Aug 10 13:13:05 mango kernel:  [<c013f073>] get_user_pages+0xd3/0x3d0
Aug 10 13:13:05 mango kernel:  [<c01408fd>] make_pages_present+0x8d/0xb0
Aug 10 13:13:05 mango kernel:  [<c0140da6>] mlock_fixup+0xa6/0xc0
Aug 10 13:13:05 mango kernel:  [<c014109b>] do_mlockall+0x7b/0x90
Aug 10 13:13:05 mango kernel:  [<c014114e>] sys_mlockall+0x9e/0xb0
Aug 10 13:13:05 mango kernel:  [<c0105f2b>] syscall_call+0x7/0xb
Aug 10 13:13:05 mango kernel: (mlockall_test/877): 2706us
non-preemptible critical section violated 1000 us preempt threshold
starting at get_user_pages+0x2f3/0x3d0 and ending at
get_user_pages+0xa5/0x3d0
Aug 10 13:13:05 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 10 13:13:05 mango kernel:  [<c01146b3>]
touch_preempt_timing+0x33/0x40
Aug 10 13:13:05 mango kernel:  [<c013f045>] get_user_pages+0xa5/0x3d0
Aug 10 13:13:05 mango kernel:  [<c01408fd>] make_pages_present+0x8d/0xb0
Aug 10 13:13:05 mango kernel:  [<c0140da6>] mlock_fixup+0xa6/0xc0
Aug 10 13:13:05 mango kernel:  [<c014109b>] do_mlockall+0x7b/0x90
Aug 10 13:13:05 mango kernel:  [<c014114e>] sys_mlockall+0x9e/0xb0
Aug 10 13:13:05 mango kernel:  [<c0105f2b>] syscall_call+0x7/0xb

So it seems that the combination of the two is somehow triggering this behaviour:

ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p

 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
 [<c013f293>] get_user_pages+0x2f3/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
(mlockall_test/862): 2701us non-preemptible critical section violated
1000 us preempt threshold starting at get_user_pages+0x2f3/0x3d0 and
ending at get_user_pages+0xa5/0x3d0
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c01146b3>] touch_preempt_timing+0x33/0x40
 [<c013f045>] get_user_pages+0xa5/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
 [<c0114576>] check_preempt_timing+0x16/0x100
 [<c0114735>] sub_preempt_count+0x45/0x60
 [<c013f282>] get_user_pages+0x2e2/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20

I also tried to disable syslogd and looked into dmesg to see the xrun reports. i don't know if they differ in any essential way:

[<c0105f2b>] syscall_call+0x7/0xb
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p

 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
 [<c0114668>] __touch_preempt_timing+0x8/0x20
 [<c01146be>] touch_preempt_timing+0x3e/0x40
 [<c013f045>] get_user_pages+0xa5/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
(mlockall_test/913): 3053us non-preemptible critical section violated
1000 us preempt threshold starting at get_user_pages+0xa5/0x3d0 and
ending at get_user_pages+0x2e2/0x3d0
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0114735>] sub_preempt_count+0x45/0x60
 [<c013f282>] get_user_pages+0x2e2/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
 [<c013f293>] get_user_pages+0x2f3/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0c
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
 [<c013f045>] get_user_pages+0xa5/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
(mlockall_test/916): 2703us non-preemptible critical section violated
1000 us preempt threshold starting at get_user_pages+0xa5/0x3d0 and
ending at get_user_pages+0x2e2/0x3d0
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0114735>] sub_preempt_count+0x45/0x60
 [<c013f282>] get_user_pages+0x2e2/0x3d0
 [<c01408fd>] make_pages_present+0x8d/0xb0
 [<c0140da6>] mlock_fixup+0xa6/0xc0
 [<c014109b>] do_mlockall+0x7b/0x90
 [<c014114e>] sys_mlockall+0x9e/0xb0
 [<c0105f2b>] syscall_call+0x7/0xb
ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p
 [<c01064ae>] dump_stack+0x1e/0x20
 [<f08c2431>] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm]
 [<f089ebce>] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx]
 [<c011b55b>] generic_handle_IRQ_event+0x3b/0x70
 [<c01078c6>] do_IRQ+0xb6/0x170
 [<c0106098>] common_interrupt+0x18/0x20
 [<c0114576>] check_preempt_timing+0x16/0x100
 [<c0114735>] sub_preempt_count+0x45/0x60
 [<c0291bc5>] schedule+0x305/0x5b0
 [<c029241e>] schedule_timeout+0x5e/0xb0
 [<c0162fd9>] do_poll+0x99/0xc0
 [<c016313f>] sys_poll+0x13f/0x240
 [<c0105f2b>] syscall_call+0x7/0xb
(qjackctl/859): 5549us non-preemptible critical section violated 1000 us
preempt threshold starting at schedule+0x5c/0x5b0 and ending at
schedule+0x305/0x5b0
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0114735>] sub_preempt_count+0x45/0x60
 [<c0291bc5>] schedule+0x305/0x5b0
 [<c029241e>] schedule_timeout+0x5e/0xb0
 [<c0162fd9>] do_poll+0x99/0xc0
 [<c016313f>] sys_poll+0x13f/0x240
 [<c0105f2b>] syscall_call+0x7/0xb

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

i've uploaded the latest version of the voluntary-preempt patch:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc3-O5

-O5 fixes the APIC lockup issues. The bug was primarily caused by PCI POST delays causing IRQ storms of level-triggered IRQ sources that were hardirq-redirected. Also found some bugs in delayed-IRQ masking and unmasking. SMP should thus work again too.

Ingo

Hi Ingo,

I've rediffed O5 agains 2.6.8-rc4-mm1-staircase. It compiles and boots for me when using voluntary-preempt=1; 2 and 3 lock up the system right after the line: 'Probing IDE interface ide1...' (dmesg & .config included).

staircase patch used:
http://ck.kolivas.org/patches/2.6/2.6.8/2.6.8-rc4-mm1/from_2.6.8-rc4-
mm1_to_staircase7.I

Thanks for all the effort,

Peter Zijlstra

The mlockall() issue seems to be fixed. Now I get this one when starting jackd:

(jackd/12427): 10882us non-preemptible critical section violated 400 us preempt threshold starting at kernel_fpu_begin+0x10/0x60 and ending at fast_clear_page+0x75/0xa0

 [<c0106777>] dump_stack+0x17/0x20
 [<c01140eb>] sub_preempt_count+0x4b/0x60
 [<c01d1585>] fast_clear_page+0x75/0xa0
 [<c013ea86>] do_anonymous_page+0x86/0x180
 [<c013ebd0>] do_no_page+0x50/0x300
 [<c013f041>] handle_mm_fault+0xc1/0x170
 [<c013da33>] get_user_pages+0x133/0x3d0
 [<c013f198>] make_pages_present+0x68/0x90
 [<c0140948>] do_mmap_pgoff+0x3f8/0x640
 [<c010b7f6>] sys_mmap2+0x76/0xb0
 [<c0106117>] syscall_call+0x7/0xb

Lee

I see these, too [at jackd startup and at client startup]:

Aug 11 01:15:21 mango kernel: (jackd/843): 3215us non-preemptible
critical secti
on violated 1000 us preempt threshold starting at
kernel_fpu_begin+0x1a/0x60 and
 ending at fast_clear_page+0x54/0x80
Aug 11 01:15:21 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 11 01:15:21 mango kernel:  [<c0114735>] sub_preempt_count+0x45/0x60
Aug 11 01:15:21 mango kernel:  [<c01daa94>] fast_clear_page+0x54/0x80
Aug 11 01:15:21 mango kernel:  [<c0140150>] do_anonymous_page+0x90/0x190
Aug 11 01:15:21 mango kernel:  [<c01402b1>] do_no_page+0x61/0x320
Aug 11 01:15:21 mango kernel:  [<c0140763>] handle_mm_fault+0xe3/0x1a0
Aug 11 01:15:21 mango kernel:  [<c013f0e7>] get_user_pages+0x147/0x3d0
Aug 11 01:15:21 mango kernel:  [<c01408fd>] make_pages_present+0x8d/0xb0
Aug 11 01:15:21 mango kernel:  [<c0142255>] do_mmap_pgoff+0x445/0x6b0
Aug 11 01:15:21 mango kernel:  [<c010b800>] old_mmap+0xe0/0x120
Aug 11 01:15:21 mango kernel:  [<c0105f2b>] syscall_call+0x7/0xb
Aug 11 01:15:21 mango kernel: ALSA sound/core/pcm_lib.c:169: XRUN:
pcmC0D0p
Aug 11 01:15:21 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 11 01:15:21 mango kernel:  [<f08c2431>]
snd_pcm_period_elapsed+0x311/0x480 [
snd_pcm]
Aug 11 01:15:21 mango kernel:  [<f089ebce>]
snd_cs46xx_interrupt+0x1be/0x1f0 [sn
d_cs46xx]
Aug 11 01:15:21 mango kernel:  [<c011b55b>]
generic_handle_IRQ_event+0x3b/0x70
Aug 11 01:15:21 mango kernel:  [<c01078c6>] do_IRQ+0xb6/0x170
Aug 11 01:15:21 mango kernel:  [<c0106098>] common_interrupt+0x18/0x20
Aug 11 01:15:40 mango gconfd (tapas-803): GConf server is not in use,
shutting d
own.
Aug 11 01:15:40 mango gconfd (tapas-803): Exiting
Aug 11 01:16:01 mango kernel: ALSA sound/core/pcm_lib.c:169: XRUN:
pcmC0D0p
Aug 11 01:16:01 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 11 01:16:01 mango kernel:  [<f08c2431>]
snd_pcm_period_elapsed+0x311/0x480 [
snd_pcm]
Aug 11 01:16:01 mango kernel:  [<f089ebce>]
snd_cs46xx_interrupt+0x1be/0x1f0 [sn
d_cs46xx]
Aug 11 01:16:01 mango kernel:  [<c011b55b>]
generic_handle_IRQ_event+0x3b/0x70
Aug 11 01:16:01 mango kernel:  [<c01078c6>] do_IRQ+0xb6/0x170
Aug 11 01:16:01 mango kernel:  [<c0106098>] common_interrupt+0x18/0x20
Aug 11 01:16:01 mango kernel:  [<c0140150>] do_anonymous_page+0x90/0x190
Aug 11 01:16:01 mango kernel:  [<c01402b1>] do_no_page+0x61/0x320
Aug 11 01:16:01 mango kernel:  [<c0140763>] handle_mm_fault+0xe3/0x1a0
Aug 11 01:16:01 mango kernel:  [<c013f0e7>] get_user_pages+0x147/0x3d0
Aug 11 01:16:01 mango kernel:  [<c01408fd>] make_pages_present+0x8d/0xb0
Aug 11 01:16:01 mango kernel:  [<c0142255>] do_mmap_pgoff+0x445/0x6b0
Aug 11 01:16:01 mango kernel:  [<c010b800>] old_mmap+0xe0/0x120
Aug 11 01:16:01 mango kernel:  [<c0105f2b>] syscall_call+0x7/0xb
Aug 11 01:16:01 mango kernel: (scsynth/870): 3230us non-preemptible
critical sec
tion violated 1000 us preempt threshold starting at
kernel_fpu_begin+0x1a/0x60 a
nd ending at fast_clear_page+0x54/0x80
Aug 11 01:16:01 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 11 01:16:01 mango kernel:  [<c0114735>] sub_preempt_count+0x45/0x60
Aug 11 01:16:01 mango kernel:  [<c01daa94>] fast_clear_page+0x54/0x80
Aug 11 01:16:01 mango kernel:  [<c0140150>] do_anonymous_page+0x90/0x190
Aug 11 01:16:01 mango kernel:  [<c01402b1>] do_no_page+0x61/0x320
Aug 11 01:16:01 mango kernel:  [<c0140763>] handle_mm_fault+0xe3/0x1a0
Aug 11 01:16:01 mango kernel:  [<c013f0e7>] get_user_pages+0x147/0x3d0
Aug 11 01:16:01 mango kernel:  [<c01408fd>] make_pages_present+0x8d/0xb0
Aug 11 01:16:01 mango kernel:  [<c0142255>] do_mmap_pgoff+0x445/0x6b0
Aug 11 01:16:01 mango kernel:  [<c010b800>] old_mmap+0xe0/0x120
Aug 11 01:16:01 mango kernel:  [<c0105f2b>] syscall_call+0x7/0xb

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

to make sure this is a real latency and not some rdtsc weirdness, could you try the latest version of preempt-timing:

http://redhat.com/~mingo/voluntary-preempt/preempt-timing-on-2.6.8-rc3-O5-A2

this adds jiffies-based latency values to the printout, e.g.:

(ksoftirqd/0/2): 3860us [3 jiffy] non-preemptible critical section violated 100 us preempt threshold starting at ___do_softirq+0x1b/0x90 and ending at cond_resched_softirq+0x57/0x70

shows that a 10 jiffy (10 msec) latency happened - which matches the rdtsc-based 3860 usecs value.

Ingo

could you also apply the patch below? This splits up fast_clear_page() overhead into 3 pieces to find out where the overhead comes from. Note that this will likely cause 'reduced' latency printouts, but those are not real because the touch_preempt_timing() lines dont show real preemptible points. You should still get a larger latency in one of those regions. The kernel-FPU code (which is triggered by the MMX ops) could be another source of overhead - but 10 msecs is so large ...

(another thing: could you turn on CONFIG_DEBUG_HIGHMEM, CONFIG_DEBUG_SPINLOCK and CONFIG_DEBUG_SPINLOCK_SLEEP? Lets make sure that what we are seeing here is not somehow caused by atomicity violations.)

Ingo

@@ -132,7 +132,9 @@ static void fast_clear_page(void *page)
 {
 	int i;
 
+	touch_preempt_timing();	
 	kernel_fpu_begin();
+	touch_preempt_timing();	
 	
 	__asm__ __volatile__ (
 		"  pxor %%mm0, %%mm0\n" : :

@@ -158,7 +160,9 @@ static void fast_clear_page(void *page)
 	__asm__ __volatile__ (
 		"  sfence \n" : :
 	);
+	touch_preempt_timing();	
 	kernel_fpu_end();
+	touch_preempt_timing();	
 }
 
 static void fast_copy_page(void *to, void *from)

@@ -260,8 +264,10 @@ static void fast_copy_page(void *to, voi
 static void fast_clear_page(void *page)
 {
 	int i;
-	
+
+	touch_preempt_timing();	
 	kernel_fpu_begin();
+	touch_preempt_timing();	
 	
 	__asm__ __volatile__ (
 		"  pxor %%mm0, %%mm0\n" : :

@@ -290,7 +296,9 @@ static void fast_clear_page(void *page)
 		page+=128;
 	}
 
+	touch_preempt_timing();	
 	kernel_fpu_end();
+	touch_preempt_timing();	
 }
 
 static void fast_copy_page(void *to, void *from)

I have highmem disabled per your previous request. Should I turn it back on?

Lee

another thing: do you see the 10 msec latency every time you run mlockall-test, or does it only happen sporadically?

Ingo

Hi,

I'm not running the voluntary-preempt-* patches. but I do see some long latencies with:

vanilla 2.6.7+preempt-timing+defer-softirq

which were NOT reported here. Is it useful the report them?

Regards

Linh Dang

Probably not. Many latency issues as well as bugs in the preempt timing patch have been fixed since then. You should try the latest version.

Lee

which "latest"? Linus's 2.6.8-rcX or Andrew's -mm's or Ingo's patches.

I've looked at Ingo patches but didn't see fixes for the followings:

1. In sys_mount(): do_mount() is called with the BKL held. on jffs2 system, jffs2 might for a big media-scan and lock preemption for several msecs. even if jffs2_scan_eraseblock() calls cond_resched() for every flash sector, scanning one sector is still very long.

2. netif_receive_skb(): the rcu_read_lock() is too broad. IMHO, it's only needed around the 2 list_for_each_entry_rcu()s. There's no reason why rcu_read_lock() is needed when calling ip_recv on the skb.

3. with Ingo's patches, if all softirqs are done by the daemon then there's should be NO need to call local_bh_disable()/enable() around the processing loop in ___do_softirq().

4. in cfi_cmdset_0002.c, using spin_lock_bh() to guard struct flchip seems to be an overkill. why a semaphore is NOT sufficient?

I'm a total newbie so it's possible that I'm totally wrong about the aboves.

Regards

Linh Dang

nope, please keep it disabled still. (You can turn the C3 CPU option back on though, it doesnt seem to have any impact on latency.)

then it's just the spinlock debugging options that should be enabled. (they make sense on UP kernels too, if CONFIG_PREEMPT is enabled.)

Ingo

most of the remaining latencies look quite suspect. E.g. the select()/tty_poll() ones:

(gnome-terminal/826): 15491us non-preemptible critical section
violated 1100 us preempt threshold starting at add_wait_queue+0x15/0x50 and ending at add_wait_queue+0x2c/0x50

[dump_stack+23/32] dump_stack+0x17/0x20 [dec_preempt_count+60/80] dec_preempt_count+0x3c/0x50 [add_wait_queue+44/80] add_wait_queue+0x2c/0x50 [normal_poll+61/375] normal_poll+0x3d/0x177 [tty_poll+97/128] tty_poll+0x61/0x80 [do_pollfd+145/160] do_pollfd+0x91/0xa0 [do_poll+95/192] do_poll+0x5f/0xc0 [sys_poll+305/544] sys_poll+0x131/0x220 [syscall_call+7/11] syscall_call+0x7/0xb

according to the trace this latency happened in a point where it's near impossible to happen. add_wait_queue() is just a couple of straight instructions on UP.

do you have any powersaving mode enabled in the BIOS? SMM handlers can introduce such latencies (low probability).

the only other possibility is either a measurement error, or some mystic IRQ overhead. But almost all IRQs are redirected so the IRQ overhead can be eliminated almost completely. Plus direct-IRQ overhead should also show up via the latest preempt-timing patch. Wrt. measurement error, the jiffies based printout ought to help somewhat.

i'm currently running a loop of mlockall-test 100MB on a 466 MHz Celeron, and not a single blip on the radar with a 1000 usecs threshold, after 1 hour of runtime ...

i've previously seen RDTSC (cycle-counter) weirdnesses on another box, in userspace. To exclude this possibility i've attached yet another patch, it tries to make all the kernel rdtsc variants more robust. Does this patch make any difference to the latency printouts? [this patch doesnt handle cases where the rdtsc value jumps forward in time permanently, but it handles the occasional blips i've seen on the other box.]

Ingo

@@ -32,15 +32,50 @@ static inline void wrmsrl (unsigned long
 	wrmsr (msr, lo, hi);
 }
 
-#define rdtsc(low,high) \
+#define __rdtsc(low,high) \
      __asm__ __volatile__("rdtsc" : "=a" (low), "=d" (high))
 
-#define rdtscl(low) \
+#define rdtsc(low,high) do {						\
+	unsigned int __low1, __high1, __low2, __high2;			\
+	for (;;) {							\
+		__rdtsc(__low1,__high1);				\
+		__rdtsc(__low2,__high2);				\
+		if (__high1 == __high2 && __low2 - __low1 < 1000)	\
+			break;						\
+	}								\
+	low = __low2;							\
+	high = __high2;							\
+} while (0)
+
+#define __rdtscl(low) \
      __asm__ __volatile__("rdtsc" : "=a" (low) : : "edx")
 
-#define rdtscll(val) \
+#define rdtscl(low) do {						\
+	unsigned int __low1, __low2;					\
+	for (;;) {							\
+		__rdtscl(__low1);					\
+		__rdtscl(__low2);					\
+		if (__low2 - __low1 < 1000)				\
+			break;						\
+	}								\
+	low = __low2;							\
+} while (0)
+
+#define __rdtscll(val) \
      __asm__ __volatile__("rdtsc" : "=A" (val))
 
+#define rdtscll(val) do {						\
+	unsigned long long __val1, __val2;				\
+	for (;;) {							\
+		__rdtscll(__val1);					\
+		__rdtscll(__val2);					\
+		if (__val2 - __val1 < 1000ULL)				\
+			break;						\
+	}								\
+	val = __val2;							\
+} while (0)
+
+
 #define write_tsc(val1,val2) wrmsr(0x10, val1, val2)
 
 #define rdpmc(counter,low,high) \

I suppose you're not using jackd. As i have noticed that these critical sections only get reported when jackd is running. It seems jackd is producing a certain kind of load which exposes them..

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

so you can only trigger the latencies via mlockall-test if jackd is also running? Or do the latencies only trigger in jackd (and related programs)?

if the later, then i'm wondering whether any of the audio code turns off caching for specific pages or does DMA to user pages, or mmap()s device (PCI) memory?

Ingo

Yes. I can happily mlockall 500 megs of ram when jackd is not running and i do not get any preempt-timing reports.. As soon as jackd is running even mlockall'ing only 20megs triggers a preempt-timing report and also a alsa xrun report. Hmm, let me try turning off xrun_debug traces while leaving preempt timing reports enabled...

Ok, when xrun_debug traces are disabled [but preempt timing is on]. mlocking 20 megs of memory triggers an xrun [now only reported by jackd in it's stdout, not in syslog] but not a preempt timing report. Lee, can you verify?

So it seems that the xrun_debug reports from the alsa interface jackd is using triggers the preempt timing reports. So these are really suspicious...

So i'm asking myself: How can jackd experience an xrun, when there's no preempt-timing report showing a kernel latency. Jackd is running SCHED_FIFO, so the mlockall_test program should not take away the cpu from jackd. Is mlockall() special in another way? Sorry, i know too little about the kernel internals to ask the right question. Maybe the alsa driver is reacting to the mlockall_test..

Another piece of info which might be valuable (i cannot judge this): I use jackd and mlockall not as root, but as normal user utilizing the realtime lsm which allows non root users to mlock, mlockall and change the scheduling class (via sched_setsched()?). I'll try runnign jackd and the mlockall_test as root to see if the results differ..

Sorry, i don't understand that question..

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

Hi,

i also want to say that some of the sprocadic xruns i see do also not seem to be cause by latencies. The preempt timing reports i saw where rather results of the xrun_debug reports i think..

How do i come to this conclusion? Well i have jack running w/o ALSA xrun_debug reports but with preempt timing running for quite a while and i see about the same number of xruns as before, but i don't see any preempt timing reports anymore...

So i think jackd itself is doing some weird stuff. Or the driver of my soundcard.

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

I believe that jackd may do all of these. I am adding Paul Davis to the
cc: list as he would know better.

Whatever is going on, it only happens at jackd startup. Jackd does not report an xrun because the developers added code not to report an xrun within the first 64 frames, so this message would not confuse users.

There is definitely some subtle bug in the preempt-timing patch, because I am getting reports of long non-preemptible sections, which do not correspond to an xrun in jackd - if these were real then even a 400usec non-preemptible section would cause an xrun. I do not seem to get many xruns during normal jackd operation.

If, during initialization, jackd called some function that could sleep *after* starting the PCM, for example if it tried to allocate memory in the same thread as the audio, this would cause an xrun, because the soundcard interrupt would occur, but jackd would not be woken up because it is sleeping on some other resource, correct? Then, when jackd eventually woke up, it would see that a lot of time had passed, and report an xrun. This would look the same as if jackd had been ready to run and had not been scheduled in time.

Lee

could you send me these latest preempt-timing warnings?

Ingo

Here are all the XRUN traces and preempt-timing warnings for the last ~24 hours. I still have not had a chance to test with the latest patches & config changes.

http://krustophenia.net/2.6.8-rc3-O5/kern.log.txt

Here are some graphs from other test runs:

http://krustophenia.net/testresults.php?dataset=2.6.8-rc3-O5
http://krustophenia.net/testresults.php?dataset=2.6.8-rc2-mm2-O3

For reference here's an -mm kernel without the voluntary-preempt patches:

http://krustophenia.net/testresults.php?dataset=2.6.8-rc3-mm2

Source code for the php script:

http://krustophenia.net/testresults.phps

I based the php script on this perl script:

http://www.oddmuse.org/cgi-bin/oddmuse/GnuPlot_Extension

The web server is my desktop machine, so please don't complain if it becomes unavailable without warning. I will try to keep the links working.

Lee

Here are all the log entries produced during this test:

rlrevell@mindpipe:~$ for test in 1 2 3 4 5; do echo; echo "Test $test";
jackd -n 100000 --realtime -d alsa --rate 48000 -D -P hw:0,0 -C hw:0,2
-p 32 -S >> mm2; done

http://krustophenia.net/2.6.8-rc3-O5-A2/kern.log.txt

When one jackd process is running, starting another jackd process, using a different device produces an xrun in the first. If mlockall-test is run while a jackd process is running, this also produces an xrun in the jackd process.

So, it seems that if a SCHED_FIFO process opens a PCM device using mmap, then mlockall's the memory, then another process mlockall's memory, the result is an xrun 100% of the time.

Lee

I have found that around 1400 KB is a magic number on my system, this triggers the preempt violation/xrun about 50% of the time. 1300 never triggers it, 1500 always triggers it.

Also the amount of memory being mlockall'ed does not affect the length of the preemption violation - if we hit it at all, there's a 10ms latency, whether we lock 1400KB or 100MB.

Hopefully O6 will give enough info to track this down.

Lee

Hi,

i think that the mlockall and client/jackd startup xruns often do not seem to correspond to a critical timing report.. Try the following: turn off xrun_debug but leave the preempt-timing stuff on. On my system, the mlockall_test provokes an xrun in jackd's output but i do not get a preempt-timing report (thresh = 500).

OTOH when the xrun_debug is on, the xrun_debug report actually seems to trigger the preempt-timing report.

I think many of the jackd xruns are really jacks business. But maybe i misinterpret the symptom.

BTW: on my system with 2*64 frames the magic mlockall number seems to be around 15megs.. mlockall'ing only 10megs is very unlikely to trigger an xrun in jackd And even mlockall'ing 100 megs, while always producing an xrun in jackd, doesn't show a corresponding preempt timing report either [with preempt_thresh = 500] as long as the xrun_debug is off.

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

Even if it is not a long non-preemptible section, mlockall-test is still doing *something* that causes an xrun in jackd. Maybe interrupts are being disabled for a long time. Whatever it is, it cannot possibly be a jackd bug, because mlockall by an unrelated, normal-priority process causes an xrun in the SCHED_FIFO jackd process.

Lee

Hmm, yes, that makes sense. I wonder: does mlockall have any influence on IPC?

Flo

Palimm Palimm!
http://affenbande.org/~tapas/

Good question. I did repeat your test (disabling xrun_debug) and I can confirm that I no longer get a preempt timing violation, but mlockall-test still triggers xruns in jackd every time. So there is something else going on here.

Lee

I also get this one with apt-get dist-upgrade:

(dpkg/11902): 444us [0 jiffy] non-preemptible critical section violated 300 us preempt threshold starting at copy_mm+0x31b/0x3f0 and ending at

copy_page_range+0x144/0x290
 [<c0106497>] dump_stack+0x17/0x20
 [<c0113dc2>] touch_preempt_timing+0x32/0x40
 [<c013b7b4>] copy_page_range+0x144/0x290
 [<c0114922>] copy_mm+0x362/0x3f0
 [<c0115243>] copy_process+0x3d3/0xb60
 [<c0115a11>] do_fork+0x41/0x1b3
 [<c01049b9>] sys_clone+0x29/0x30
 [<c0105e57>] syscall_call+0x7/0xb

Shouldn't fork()'ing a dpkg process be a lot faster than that, with copy-on-write etc?

Lee

this later phenomenon is expected and unrelated: printk-ing to the console (as the ALSA xrun kernel message does) is quite expensive, especially with a full stack dump included. So this fact alone doesnt tell us much about why the xrun itself happened.

if there is no preempt-timing report when the ALSA xrun debugging is disabled it strongly suggests that whatever causes the xrun, it's not due to the length of a non-preemptible critical section, but some other phenomenon (either in userspace or in kernelspace) that causes an xrun.

irqs being left disabled by accident is one such possibility - the preempt-timing patch does not (yet) track irqs-off sections.

either jack's or the kernel's - but it's less likely to be the classical non-preemptible sections we were focused on so far. (it could still be a bug in the preempt-timing patch producing a false negative - but the likelyhood is low i'd say.)

Ingo

Here is the preempt-timing violation and accompanying xrun I got when starting jackd. It looks like the jiffies value matches the rdtsc:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139:
XRUN: pcmC0D2c

 [<c0106497>] dump_stack+0x17/0x20
 [<de92714b>] snd_pcm_period_elapsed+0x27b/0x3e0 [snd_pcm]
 [<de963171>] snd_emu10k1_interrupt+0xd1/0x380 [snd_emu10k1]
 [<c011a693>] generic_handle_IRQ_event+0x33/0x60
 [<c010765e>] do_IRQ+0xbe/0x180
 [<c0106078>] common_interrupt+0x18/0x20
 [<c013d28e>] do_no_page+0x4e/0x300
 [<c013d6e1>] handle_mm_fault+0xb1/0x150
 [<c013c118>] get_user_pages+0x138/0x3e0
 [<c013d828>] make_pages_present+0x68/0x90
 [<c013ef5f>] do_mmap_pgoff+0x40f/0x670
 [<c010b245>] sys_mmap2+0x75/0xb0
 [<c0105e57>] syscall_call+0x7/0xb
(jackd/1359): 9174us [10 jiffy] non-preemptible critical section
violated 400 us preempt threshold starting at do_IRQ+0x19/0x180 and
ending at do_IRQ+0x121/0x180 [<c0106497>] dump_stack+0x17/0x20
 [<c0113e5b>] sub_preempt_count+0x4b/0x60
 [<c01076c1>] do_IRQ+0x121/0x180
 [<c0106078>] common_interrupt+0x18/0x20
 [<c013d28e>] do_no_page+0x4e/0x300
 [<c013d6e1>] handle_mm_fault+0xb1/0x150
 [<c013c118>] get_user_pages+0x138/0x3e0
 [<c013d828>] make_pages_present+0x68/0x90
 [<c013ef5f>] do_mmap_pgoff+0x40f/0x670
 [<c010b245>] sys_mmap2+0x75/0xb0
 [<c0105e57>] syscall_call+0x7/0xb

Lee

Correction, mlockall-test *does* cause xruns. Here is the trace:

(mlockall-test/12466): 10303us non-preemptible critical section violated 400 us preempt threshold starting at get_user_pages+0xa5/0x3d0 and ending at get_user_pages+0x2e7/0x3d0

 [<c0106777>] dump_stack+0x17/0x20
 [<c01140eb>] sub_preempt_count+0x4b/0x60
 [<c013dbe7>] get_user_pages+0x2e7/0x3d0
 [<c013f198>] make_pages_present+0x68/0x90
 [<c013f5ed>] mlock_fixup+0x8d/0xb0
 [<c013f8d0>] do_mlockall+0x70/0x90
 [<c013f989>] sys_mlockall+0x99/0xa0
 [<c0106117>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D2c
 [<c0106777>] dump_stack+0x17/0x20
 [<de92f79b>] snd_pcm_period_elapsed+0x28b/0x3f0 [snd_pcm]
 [<de96c1d1>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c011ac63>] generic_handle_IRQ_event+0x33/0x60
 [<c0107a27>] do_IRQ+0xb7/0x190
 [<c0106338>] common_interrupt+0x18/0x20
 [<c0114008>] __touch_preempt_timing+0x8/0x20
 [<c013dbf4>] get_user_pages+0x2f4/0x3d0
 [<c013f198>] make_pages_present+0x68/0x90
 [<c013f5ed>] mlock_fixup+0x8d/0xb0
 [<c013f8d0>] do_mlockall+0x70/0x90
 [<c013f989>] sys_mlockall+0x99/0xa0
 [<c0106117>] syscall_call+0x7/0xb

Here is a different one:

ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: XRUN: pcmC0D0p

 [<c0106777>] dump_stack+0x17/0x20
 [<de92f79b>] snd_pcm_period_elapsed+0x28b/0x3f0 [snd_pcm]
 [<de96c437>] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
 [<c011ac63>] generic_handle_IRQ_event+0x33/0x60
 [<c0107a27>] do_IRQ+0xb7/0x190
 [<c0106338>] common_interrupt+0x18/0x20
 [<c0266777>] schedule+0x2d7/0x5b0
 [<c0266fa7>] schedule_timeout+0x57/0xa0
 [<c015fef1>] do_poll+0xa1/0xc0
 [<c0160041>] sys_poll+0x131/0x220
 [<c0106117>] syscall_call+0x7/0xb
(jackd/12430): 17135us non-preemptible critical section violated 400 us preempt threshold starting at schedule+0x57/0x5b0 and ending at schedule+0x2ef/0x5b0
 [<c0106777>] dump_stack+0x17/0x20
 [<c01140eb>] sub_preempt_count+0x4b/0x60
 [<c026678f>] schedule+0x2ef/0x5b0
 [<c0266fa7>] schedule_timeout+0x57/0xa0
 [<c015fef1>] do_poll+0xa1/0xc0
 [<c0160041>] sys_poll+0x131/0x220
 [<c0106117>] syscall_call+0x7/0xb

i've uploaded the latest version of the voluntary-preempt patch:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6

during the past couple of weeks there has been a steady trend towards rarer and harder to analyze latencies.

The preempt-timing patch was a nice starting point but it only prints limited info about the beginning and the end of a critical section - often leaving us in the dark about what happened within the critical section. Often the trace only contains generic entry/exit points like e.g. do_poll() which are not very helpful in determining the precise reason for the latency.

so in -O6 i've implemented a 'latency tracer', which automatically records all kernel functions called during a maximum-latency incident. This typically means thousands of functions per critical section. I've combined this tracer with the preempt-timing approach to produce a pretty powerful tool to find & squash latencies.

there's a new /proc/latency_trace file that holds the current latency trace (belonging to the previous high-latency event). It has a format that is intended to make it as easy as possible for kernel developers to fix any particular latency source. Audio developers and users can generate such traces and send them along to kernel developers as text files.

Sample use of the latency tracer:

E.g. the following incident:

(default.hotplug/1470): 121 us critical section violates 100 us threshold.
=> started at: <kmap_high+0x2b/0x2d0>
=> ended at: <kmap_high+0x1a9/0x2d0>

  [<c0105a23>] dump_stack+0x23/0x30
  [<c0140d14>] check_preempt_timing+0x184/0x1e0
  [<c0140e84>] sub_preempt_count+0x54/0x5d
  [<c0152959>] kmap_high+0x1a9/0x2d0
  [<c017655a>] copy_strings+0xea/0x230
  [<c01766db>] copy_strings_kernel+0x3b/0x50
  [<c017840d>] do_execve+0x12d/0x1f0
  [<c0103284>] sys_execve+0x44/0x80
  [<c0104b95>] sysenter_past_esp+0x52/0x71

this doesnt tell us too much about why it took 121 usecs to get from one end of kmap_high() to the other end of kmap_high(). Looking at /proc/latency_trace tells us the full story:

preemption latency trace v1.0
-----------------------------
latency: 121 us, entries: 1032 (1032)
process: default.hotplug/1470, uid: 0
nice: -10, policy: 0, rt_priority: 0
=======>
0.000ms (+0.000ms): page_address (kmap_high) 0.000ms (+0.000ms): page_slot (page_address) 0.000ms (+0.000ms): flush_all_zero_pkmaps (kmap_high) 0.000ms (+0.000ms): set_page_address (flush_all_zero_pkmaps)
[...]
0.118ms (+0.000ms): page_slot (set_page_address) 0.118ms (+0.000ms): check_preempt_timing (sub_preempt_count)

it's the rare but possible call to flush_all_zero_pkmaps() that generates this particular latency.

as can be seen in the above the example, the trace contains a header portion and a trace line for every kernel function called. Only function entries are recorded (not function returns) so i've added the parent function to the trace too, for easier identification of the call sequence.

there's a MAX_TRACE define in kernel/latency.c - set to 4000 currently - this is the maximum number of function calls traced per critical section. Feel free to increase/decrease this. The header portion shows the true number of functions called in a critical section, e.g.:

latency: 1531 us, entries: 4000 (16098)

tells us that there were 16098 trace entries but only the first 4000 were recorded.

-O6 also adds another timing option besides preempt_thresh: if preempt_thresh is set to 0 then the tracer will automatically track the largest-previous latency. (i.e. the system does a search for the absolute maximum latency.) The /proc/sys/kernel/preempt_max_latency control can be used to reset this value to conduct a new search for a new workload, without having to reboot the system.

-O6 also does some SMP improvements: the IRQ threads now listen to the /proc/irq/*/smp_affinity mask and bind themselves to the configured CPU. This means that e.g. the irqbalance daemon will work as expected.

-O6 also fixes and cleans up a number of other aspects of the preempt-timing mechanism.

the latency tracer can be turned on/off via CONFIG_LATENCY_TRACE at compile time. An active tracer means considerable runtime overhead. Especially code that does alot of small function calls will see a performance hit. I'm seeing a ~10% overhead on a 2GHz system, but YMMV.

reports, suggestions welcome,

Ingo

Does not compile. For each module I get:

WARNING: /lib/modules/2.6.8-rc4-O6/kernel/drivers/ieee1394/ohci1394.ko needs unknown symbol mcount

Lee

Never mind, stupid mistake on my part.

Lee

Argh, this is actually a fatal bug, and not a mistake on my part. mcount is an unknown symbol, and make modules_install does not like that.

I checked Module.symvers and it is not in there, but this seems to be a generated file, and I have no idea why mcount does not appear.

Lee

I think appending this to i386_ksyms.c fixes the problem:

#ifdef CONFIG_PREEMPT_TIMING
EXPORT_SYMBOL(mcount);
#endif

Possibly that should be CONFIG_LATENCY_TRACE.

Lee

I believe this is the correct patch, based on arch/sparc64/kernel/sparc64_ksyms.c. Ingo, are you using a sparc64 for your testing?

@@ -59,6 +59,11 @@
 extern unsigned long cpu_khz;
 extern unsigned long get_cmos_time(void);
 
+#if defined(CONFIG_MCOUNT)
+extern void mcount(void);
+EXPORT_SYMBOL_NOVERS(mcount);
+#endif
+
 /* platform dependent support */
 EXPORT_SYMBOL(boot_cpu_data);
 EXPORT_SYMBOL(MCA_bus);

Lee> I believe this is the correct patch, based on Lee> arch/sparc64/kernel/sparc64_ksyms.c. Ingo, are you using a Lee> sparc64 for your testing?

He's probably just not using modules. There's no way LATENCY_TRACE can work on anything except i386, since that's the only definition of mcount that's provided (and if one were being anal, it would probably make more sense to add the config stuff to arch/i386/Kconfig rather than init/Kconfig).

- R.

It also exists on sparc64, it's just called _mcount.

Lee

Lee> It also exists on sparc64, it's just called _mcount.

That's something completely different (used for stack overflow debugging, I think). (and ".globl mcount, _mcount" means it's also called mcount)

Look at Ingo's patch; it only adds mcount() to arch/i386 (although __mcount is defined in kernel/latency.c, there's no way for any other arch to call it).

- Roland

should be trivial to add it to other arches. But the patch indeed is x86-only for the time being - 100% of the testers so far were x86 users so i dont see any point in bloating the patch with untested arch changes. Tested contributions are welcome of course!

Ingo

Ingo,

I get the following error when I have CONFIG_PREEMPT_TIMING=n

AS arch/i386/kernel/entry.o
CC arch/i386/kernel/traps.o
arch/i386/kernel/traps.c: In function `do_nmi':
arch/i386/kernel/traps.c:539: error: syntax error before "do" arch/i386/kernel/traps.c:539: error: syntax error before ')' token arch/i386/kernel/traps.c:537: warning: unused variable `cpu' arch/i386/kernel/traps.c: At top level:
arch/i386/kernel/traps.c:541: warning: type defaults to int' in declaration of cpu'
arch/i386/kernel/traps.c:541: warning: data definition has no type or storage class
arch/i386/kernel/traps.c:542: error: syntax error before '++' token arch/i386/kernel/traps.c:500: warning: `default_do_nmi' defined but not used make[1]: *** [arch/i386/kernel/traps.o] Error 1
make: *** [arch/i386/kernel] Error 2

Matt