Voluntary Kernel Preemption Patch

as most of you are probably aware of it, there have been complaints on lkml that the 2.6 kernel is not suitable for serious audio work due to high scheduling latencies (e.g. the Jackit people complained). I took a look at latencies and indeed 2.6.7 is pretty bad - latencies up to 50 msec (!) can be easily triggered using common workloads, on fast 2GHz+ x86 system - even when using the fully preemptible kernel!

to solve this problem, Arjan van de Ven and I went over various kernel functions to determine their preemptability and we re-created from scratch a patch that is equivalent in performance to the 2.4 lowlatency patches but is different in design, impact and approach:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.7-bk20-H2

(Note to kernel patch reviewers: the split voluntary_resched type of APIs, the feature #ifdefs and runtime flags are temporary and were only introduced to enable a easy benchmarking/comparisons. I'll split this up into small pieces once there's testing feedback and actual audio users had their say!)

unlike the lowlatency patches, this patch doesn't add a lot of new scheduling points to the source code, it rather reuses a rich but currently inactive set of scheduling points that already exist in the 2.6 tree: the might_sleep() debugging checks. Any code point that does might_sleep() is in fact ready to sleep at that point. So the patch activates these debugging checks to be scheduling points. This reduces complexity and impact quite significantly.

but even using these (over one hundred) might_sleep() points there were still a number of latency sources in the kernel - we identified and fixed them by hand, either via additional might_sleep() checks, or via explicit rescheduling points. Sometimes lock-break was necessary as well.

as a practical goal, this patch aims to fix all latency sources that generate higher than ~1 msec latencies. We'd love to learn about workloads that still cause audio skipping even with this patch applied, but i've been unable to generate any load that creates higher than 1msec latencies. (not counting driver initialization routines.)

this patch is also more configurable than the 2.4 lowlatency patches
were: there's a .config option to enable voluntary preemption, and there are runtime /proc/sys knobs and boot-time flags to turn voluntary preemption (CONFIG_VOLUNTARY_PREEMPT) and kernel preemption (CONFIG_PREEMPT) on/off:

        # turn on/off voluntary preemption (if CONFIG_VOLUNTARY_PREEMPT)
	echo 1 > /proc/sys/kernel/voluntary_preemption
	echo 0 > /proc/sys/kernel/voluntary_preemption

        # turn on/off the preemptible kernel feature (if CONFIG_PREEMPT)
	/proc/sys/kernel/kernel_preemption
	/proc/sys/kernel/kernel_preemption

the 'voluntary-preemption=0/1' and 'kernel-preemption=0/1' boot options can be used to control these flags at boot-time.

all 4 combinations make sense if both CONFIG_PREEMPT and CONFIG_VOLUNTARY_PREEMPT are enabled - great for performance/latency testing and comparisons.

The stock 2.6 kernel is equivalent to:

voluntary_preemption:0 kernel_preemption:0

the 2.6 kernel with voluntary kernel preemption is equivalent to:

voluntary_preemption:1 kernel_preemption:0

the 2.6 kernel with preemptible kernel enabled is:

voluntary_preemption:0 kernel_preemption:1

and the preemptible kernel enhanced with additional lock-breaks is enabled via:

voluntary_preemption:1 kernel_preemption:1

it is safe to change these flags anytime.

The patch is against 2.6.7-bk20, and it also includes fixes for kernel bugs that were uncovered while developing this patch. While it works for me, be careful when using this patch!

Testreports, comments, suggestions are more than welcome,

Ingo

I don't think this is a good idea. Just because a function might sleep it doesn't mean it should sleep. I'd rather add the might_sleep() to cond_resched() and replace the former with the latter in the cases where it makes sense.

agreed. might_sleep() just like BUG() can be defined to noop.

cond_resched() is the API to use.

the other bad thing is that there is no point for the sysctl (in 2.4 that made no sense at all too, yeah it only makes sense for benchmarking easily w/ and w/o the feature but it must be optimized away at the very least with a config option for production), if need_resched is set we _must_ schedule no matter what (a sysctl can only introduce a bug if something). If we spend any cpu checking the sysctl, we should instead spend such cpu to check need_resched in the first place.

The rest is of course very welcome, but you should remove all the pollution from the patch to make it mergeable.

Just convert all those might to cond_resched() and remove all the superflous volountary stuff and config options.

As worse you can leave a single config option LOW_RESCHEDULE_OVERHEAD with PREEMPT=n, that could remove some cond_resched() from an extremely fast path if you're concerned about adding branches in some critical point, but you really seem not concerned since with CONFIG_PREEMPT_VOLUNTARY=y (the only way to enable it) you even _waste_ cpu on these paths to check a worthless sysctl that can only introduce bugs at runtime since it overrides the wishes of the scheduler.

If scheduler is bad fix the scheduler, but as soon as need_resched is set no sysctl must be allowed to mask the wishes of the scheduler.

BTW, this reminded me a related topic that I can't recall being ever mentioned on l-k: BUG_ON can also be optimized away. So people should be careful not to do write this:

        BUG_ON(test_and_set_bit(p))

but to write this instead:

        if (unlikely(test_and_set_bit(p))
                BUG()

(in short the check inside a BUG_ON must be strictly read-only since it's not guaranteed to be computed)

google for 'BUG_ON side effects'. It's come up a number of times 8-) Doesn't mean it isn't worth repeating however.

Dave

At Sat, 10 Jul 2004 02:52:08 +0200,

Couldn't it be simply written like below?

#define BUILD_BUG_ON(condition) do { if (unlikely(condition)) BUILD_BUG(); } while(0)

Takashi

BUILD_BUG_ON is a different thing. the "condition" is meant to be evaluated at _compile_ time, not at runtime (so the unlikely is useless since the compiler knows the result before it generates the bytecode). This is why BUILD_BUG() isn't implemented anywhere, so you get a linker error during the compilation.

For example with it you can do things like:

	BUILD_BUG_ON(offsetof(struct task_struct, thread.i387.fxsave) & 15);

(see asm-i386/bugs.h, it's doing the BUILD_BUG_ON by hand right now)

At Mon, 12 Jul 2004 21:36:06 +0200,

Yes, sorry for confusing, copy & paste from a wrong place.

I'm just wondering whether '!=0' is needed inside unlikely() as defined in asm-i386/bug.h:

#define BUG_ON(condition) do { if (unlikely((condition)!=0)) BUG(); } while(0)

Without '!= 0', it's expanded identically as you wrote. Well, the compiler may get rid of it after optimization...

BTW, BUG_ON(a||b) is a different story, of course :)

Takashi

as Ingo wrote, that is the plan, all that "crud" is there just to make it easy to benchmark for now.

[snipped another 30 lines of rant]

           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Ingo

A patch against 2.6.7 would be more appreciated as Linus looks like won't release 2.6.8 soon.

Time is what you make of it

i've uploaded the -H3 patch against 2.6.7-vanilla to:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.7-vanilla-H3

(NOTE: this patch upgrades to Jens' latest version of cfq-iosched.c, because one of the might_sleep() additions uncovered a bug there.)

i've done a quick testboot on x86, seems to work fine.

Ingo

i've uploaded the latest (-H4) voluntary-preempt patch to:

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

Changes from -H3 to -H4:

- fixes the ext3 bug reported by Zwane Mwaikambo
- port to 2.6.8-rc2

There are also patches are against 2.6.7-vanilla, 2.6.7-mm7 and 2.6.7-bk20.

Ingo

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Ingo Molnar wrote:

| i've uploaded the latest (-H4) voluntary-preempt patch to:
|
|   http://redhat.com/~mingo/voluntary-preempt/
|
| Changes from -H3 to -H4:
|
|  - fixes the ext3 bug reported by Zwane Mwaikambo
|  - port to 2.6.8-rc2
|
| There are also patches are against 2.6.7-vanilla, 2.6.7-mm7 and
| 2.6.7-bk20.

With 2.6.8-rc2 I get this with loop module

loop: Unknown symbol voluntary_resched

- --
Ram?n Rey Vicente <ramon dot rey at hispalinux dot es>
jabber ID <rreylinux at jabber dot org>
GPGid 9F28E377 - 0BC2 8014 2445 51E8 DE87 C888 C385 A9D3 9F28 E377
===================================================================
"Copyright doesn't cover ideas; it's your expression of those ideas." (Richard M. Stallman)
===================================================================
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (GNU/Linux)
Comment: Using GnuPG with Thunderbird - http://enigmail.mozdev.org

iD8DBQFA/Hd4w4Wp058o43cRAlN3AJ4o3UMjamq7tsPyh1q29XbV9+ke/gCdFrJG 3X5SmTFL23bduwutltZw01o=
=kIAm
-----END PGP SIGNATURE-----

ok, just add this to kernel/sched.c:

	EXPORT_SYMBOL(voluntary_resched);

i'll update the patch.

Ingo

if this means you agree with Christoph's other points too that's fine with me.

think of voluntary preemption as a variant of CONFIG_PREEMPT with different tradeoffs: it doesnt preempt as much code but it's cheaper (in terms of code footprint and overhead) and less risky (in terms of code affected).

What you say is equivalent to: 'because a process has higher priority it doesnt mean it should be scheduled to', which is the wrong approach because it is ultimately the decision of the user which tasks get scheduled (by giving processes various priorities) and the decision of the scheduler (for freely schedulable tasks). The preemption decision does not depend and should not depend on the kernel function utilized!

if you dont care about latencies and want to maximize throughput (for e.g. servers) then you dont want to enable CONFIG_PREEMPT_VOLUNTARY. That way you get artificial batching of parallel workloads.

FYI, i am also preparing a preemption patch where there's a (per-task) tunable for 'expected maximum latency' and the kernel would measure latencies and not do a forced preemption unless this latency is being exceeded.

Voluntary preemption and CONFIG_PREEMPT means this tunable has a value of 0 - we reschedule as soon as possible. Server workloads mean a much higher tolerated latency value in the range of 50 msecs or so. Both are fair expectations and settings.

Ingo

I've conducted some of the old fashioned Benno's latency test on this patch in various sysctl configurations. This was done on top of a different tree but everything else was kept static. I have to preface these results by saying I don't really get the 50ms size latencies normally but I'm usually unable to get better than 3ms so I wasn't sure what to expect.

Only the both preempt off showed any "outlying" results with one spike of ~20ms but the rest of the time being ~3ms. Enabling both forms of preempt seemed to help a little but nothing drastic, and never below 1ms. It was not universal that the latencies were better, but there was a trend towards better latency. I suspect that those who are getting huge latencies may see a bigger change with this patch than I did.

http://ck.kolivas.org/latency/

Con

is that the test which skews with irq's disabled ? (eg uses normal interrupts and not nmi's for it's initial time inrq)

It probably is; in which case all these results would be useless, no?

http://www.gardena.net/benno/linux/latencytest-0.42.tar.gz

Con

I think Arjan is referring to rtl_latencytest.c

So to state the bleedingly obvious, this would make these benchmark results valid.

If you're interested the command I used was:
./do_tests none 3 256 0 1500000000
as root

Which uses a 1.5Gb file during the disk i/o tests since my machine has 1Gb ram.

Con

Brain packet loss, make that rtc_latencytest.c

did you run latencytest as root?

Ingo

I wish it were that simple to fix it. Here's what I said later in this thread:

---
If you're interested the command I used was:
./do_tests none 3 256 0 1500000000
as root

Which uses a 1.5Gb file during the disk i/o tests since my machine has 1Gb ram.
---

Con

Ooops forgot to mention this was running reiserFS 3.6 on software raid0 2x IDE with cfq elevator.

Con

ok, reiserfs (and all journalling fs's) definitely need a look - as you can see from the ext3 mods in the patch. Any chance you could try ext3 based tests? Those are the closest to my setups.

Ingo

Sorry, I only have one machine to my name and I have to share it with both the family and testing so no such luck.

Con

Well, I'm now only working on some documentation, so I think I can run some tests if they are automated enough, on either i686 or x86-64 machine (both SMP). There's about 5 - 10 GB of free disk space on each (ext3, but I can create a reiserfs easily, if needed).

If you want me to do this, please provide me with:
a) patches to test,
b) benchmark tools,
c) instructions (what to turn on/off in the kernel config, how to run the benchmarks - I need to be able to use a text editor while they are running and occasionally run a web browser or acroread, but I don't care much if the system crashes on them).

Yours,
rjw

Rafael J. Wysocki
----------------------------
For a successful technology, reality must take precedence over public 
relations, for nature cannot be fooled.
					-- Richard P. Feynman

Ingo, what are you using for measuring thread wakeup latency?

Ok I've done one better than that ;) I had wli help make some instrumentation for me to help find the remaining non preemptible kernel portions and set the cutoff to 2ms. Here is what I found:

7ms non-preemptible critical section violated 2 ms preempt threshold starting at reiserfs_sync_fs+0x2d/0xc2 and ending at reiser fs_lookup+0xe2/0x221

9ms non-preemptible critical section violated 2 ms preempt threshold starting at reiserfs_dirty_inode+0x37/0x10e and ending at r eiserfs_dirty_inode+0xb0/0x10e

These seem to be the two offenders. Hope this helps.

Con

Oh and here are two different ones:

5ms non-preemptible critical section violated 2 ms preempt threshold starting at add_wait_queue+0x21/0x82 and ending at add_wait _queue+0x4a/0x82

3ms non-preemptible critical section violated 2 ms preempt threshold starting at exit_mmap+0x1c/0x188 and ending at exit_mmap+0x 118/0x188

Con

great!

meanwhile i spent an afternoon with another latency testing suite:

http://www.alsa-project.org/~iwai/latencytest-0.5.3.tar.gz

it was reporting more accurate latencies, except that there were strange spikes of latencies. It turned out that for whatever reason, userspace RDTSC is not always reliable on my box (!).

I've attached two fixes against latencytest - one makes rdtsc timestamps more reliable, the other one fixes an SMP bug in the kernel module (it would lock up under SMP otherwise.).

here's a latencytest QuickStart: 'cd latencytest; make', then 'insmod kernel/latency-test.ko', then 'cd tests; ../bin/run_tests'.

Assuming you have RTC and audio enabled in your kernel it should work fine. It produces PNGs in the same format as Benno's latencytest suite.

Ingo

@@ -41,7 +41,7 @@ static void my_interrupt(void *private_d
 	spin_lock(&my_lock);
 	count++;
 	if (count < irq_count)
-		return;
+		goto out_unlock;
 	count = 0;
 	if (irq_info.processed < MAX_PROC_CNTS) {
 		int i;

@@ -69,6 +69,7 @@ static void my_interrupt(void *private_d
 	}
 	irq_info.processed++;
 	wake_up(&my_sleep);
+out_unlock:
 	spin_unlock(&my_lock);
 }
 

@@ -35,9 +35,13 @@ static FILE *profile_fd;
 
 static inline unsigned long long int rdtsc(void)
 {
-	unsigned long long int x;
-	__asm__ volatile ("rdtsc" : "=A" (x));
-	return x;
+	unsigned long long int x, y;
+	for (;;) {
+		__asm__ volatile ("rdtsc" : "=A" (x));
+		__asm__ volatile ("rdtsc" : "=A" (y));
+		if (y - x < 1000)
+			return y;
+	}
 }
 
 static unsigned long long time_offset;

Hi, can anyone explain this:

Using Ingo's first patch when I:
echo 1 > /proc/sys/kernel/kernel_preempt

my system hang up after 2 seconds aproximately.

Using Ingo's modifications + Con's it doesn't lock anymore

and is the best kernel that I have used to test..

Thanks!

[]s,

André

I had the same problem.

Yes, my too. Maybe H3 version of Ingo's patch fixed that?

Yes, 2.6.7-bk20-ck5 is really the best!

Thanks,

Grzegorz Kulewski

You have an earlier snapshot wich had Ingo's H2 patch which was buggy. The last snapshot I announced had Ingo's H3 patch which fixed that exact problem.

Cheers,
Con

Yes I tried with pure H3 in the meantime and I can confirm my and yours
words: it fixed the problem.

Thanks,

Grzegorz Kulewski

Hi All!

I still use in my home minicomputer under Linux, where
3 users use one CPU/RAM , but own video.
By default 2.6.XX task scheduler don' t like concurent applications
at all. 2.6.XX task scheduler allways raise on top of tasks only one task and keep it on top until user stop it.
This rule is very unwanted for minicomputers, because multile
local users will use one CPU and feel lucky.

As point of reference i use 2.4.XX tack scheduler, which is very
"righteous" and allways give CPU time for all tasks. Under 2.4.XX concurent games run smooth.

2.6.XX non-preemptive and 2.6.XX voluntary-preemptive task
scheduling looks very similar. My gamer' s eye report me very thiny and very subjective difference - preferable is voluntary-preemtive. Anyway all concurent CPU intensive tasks should be started with nice -n +19 game-bin . Any other nice value remake one of running game to slide show or both running games became slide show.

So we should start any game with nice +19. In is this set goes in
netscape and konqueror because of java web-chat and games.

At least voluntary-preemptive allow me move away from 2.4.26

Aivils Stoss

I'm not sure I understand you. You said that voluntary preempt and preempt look the same yet in your last line you say voluntary preempt allows you to move away from 2.4.26?

Anyway apart from that comment I'm not really sure how you can address this because if nice +19 works at smoothing out the games then that almost surely suggests a yield() implementation in your games. Unfortunately this, I noticed while coding my new scheduler policy, seems to be _very_ common. There were lots of "big name" new games that did the same thing. It was decided quite a while back in 2.5 development that applications that use yield() for locking were broken by design. If nice +19 fixes the problem then all I can suggest for the time being is to use nice +19. The fact that the current processor is much more out-of-order in it's scheduling is what is fooling these applications now, and their unfortunate programming suffers in that setting.

What you need to cope with this is gang scheduling, but that's absurd to implement such a complicated policy to cope with poor application coding. Gang may be implemented in the future for different reasons, though.

Con

He said that voluntary preempt and non-preempt look similar but voluntary preempt subjectively feels better. Standard preempt was not compared as I understand.

Lenar

Before moving away from 2.4.26 was insane for me. I check out vanilla and Your kernels and reboot back to 2.4.26 as soon as i can. My decision is _subjective_.

I will more play games neither measure miliseconds :)
I do not know how to profile all 4-5 threads of game, epspecialy if runs two copies. Video, audio, net, game-logic latency ?

Seems magic touch is "nice +19" , scheduler independ.

Actulay i do not need because 2.4.XX do all things. I will notify developers about exisiting of trouble. sched.c developers do all counter my needs :)

Aivils

The CPU scheduler in 2.6 does a lot of special casing in order to boost interactivity. This can cause weird behaviour and imbalances like you are seeing when multiple things are running.

2.6's CPU scheduler gives nice +19 tasks shorter timeslices, so you are effectively giving everything better latency.

I have a patchset for 2.6 with some scheduler changes that you might like to try, here: http://www.kerneltrap.org/~npiggin/2.6.7-np8/, and let me know how it goes if you do try it. If you need any help getting it going, please email me privately.

Would the fact that rdtsc is not serializing have any effect here? Or would that be a small enough error to not have any effect?

Chris

even though it's not serializing (to other instructions), one would expect the '64-bit cycle counter' to be fetched atomically. And several milliseconds cannot be explained with any micr-op delays anyway.

Ingo

you just agreed a second time to make all the pollution go away, so why are you talking about servers now? I mean, I don't see why production environments should run the benchmarking testcode. And I totally disagree CONFIG_PREEMPT_VOLUNTARY disabled could provide any benefit on a server (even with the benchmarking on). Servers have to start the next I/O too to avoid leaving some disk idle during a copy-user etc..

let's assume you convert the benchmark sysctl knob into a CONFIG_LOW_RESCHEDULE_OVERHEAD as I suggested in the 30 lines rant, only then it could make sense to classify some of the scheduling points as "high-overhead", but I don't see the need of CONFIG_LOW_RESCHEDULE_OVERHEAD happening any time soon. Though such a config option would make sense theoretically.

this all seems pretty cool...
do you think you could make a patch against mm for this? it would be greatly apreciated

it should apply cleanly to 2.6.7-mm6. -mm7 already includes most of the might_sleep() additions. I'll do a patch against -mm7 too.

Ingo

here's the patch against -mm7:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.7-mm7-H3

the patch got really small because most of the fixes and infrastructure enhancements that resulted out of this patch are in -mm7 already. It will get even smaller later on.

Ingo

Tested on 2.6.7-bk20, Pentium3 700 mhz, 576 mb RAM

I did cp -rf big_folder new_folder . Then opened up a gui ftp client and music in amarok started to skip like for 2-3 seconds.

Btw Amarok uses Artsd ( KDE Sound Daemon ) which in turn set to use Jack Alsa Backend.

Cheers,
ismail

Time is what you make of it

that somewhat sounds more like a disk IO stall... which IO scheduler are you using ?

(I can recommend using CFQ for this)

cartman@southpark:~$ dmesg | grep sched
Using anticipatory io scheduler

Problem is I rarely do this copy operations like once a week or 2 weeks. Guess there is no scheduler that fits both desktop usage + these kinds of operations?

Cheers,
ismail

Time is what you make of it

CFQ seems to be quite good for desktop too in my experience...

For our benefit, could you try to recreate the situation with the cfq scheduler, and see if it still skips? If not, also do a run with the anticpatory scheduler again to see if your recreation was enough to cause a skip there...

That would at least point to the culprit (disk or cpu starvation)

Thanks
Nick

what filesystem are you using?

also, are you sure it's not pure IO latency (or swapout) that hits you? Do you get the same if you copy the music file to /dev/shm and play from there?

Ingo

XFS

Ok tested with mplayer -ao jack it *didn't* skip once during a large copy ( Tested with CFQ ). So I guess aRts has some problems with jack.

Cheers,
ismail

Time is what you make of it

i've fixed latencies in ext3, i'm not sure how bad XFS is. But 2-3 seconds delay is almost impossible to be a true scheduling latency - it's probably IO latency impacting your audio application. (it could also be normal preemption latency, if those tasks are not running as SCHED_FIFO - but 2-3 seconds preemption latency should not be caused by a simple cp -a. This leaves IO latency.).

Ingo

But it only skips when using aRts, which points the other way ;)

If all tasks are using realtime scheduling, then this discounts the scheduler from the equation, however I'm not sure if this is the case?

jack uses realtime through realtime lsm module so it can do mlock() , I tried making aRts run real time too but it didn't prevent skips either.

Cheers,
ismail

Time is what you make of it

At Sat, 10 Jul 2004 13:55:25 +0300,

Did you run JACK on linuxthreads (with LD_ASSUME_KERNEL=2.4.xx) ?

On NPTL with jackstart, JACK clients don't get set to SCHED_FIFO correctly.

Takashi

I dont't have NPTL.

Time is what you make of it

At Mon, 12 Jul 2004 16:09:14 +0300,

Then the problem must be on artsd, possibly handling the job with a normal scheduling. Stalling for 2-3 seconds with RT task is quite unusual.

Takashi

This looks great - one small problem: when compiling with ext3 as a module, I get:

WARNING: /lib/modules/2.6.7-bk20-vp/kernel/fs/jbd/jbd.ko needs unknown symbol voluntary_preemption

I just compiled ext3 in, solving that problem, and am taking it for a spin as soon as I send this and reboot...

Torrey Hoffman
[email protected]

...

ok, i fixed this bug in -H3:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.7-bk20-H3

(-H3 also fixes another bug when enabling CONFIG_PREEMPT.)

Ingo

Looks nice.

I think you may have mixed up your trees. I think this change is the cfq bad allocation fix which I dont think is part of your voluntary preemption patch:

--- linux/drivers/block/cfq-iosched.c.orig
+++ linux/drivers/block/cfq-iosched.c

Otherwise, cheers! I'll give it a bit of a run and see what numbers come up.

Con

It was this patch that found this bug 8-) Without voluntary-preempt it had been lying there unexposed for a while. It's sort of must-have if you use this patch, so I guess that's why Ingo rolled it in until mainline gets the same fix.

Dave

correct. E.g. 2.6.7-mm7 already has the patch so for that tree there's no cfq-iosched.c change in the voluntary-preempt patch. And for 2.6.7-vanilla there's a big cfq-iosched.c delta to include the other improvements from Jens as well on which the bugfix depends.

the patch didnt really trigger the bug itself, it triggered an annoying debugging message instead ;)

Ingo

What were those workloads?

Certainly 2.6+preempt is not as good as 2.4+LL at this time, but 2.6 isn't too bad either. Even under heavy filesystem load it's hard to exceed a 0.5 millisecond holdoff. There are still a few problem in the ext3 checkpoint buffer handling, but those seem pretty hard to hit. I doubt if the Jack' testers were running dbench 1000' during their testing.

All of which makes me suspect that the problems which the `Jack' testers saw were not directly related to long periods of non-preemption in-kernel. At least, not in core kernel/fs/mm code. There have been problem in the past in places like i2c drivers, fbdev scrolling, etc.

What we need to do is to encourage audio testers to use ALSA drivers, to enable CONFIG_SND_DEBUG in the kernel build and to set /proc/asound/*/*/xrun_debug and to send us the traces which result from underruns.

As for the patch, well, sprinkling rescheduling points everywhere is still not the preferred approach. But adding more might_sleep() checks is a sneaky way of making it more attractive ;)

Minor point: this:

	cond_resched();
	function_which_might_sleep();

is less efficient than

	function_which_might_sleep();
	cond_resched();

because if function_which_might_sleep() _does_ sleep, need_resched() will likely be false when we hit cond_resched(), thus saving a context switch. Unfortunately, might_sleep() calls tend to go at the entry to functions, whereas cond_resched() calls should be neat the exit point, or inside loop bodies.

agreed, but the argument goes both ways. Whether entry or exit scheduling is better very much depends on the function.

E.g. for user copy type of stuff we often want to do the reschedule _first_, to not pollute the cache with hot (dirty) cachelines that likely get thrown away - and which have to be brought back again later on.

For IO type of functions that will sleep we most likely want to preempt at the exit of the function.

but we'd like to profile the typical preemption points (hence the profile=sched profiling change) to determine which are the hottest functions. For those handful of functions we can do __might_sleep() at the front of the function and a cond_resched() at the back. For all the other 200 might_sleep() points it doesnt matter much.

i've also added the nr_preempt counter so that we can see the proportion of forced preemption vs. intentional reschedules for various workloads.

Ingo

Sorry, but an additional 100 might_sleep()s is surely excessive for debugging purposes, and unneeded for latency purposes: all these sites are preemptible anyway.

Let me repeat that I am unconvinced as to the diagnosis of the current audio problems - more analysis might prove me wrong of course.

And I'm unconvinced that we need to do anything apart from identifying and fixing the remaining spinlocks which are holding off preemption for too long.

IOW, I am questioning the very need for a "voluntary preemption" feature at all when "involuntary preemption" works perfectly well.

nono, i mean the existing ones. (it's 116 not 200) There's no plan to add another 100, you've seen all the ones we found to be necessary for this.

Ingo

OK, but most of the new ones are unneeded with CONFIG_PREEMPT=y. I'm still failing to see why a non-preempt, voluntary preemption kernel even needs to try to be competitive with a preemptible kernel?

the reason is difference in overhead (codesize, speed) and risks (driver robustness). We do not want to enable preempt for Fedora yet because it breaks just too much stuff and is too heavy. So we looked for a solution that might work for a generic distro.

here are the code size differences. With a typical .config (debugging options disabled), the 2.6.7-mm7(+voluntary-preempt) UP x86 kernel gets the following .text sizes:

orig: 1776911 bytes
preempt: 1855519 bytes (+4.4%)
voluntary: 1783407 bytes (+0.3%)

so if voluntary-preempt can get close to real preempt's numbers for practical stuff then we get most of the benefits while excluding some of the nastiest risks and disadvantages.

(Long-term i'd like to see preempt be used unconditionally - at which point the 10-line CONFIG_VOLUNTARY_PREEMPT Kconfig and kernel.h change could go away.)

Ingo

I don't recall any testing results which showed a significant performance difference from CONFIG_PREEMPT.

What stuff?

We'll never get there if people don't at least report the broken "stuff", let alone fix it. And "stuff" is already broken on SMP, yes?

Your voluntary preempt patch will need to borrow preempt_spin_lock() and preempt_write_lock() btw - otherwise it won't improve worst-case latencies on SMP at all.

just look over all the "fix preempt" stuff that got added to the kernel in the last 6 months. Sometimes subtle sometimes less so. From a distribution POV I don't want a potential slew of basically impossible to reproduce problems, especially this young in 2.6, there are plenty of other problems already (and before you ask "which", just look at how many bugs got fixed in the last X weeks for any value of X, and look at say acpi issues). Yes I understand this puts you into a bit of a bad position, several distros not enabling preempt means that it gets less testing than it should. However.. there's only so much issues distros can take and with 2.6 still quite fresh...

That's the classic preempt "myth"; it's true if you ignore per cpu stuff and some other subtle issues ;) And even then, yes a lot of our drivers are not quite SMP safe. Take ISDN or any of the other declared SMP-broken drivers. Not to speak of the ones that aren't declared as such yet still are. Regardless of Hyperthreading, smp is still quite rare while crappy hardware/drivers are not.

Do the BROKEN_ON_SMP tests get triggered in Kconfig for PREEMPT ? It probably should.

Greetings,
Arjan van de Ven

IOW: "we haven't found any such stuff". Sounds fuddy to me.

?

Sticking a WARN_ON(!in_atomic()) if CONFIG_PREEMPT into smp_processor_id() should catch any missed fixes.

Oh I can buy the make-the-bugs-less-probable practical argument, but sheesh. If you insist on going this way we can stick the patch in after 2.7 has forked. I spose. The patch will actually slow the rate of improvement of the kernel :(

For example the recent race that corrupted file content on ext3 and reiserfs when fsync and write were called simultaneously ... it was possible on SMP too, but with tiny probability --- CONFIG_PREEMPT triggered it wide open.

Mikulas

Looks like some of the voluntary preemption changes might need some eyeballing too. This appears to be a use after free, probably since we unlocked j_{list,state}_lock.

Unable to handle kernel paging request at virtual address d90ccfa0
 printing eip:
c01e667f
*pde = 00066067
Oops: 0000 [#1]
PREEMPT SMP DEBUG_PAGEALLOC
Modules linked in:
CPU:    1
EIP:    0060:[<c01e667f>]    Not tainted
EFLAGS: 00010202   (2.6.7-bk20-ck5)

EIP is at __journal_clean_checkpoint_list+0x3f/0x1d0
eax: 00000001 ebx: 00000000 ecx: df34bdf8 edx: d90ccf78
esi: df34be0c edi: df34bedc ebp: de893dac esp: de893d88
ds: 007b es: 007b ss: 0068
Process kjournald (pid: 36, threadinfo=de892000 task=deea8a50)

Stack: de892000 d23fa7e4 00000172 d91a9f78 c7da0f78 d90ccf78 de892000 df34bdf8
       df34be7c de893f50 c01e3956 df34bdf8 c014cc71 dffb1200 c4cccf60 00000046
       de892000 df34bedc df1d1e18 c4cccf60 d8b0efb0 df34be0c 00000000 00000000
Call Trace:
 [<c0107775>] show_stack+0x75/0x90
 [<c01078d5>] show_registers+0x125/0x180
 [<c0107a67>] die+0xa7/0x170
 [<c011ad08>] do_page_fault+0x1e8/0x57d
 [<c01073cd>] error_code+0x2d/0x40
 [<c01e3956>] journal_commit_transaction+0x316/0x1aa0
 [<c01e7994>] kjournald+0x114/0x3b0
 [<c01042a5>] kernel_thread_helper+0x5/0x10
Code: 8b 72 28 85 f6 74 58 8b 4e 2c b8 00 e0 ff ff 89 4d e0 89 f7
 <6>note: kjournald[36] exited with preempt_count 2

(gdb) list *0xc01e667f
0xc01e667f is in __journal_clean_checkpoint_list (fs/jbd/checkpoint.c:485).
480 struct journal_head *jh;
481
482 transaction = next_transaction;
483 next_transaction = transaction->t_cpnext;
484 retry:
485 jh = transaction->t_checkpoint_list;
486 if (jh) {
487 struct journal_head *last_jh = jh->b_cpprev;
488 struct journal_head *next_jh = jh;
489

thx - this is the new __journal_clean_checkpoint_list() chunk:

@@ -465,6 +470,7 @@ int __journal_clean_checkpoint_list(jour
 	transaction_t *transaction, *last_transaction, *next_transaction;
 	int ret = 0;
 
+retry:
 	transaction = journal->j_checkpoint_transactions;
 	if (transaction == 0)
 		goto out;

@@ -487,6 +493,14 @@ int __journal_clean_checkpoint_list(jour
 				/* Use trylock because of the ranknig */
 				if (jbd_trylock_bh_state(jh2bh(jh)))
 					ret += __try_to_free_cp_buf(jh);
+				if (voluntary_need_resched()) {
+					spin_unlock(&journal->j_list_lock);
+					spin_unlock(&journal->j_state_lock);
+					voluntary_resched();
+					spin_lock(&journal->j_state_lock);
+					spin_lock(&journal->j_list_lock);
+					goto retry;
+				}
 			} while (jh != last_jh);
 		}
 	} while (transaction != last_transaction);

I think we should work toward being able to enable kernel preemption in Fedora, then, instead of other tangential solutions.

And I disagree with the overhead argument. I have seen no specific arguments that show a significant overhead. Heck, when people tried to show that kernel preemption hurt throughput, we saw tests that showed improved throughput (probably due to better utilization of I/O).

But stability is a subjective argument (and I agree we need more driver love, at least for obscure drivers) wrt kernel preemption. So I would say we should concentrate on working on the stability[1] so we could just enable kernel preemption unconditionally and not designing new solutions.

Best,

Robert Love

[1] What better way than enabling CONFIG_PREEMPT for Fedora? Enable it for Fedora, and do not enable it for Red Hat Enterprise until you are confidant. ;-)

You left off the smiley, if the existing approach worked perfectly well then users wouldn't complain and Ingo would be doing something else with his time.

Naturally after you identify and fix all those spinlock delays this will all work even better.

   -bill davidsen ([email protected])
"The secret to procrastination is to put things off until the
 last possible moment - but no longer"  -me

Andrew> What were those workloads?

Andrew> Certainly 2.6+preempt is not as good as 2.4+LL at this time, Andrew> but 2.6 isn't too bad either. Even under heavy filesystem Andrew> load it's hard to exceed a 0.5 millisecond holdoff. There are Andrew> still a few problem in the ext3 checkpoint buffer handling, Andrew> but those seem pretty hard to hit. I doubt if the Jack' Andrew> testers were running dbench 1000' during their testing.

I'd like to chime in here with a data point, though I'm not sure how usefull it really is. I've got a Dual CPU, 550mhz, 768mb 440BX system. Running 2.6.7 plain. I was playing XMMS and some music, and trying to do the following from my mirrored data disks, to a new USB external storage case, with the exact same drive as the pair of internal systems.

cd /home
tar cf - . | (cd /mnt/portable; tar xpf -)

And the system load jumped to around 5 or 7. Part of it was because I had turned on usb-storage debugging, so syslog was hammering the disks. Note, root, /usr, and such are on a seperate SCSI disk from /home and /local. I had xmms, some xterms and galeon up and running. Occassionally, xmms would stutter. Then the entire system locked up with xmms stuck in a loop playing the same sound over and over again. No response on the USB bus, SysRq didn't work. Had to hit the main reset button to get it back again.

All filesystems are ext3 on here as well. More details as I get this tested out more, and I'll try to fill out a report on the usb-devel list as well.

So in summary, there are some problems still in 2.6.7, though they are more related to:

1. The delay in starting writeout to disk when streaming large (I know, a subjective number) transfers. The above tar commands didn't start kicking data to the USB device for quite a while. I know there's overheard of reading the directory structure first, so that could be it. But it just seems to wait a bit before actually writing data out.

John

OK, here goes. The following traces result from running JACK overnight like so, on an otherwise idle system. Hardware is a VIA EPIA 6000, with a 600Mhz C3 processor. Kernel is 2.6.7 + volunatary_preempt patch. voluntary_preempt and kernel_preemption are both on.

jackd -v --realtime -d alsa --outchannels 2 --rate 48000 --shorts --playback --period 32 --nperiods 2

These settings require less than 666 microseconds scheduler latency. The average performance is quite good - 5-20 *microseconds*!

load = 0.3754 max usecs: 5.000, spare = 661.000
load = 1.1637 max usecs: 13.000, spare = 653.000
load = 3.0593 max usecs: 33.000, spare = 633.000
load = 1.9050 max usecs: 5.000, spare = 661.000
load = 1.4780 max usecs: 7.000, spare = 659.000
load = 1.2645 max usecs: 7.000, spare = 659.000
load = 1.0076 max usecs: 5.000, spare = 661.000
load = 1.1044 max usecs: 8.000, spare = 658.000
load = 0.9276 max usecs: 5.000, spare = 661.000
load = 1.5148 max usecs: 14.000, spare = 652.000
load = 1.1328 max usecs: 5.000, spare = 661.000
load = 1.0168 max usecs: 6.000, spare = 660.000

However there are periodic XRUNS. I noticed that many of these seem APM-related, so here are the relevant settings:

# Power management options (ACPI, APM)
# APM (Advanced Power Management) BIOS Support
CONFIG_APM=y
# CONFIG_APM_IGNORE_USER_SUSPEND is not set
# CONFIG_APM_DO_ENABLE is not set
CONFIG_APM_CPU_IDLE=y
# CONFIG_APM_DISPLAY_BLANK is not set
CONFIG_APM_RTC_IS_GMT=y
# CONFIG_APM_ALLOW_INTS is not set
# CONFIG_APM_REAL_MODE_POWER_OFF is not set

I did not intend to activate these settings when I compiled the kernel, but as this is certainly not an idle system, it seems like there may be a bug lurking.

The log excerpts below are annotated. Sorry if it is too long.

This section of the log is from running JACK overnight:

Jul 12 06:56:07 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 06:56:07 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 06:56:07 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 06:56:07 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 06:56:07 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 06:56:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 06:56:07 mindpipe kernel:  [preempt_schedule+16/80] preempt_schedule+0x10/0x50
Jul 12 06:56:07 mindpipe kernel:  [rt_run_flush+135/144] rt_run_flush+0x87/0x90
Jul 12 06:56:07 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 06:56:07 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 06:56:07 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 06:56:07 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 06:56:07 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 06:56:07 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 06:56:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 06:56:07 mindpipe kernel:
Jul 12 07:46:07 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 07:46:07 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 07:46:07 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 07:46:07 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 07:46:07 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 07:46:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 07:46:07 mindpipe kernel:  [preempt_schedule+1/80] preempt_schedule+0x1/0x50
Jul 12 07:46:07 mindpipe kernel:  [rt_run_flush+135/144] rt_run_flush+0x87/0x90
Jul 12 07:46:07 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 07:46:07 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 07:46:07 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 07:46:07 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 07:46:07 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 07:46:07 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 07:46:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 07:46:07 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 07:46:07 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 07:46:07 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 07:46:07 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 07:46:07 mindpipe kernel:
Jul 12 08:06:07 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 08:06:07 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 08:06:07 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 08:06:07 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 08:06:07 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 08:06:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:06:07 mindpipe kernel:  [local_bh_enable+46/112] local_bh_enable+0x2e/0x70
Jul 12 08:06:07 mindpipe kernel:  [rt_run_flush+92/144] rt_run_flush+0x5c/0x90
Jul 12 08:06:07 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 08:06:07 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 08:06:07 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 08:06:07 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 08:06:07 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 08:06:07 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 08:06:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:06:07 mindpipe kernel:
Jul 12 08:26:06 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 08:26:06 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 08:26:06 mindpipe kernel:  [ide_build_sglist+50/160] ide_build_sglist+0x32/0xa0
Jul 12 08:26:06 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 08:26:06 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 08:26:06 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 08:26:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:26:06 mindpipe kernel:  [del_timer+110/144] del_timer+0x6e/0x90
Jul 12 08:26:06 mindpipe kernel:  [schedule_timeout+94/176] schedule_timeout+0x5e/0xb0
Jul 12 08:26:06 mindpipe kernel:  [process_timeout+0/16] process_timeout+0x0/0x10
Jul 12 08:26:06 mindpipe kernel:  [do_poll+161/192] do_poll+0xa1/0xc0
Jul 12 08:26:06 mindpipe kernel:  [sys_poll+330/560] sys_poll+0x14a/0x230
Jul 12 08:26:06 mindpipe kernel:  [__pollwait+0/160] __pollwait+0x0/0xa0
Jul 12 08:26:06 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 08:26:06 mindpipe kernel:
Jul 12 08:36:06 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 08:36:06 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 08:36:06 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 08:36:06 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 08:36:06 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 08:36:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:36:06 mindpipe kernel:  [rt_run_flush+66/144] rt_run_flush+0x42/0x90
Jul 12 08:36:06 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 08:36:06 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 08:36:06 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 08:36:06 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 08:36:06 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 08:36:06 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 08:36:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:36:06 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 08:36:06 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 08:36:06 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 08:36:06 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 08:36:06 mindpipe kernel:
Jul 12 08:46:06 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 08:46:06 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 08:46:06 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 08:46:06 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 08:46:06 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 08:46:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:46:06 mindpipe kernel:  [rt_run_flush+123/144] rt_run_flush+0x7b/0x90
Jul 12 08:46:06 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 08:46:06 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 08:46:06 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 08:46:06 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 08:46:06 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 08:46:06 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 08:46:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:46:06 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 08:46:06 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 08:46:06 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 08:46:06 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 08:46:06 mindpipe kernel:
Jul 12 08:56:06 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 08:56:06 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 08:56:06 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 08:56:06 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 08:56:06 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 08:56:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:56:06 mindpipe kernel:  [rt_run_flush+123/144] rt_run_flush+0x7b/0x90
Jul 12 08:56:06 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 08:56:06 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 08:56:06 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 08:56:06 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 08:56:06 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 08:56:06 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 08:56:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 08:56:06 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 08:56:06 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 08:56:06 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 08:56:06 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 08:56:06 mindpipe kernel:
Jul 12 09:06:06 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 09:06:06 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 09:06:06 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 09:06:06 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 09:06:06 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 09:06:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 09:06:06 mindpipe kernel:  [preempt_schedule+1/80] preempt_schedule+0x1/0x50
Jul 12 09:06:06 mindpipe kernel:  [rt_run_flush+135/144] rt_run_flush+0x87/0x90
Jul 12 09:06:06 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 09:06:06 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 09:06:06 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 09:06:06 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 09:06:06 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 09:06:06 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 09:06:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 09:06:06 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 09:06:06 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 09:06:06 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 09:06:06 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 09:06:06 mindpipe kernel:
Jul 12 09:36:06 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 09:36:06 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 09:36:06 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 09:36:06 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 09:36:06 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 09:36:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 09:36:06 mindpipe kernel:  [local_bh_enable+23/112] local_bh_enable+0x17/0x70
Jul 12 09:36:06 mindpipe kernel:  [rt_run_flush+92/144] rt_run_flush+0x5c/0x90
Jul 12 09:36:06 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 09:36:06 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 09:36:06 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 09:36:06 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 09:36:06 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 09:36:06 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 09:36:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 09:36:06 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 09:36:06 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 09:36:06 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 09:36:06 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 09:36:06 mindpipe kernel:
Jul 12 09:46:06 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 09:46:06 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 09:46:06 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 09:46:06 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 09:46:06 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 09:46:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 09:46:06 mindpipe kernel:  [preempt_schedule+23/80] preempt_schedule+0x17/0x50
Jul 12 09:46:06 mindpipe kernel:  [rt_run_flush+92/144] rt_run_flush+0x5c/0x90
Jul 12 09:46:06 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 09:46:06 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 09:46:06 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 09:46:06 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 09:46:06 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 09:46:06 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 09:46:06 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 09:46:06 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 09:46:06 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 09:46:06 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 09:46:06 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 09:46:06 mindpipe kernel:
Jul 12 10:16:05 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 10:16:05 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 10:16:05 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 10:16:05 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 10:16:05 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 10:16:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 10:16:05 mindpipe kernel:  [preempt_schedule+73/80] preempt_schedule+0x49/0x50
Jul 12 10:16:05 mindpipe kernel:  [rt_run_flush+135/144] rt_run_flush+0x87/0x90
Jul 12 10:16:05 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 10:16:05 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 10:16:05 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 10:16:05 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 10:16:05 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 10:16:05 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 10:16:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 10:16:05 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 10:16:05 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 10:16:05 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 10:16:05 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 10:16:05 mindpipe kernel:
Jul 12 10:46:05 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 10:46:05 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 10:46:05 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 10:46:05 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 10:46:05 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 10:46:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 10:46:05 mindpipe kernel:  [rt_run_flush+94/144] rt_run_flush+0x5e/0x90
Jul 12 10:46:05 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 10:46:05 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 10:46:05 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 10:46:05 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 10:46:05 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 10:46:05 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 10:46:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 10:46:05 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 10:46:05 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 10:46:05 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 10:46:05 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 10:46:05 mindpipe kernel:
Jul 12 10:56:05 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 10:56:05 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 10:56:05 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 10:56:05 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 10:56:05 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 10:56:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 10:56:05 mindpipe kernel:  [local_bh_enable+8/112] local_bh_enable+0x8/0x70
Jul 12 10:56:05 mindpipe kernel:  [rt_run_flush+92/144] rt_run_flush+0x5c/0x90
Jul 12 10:56:05 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 10:56:05 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 10:56:05 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 10:56:05 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 10:56:05 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 10:56:05 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 10:56:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 10:56:05 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 10:56:05 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 10:56:05 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 10:56:05 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 10:56:05 mindpipe kernel:
Jul 12 11:06:05 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 11:06:05 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 11:06:05 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 11:06:05 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 11:06:05 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 11:06:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 11:06:05 mindpipe kernel:  [preempt_schedule+9/80] preempt_schedule+0x9/0x50
Jul 12 11:06:05 mindpipe kernel:  [rt_run_flush+92/144] rt_run_flush+0x5c/0x90
Jul 12 11:06:05 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 11:06:05 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 11:06:05 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 11:06:05 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 11:06:05 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 11:06:05 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 11:06:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 11:06:05 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 11:06:05 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 11:06:05 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 11:06:05 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 11:06:05 mindpipe kernel:
Jul 12 11:36:05 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 11:36:05 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 11:36:05 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 11:36:05 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 11:36:05 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 11:36:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 11:36:05 mindpipe kernel:  [local_bh_enable+0/112] local_bh_enable+0x0/0x70
Jul 12 11:36:05 mindpipe kernel:  [rt_run_flush+92/144] rt_run_flush+0x5c/0x90
Jul 12 11:36:05 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 11:36:05 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 11:36:05 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 11:36:05 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 11:36:05 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 11:36:05 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 11:36:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 11:36:05 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 11:36:05 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 11:36:05 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 11:36:05 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0
Jul 12 11:36:05 mindpipe kernel:
Jul 12 11:46:05 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 11:46:05 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 11:46:05 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 11:46:05 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 11:46:05 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 11:46:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 11:46:05 mindpipe kernel:  [rt_run_flush+66/144] rt_run_flush+0x42/0x90
Jul 12 11:46:05 mindpipe kernel:  [rt_secret_rebuild+0/48] rt_secret_rebuild+0x0/0x30
Jul 12 11:46:05 mindpipe kernel:  [rt_secret_rebuild+14/48] rt_secret_rebuild+0xe/0x30
Jul 12 11:46:05 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 11:46:05 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 11:46:05 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 11:46:05 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 11:46:05 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 11:46:05 mindpipe kernel:  [default_idle+35/64] default_idle+0x23/0x40
Jul 12 11:46:05 mindpipe kernel:  [apm_cpu_idle+165/384] apm_cpu_idle+0xa5/0x180
Jul 12 11:46:05 mindpipe kernel:  [cpu_idle+45/64] cpu_idle+0x2d/0x40
Jul 12 11:46:05 mindpipe kernel:  [start_kernel+392/464] start_kernel+0x188/0x1d0

That continues until I sat down at the machine and switched consoles. I am aware that this is a known latency 'hot spot' and not trivial to fix. Here are the traces anyway:

Jul 12 17:33:42 mindpipe kernel:
Jul 12 17:33:42 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p Jul 12 17:33:42 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:33:42 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:33:42 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:33:42 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:33:42 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:33:42 mindpipe kernel:  [release_console_sem+129/208] release_console_sem+0x81/0xd0
Jul 12 17:33:42 mindpipe kernel:  [do_con_write+657/1888] do_con_write+0x291/0x760
Jul 12 17:33:42 mindpipe kernel:  [con_put_char+51/64] con_put_char+0x33/0x40
Jul 12 17:33:42 mindpipe kernel:  [opost+162/464] opost+0xa2/0x1d0
Jul 12 17:33:42 mindpipe kernel:  [write_chan+437/544] write_chan+0x1b5/0x220
Jul 12 17:33:42 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 12 17:33:42 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 12 17:33:42 mindpipe kernel:  [tty_write+434/608] tty_write+0x1b2/0x260
Jul 12 17:33:42 mindpipe kernel:  [write_chan+0/544] write_chan+0x0/0x220
Jul 12 17:33:42 mindpipe kernel:  [vfs_write+186/256] vfs_write+0xba/0x100
Jul 12 17:33:42 mindpipe kernel:  [sys_write+45/80] sys_write+0x2d/0x50
Jul 12 17:33:42 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:33:42 mindpipe kernel:
Jul 12 17:33:42 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:33:42 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:33:42 mindpipe kernel:  [avc_has_perm+72/96] avc_has_perm+0x48/0x60
Jul 12 17:33:42 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:33:42 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:33:42 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:33:42 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:33:42 mindpipe kernel:  [lf+1/112] lf+0x1/0x70
Jul 12 17:33:42 mindpipe kernel:  [do_con_trol+2907/3360] do_con_trol+0xb5b/0xd20
Jul 12 17:33:42 mindpipe kernel:  [do_con_write+1128/1888] do_con_write+0x468/0x760
Jul 12 17:33:42 mindpipe kernel:  [con_put_char+51/64] con_put_char+0x33/0x40
Jul 12 17:33:42 mindpipe kernel:  [opost+162/464] opost+0xa2/0x1d0
Jul 12 17:33:42 mindpipe kernel:  [write_chan+437/544] write_chan+0x1b5/0x220
Jul 12 17:33:42 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 12 17:33:42 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 12 17:33:42 mindpipe kernel:  [tty_write+434/608] tty_write+0x1b2/0x260
Jul 12 17:33:42 mindpipe kernel:  [write_chan+0/544] write_chan+0x0/0x220
Jul 12 17:33:42 mindpipe kernel:  [vfs_write+186/256] vfs_write+0xba/0x100
Jul 12 17:33:42 mindpipe kernel:  [sys_write+45/80] sys_write+0x2d/0x50
Jul 12 17:33:42 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:33:42 mindpipe kernel:

It looks like reiserfs has a hot spot as well:

Jul 12 17:55:11 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:55:11 mindpipe kernel:  [do_pollfd+125/144] do_pollfd+0x7d/0x90
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:55:11 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:55:11 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:55:11 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:55:11 mindpipe kernel:
Jul 12 17:55:11 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:55:11 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:55:11 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:55:11 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:55:11 mindpipe kernel:  [free_hot_cold_page+21/288] free_hot_cold_page+0x15/0x120
Jul 12 17:55:11 mindpipe kernel:  [poll_freewait+68/80] poll_freewait+0x44/0x50
Jul 12 17:55:11 mindpipe kernel:  [sys_poll+489/560] sys_poll+0x1e9/0x230
Jul 12 17:55:11 mindpipe kernel:  [__pollwait+0/160] __pollwait+0x0/0xa0
Jul 12 17:55:11 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:55:11 mindpipe kernel:
Jul 12 17:55:11 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:55:11 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:55:11 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:55:11 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:55:11 mindpipe kernel:  [can_dirty+99/192] can_dirty+0x63/0xc0
Jul 12 17:55:11 mindpipe kernel:  [dirty_one_transaction+74/128] dirty_one_transaction+0x4a/0x80
Jul 12 17:55:11 mindpipe kernel:  [flush_commit_list+519/944] flush_commit_list+0x207/0x3b0
Jul 12 17:55:11 mindpipe kernel:  [do_journal_end+2081/2848] do_journal_end+0x821/0xb20
Jul 12 17:55:11 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:55:11 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:55:11 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:55:11 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:55:11 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:55:11 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:55:11 mindpipe kernel:
Jul 12 17:55:11 mindpipe kernel:
Jul 12 17:55:11 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:55:11 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:55:11 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:55:11 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:55:11 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:55:11 mindpipe kernel:  [finish_task_switch+34/112] finish_task_switch+0x22/0x70
Jul 12 17:55:11 mindpipe kernel:  [schedule+731/1424] schedule+0x2db/0x590
Jul 12 17:55:11 mindpipe kernel:  [__mod_timer+206/384] __mod_timer+0xce/0x180
Jul 12 17:55:11 mindpipe kernel:  [schedule_timeout+88/176] schedule_timeout+0x58/0xb0
Jul 12 17:55:11 mindpipe kernel:  [process_timeout+0/16] process_timeout+0x0/0x10
Jul 12 17:55:11 mindpipe kernel:  [do_poll+161/192] do_poll+0xa1/0xc0
Jul 12 17:55:11 mindpipe kernel:  [sys_poll+330/560] sys_poll+0x14a/0x230
Jul 12 17:55:11 mindpipe kernel:  [__pollwait+0/160] __pollwait+0x0/0xa0
Jul 12 17:55:11 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:55:11 mindpipe kernel:
Jul 12 17:55:17 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:55:17 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:55:17 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:55:17 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:55:17 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:55:17 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:55:17 mindpipe kernel:  [remove_journal_hash+72/208] remove_journal_hash+0x48/0xd0
Jul 12 17:55:17 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:55:17 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:55:17 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:55:17 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:55:17 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:55:17 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:55:17 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:55:17 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:55:17 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:55:17 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:55:17 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:55:17 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:55:17 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:55:17 mindpipe kernel:
Jul 12 17:55:17 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:55:17 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:55:17 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:55:17 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:55:17 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:55:17 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:55:17 mindpipe kernel:  [remove_journal_hash+67/208] remove_journal_hash+0x43/0xd0
Jul 12 17:55:17 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:55:17 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:55:17 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:55:17 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:55:17 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:55:17 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:55:17 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:55:17 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:55:17 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:55:17 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:55:17 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:55:17 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:55:17 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:55:17 mindpipe kernel:

A few minutes later:

Jul 12 17:56:54 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:56:54 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:56:54 mindpipe kernel:  [i8042_timer_func+0/16] i8042_timer_func+0x0/0x10
Jul 12 17:56:54 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:56:54 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:56:54 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:56:54 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:56:54 mindpipe kernel:  [can_dirty+144/192] can_dirty+0x90/0xc0
Jul 12 17:56:54 mindpipe kernel:  [dirty_one_transaction+74/128] dirty_one_transaction+0x4a/0x80
Jul 12 17:56:54 mindpipe kernel:  [flush_commit_list+519/944] flush_commit_list+0x207/0x3b0
Jul 12 17:56:54 mindpipe kernel:  [do_journal_end+2081/2848] do_journal_end+0x821/0xb20
Jul 12 17:56:54 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:56:54 mindpipe kernel:  [reiserfs_sync_fs+61/128] reiserfs_sync_fs+0x3d/0x80
Jul 12 17:56:54 mindpipe kernel:  [sync_supers+174/192] sync_supers+0xae/0xc0
Jul 12 17:56:54 mindpipe kernel:  [wb_kupdate+47/256] wb_kupdate+0x2f/0x100
Jul 12 17:56:54 mindpipe kernel:  [deactivate_task+29/64] deactivate_task+0x1d/0x40
Jul 12 17:56:54 mindpipe kernel:  [__pdflush+200/496] __pdflush+0xc8/0x1f0
Jul 12 17:56:54 mindpipe kernel:  [pdflush+0/48] pdflush+0x0/0x30
Jul 12 17:56:54 mindpipe kernel:  [pdflush+30/48] pdflush+0x1e/0x30
Jul 12 17:56:54 mindpipe kernel:  [wb_kupdate+0/256] wb_kupdate+0x0/0x100
Jul 12 17:56:54 mindpipe kernel:  [kthread+163/176] kthread+0xa3/0xb0
Jul 12 17:56:54 mindpipe kernel:  [kthread+0/176] kthread+0x0/0xb0
Jul 12 17:56:54 mindpipe kernel:  [kernel_thread_helper+5/16] kernel_thread_helper+0x5/0x10
Jul 12 17:56:54 mindpipe kernel:

Another one:

Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+67/208] remove_journal_hash+0x43/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+72/208] remove_journal_hash+0x48/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+99/208] remove_journal_hash+0x63/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+72/208] remove_journal_hash+0x48/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+72/208] remove_journal_hash+0x48/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+67/208] remove_journal_hash+0x43/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+108/208] remove_journal_hash+0x6c/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [remove_journal_hash+72/208] remove_journal_hash+0x48/0xd0
Jul 12 17:57:22 mindpipe kernel:  [remove_all_from_journal_list+78/160] remove_all_from_journal_list+0x4e/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+496/1344] flush_journal_list+0x1f0/0x540
Jul 12 17:57:22 mindpipe kernel:  [flush_older_journal_lists+48/64] flush_older_journal_lists+0x30/0x40
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+795/1344] flush_journal_list+0x31b/0x540 Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 17:57:22 mindpipe kernel:
Jul 12 17:57:22 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 17:57:22 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1] Jul 12 17:57:22 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:57:22 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:57:22 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:57:22 mindpipe kernel:  [generic_unplug_device+32/96] generic_unplug_device+0x20/0x60
Jul 12 17:57:22 mindpipe kernel:  [blk_backing_dev_unplug+35/48] blk_backing_dev_unplug+0x23/0x30
Jul 12 17:57:22 mindpipe kernel:  [sync_buffer+53/64] sync_buffer+0x35/0x40
Jul 12 17:57:22 mindpipe kernel:  [__wait_on_buffer+150/160] __wait_on_buffer+0x96/0xa0
Jul 12 17:57:22 mindpipe kernel:  [bh_wake_function+0/64] bh_wake_function+0x0/0x40
Jul 12 17:57:22 mindpipe kernel:  [bh_wake_function+0/64] bh_wake_function+0x0/0x40
Jul 12 17:57:22 mindpipe kernel:  [_update_journal_header_block+177/240] _update_journal_header_block+0xb1/0xf0
Jul 12 17:57:22 mindpipe kernel:  [update_journal_header_block+21/48] update_journal_header_block+0x15/0x30
Jul 12 17:57:22 mindpipe kernel:  [flush_journal_list+835/1344] flush_journal_list+0x343/0x540 Jul 12 17:57:22 mindpipe kernel:  [flush_used_journal_lists+147/160] flush_used_journal_lists+0x93/0xa0
Jul 12 17:57:22 mindpipe kernel:  [flush_old_journal_lists+69/112] flush_old_journal_lists+0x45/0x70
Jul 12 17:57:22 mindpipe kernel:  [do_journal_end+1853/2848] do_journal_end+0x73d/0xb20
Jul 12 17:57:22 mindpipe kernel:  [journal_end_sync+54/112] journal_end_sync+0x36/0x70
Jul 12 17:57:22 mindpipe kernel:  [__commit_trans_jl+223/240] __commit_trans_jl+0xdf/0xf0
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_commit_for_inode+32/64] reiserfs_commit_for_inode+0x20/0x40
Jul 12 17:57:22 mindpipe kernel:  [reiserfs_sync_file+77/144] reiserfs_sync_file+0x4d/0x90
Jul 12 17:57:22 mindpipe kernel:  [sys_fsync+123/176] sys_fsync+0x7b/0xb0
Jul 12 17:57:22 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb

Hopefully this is not too much information. You did ask for details...

Lee Revell
Mindpipe Audio

OK, thanks. The problem areas there are the timer-based route cache flushing and reiserfs.

We can probably fix the route caceh thing by rescheduling the timer after having handled 1000 routes or whatever, although I do wonder if this is a thing we really need to bother about - what else was that machine up to?

resierfs: yes, it's a problem. I "fixed" it multiple times in 2.4, but the fixes ended up breaking the fs in subtle ways and I eventually gave up.

andrew, this is really helpful. should we conclude that until some announcement from reiser that they have addressed this, the reiserfs should be avoided on low latency systems?

--p

It seems that way, yes. I do not know how common the holdoffs are in real life. It would be interesting if there was a user report that switching from reiserfs to ext2/ext3 actually made a difference - this would tell us that it is indeed a real-world problem.

Note that this info because available because someone set /proc/asound/*/*/xrun_debug. We need more people doing that.

Can I just point out that the reiserfs3.6 delays that I originally reported with the preempt threshhold test did not come up once the patch was fixed. I have my preempt threshold set at 1ms and did not see one single reiserfs dump in my syslog. ie I don't think I am personally seeing any significant reiserfs3.6 latencies.

Cheers,
Con

This was not a synthetic benchmark, I would consider this a 'real-world' problem now. Repeating the test with ext3 would just tell you whether it has the same problem.

If it is neccesary to get the reiserfs issue addressed, I will repeat the test with an ext3 system in the next few days, I would like to hear from reiser on this before doing much more.

This goes back to the need for ALSA documentation. Someone needs to write some. This will probably require paying that person. Hopefully SuSe is working on this, though I suspect I would have heard something.

At Mon, 12 Jul 2004 21:01:16 -0400,

Documentation/sound/alsa/Procfile.txt

Takashi

I should have been more specific, I mean user-level documentation. All the necessary information for developers is certainly out there, your driver guide for example is excellent. I also didn't mean to imply that the ALSA developers should do it, they are busy enough already...

Lee

i have one concern about this that i talked to takashi about when we were in bordeaux. it seems to me that the ALSA xrun debug stuff is measuring things when the interrupt handler for the ALSA device executes and detects an xrun. if the handler itself was delayed, then the stack trace for its execution doesn't or might not show what caused the delay. this means, perhaps, that we need to be rather careful interpreting these traces.

--p

We can usually tell that from the trace. If it points up into a busy piece of code then it's pretty obvious what's happening. If the trace is due to a long irq-off time then it will point up into the offending local_irq_enable().

schedule should be called with irq enabled, and I noticed here it's not (jnz work_resched is executed with irq off so there is a window for schedule to be called with irq off):

Index: linux-2.5/arch/i386/kernel/entry.S
===================================================================
RCS file: /home/andrea/crypto/cvs/linux-2.5/arch/i386/kernel/entry.S,v retrieving revision 1.86

diff -u -p -r1.86 entry.S
@@ -302,6 +310,7 @@ work_pending:
 	testb $_TIF_NEED_RESCHED, %cl
 	jz work_notifysig
 work_resched:
+	sti
 	call schedule
 	cli				# make sure we don't miss an interrupt
 					# setting need_resched or sigpending

I'm wondering what this message actually means. "Unexpected hw_pointer value"?

Does this actually indicate an underrun, or is the debug code screwy?

Not sure. Here is what Takashi had to say about it:

"The message appears when an unexpected DMA pointer is read in the interrupt handler. Either the handling of irq was delayed more than the buffer size, an irq is issued at the wrong timing, or the DMA pointer reigster is somehow screwed up.

Since you're using quite small buffer, I guess the former case."

My response:

"I thought this was what an XRUN was, when the handling of the irq is delayed more than the buffer size. Sometimes these messages are associated with XRUNs, sometimes not."

Haven't heard back yet.

Is it possible that I am simply pushing my hardware past its limits? Keep in mind this is a 600Mhz C3 processor.

Lee

At Tue, 13 Jul 2004 17:45:30 -0400,

I think yes. 32 frames / 44.1kHz = 0.725 ms.

Takashi

I am runnign at 48kHz so it's actually 0.666 ms. But, the average response is quite good, 20-30 microseconds. The spikes are infrequent enought that I think this is achievable. If not then 64 frames definitely is.

So what is the difference between the above message and an XRUN? I thought an XRUN occurred when the handling of the IRQ is delayed more than the buffer size.

Lee

At Wed, 14 Jul 2004 05:36:31 -0400,

Yes, XRUN is so.

The message above is not directly related with XRUN. It appears when an unexpected DMA pointer is returned. This can happen e.g. when the irq handler is called at the wrong timing, or the register returns a bogus value.

Takashi

I am still kind of confused. It sounds like this is more serious than an XRUN. What would cause this to happen?

Lee

OK, I think I understand the distinction. An XRUN is when a process is writing (or reading) to a PCM device, the buffer half empty interrupt occurs, and the interrupt handler runs, which makes the process ready to run, but the scheduler does not run it in time to write the next block of data to the buffer.

The "Unexpected hw_pointer" error would occur when the device generates an interrupt, but there is a delay in running the interrupt handler, and by the time the interrupt handler runs, the hardware pointer has moved somewhere we don't expect it to be. This would occur if we missed an interrupt, or several, due to interrupts being disabled for longer than the period size. So the distinction is scheduler latency vs. interrupt response latency.

What is the longest that the kernel disables interrupts? I remember hearing 500 microseconds, but this was a while back.

Lee

I don't think so, I think it's because the Linux scheduler (and kernel in general) since it's not a RTOS is pushed to the limits. (but as we see it can still be optimized).

For example I used the same VIA box with RTLinux to remote control servo motors which need a PWM signal of the duration of 2msec and based on the location of the negative flank (from high to low) the servo motor goes in a certain position.
For example if the duration of the pulse is 2msec then setting the flank at 0msec (at the beginning of the cycle) the servo goes to -45degrees , 1msec 0degrees , 2msec +45degrees.

Jitter in the pulse can be detected when the servo is vibrating a bit around the nominal position. Of course a very short lived spike cannot be detected by the servo because of the motor's inertia but I tried to put the box under very high load especially video playback (the VIA box uses a shared bus architecture holding the video data in the PC's RAM), HD load etc but the jitter is very minimal, probably 30-40usec because the servos vibrate only about 1degree or so (only when the box is under very high load).

This just to say that the VIA box should easily be able to cope with 32 audio frames (0.6msec buffers) from a hardware point of view.
Anyway "worst case" latencies (or better latencies under very high load) of <0.5-1msec are completely adequate for
real time multimedia because if you shorten your audio processing cycles too much (eg 32 frames) then the setup
overhead of DSP routines, and scheduling overhead becomes big and the efficiency of
the algorithms decrease quite a bit.
imagine running jack with 10 client applications and 32 frames (0.6msec periods) , this means that within 0.6msec you need to reschedule 10 times = 60 usec per client. I don't know how much the actual rescheduling of a process takes (AFAIK around 1usec ?) but I guess the main problem is the constant invalidation of the cache because those audio clients run for a really short time. Of course if you have only 1-2 clients running then the efficiency at 32 frames should still be good (but it will certainly provide 10-20% less perfromance than using 64 or 128 frames).
Our goal should be rock solid operation at 64msec (around 1msec-1.5msec processing periods).
If you use 2-3 buffers then the kernel has still another 1.5-3msec of headroom before an actual (audible) xrun occurs.

cheers,
Benno
http://www.linuxsampler.org

we can remove the irqs_disabled() check in might_sleep then, I'd like to call might_sleep from cond_resched.

Confused. Where do we call cond_resched() with local interrupts disabled?

Sleeping with local interrupts disabled is usually a bug, so we should prefer to keep that check in might_sleep().

there are a lot of cond_resched, we might be calling it with irq disabled, nobody ever did a might_sleep in the fast path of cond_resched. And even if nobody does, if entry.S and sched_yield can optimize, then everybody else can optimize too. It's not like that entry.S is a piece of scheduler internal that will be obviously modified if we modify the scheduler. so if you intend to leave those two there's no point to forbid others to optimize, and there's no might_sleep in current cond_resched anyways so you're already allowing people to optimize and I want to allow it still after I add might_sleep there.

either it's _always_ a bug including for entry.S or sched_yield, or it's _never_ a bug. I don't understand the "usually".

If some code does:

	local_irq_disable();
	<fiddle with per-cpu stuff>
	kmalloc(GFP_KERNEL);
	<fiddle with per-cpu stuff>
	local_irq_enable();

or

	local_irq_disable();
	<fiddle with per-cpu stuff>
	function_which_calls_cond_resched();
	<fiddle with per-cpu stuff>
	local_irq_enable();

then we want might_sleep() to warn about the bug.

The fact that a couple of scheduler-internal fastpaths happen to know that they can call schedule() with interrupts disabled is not relevant to this.

might_sleep currently _doesn't_ warn about any bug in the above case I quoted.

the kmalloc example is trapped instead.

(and I would definitely put a debug check in schedule() for that, guess how I found about the missing sti in entry.S btw). But if you are ok with people calling schedule with irq disabled then I cannot put a check in there. sti doesn't cost that much, and the work-to-do and sched_yield paths are _never_ fast paths, so they don't worth an hack like that.

Yeah, I know. might_sleep() in cond_resched() makes sense.

I'd agree with that. But when I "fixed" it, Ingo unfixed it again and I didn't have sufficiently strong feelings either way to object.

What I'm doing is basically to replace all might_sleep with cond_resched and then I add might_sleep in cond_resched. I also merged all new might_sleep in Ingo's patch (converted to cond_resched). We'll see what happens then when I try to boot such a thing (the sti and sched_yield already given me some troubles).

I was considering adding a cond_resched_costly but I didn't see anything really that costly to need a CONFIG_LOW_RESCHED_OVERHEAD.

btw, cond_resched should only be defined as might_sleep with PREEMPT enabled, otherwise it's pointless to check need_resched at almost every spin_unlock and to do it during cond_resched too. if might_sleep doesn't BUG it means we didn't need to check need_resched in the first place if preempt is enabled.

cond_resched_lock is another story of course.

I cannot see a lot of point in that. They are semantically different things and should look different in the source.

And it's currently OK to add a might_sleep() to (say) an inline path which is expended a zillion times because we know it'll go away for production builds. If those things become cond_resched() calls instead, the code increase will be permanent.

cond_resched_lock() doesn't work on SMP. I'll probably be removing it in favour of unconditionally dropping the lock every N times around the loop, to allow the other CPU (the one with need_resched() true) to get in there and take it.

And please let me repeat: preemption is the way in which we wish to provide low-latency. At this time, patches which sprinkle cond_resched() all over the place are unwelcome. After 2.7 forks we can look at it again.

I've yet to go through Arjan's patch - I suspect a lot of it is not needed.

this is exactly why I'm making this change: so you can still add might_sleep in a inline path expected to run a zillion times. With Ingo's change you would be doing cond_sched internally to might_sleep, I do the other way around so might_sleep remains a debugging statement.

As Ingo basically showed (and I agree), all current might_sleep seems suitable to be converted to cond_resched. I checked all them and there's none that seems to be called in a loop for no good reason. the ones in the semaphore are quite nice too since it's better to schedule right before taking the semaphore than after getting it. The one in the semaphore and in the copy-user are the only place where preempt seems to be lower overhead but in most other places a spinlock is being taken very near to the cond_resched.

I think it's a mistake to believe people that leaves preempt off don't care about lowlatency (this is also why I always keep this change in my tree)

Index: linux-2.5/mm/memory.c
===================================================================
RCS file: /home/andrea/crypto/cvs/linux-2.5/mm/memory.c,v retrieving revision 1.178

diff -u -p -r1.178 memory.c
@@ -479,20 +479,13 @@ static void unmap_page_range(struct mmu_
 }
 
 /* Dispose of an entire struct mmu_gather per rescheduling point */
-#if defined(CONFIG_SMP) && defined(CONFIG_PREEMPT)
+#if defined(CONFIG_SMP)
 #define ZAP_BLOCK_SIZE	(FREE_PTE_NR * PAGE_SIZE)
-#endif
-
+#else
 /* For UP, 256 pages at a time gives nice low latency */
-#if !defined(CONFIG_SMP) && defined(CONFIG_PREEMPT)
 #define ZAP_BLOCK_SIZE	(256 * PAGE_SIZE)
 #endif
 
-/* No preempt: go for improved straight-line efficiency */
-#if !defined(CONFIG_PREEMPT)
-#define ZAP_BLOCK_SIZE	(1024 * PAGE_SIZE)
-#endif
-
 /**
  * unmap_vmas - unmap a range of memory covered by a list of vma's
  * @tlbp: address of the caller's struct mmu_gather

having a CONFIG_PREEMPT in the above code, means you believe the people who leaves preempt off don't care about lowlatency and that's really not true. Ingo's effort as well shows people care about lowlatency even with preempt off.

The people who leaves preempt off simply thinks they can get the same lowlatency but with less overhead in the locks (though there will be cond_resched in the semaphore, but semaphore is less performance critical than the spinlock normally, and semaphore is usually hold for a longer period of time, short critical sections would better go with the spinlock anyways to avoid overscheduling).

Arjan's or Ingo's? I've seen Ingo's patch but maybe I missed Arjan's one.

OK.

cond_resched() is usually a waste of space with CONFIG_PREEMPT. It might make sense to define a cond_resched_if_not_preempt thingy, which only does things if !CONFIG_PREEMPT. We'd still need to use cond_resched() inside lock_kernel().

I think Ingo's patch includes Arjan's one. Ingo's patch apparently breaks ext3. I have a bunch of ext3 and other fixes here, but there's still an occasional problem on SMP.

Though most of the current cond_resched invocations in mainline (and the future ones too) should be optimized away with preempt enabled, so maybe it's simpler to just implement a cond_resched_force() that isn't optimized away with preempt enabled and use it in lock_kernel? I'm missing where cond_resched is needed inside lock_kernel though, preempt_schedule already checks TIF_NEED_RESCHED by hand (on the top of my mind I don't recall cond_rescheds that shouldn't be optimized away with preempt enabled).

Ok.

I also had instability with it and I've seen debug checks in ext3 too (but it's not finished anyways), and I've still a bit of printk flooding so I'm uncertain if it's my mistake due the more strict debugging I added in schedule() or an issue in the newer cond_resched but thanks for the info (sounds like not all the debug checks triggering are my mistake ;).

Anywhere where we do lots of work inside lock_kernel(). Various ioctls and ext3 journal recovery are instances.

yes. Btw., i'm not sure whether you've noticed but last week i've also created a 'clean' variant of the patch. The latest version against -mm is:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-clean-2.6.7-mm7-H4

this one doesnt have any of the debugging/development helpers and switches. I have still made it a .config option. Note how minimal the patch became this way.

Ingo

Hi Ingo,

as said in a part of a previous email might_sleep() just like BUG() can be defined to noop.

cond_resched() is the API to use.

if you're scared that there are too many cond_resched (I'm not scared and people should enable them anyways if they make a difference, they still should be less than the number of spin_unlocks with preempt enabled), then you should add a cond_resched_costly and add a config option that turns it off. I think you don't even need to add the config option, you can define cond_resched_costly as cond_resched, and to just use it to mark the places that might be expensive.

Then you should change cond_resched to call might_sleep in the else branch (as I discussed with Andrew last month).

this was the core of the patch I was playing with last month which should be still valid and it solves the preprocessor issues with cond_resched (and I hope the bug was not in the below code ;)

could you modify your patch accordingly? thanks!

Index: linux-2.5/include/linux/kernel.h
===================================================================
RCS file: /home/andrea/crypto/cvs/linux-2.5/include/linux/kernel.h,v retrieving revision 1.53

diff -u -p -r1.53 kernel.h
@@ -48,12 +48,23 @@ struct completion;
 #ifdef CONFIG_DEBUG_SPINLOCK_SLEEP
 void __might_sleep(char *file, int line);
 #define might_sleep() __might_sleep(__FILE__, __LINE__)
-#define might_sleep_if(cond) do { if (unlikely(cond)) might_sleep(); } while (0)
 #else
 #define might_sleep() do {} while(0)
-#define might_sleep_if(cond) do {} while (0)
 #endif
 
+#define need_resched() unlikely(test_thread_flag(TIF_NEED_RESCHED))
+
+extern void __cond_resched(void);
+#define cond_resched()				\
+do {						\
+	if (need_resched())			\
+		__cond_resched();		\
+	else					\
+		might_sleep();			\
+} while (0)
+
+#define cond_resched_if(cond) do { if (unlikely(cond)) cond_resched(); } while (0)
+
 #define abs(x) ({				\
 		int __x = (x);			\
 		(__x < 0) ? -__x : __x;		\

Index: linux-2.5/include/linux/sched.h
===================================================================
RCS file: /home/andrea/crypto/cvs/linux-2.5/include/linux/sched.h,v retrieving revision 1.245

diff -u -p -r1.245 sched.h
@@ -1012,18 +1013,6 @@ static inline int signal_pending(struct 
 {
 	return unlikely(test_tsk_thread_flag(p,TIF_SIGPENDING));
 }
-  
-static inline int need_resched(void)
-{
-	return unlikely(test_thread_flag(TIF_NEED_RESCHED));
-}
-
-extern void __cond_resched(void);
-static inline void cond_resched(void)
-{
-	if (need_resched())
-		__cond_resched();
-}
 
 /*
  * cond_resched_lock() - if a reschedule is pending, drop the given lock,

None of these approaches improves worst-case latency at all on SMP. If we're not going to address the SMP problem we could just make it UP-only, in which case increased locking costs are a non-issue.

I'd prefer that we find a solution for SMP too though.

i have solved the fundamental SMP latency problems in the -Q7 patch, by redesigning how SMP preemption is done. Here's the relevant changelog entry:

[...]

the main change in this patch are more SMP latency fixes. The stock kernel, even with CONFIG_PREEMPT enabled, didnt have any spin-nicely preemption logic for the following, commonly used SMP locking
primitives: read_lock(), spin_lock_irqsave(), spin_lock_irq(), spin_lock_bh(), read_lock_irqsave(), read_lock_irq(), read_lock_bh(), write_lock_irqsave(), write_lock_irq(), write_lock_bh(). Only spin_lock() and write_lock() [the two simplest cases] where covered.

In addition to the preemption latency problems, the _irq() variants in the above list didnt do any IRQ-enabling while spinning - possibly resulting in excessive irqs-off sections of code!

-Q7 fixes all of these latency problems: we now re-enable interrupts while spinning in all possible cases, and a spinning op stays preemptible if this is a beginning of a new critical section.

[...]

feedback from Mark H Johnson:

http://lkml.org/lkml/2004/8/30/202

the latest patch is:

http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-R0

i'm already in the process of cleaning up the patch and making it ready for splitup & merge. The spinlock fixes will be amongst the first patches i'll send you.

Ingo

also this changelog explains the core changes that enable good preemption latencies on SMP:

[...]

i took another look at SMP latencies, the last larger chunk of code that produced millisec-category latencies. CONFIG_PREEMPT tries to solve some of the SMP issues but there were still lots of problems remaining: main problem area is spinlocks nested at multiple levels. If a piece of code (e.g. the MM or ext3's journalling code) does the following:

        spin_lock(&spinlock_1);
        ...
        spin_lock(&spinlock_2);
        ...

then even with CONFIG_PREEMPT enabled, current kernels may spin on spinlock_2 indefinitely. A number of critical sections break their long paths by using cond_resched_lock(), but this does not break the path on SMP, because need_resched() is not set in the above case.

(The -mm kernel introduced a couple of patches that try to drop spinlocks unconditionally at a high frequency: but besides being a kludge it's also a performance problem, we keep dropping/waiting/retaking locks quite frequently. That solution also doesnt solve the problem of cond_resched_lock() not working on SMP.)

to solve the problem i've introduced a new spinlock field, lock->break_lock, which signals towards the holding CPU that a spinlock-break is requested by another CPU. This field is only set if a CPU is spinning in __preempt_spin_lock [at any locking depth], so the default overhead is zero. I've extended cond_resched_lock() to check for this flag - in this case we can also save a reschedule. I've added the lock_need_resched(lock) and need_lockbreak(lock) methods to check for the need to break out of a critical section.

preliminary results on a dual x86 box show a dramatic reduction in latencies on SMP - where there used to be 5-10 msec latencies there are close-to-UP latencies now. But it needs more testing.

[...]

Ingo

At Mon, 12 Jul 2004 20:01:51 -0400,

Well, it can catch up too long critical sections in most cases, although it cannot measure the latency to wake up the audio thread. So, the detection can't be 100% guaranteed.

Takashi

Gnutella client. Forgot about that. I agree, it is not reasonable to expect low latency with this kind of network traffic happening. I am impressed it worked as well as it did.

Interesting. There is an overwhelming consensus amongst Linux audio folks that you should use reiserfs for low latency work. Should I try ext3?

Lee

It seems to be misplaced. A simple make-a-zillion-teeny-files test here exhibits a 14 millisecond holdoff.

ext3 is certainly better than that, but still has a couple of potential problem spots. ext2 is probably the best at this time.

Here are a few more:

Jul 12 22:20:41 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 22:20:41 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 22:20:41 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 22:20:41 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 22:20:41 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 22:20:41 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 22:20:41 mindpipe kernel:  [unix_stream_recvmsg+135/1088] unix_stream_recvmsg+0x87/0x440
Jul 12 22:20:41 mindpipe kernel:  [avc_has_perm+72/96] avc_has_perm+0x48/0x60
Jul 12 22:20:41 mindpipe kernel:  [sock_aio_read+155/176] sock_aio_read+0x9b/0xb0
Jul 12 22:20:41 mindpipe kernel:  [do_sync_read+125/192] do_sync_read+0x7d/0xc0
Jul 12 22:20:41 mindpipe kernel:  [do_select+435/752] do_select+0x1b3/0x2f0
Jul 12 22:20:41 mindpipe kernel:  [vfs_read+223/256] vfs_read+0xdf/0x100
Jul 12 22:20:42 mindpipe kernel:  [sys_read+45/80] sys_read+0x2d/0x50
Jul 12 22:20:42 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 12 22:20:42 mindpipe kernel:
Jul 12 22:20:44 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 22:20:44 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 22:20:44 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 22:20:44 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 22:20:44 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 22:20:44 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 22:20:44 mindpipe kernel:
Jul 12 22:20:49 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 12 22:20:49 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 12 22:20:49 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 22:20:49 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 22:20:49 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 22:20:49 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 22:20:49 mindpipe kernel:

Lee

Oh dear, these don't make much sense.

You'll have the best chance of getting decent traces with CONFIG_FRAME_POINTER=y and CONFIG_4KSTACKS=n, but I'm not sure that this will help a lot. Are you sure that CONFIG_PREEMPT is enabled on that kernel?

Yes:

root@mindpipe:/home/rlrevell/kernel-source/kernel-source-2.6.7# grep . /proc/sys/kernel/*_preemption
/proc/sys/kernel/kernel_preemption:1
/proc/sys/kernel/voluntary_preemption:1

My testing also uncovered a possible bug in the emu10k1 driver, I am looking into this. I don't think it's related because the log entries are spaced minutes apart. Could this be a driver problem? Hardware?

Just as a reference point, what do you think is the longest delay I *should* be seeing? I recall hearing that BEOS guaranteed that interrupts are never disabled for more than 50 usecs. This seems achievable, as the average delay I am seeing is 15 usecs.

I will set CONFIG_FRAME_POINTER=Y and CONFIG_4KSTACKS=n and test some more.

Lee

ATA hardirq latency can be as high as 700 usecs under load even on modern hw, when big DMA requests are created with long scatter-gather lists. We also moved some of the page IO completion code into irq context which further increased hardirq latencies. Since these all touch cold cachelines it all adds up quite quickly.

Ingo

typically all of this happens with irqs enabled (unmask=1), but it still increases scheduling latencies.

with the default DMA setup of today's ATA hw there can be a maximum of 256 entries in the sg-table all zapped in ide_end_request() -> __end_that_request_first().

Plus the IDE driver also builds the sg-table of the next request in hardirq context. (ide_build_dmatable() and ide_build_sglist()).

Ingo

Does this scale in a linear fashion with respect to CPU speed? You mentioned you were testing on a 2Ghz machine, does 700 usecs on that translate to 2800 usecs on a 500Mhz box?

On a 2Ghz machine, 700 usecs is about one million CPU cycles. In other words, the highest priority process can become runnable, then have to wait *one million cycles* to get the CPU.

How much I/O do you allow to be in flight at once? It seems like by decreasing the maximum size of I/O that you handle in one interrupt you could improve this quite a bit. Disk throughput is good enough, anyone in the real world who would feel a 10% hit would just throw hardware at the problem.

Lee

given that this particular latency is dominated by cachemisses the DRAM latency controls it too which is independent of CPU MHz. Wrt. cachemiss costs, newer CPUs typically have twice the L2-cache line size (so it takes more bus cycles to fetch it) - the improvements in bandwidth of fetching a single line should offset most of this. DRAM latencies didnt improve much in the past 10 years so that's almost a constant between a 500MHz/100MHz(system-bus) vs. 2GHz/400MHz system. So i'd guesstimate a 500 MHz box to do somewhere around 1000-1500 usecs.

i'm not sure whether this particular value (max # of sg-entries per IO op) is runtime tunable. Jens? Might make sense to enable elvtune-alike tunability of this value.

limiting the in-flight IO will only work with IDE/PATA that doesnt have multiple commands in flight for a given disk. SATA and SCSI handles multiple command completions per IRQ invocation so limiting the size of a single IO op has less effect there.

Ingo

The particular system I am working with is a Via EPIA M-6000, which is quite new but has a 600Mhz CPU due to it being fanless. I would imagine this would put it closer to a 'modern system' in this regard, as it uses DDR266.

Yes, this would be a nice improvement.

But the current behavior only causes latency problems for an IDE system, so if this were made runtime-tunable then it would only be an issue for SATA, right? This would cover 99.9% of audio users, who would gladly trade some disk throughput for lower latency. You can record a *lot* of tracks with even a few MB/s of disk throughput.

Lee

it's an issue for all block IO drivers that do IO completions from IRQ context and that can do DMA - i.e. every block IO hardware that uses interrupts. This includes SCSI too. In fact for SCSI it's a norm to have tagged queueing active so there the latencies ought to be even higher (although i havent measured this). IDE/PATA's limitation in this regard limits latencies as well.

being able to control the max size of sg-tables and the max # of outstanding commands per IRQ source [this later should already be possible via driver options] should enable us to control the maximum hardirq latency introduced by block IO.

(if the hardware & disk is fast enough, or you use a high # of controllers and disks then you could still overload your system with a stream of interrupts and cause unbound scheduling latencies - but this is a separate problem.)

Ingo

Should work. For example, the RTLinux people report excellent results on SMP systems by binding all RT threads to one CPU and having the Linux part of the system run on the other. This is just a "softer" version of that setup. Even if there are cases where IRQs are disabled globally, it would be an improvement. I suspect you are not getting much of a response because no one has actually tested it with an audio system.

Lee

While locking a RT process to a CPU to achieve even lower latencies might be useful to some
the general userbase wants good latencies on simple UP, non HT-enabled hardware too.
(AMD is gaining marketshare and we cannot simply expect that good multimedia performance (aka low latency) can be achieved only on those SMP/HT boxes where the truth is that except in the case of really crappy hardware, those common UP machines are actually capable to delives latencies in the range of dozen of usecs. (taking the RTLinux benchmarks as reference).
Of course Linux != RTLinux and we never expect nor pretend Linux to match the response time of RTLinux but as said earlier latencies at around 1msec should are doable on decent UP boxes and this is more than adequate to run demanding real time audio applications like software synthesizers, samples, real time effects etc. The only hope is that the hard work from Ingo, Andrew and all the others gets soon integrated in the mainstream 2.6 kernel so all Linux users can take run demanding multimedia applications out of the box without going through the painful patching,kernel recompiling etc.
Or is this still not realistic at this point ?
(see the old issue with kernel 2.4, low latency patches were too unclean to make it into the ufficial kernel tree).

Plus what's very important is that every kernel developer and driver developer (even thirdparty, especially those that do closed source stuff like Nvidia etc) takes into account the latency problems that code paths that run for too long time (or disable IRQs for too long etc) might create.
While I'm not a kernel expert I assume the premptible kernel alleviates this problem but I guess it still cannot completely get rid of low latency-unfriendly routines and drivers.
Perhaps in upcoming Linux kernel/driver programming books this issue should be stressed out and mentioned prominently in order to avoid the eternal:
fixing latencies in kernel x.y.z -> new kernel versions with new drivers/changes/enhancements comes out -> latencies are bad again -> fix latencies in this new kernel version ..... ( iterate at infinitum)

cheers,
Benno
http://www.linuxsampler.org

There are still a few areas that need work, ioctl gives me problems, but the latest 2.6 kernels are quite good. If you look at the 'clean' version of the voluntary kernel preemption patch it is pretty small. My understanding is that the kernel is already preemptible anytime that a spin lock (including the BKL) is not held, and that the voluntary kernel preemption patch adds some scheduling points in places where it is safe to sleep, but preemption is disabled because we are holding the BKL, and that the number of these should approach zero as the kernel is improved anyway.

Yes, this is important. One problem I had recently with the Via EPIA board was that unless 2D acceleration was disabled by setting 'Option "NoAccel"' in /etc/X11/XF86Config-4, overloading the X server would cause interrupts from the soundcard to be completely disabled for tens of milliseconds. Users should keep in mind that by using 2D or 3D hardware acceleration in X, you are allowing the X server to directly access hardware, which can have very bad results if the driver is buggy. I am not sure the kernel can do anything about this.

Lee

That's confusing to me. It was my understanding that the BKL is used to completely lock down the kernel so that no other CPU can have a process get into the kernel... something like how SMP was done under 2.0.

So, if you sleep during a BKL, wouldn't that imply that nothing else would be allowed to enter the kernel until after the kernel thread that took the lock wakes up and releases the lock?

That's confusing to me. It was my understanding that the BKL is used to completely lock down the kernel so that no other CPU can have a process get into the kernel... something like how SMP was done under 2.0.

So, if you sleep during a BKL, wouldn't that imply that nothing else would be allowed to enter the kernel until after the kernel thread that took the lock wakes up and releases the lock?

Yes, I was incorrect. The vountary kernel preemption patch takes sections that are non-preemptible (aka holding a spinlock) and that would otherwise run for an unbounded time and adds logic to break out of those loops, releasing any locks, in order to allow a higher priority process to run. It is voluntary because even though you are in a non-preemptible section you voluntarily release any locks and yield to a higher priority process. It has nothing to do with the BKL as such.

Lee

I'm guessing, then, that if you get preempted, then the function call to voluntarily preempt returns a value which tells you whether or not you got preempted, so that you know whether or not to clean up the results of having your locks broken? (ie. re-lock)

And how does the voluntary-preempt code know which locks to break? All of them?

Thanks.

If we hit a voluntary preemption point and there is no higher priority process ready to run, it's a NOOP, the code just continues without breaking any locks. If there is a runnable higher priority process, then you have to release all spin locks to become preemptible. This is handled on a case-by-case basis, depending on what you have locked and why. When Ingo talks about points in the code being 'latency-aware' this usually means in practice that we are iterating over some list that could be very large, so one way to deal with it is to break out of the loop and release the spinlock after N iterations, where N has to be determined by benchmarking latencies.

Lee

Hi,

interesting that you mention the Xserver. I use a dual graphics card setup atm [Nvidia GF3 TI and some matrox pci card]. The nvidia card seems to work flawlessly even with HW accelleration [i use nvidias evil binary only drivers]. The matrox card OTH disturbs the soundcard severely. Whenever i have activity on my second monitor i get sound artefacts in jack's output [no cracklling, it's rather as if the volume is set to 0 for short moments and then back to normal]. There's a certain chance that this artefact produces an xrun. I suppose it's because the card is on the pci bus.

I figured it's maybe an irq issue problem, but whatever slot i put the gfx card in - it made no difference [btw: how do i find out which resources this card uses? it is not shown by /proc/interrupts]. I also tried putting the soundcard in many different slots to maybe get it on higher prio irq, but it always gets irq 5 [according to /proc/interrupts]..

Should i try a different 2nd gfx card? Should i avoid pci gfx cards at all costs? Will i just have to live w/o second monitor? How do i find out which hw resources X is really using?

Florian Schmidt

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

You could try to adjust the pci latency timer value of your graphic card and sound card, see this link for a paper on the subject by Daniel Robbins :
http://www-106.ibm.com/developerworks/library/l-hw2.html

Thomas

Hi,

good idea. Sadly it doesn't make a difference. Interesting is that lspci -v doesn't show any latency for my mga card:

tapas@mango:~$ lspci -v

[parts snipped, see end of mail]

0000:00:0d.0 Multimedia audio controller: Cirrus Logic CS 4614/22/24 [CrystalClear SoundFusion Audio Accelerator] (rev 01)
Subsystem: TERRATEC Electronic GmbH: Unknown device 112e
Flags: bus master, medium devsel, latency 248, IRQ 5
Memory at cfffb000 (32-bit, non-prefetchable)
Memory at cfe00000 (32-bit, non-prefetchable) [size=1M]
Capabilities: <available only to root>

This is the relevant entry:

0000:00:0f.0 VGA compatible controller: Matrox Graphics, Inc. MGA 2064W [Millennium] (rev 01) (prog-if 00 [VGA])

        Flags: stepping, medium devsel, IRQ 11
        Memory at cfffc000 (32-bit, non-prefetchable) [size=cffe0000]
        Memory at cd000000 (32-bit, prefetchable) [size=8M]
        Expansion ROM at 00010000 [disabled]

0000:01:00.0 VGA compatible controller: nVidia Corporation NV20 [GeForce3 Ti 200] (rev a3) (prog-if 00 [VGA])

        Subsystem: Micro-Star International Co., Ltd.: Unknown device 8503
        Flags: bus master, 66MHz, medium devsel, latency 248, IRQ 3
        Memory at ce000000 (32-bit, non-prefetchable) [size=cfcf0000]
        Memory at c0000000 (32-bit, prefetchable) [size=128M]
        Memory at cca80000 (32-bit, prefetchable) [size=512K]
        Expansion ROM at 00010000 [disabled]
        Capabilities: <available only to root>

Besides not showing a latency the mga card seems to be the only device which has the Flag: "stepping" instead of "bus master".. I tried setting the latency to 0 anyways, and increased it to ffh for my soundcard. The mga card has become really slow though switching desktops still provokes xruns just as easily.. Any other mga card users here? Is this normal behaviour for a dual gfx card setup? Other values didn't help either..

The rest of the lspci -v output:

0000:00:00.0 Host bridge: Silicon Integrated Systems [SiS] 735 Host (rev 01)
Flags: bus master, medium devsel, latency 32
Memory at d0000000 (32-bit, non-prefetchable)
Capabilities: <available only to root>

0000:00:01.0 PCI bridge: Silicon Integrated Systems [SiS] Virtual PCI-to-PCI bridge (AGP) (prog-if 00 [Normal decode])
Flags: bus master, fast devsel, latency 64
Bus: primary=00, secondary=01, subordinate=01, sec-latency=64
Memory behind bridge: cdc00000-cfcfffff
Prefetchable memory behind bridge: bc900000-ccafffff

0000:00:02.0 ISA bridge: Silicon Integrated Systems [SiS] SiS85C503/5513 (LPC Bridge)
Flags: bus master, medium devsel, latency 0

0000:00:02.1 SMBus: Silicon Integrated Systems [SiS]: Unknown device 0016
Flags: medium devsel
I/O ports at 0c00 [size=32]

0000:00:02.5 IDE interface: Silicon Integrated Systems [SiS] 5513 [IDE] (rev d0) (prog-if 80 [Master])
Subsystem: Silicon Integrated Systems [SiS] SiS5513 EIDE Controller (A,B step)
Flags: bus master, fast devsel, latency 128
I/O ports at ff00 [size=16]

0000:00:03.0 Ethernet controller: Silicon Integrated Systems [SiS] SiS900 PCI Fast Ethernet (rev 90)
Subsystem: Elitegroup Computer Systems: Unknown device 0a14
Flags: bus master, medium devsel, latency 64, IRQ 10
I/O ports at dc00 [size=cffa0000]
Memory at cfff9000 (32-bit, non-prefetchable) [size=4K]
Expansion ROM at 00020000 [disabled]
Capabilities: <available only to root>

Thanks, Florian Schmidt

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

The mga dri kernel driver shares a problem with the radeon (which I use a lot) and the r128 drivers. They have high latency points that reach 10-15 msecs in normal operation[*]. I have a very old patch (not mine, I don't quite remember where I got it from) that solves this, but it is not a "legal" patch in the sense that in schedules with a lock held. It seems to work but it will lock the computer at some point. AFAIK there is no proper patch for this latency point at this time. Turning off acceleration should get rid of the latency spikes with the usual tradeoff of slow video performance.

-- Fernando

[*] with the (bad) patch:
http://ccrma.stanford.edu/~nando/latencytest/20040323/2.6.4-1.279.ll.ccrma.radeon/
without the patch:
http://ccrma.stanford.edu/~nando/latencytest/20040323/2.6.4-1.279.ll.ccrma/

<snip>

It is a PCI bus issue. You simply don't have enough PCI bus cycles available to do what you want to do. The resource you're running out of is bus bandwidth, and there's nothing to be done about it, other than remove the PCI gfx card from the system.

If you get another dualhead AGP graphics card (anything will do), the problem should go away. We have a developer who does lowlatency multichannel sound stuff on a machine with a Matrox G450 dualhead card no problem. I expect my own system (Radeon 9800 Pro and M-Audio 1010LT audio) would be fine dualhead too, although I only run it singlehead at the moment. The 1010LT is 10 channels in and out of 24-bit 96kHz audio and works great down to 1.5ms buffers, so it is no small bus load itself.

Andrew

---------
Andrew McGregor
Director, Scientific Advisor
IndraNet Technologies Ltd
http://www.indranet-technologies.com/

-----BEGIN GEEK CODE BLOCK-----
Version: 3.1
GS/E/B/PA/SS d+(++) s+:+ a C++$ ULS++++ !P+++(---)$ L++++$ E++ W++ !N w(+++) !O() M++ V--() Y+$ PGP+ t- !5? X- !R !tv@ b++(++++) DI++ D+++@ G e+++ h(*)@ r%
------END GEEK CODE BLOCK------

Hi,

thanks for the advice. I have tried some more pci cards and a very slow Virge 64 or something actually reduced the problem. Not completely though. I think i'll get me one of those G450 dual head cards..

Florian Schmidt

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

that's bad news.
VIA markets those mini-itx mainboards (with onboard audio/video/network) as multimedia appliances and therefore I'd expect the hardware providing low latencies when both video acceleration and audio is used. Hopefully only a driver issue (as in most of cases)

Since VIA released the unichrome (the gfx chipset contained in their mainboards) sources someone should contact these folks :
http://unichrome.sourceforge.net/
to check what is causing those latency spikes ?
Any unichrome developer lurking on LKML ?

cheers,
Benno
http://www.linuxsampler.org

elvtune is long dead :-)

it's not tweakable right now, but if you wish to experiment you just need to add a line to ide-disk.c:idedisk_setup() - pseudo patch:

+ blk_queue_max_sectors(drive->queue, 32);
+

	printk("%s: max request size: %dKiB\n", drive->name, drive->queue->max_sectors / 2);

	/* Extract geometry if we did not already have one for the drive */

above will limit max request to 16kb, experiment as you see fit.

Jens Axboe

I will give this a try.

Using 2.6.8-rc1-mm1, with La Monte H. P. Yarroll's patch to daemonize softirqs, running two jackds (one in the playback direction, one in capture, to work around an issue with the emu10k1 driver) with 2 periods of 32 frames (666 usec), I am no longer seeing any XRUNS at all once the jackd processes are up and running. I tried stressing the filesystem by recompiling ALSA while running a 'du /' and a 'find / -ls'. The scheduling jitter peaks occasionally at around 100000 CPU cycles (166 usecs) every few seconds, but this is as high as it goes.

This is as good or better than a 2.4 kernel with the low latency patches.

I do not have voluntary preemption enabled, as I do not have a version of the patch that corresponds to this kernel.

The only XRUNS I still get seem related to ioctl() and mlockall(). These both cause an XRUN in one jackd process when starting another:

Jul 20 16:25:46 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 20 16:25:46 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 20 16:25:46 mindpipe kernel:  [__crc_totalram_pages+115469/3518512] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 20 16:25:46 mindpipe kernel:  [__crc_totalram_pages+291773/3518512] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
Jul 20 16:25:46 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 20 16:25:46 mindpipe kernel:  [do_IRQ+161/320] do_IRQ+0xa1/0x140
Jul 20 16:25:46 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 20 16:25:46 mindpipe kernel:  [do_anonymous_page+124/384] do_anonymous_page+0x7c/0x180
Jul 20 16:25:46 mindpipe kernel:  [do_no_page+78/784] do_no_page+0x4e/0x310
Jul 20 16:25:46 mindpipe kernel:  [handle_mm_fault+193/368] handle_mm_fault+0xc1/0x170
Jul 20 16:25:46 mindpipe kernel:  [get_user_pages+337/960] get_user_pages+0x151/0x3c0
Jul 20 16:25:46 mindpipe kernel:  [make_pages_present+104/144] make_pages_present+0x68/0x90
Jul 20 16:25:46 mindpipe kernel:  [mlock_fixup+141/176] mlock_fixup+0x8d/0xb0
Jul 20 16:25:46 mindpipe kernel:  [do_mlockall+112/144] do_mlockall+0x70/0x90
Jul 20 16:25:46 mindpipe kernel:  [sys_mlockall+150/160] sys_mlockall+0x96/0xa0
Jul 20 16:25:46 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 20 16:25:46 mindpipe kernel: IRQ: delay =  9213566 cycles, jitter = 8820554

Jul 20 16:54:02 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D2c
Jul 20 16:54:02 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+115469/3518512] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+291159/3518512] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 20 16:54:02 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 20 16:54:02 mindpipe kernel:  [do_IRQ+161/320] do_IRQ+0xa1/0x140
Jul 20 16:54:02 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+86289/3518512] snd_pcm_hw_rule_div+0x4b/0x60 [snd_pcm]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+77959/3518512] snd_pcm_hw_refine+0x371/0x4a0 [snd_pcm]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+111312/3518512] snd_pcm_hw_param_mask+0x3a/0x50 [snd_pcm]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+882570/3518512] snd_pcm_oss_change_params+0xf4/0x850 [snd_pcm_oss]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+884572/3518512] snd_pcm_oss_get_active_substream+0x76/0x90 [snd_pcm_oss]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+888499/3518512] snd_pcm_oss_get_formats+0x1d/0x120 [snd_pcm_oss]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+888796/3518512] snd_pcm_oss_set_format+0x26/0x60 [snd_pcm_oss]
Jul 20 16:54:02 mindpipe kernel:  [__crc_totalram_pages+894737/3518512] snd_pcm_oss_ioctl+0x49b/0x740 [snd_pcm_oss]
Jul 20 16:54:02 mindpipe kernel:  [sys_ioctl+256/608] sys_ioctl+0x100/0x260
Jul 20 16:54:02 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 20 16:54:02 mindpipe kernel: IRQ: delay =  6702030 cycles, jitter = 6302828

Lee

I tested this and the improvement is drastic. With the default value of 1024KB, running 'bonnie' produced XRUNS of 10+ ms. When this is changed to 16KB, running bonnie only produces latency spikes of up to about 90 usecs, I did not see a single one hit 100usecs.

According to hdparm, the throughput is still quite good (42MB/sec on a sub-$100 IDE drive).

This should definitely be made tunable, I would imagine this would be easy to put in /proc. The default could stay at 1024KB, and users with low latency requirements could lower it.

I am currently testing the effect on throughput and will have some better numbers soon.

Lee

OK, here are my bonnie test results. They are not what I expected - read and write performance is significantly better with 16KB max request size, while seeking is much better with 1024KB.

jackd was running in the background in both cases. With 1024KB, there were massive XRUNS, and worse, occasionally the soundcard interrupt was completely lost for tens of milliseconds. This is what I would expect if huge SG lists are being built in hardirq context. With 16KB, jackd ran perfectly, the highest latency I was was about 100 usecs.

Kernel is 2.6.8-rc2 + voluntary-preempt-I4. CPU is 600Mhz, 512MB RAM.

16KB:

Version 1.03 ------Sequential Output------ --Sequential Input- --Random-

                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
mindpipe         1G  3002  88 31164  60 13485  29  3035  84 32838  36  56.7   0
                    ------Sequential Create------ --------Random Create--------
                    -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16    94  40 +++++ +++ 15510  66   204  86 +++++ +++   906  83 

mindpipe,1G,3002,88,31164,60,13485,29,3035,84,32838,36,56.7,0,16,94,40,+++++,+++,15510,66,204,86,+++++,+++,906,83

1024KB:

Version 1.03 ------Sequential Output------ --Sequential Input- --Random-

                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
mindpipe         1G  2988  86 17647  29 10979  17  3114  90 28556  25 156.7   1
                    ------Sequential Create------ --------Random Create--------
                    -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16   210  88 +++++ +++ 13295  62   215  89 +++++ +++   920  84 

mindpipe,1G,2988,86,17647,29,10979,17,3114,90,28556,25,156.7,1,16,210,88,+++++,+++,13295,62,215,89,+++++,+++,920,84

HD info:
/dev/hdc:

Model=Maxtor 6Y160P0, FwRev=YAR41BW0, SerialNo=Y44K8TZE Config={ Fixed }
RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=57 BuffType=DualPortCache, BuffSize=7936kB, MaxMultSect=16, MultSect=16 CurCHS=4047/16/255, CurSects=16511760, LBA=yes, LBAsects=268435455 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120} PIO modes: pio0 pio1 pio2 pio3 pio4
DMA modes: mdma0 mdma1 mdma2
UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6 AdvancedPM=yes: disabled (255) WriteCache=enabled
Drive conforms to: (null):

* signifies the current active mode

Lee

I repeated the test with 'bonnie -f' and without jackd running, and with 32KB vs. 1024KB. The results are not as drastic, which suggests that all the overhead from the XRUN tracing was a factor.

These results show that 32KB is better than 1024KB in some areas, and not singificantly worse in any of these metrics.

32KB:

Version 1.03 ------Sequential Output------ --Sequential Input- --Random-

                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
mindpipe         1G           38499  68 16383  28           35913  34 154.5   1
                    ------Sequential Create------ --------Random Create--------
                    -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16   257  99 +++++ +++ 24008  98   256  99 +++++ +++  1179  98

mindpipe,1G,,,38499,68,16383,28,,,35913,34,154.5,1,16,257,99,+++++,+++,24008,98,256,99,+++++,+++,1179,98

1024KB:

Version 1.03 ------Sequential Output------ --Sequential Input- --Random-

                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
mindpipe         1G           38285  60 13961  20           33694  28 155.2   1
                    ------Sequential Create------ --------Random Create--------
                    -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16   259  99 +++++ +++ 24250  98   256  99 +++++ +++  1184  98

mindpipe,1G,,,38285,60,13961,20,,,33694,28,155.2,1,16,259,99,+++++,+++,24250,98,256,99,+++++,+++,1184,98

Lee

ok, i'll put in a tunable for the sg size.

Btw., it's not really the building of the SG list that is expensive, it's the completion activity that is expensive since e.g. in the case of ext3 IO traffic it goes over _every single_ sg entry with the following fat codepath:

__end_that_request_first()
bio_endio()

    end_bio_bh_io_sync()
      journal_end_buffer_io_sync()
         unlock_buffer()
           wake_up_buffer()
    bio_put()
      bio_destructor()
        mempool_free()
          mempool_free_slab()
            kmem_cache_free()
        mempool_free()
          mempool_free_slab()
            kmem_cache_free()

the buffer_head, the bio and bio->bi_io_vec all lie on different cachelines and are very likely to be not cached after long IO latencies. So we eat at least 3 big cachemisses, times 256.

Jens, one solution would be to make BIO completion a softirq - like SCSI does. That makes the latencies much easier to control.

Another thing would be to create a compound structure for bio and [typical sizes of] bio->bi_io_vec and free them as one entity, this would get rid of one of the cachemisses. (there cannot be a 3-way compound structure that includes the bh too because the bh is freed later on by ext3.)

Ingo

I tested this with every power of two from 16KB to 1024KB. The current default on my system is 1024KB. This may be affected by disk controller or other factors, someone else reported a default of 128KB with the same drive. Using jackd at the lowest reasonable latency setting (32 frames/period at 48000 frames/sec = 666 usecs/period ), the highest value that does not cause problems is 256KB. The maximum latency spike I saw with this setting was ~220 usecs.

For anyone unfamiliar, if jackd detects that it has been delayed by more than half a period it considers this an error condition because even though there was not an XRUN, it probably does not have enough time left to process a block of audio, and even if it did, it would probably not get scheduled in time to deliver it (IOW there would be an XRUN on the next write) so it restarts.

I therefore propose 256KB as a good default for a low latency system once this is made tunable. This might be a good default for any system, I am not sure under what conditions this would be a bottleneck, but for example this would let you handle multiple NFS clients using 8K or even 32K block sizes without compromising latency. For a single-user, audio-centric system like a DAW, I would go as low as possible until you see disk throughput start to drop, 16KB works well for me.

You would want this as high as possible for, say, a CD burner, but I don't see the point is going as high as 1024KB for a disk drive.

Lee

Scratch this, I got a 380 usec spike with 256KB, enough to trigger jackd to reatart. 128KB so far has only gone as high as 185 usecs.

Lee

Hello.

I was just wondering why the default max request size is 128KiB on my drive, which is almost the same as the one you tested?!

/dev/hda:

Model=Maxtor 6Y120P0, FwRev=YAR41BW0, SerialNo=... Config={ Fixed }
RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=57 BuffType=DualPortCache, BuffSize=7936kB, MaxMultSect=16, MultSect=off CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=240121728 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120} PIO modes: pio0 pio1 pio2 pio3 pio4
DMA modes: mdma0 mdma1 mdma2
UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6 AdvancedPM=yes: disabled (255) WriteCache=enabled
Drive conforms to: (null):

* signifies the current active mode

Thanks.

Rudo.

Your disk controller must not support that. It looks like the default is 1024KiB or whatever the max your controller supports is:

drivers/ide/ide-disk.c:

         if (drive->addressing == 1) { 
                ide_hwif_t *hwif = HWIF(drive);
                int max_s = 2048; 

                if (max_s > hwif->rqsize)
                        max_s = hwif->rqsize;

                blk_queue_max_sectors(drive->queue, max_s); 
        }

Lee

For drives smaller than 128GiB the "48-bit Address feature set" is optional, hence many older drives do not support it (since the old 28-bit LBA addressing is suffient).

With 28-bit addressing the number sectors which can be transferred in one request is limited to 256. Linux 2.4 limited this further to 128 (i.e. 64KiB). With 48-bit addressing up to 2^16 sectors could be transferred in one request, but Linux 2.6 puts an arbitrarily chosen limit of 1024KiB on it.

'hdparm -I /dev/hda' will tell you whether your drive supports 48-bit addressing:

Commands/features:
Enabled Supported:
* 48-bit Address feature set

For full details see the ATA/ATAPI-7 spec at http://www.t13.org/.

Johannes

It's the drive. lba28 cannot do more than 256 sectors, while lba48 can do 65536. The controller only has an impact on this if it's buggy.

Jens Axboe

Note that the method used by hdparm tends to underreport achievable throughput somewhat, because it generally only ever has one I/O "in flight".

Cheers

Mark Lord
(hdparm keeper & the original "Linux IDE Guy")

...

This one occured several times while bonnie was cleaning up after itself:

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

 [<c01066a7>] dump_stack+0x17/0x20
 [<de935377>] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
 [<de945211>] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
 [<c01078c3>] handle_IRQ_event+0x33/0x60
 [<c0107c05>] do_IRQ+0xa5/0x170
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0161b81>] shrink_dcache_parent+0x21/0x30
 [<c0159d69>] d_unhash+0x39/0xb0
 [<c0159e4c>] vfs_rmdir+0x6c/0x1b0
 [<c015a05f>] sys_rmdir+0xcf/0xf0
 [<c0106047>] syscall_call+0x7/0xb
ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:169:
XRUN: pcmC0D0p
 [<c01066a7>] dump_stack+0x17/0x20
 [<de935377>] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
 [<de945477>] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
 [<c01078c3>] handle_IRQ_event+0x33/0x60
 [<c0107c05>] do_IRQ+0xa5/0x170
 [<c0106268>] common_interrupt+0x18/0x20
 [<c0161b81>] shrink_dcache_parent+0x21/0x30
 [<c0159d69>] d_unhash+0x39/0xb0
 [<c0159e4c>] vfs_rmdir+0x6c/0x1b0
 [<c015a05f>] sys_rmdir+0xcf/0xf0
 [<c0106047>] syscall_call+0x7/0xb

Lee

Here are some more. These happen when I switch from X to a text console and back:

Jul 13 04:27:50 mindpipe kernel:
Jul 13 04:27:50 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:27:50 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:27:50 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:27:50 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:27:50 mindpipe kernel:  [do_con_write+397/1888] do_con_write+0x18d/0x760
Jul 13 04:27:50 mindpipe kernel:  [con_write+27/48] con_write+0x1b/0x30
Jul 13 04:27:50 mindpipe kernel:  [opost_block+210/400] opost_block+0xd2/0x190
Jul 13 04:27:50 mindpipe kernel:  [__alloc_pages+458/864] __alloc_pages+0x1ca/0x360
Jul 13 04:27:50 mindpipe kernel:  [write_chan+396/544] write_chan+0x18c/0x220
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [tty_write+434/608] tty_write+0x1b2/0x260
Jul 13 04:27:50 mindpipe kernel:  [write_chan+0/544] write_chan+0x0/0x220
Jul 13 04:27:50 mindpipe kernel:  [vfs_write+186/256] vfs_write+0xba/0x100
Jul 13 04:27:50 mindpipe kernel:  [sys_write+45/80] sys_write+0x2d/0x50
Jul 13 04:27:50 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 04:27:50 mindpipe kernel:
Jul 13 04:27:50 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:27:50 mindpipe kernel:  [group_send_sig_info+101/144] group_send_sig_info+0x65/0x90
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:27:50 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:27:50 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:27:50 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:27:50 mindpipe kernel:  [_mmx_memcpy+141/384] _mmx_memcpy+0x8d/0x180
Jul 13 04:27:50 mindpipe kernel:  [scrup+242/320] scrup+0xf2/0x140
Jul 13 04:27:50 mindpipe kernel:  [lf+96/112] lf+0x60/0x70
Jul 13 04:27:50 mindpipe kernel:  [do_con_trol+2907/3360] do_con_trol+0xb5b/0xd20
Jul 13 04:27:50 mindpipe kernel:  [do_con_write+1128/1888] do_con_write+0x468/0x760
Jul 13 04:27:50 mindpipe kernel:  [con_put_char+51/64] con_put_char+0x33/0x40
Jul 13 04:27:50 mindpipe kernel:  [opost+162/464] opost+0xa2/0x1d0
Jul 13 04:27:50 mindpipe kernel:  [write_chan+437/544] write_chan+0x1b5/0x220
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [tty_write+434/608] tty_write+0x1b2/0x260
Jul 13 04:27:50 mindpipe kernel:  [write_chan+0/544] write_chan+0x0/0x220
Jul 13 04:27:50 mindpipe kernel:  [vfs_write+186/256] vfs_write+0xba/0x100
Jul 13 04:27:50 mindpipe kernel:  [sys_write+45/80] sys_write+0x2d/0x50
Jul 13 04:27:50 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 04:27:50 mindpipe kernel:
Jul 13 04:27:50 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:27:50 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:27:50 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:27:50 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:27:50 mindpipe kernel:  [__do_softirq+48/144] __do_softirq+0x30/0x90
Jul 13 04:27:50 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 13 04:27:50 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 13 04:27:50 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:27:50 mindpipe kernel:
Jul 13 04:27:50 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:27:50 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:27:50 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:27:50 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:27:50 mindpipe kernel:  [do_con_write+1035/1888] do_con_write+0x40b/0x760
Jul 13 04:27:50 mindpipe kernel:  [con_write+27/48] con_write+0x1b/0x30
Jul 13 04:27:50 mindpipe kernel:  [opost_block+210/400] opost_block+0xd2/0x190
Jul 13 04:27:50 mindpipe kernel:  [__alloc_pages+458/864] __alloc_pages+0x1ca/0x360
Jul 13 04:27:50 mindpipe kernel:  [write_chan+396/544] write_chan+0x18c/0x220
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [tty_write+434/608] tty_write+0x1b2/0x260
Jul 13 04:27:50 mindpipe kernel:  [write_chan+0/544] write_chan+0x0/0x220
Jul 13 04:27:50 mindpipe kernel:  [vfs_write+186/256] vfs_write+0xba/0x100
Jul 13 04:27:50 mindpipe kernel:  [sys_write+45/80] sys_write+0x2d/0x50
Jul 13 04:27:50 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 04:27:50 mindpipe kernel:
Jul 13 04:27:50 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:27:50 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:27:50 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:27:50 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:27:50 mindpipe kernel:  [do_con_write+974/1888] do_con_write+0x3ce/0x760
Jul 13 04:27:50 mindpipe kernel:  [con_put_char+51/64] con_put_char+0x33/0x40
Jul 13 04:27:50 mindpipe kernel:  [opost+327/464] opost+0x147/0x1d0
Jul 13 04:27:50 mindpipe kernel:  [write_chan+437/544] write_chan+0x1b5/0x220
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [tty_write+434/608] tty_write+0x1b2/0x260
Jul 13 04:27:50 mindpipe kernel:  [write_chan+0/544] write_chan+0x0/0x220
Jul 13 04:27:50 mindpipe kernel:  [vfs_write+186/256] vfs_write+0xba/0x100
Jul 13 04:27:50 mindpipe kernel:  [sys_write+45/80] sys_write+0x2d/0x50
Jul 13 04:27:50 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 04:27:50 mindpipe kernel:
Jul 13 04:27:50 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:27:50 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:27:50 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:27:50 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:27:50 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:27:50 mindpipe kernel:  [do_con_write+1448/1888] do_con_write+0x5a8/0x760
Jul 13 04:27:50 mindpipe kernel:  [con_write+27/48] con_write+0x1b/0x30
Jul 13 04:27:50 mindpipe kernel:  [opost_block+210/400] opost_block+0xd2/0x190
Jul 13 04:27:50 mindpipe kernel:  [__alloc_pages+458/864] __alloc_pages+0x1ca/0x360
Jul 13 04:27:50 mindpipe kernel:  [write_chan+396/544] write_chan+0x18c/0x220
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [default_wake_function+0/32] default_wake_function+0x0/0x20
Jul 13 04:27:50 mindpipe kernel:  [tty_write+434/608] tty_write+0x1b2/0x260
Jul 13 04:27:50 mindpipe kernel:  [write_chan+0/544] write_chan+0x0/0x220
Jul 13 04:27:50 mindpipe kernel:  [vfs_write+186/256] vfs_write+0xba/0x100
Jul 13 04:27:50 mindpipe kernel:  [sys_write+45/80] sys_write+0x2d/0x50
Jul 13 04:27:50 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 04:27:50 mindpipe kernel:

Lee

framebuffer scrolling inside lock_kernel(). Tricky. Suggest you use X or vgacon. You can try removing the lock_kernel() calls from do_tty_write(), but make sure you're wearing ear protection.

OK, I figured this was not an easy one. I can just not do that.

Here are some more. These result from using mplayer with ALSA OSS emulation:

Jul 13 04:31:49 mindpipe kernel:
Jul 13 04:31:49 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:31:49 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:31:49 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:31:49 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1394929/5353478] snd_pcm_format_set_silence+0x4b/0x1d0 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2165815/5353478] snd_pcm_oss_change_params+0x5a1/0x850 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2166620/5353478] snd_pcm_oss_get_active_substream+0x76/0x90 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2170556/5353478] snd_pcm_oss_get_formats+0x26/0x100 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [kfree_skbmem+23/32] kfree_skbmem+0x17/0x20
Jul 13 04:31:49 mindpipe kernel:  [__kfree_skb+101/240] __kfree_skb+0x65/0xf0
Jul 13 04:31:49 mindpipe kernel:  [packet_rcv_spkt+380/544] packet_rcv_spkt+0x17c/0x220
Jul 13 04:31:49 mindpipe kernel:  [dev_queue_xmit_nit+179/288] dev_queue_xmit_nit+0xb3/0x120
Jul 13 04:31:49 mindpipe kernel:  [avc_has_perm_noaudit+104/512] avc_has_perm_noaudit+0x68/0x200
Jul 13 04:31:49 mindpipe kernel:  [avc_has_perm+72/96] avc_has_perm+0x48/0x60
Jul 13 04:31:49 mindpipe kernel:  [inode_has_perm+73/144] inode_has_perm+0x49/0x90
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1377866/5353478] snd_pcm_hw_constraint_minmax+0x34/0x40 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1359876/5353478] snd_pcm_hw_constraints_complete+0x17e/0x290 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [selinux_file_ioctl+213/784] selinux_file_ioctl+0xd5/0x310
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2174928/5353478] snd_pcm_oss_open+0x1aa/0x350 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [soundcore_open+328/768] soundcore_open+0x148/0x300
Jul 13 04:31:49 mindpipe kernel:  [chrdev_open+233/528] chrdev_open+0xe9/0x210
Jul 13 04:31:49 mindpipe kernel:  [dentry_open+260/560] dentry_open+0x104/0x230
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2170812/5353478] snd_pcm_oss_set_format+0x26/0x60 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2176960/5353478] snd_pcm_oss_ioctl+0x51a/0x850 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [sys_ioctl+256/608] sys_ioctl+0x100/0x260
Jul 13 04:31:49 mindpipe kernel:  [sys_fcntl64+87/144] sys_fcntl64+0x57/0x90
Jul 13 04:31:49 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 04:31:49 mindpipe kernel:
Jul 13 04:31:49 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 04:31:49 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 04:31:49 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 04:31:49 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1373142/5353478] snd_interval_refine+0xa0/0x1c0 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1357711/5353478] snd_pcm_hw_rule_div+0x49/0x50 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1347991/5353478] snd_pcm_hw_refine+0x371/0x4a0 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+1383137/5353478] snd_pcm_hw_param_mask+0x3b/0x50 [snd_pcm]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2164618/5353478] snd_pcm_oss_change_params+0xf4/0x850 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [chrdev_open+233/528] chrdev_open+0xe9/0x210
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2166620/5353478] snd_pcm_oss_get_active_substream+0x76/0x90 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2170887/5353478] snd_pcm_oss_get_format+0x11/0x30 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [__crc_totalram_pages+2176960/5353478] snd_pcm_oss_ioctl+0x51a/0x850 [snd_pcm_oss]
Jul 13 04:31:49 mindpipe kernel:  [sys_ioctl+256/608] sys_ioctl+0x100/0x260
Jul 13 04:31:49 mindpipe kernel:  [sys_fcntl64+87/144] sys_fcntl64+0x57/0x90
Jul 13 04:31:49 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 04:31:49 mindpipe kernel:

Lee

Why not? You can certainly try removing those [un]lock_kernel() calls.

Looks like those memcpys in snd_pcm_format_set_silence() are hurting.

At Tue, 13 Jul 2004 02:00:25 -0700,

Hmm, but it's not in lock at least...

Takashi

It is - see chrdev_open().

You can do unlock_kernel()/lock_kernel() in soundcore_open().

At Tue, 13 Jul 2004 02:25:01 -0700,

Oh yeah...

I remember ioctl() is also in lock_kernel()?

Takashi

yes, you'll need to do unlock_kernel/lock_kernel there too. If someone changes the rules, or otherwise calls your ioctl withoht lock_kernel() held it will reliably go BUG with spinlock debugging enabled, so make sure you test with CONFIG_DEBUG_SPINLOCK=y.

Maybe I missed something. What exactly do you mean by 'make sure you're wearing ear protection'?

Lee

It might go boom. If it does screw up, it probably won't be very seriously bad - maybe some display glitches. Just an experiment.

Heh, I thought you literally meant it could destroy my speakers. I have a pretty loud amp hooked up to this thing! I will try that.

Meanwhile, here are some more XRUS traces from the same test, run overnight, without any significant network activity. I believe updatedb may have caused these. I left out the reiserfs related ones because that seems to be a known issue.

Jul 13 06:22:07 mindpipe kernel:
Jul 13 06:22:07 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 06:22:07 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 06:22:07 mindpipe kernel:  [do_pollfd+125/144] do_pollfd+0x7d/0x90
Jul 13 06:22:07 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 06:22:07 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 06:22:07 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 06:22:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 06:22:07 mindpipe kernel:
Jul 13 06:22:07 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 06:22:07 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 06:22:07 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 06:22:07 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 06:22:07 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 06:22:07 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 06:22:07 mindpipe kernel:  [__kmalloc+110/160] __kmalloc+0x6e/0xa0
Jul 13 06:22:07 mindpipe kernel:  [sys_poll+209/560] sys_poll+0xd1/0x230
Jul 13 06:22:07 mindpipe kernel:  [__pollwait+0/160] __pollwait+0x0/0xa0
Jul 13 06:22:07 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 06:22:07 mindpipe kernel:
Jul 13 06:22:19 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 06:22:19 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 06:22:19 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 06:22:19 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 06:22:19 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 06:22:19 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 06:22:19 mindpipe kernel:
Jul 13 06:26:13 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D0p
Jul 13 06:26:13 mindpipe kernel:  [__crc_totalram_pages+1387264/5353478] snd_pcm_period_elapsed+0x2ca/0x410 [snd_pcm]
Jul 13 06:26:13 mindpipe kernel:  [__crc_totalram_pages+2260290/5353478] find_attr+0xdc/0x250 [ntfs]
Jul 13 06:26:13 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 13 06:26:13 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 13 06:26:13 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 13 06:26:13 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 13 06:26:13 mindpipe kernel:  [__crc_totalram_pages+2275930/5353478] ntfs_readdir+0xd24/0xfe0 [ntfs]
Jul 13 06:26:13 mindpipe kernel:  [filldir64+0/256] filldir64+0x0/0x100
Jul 13 06:26:13 mindpipe kernel:  [vfs_readdir+133/160] vfs_readdir+0x85/0xa0
Jul 13 06:26:13 mindpipe kernel:  [filldir64+0/256] filldir64+0x0/0x100
Jul 13 06:26:13 mindpipe kernel:  [sys_getdents64+102/163] sys_getdents64+0x66/0xa3
Jul 13 06:26:13 mindpipe kernel:  [filldir64+0/256] filldir64+0x0/0x100
Jul 13 06:26:13 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 13 06:26:13 mindpipe kernel:

Lee

Seems to work perfectly. No visible display glitches.

I would imagine that putting a modem on a tty, then stressing the system and watching for line errors would be a definitive test.

@@ -684,17 +684,13 @@
                return -ERESTARTSYS;
        }
        if ( test_bit(TTY_NO_WRITE_SPLIT, &tty->flags) ) {
-               lock_kernel();
                written = write(tty, file, buf, count);
-               unlock_kernel();
        } else {
                for (;;) {
                        unsigned long size = max((unsigned long)PAGE_SIZE*2, 16384UL);
                        if (size > count)
                                size = count;
-                       lock_kernel();
                        ret = write(tty, file, buf, size);
-                       unlock_kernel();
                        if (ret <= 0)
                                break;
                        written += ret;

Lee

At Mon, 12 Jul 2004 17:46:39 -0700,

Yes, I measured a similar on reiserfs, too.
Creation and deletion of many small files causes high latencies.

The creation latency appears with ext3, too, but vanishes when preemption is enabled.

The deletion peaks appear on all systems. It's in the long loop of shrink_dcache_parent().

IIRC, the RCU tasklet stall was another cause of latency in some very heavy cases.

But, except for creation/deletion of zillon-files, I've not seen any big latencies during my tests with reiserfs. Reading/writing big files (a few GB) are totally OK on reiserfs, all under 1.5 ms.

Takashi

Does anyone have any data points on XFS in this regard? I agree that ext2 is faster than ext3, and ext3 probably has lower latency than reiser3, but I have no info at all on XFS. My JFS experience is all on AIX, as well, so if anyone has that info it might be interesting as well.

   -bill davidsen ([email protected])
"The secret to procrastination is to put things off until the
 last possible moment - but no longer"  -me

On Tue, 13 Jul 2004 18:40:30 -0400 Bill Davidsen wrote:

| Andrew Morton wrote:
| > Lee Revell <[email protected]> wrote:
| > 
| >>>resierfs: yes, it's a problem.  I "fixed" it multiple times in 2.4, but the
| >>
| >> > fixes ended up breaking the fs in subtle ways and I eventually gave up.
| >> > 
| >>
| >> Interesting.  There is an overwhelming consensus amongst Linux audio
| >> folks that you should use reiserfs for low latency work.
| > 
| > 
| > It seems to be misplaced.  A simple make-a-zillion-teeny-files test here
| > exhibits a 14 millisecond holdoff.
| > 
| > 
| >> Should I try ext3?
| > 
| > 
| > ext3 is certainly better than that, but still has a couple of potential
| > problem spots.  ext2 is probably the best at this time.
| 
| Does anyone have any data points on XFS in this regard? I agree that 
| ext2 is faster than ext3, and ext3 probably has lower latency than 
| reiser3, but I have no info at all on XFS. My JFS experience is all on 
| AIX, as well, so if anyone has that info it might be interesting as well.

Yes, but not recent. I did lots of journaling-fs testing and workloads on 2.4.19-pre7 for LinuxWorld Aug. 2004. Presentation is here:
http://developer.osdl.org/rddunlap/journal_fs/lwe-jgfs.pdf

Simplified summary:

XFS fared well on (large) sequential IO workloads. And of course, none of the journaling fs-es beat ext2, but XFS came the closest.

At the time of that presentation, JFS was very slow. The JFS team was working on correctness/robustness only, not performance. I don't know the status of that today.
It's somewhat of a shame, because on paper JFS looks like a great filesystem (IMO).

--
~Randy

with the voluntary-preempt patch applied ext3 is below ~500 usecs for all things i tried on a 2GHz CPU. Without the patch i can trigger latencies up to milliseconds (even with CONFIG_PREEMPT) by triggering a bigger commit stream via some large file write or a cached du / causing a stream of atime updates. (I very much suspect that all other journalled filesystems have similar problems and they'll need measurements and fixing just like ext3 does.)

another bigger problem area is the VM - see my patch for details. pagetable zapping and page reclaim are both problematic and need fixups even under CONFIG_PREEMPT. Doing a simple 'make -j' kernel build that hits swap triggers these easily. (after applying my patch the latencies go below 1msec even with a 'make -j' overload.)

Ingo

I discovered I can reliably produce a large XRUN by toggling Caps Lock, Scroll Lock, or Num Lock. This is with 2.6.8-rc1-mm1 + voluntary preempt (I modified the patch by hand to apply on this kernel, as 2.6.8-rc2 disables my network card). Here is the XRUN trace.

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

 [<c01066f7>] dump_stack+0x17/0x20
 [<de952477>] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
 [<de962477>] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
 [<c0107913>] handle_IRQ_event+0x33/0x60
 [<c0107c55>] do_IRQ+0xa5/0x170
 [<c01062b8>] common_interrupt+0x18/0x20
 [<c01d3f7f>] __delay+0xf/0x20
 [<c021881a>] atkbd_sendbyte+0x5a/0xa0
 [<c0218a35>] atkbd_command+0x1d5/0x200
 [<c0218bcb>] atkbd_event+0x16b/0x200
 [<c0215a95>] input_event+0x115/0x3d0
 [<c01ecaeb>] kbd_bh+0xbb/0x160
 [<c011a554>] tasklet_action+0x44/0x70
 [<c011a303>] __do_softirq+0x83/0x90
 [<c011a345>] do_softirq+0x35/0x40
 [<c0107cc5>] do_IRQ+0x115/0x170
 [<c01062b8>] common_interrupt+0x18/0x20
 [<c014b95e>] sys_read+0x2e/0x50
 [<c0106097>] syscall_call+0x7/0xb

Lee

That's odd. I wonder if the hardware is sick. What is the duration is the underrun? The info you sent didn't include that.

eh? That's a rather more serious problem. Does the via-rhine.c from 2.6.8-rc1-mm1 work OK if you move it into 2.6.8-rc2?

I don't think so, it's a Dell QuietKey PS/2 keyboard, plugged into a regular PS/2 port. The XRUN is 24-70ms, usually about 32ms.

I posted this to LKML, the error I get is 'Invalid MAC Address'. I will try the older version.

Lee

no, it's the ps2 driver that is sick. The ps2 keyboard driver is one of the few places that busy-polls for IRQ completion from within a tasklet context for things like led switching (yuck) - this can cause many millisecs delays on all boards i tried.

Ingo

I can also add that La Monte H. P. Yarroll's patch to daemonize softirqs seems to provide major improvements in latency (does not help this problem of course). There has been at least one other patch posted to LKML that that does the same thing. Will this feature be in the kernel anytime soon?

Lee

we already 'daemonize' softirqs in the stock kernel if the load is high enough. (this is what ksoftirqd does) So the only question is a tunable to make this deferring of softirq load mandatory. Yarroll's patch is quite complex, i dont think that is necessary. It also has at least one conceptual problem, the NOP-ing of local_bh_disable/enable in case of CONFIG_SOFTIRQ_THREADS is clearly wrong. Yarroll?

I've added a very simple solution to daemonize softirqs similar to Yarroll's patch to the -H5 version of voluntary-preempt:

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

the 'level' of preemption is controlled via the value of voluntary_preempt - a level of 2 (default) means that softirq-deferring is done too. A level of 1 means only the extra preemption points are activated, level 0 means the vanilla scheduling and softirq behavior.

below i've also attached a softirq.c patch against 2.6.8-rc2 that does unconditional deferring. (this patch is of course not intended to be merged upstream as-is, since normally we want to process softirqs right after the irq context.)

Ingo

@@ -70,7 +70,7 @@ static inline void wakeup_softirqd(void)
  */
 #define MAX_SOFTIRQ_RESTART 10
 
-asmlinkage void __do_softirq(void)
+asmlinkage void ___do_softirq(void)
 {
 	struct softirq_action *h;
 	__u32 pending;

@@ -106,6 +106,23 @@ restart:
 	__local_bh_enable();
 }
 
+asmlinkage void __do_softirq(void)
+{
+	/*
+	 * 'preempt harder'. Push all softirq processing off to ksoftirqd.
+	 */
+	if (local_softirq_pending())
+		wakeup_softirqd();
+}
+
+asmlinkage void _do_softirq(void)
+{
+	local_irq_disable();
+	___do_softirq();
+	local_irq_enable();
+}
+
+
 #ifndef __ARCH_HAS_DO_SOFTIRQ
 
 asmlinkage void do_softirq(void)

@@ -340,7 +363,7 @@ static int ksoftirqd(void * __bind_cpu)
 			preempt_disable();
 			if (cpu_is_offline((long)__bind_cpu))
 				goto wait_to_die;
-			do_softirq();
+			_do_softirq();
 			preempt_enable();
 			cond_resched();
 		}

i've got a more complete patch against vanilla 2.6.8-rc2:

http://redhat.com/~mingo/voluntary-preempt/defer-softirqs-2.6.8-rc2-A2

which introduces the following tunable:

/proc/sys/kernel/defer_softirqs (default: 0)

this, if enabled, causes all softirqs to be processed within ksoftirqd, and it also breaks out of the softirq loop if preemption of ksoftirqd has been triggered by a higher-prio task.

I've also added this additional break-out to the -H6 patch of voluntary-preempt:

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

it's enabled by default.

Ingo

What do you think about deferring softirqs just while in critical sections?

I'm not sure how well this works, and it is CONFIG_PREEMPT only but in theory it should prevent unbounded softirqs while under locks without taking the performance hit of doing the context switch.

---

 linux-2.6-npiggin/include/asm-i386/hardirq.h |    8 ++++++--
 linux-2.6-npiggin/include/linux/preempt.h    |    6 +-----
 linux-2.6-npiggin/kernel/sched.c             |   13 +++++++++++--
 linux-2.6-npiggin/kernel/softirq.c           |    4 ++--
 4 files changed, 20 insertions(+), 11 deletions(-)

diff -puN kernel/softirq.c~lat-softirq kernel/softirq.c
@@ -68,7 +68,7 @@ static inline void wakeup_softirqd(void)
  * we want to handle softirqs as soon as possible, but they
  * should not be able to lock up the box.
  */
-#define MAX_SOFTIRQ_RESTART 10
+#define MAX_SOFTIRQ_RESTART 4
 
 asmlinkage void __do_softirq(void)
 {

@@ -322,7 +322,7 @@ void __init softirq_init(void)
 
 static int ksoftirqd(void * __bind_cpu)
 {
-	set_user_nice(current, 19);
+	set_user_nice(current, 10);
 	current->flags |= PF_NOFREEZE;
 
 	set_current_state(TASK_INTERRUPTIBLE);

diff -puN include/asm-i386/hardirq.h~lat-softirq include/asm-i386/hardirq.h
@@ -80,17 +80,21 @@ typedef struct {
 # include <linux/smp_lock.h>
 # define in_atomic()	((preempt_count() & ~PREEMPT_ACTIVE) != kernel_locked())
 # define IRQ_EXIT_OFFSET (HARDIRQ_OFFSET-1)
+#define irq_exit()							\
+do {									\
+		preempt_count() -= IRQ_EXIT_OFFSET;			\
+		preempt_enable_no_resched(); /* This will catch the softirq */ \
+} while (0)
 #else
 # define in_atomic()	(preempt_count() != 0)
 # define IRQ_EXIT_OFFSET HARDIRQ_OFFSET
-#endif
 #define irq_exit()							\
 do {									\
 		preempt_count() -= IRQ_EXIT_OFFSET;			\
 		if (!in_interrupt() && softirq_pending(smp_processor_id())) \
 			do_softirq();					\
-		preempt_enable_no_resched();				\
 } while (0)
+#endif
 
 #ifndef CONFIG_SMP
 # define synchronize_irq(irq)	barrier()

diff -puN include/linux/preempt.h~lat-softirq include/linux/preempt.h
@@ -16,12 +16,8 @@ do { \
 	preempt_count()++; \
 } while (0)
 
-#define dec_preempt_count() \
-do { \
-	preempt_count()--; \
-} while (0)
-
 #ifdef CONFIG_PREEMPT
+void dec_preempt_count(void);
 
 asmlinkage void preempt_schedule(void);
 

diff -puN kernel/sched.c~lat-softirq kernel/sched.c
@@ -3968,8 +3968,16 @@ void __might_sleep(char *file, int line)
 EXPORT_SYMBOL(__might_sleep);
 #endif
 
+#ifdef CONFIG_PREEMPT
+void dec_preempt_count(void)
+{
+	if (unlikely(preempt_count() == 1 &&
+				softirq_pending(smp_processor_id())))
+		do_softirq();
+	preempt_count()--;
+}
 
-#if defined(CONFIG_SMP) && defined(CONFIG_PREEMPT)
+#ifdef CONFIG_SMP
 /*
  * This could be a long-held lock.  If another CPU holds it for a long time,
  * and that CPU is not asked to reschedule then *this* CPU will spin on the

@@ -4012,4 +4020,5 @@ void __sched __preempt_write_lock(rwlock
 }
 
 EXPORT_SYMBOL(__preempt_write_lock);
-#endif /* defined(CONFIG_SMP) && defined(CONFIG_PREEMPT) */
+#endif /* CONFIG_SMP */
+#endif /* CONFIG_PREEMPT */

_

You're still running do_softirq() with preemption disabled, which is almost as bad as doing it under a lock.

-Scott

well softirqs are designed like that. I've added extra preemption code to the latest patch to avoid repeat processing.

Ingo

And those who wish to continue using them like that can. However, in my patch they never run with preemption disabled, which can result in substantial latency improvement (as long as nothing else is causing similar delays). I see nothing in the design that *requires* them to continue running with preemption disabled.

Likewise, interrupts are "designed" to be unpreemptible, but it is possible to run them in their own threads so as to further reduce sources of latency (at a throughput cost, of course). This allows long-held spinlocks that an interrupt handler needs to acquire to be replaced with mutexes that don't inhibit preemption.

Of course, a better fix is to keep the interrupt handlers and critical sections short, but threading them can be very effective for producing low latencies in the short term (we were able to achieve worst measured case latencies of well under 100us on ordinary PC hardware under 2.4.x using this approach).

Do you also add preemption checks in all of the various loops that can be run from within a single softirq instance?

-Scott

do you have a 2.6 patch for hardirq redirection too? I always thought this to be the best approach to achive hard-RT class latency guarantees under Linux (but never coded it up). The problem with RTLinux is that it introduces a separate OS (with separate APIs). It is (much) further ahead of Linux in terms of latencies, algorithms and guarantees but is still a separate OS. I believe there is a natural synergy between low latencies needed for good desktop and multiuser performance and soft-RT/hard-RT needs, which we should use - RTLinux doesnt generate this synergy.

if both hardirqs and softirqs are redirectable to process contexts then the only unpredictable latency would be the very short IRQ entry stub of a new hardirq costing ~5 usecs - which latency is limited in effect unless the CPU is hopelessly bombarded with interrupts.

to solve the spinlock problem of hardirqs i'd propose a dual type spinlock that is a spinlock if hardirqs are immediate (synchronous) and it would be a mutex if hardirqs are redirected (asynchronous). Then some simple driver could be converted to this RT-aware spinlock and we'd see how well it works. Have you done experiments in this direction? I believe this all could be merged upstream, given sufficient cleanliness.

Ingo

Yes, and I'll try to get it cleaned up and posted soon. It depends on threaded softirqs, though (so I'll have to do something with the local_bh_disable; probably put it back to the way it was, at least for now).

If you really want hard-RT-type guarantees, though, you'd need to go with a scheme whereby interrupts/preemption are disabled only where the code has specifically been "approved" as not capable of causing excessive latency (which IRQ threads are a step towards, and which is what we did in 2.4), as opposed to the current scheme of benchmarking latencies and fixing those places which actually show up as being problematic. There's always the possibility that a different usage case will show up later, causing the latency in some piece of code to go way up.

Those aren't the only sources; you also have preempt_disable() and such (as well as hardware weirdness, though there's not much we can do about that).

This sort of substitution is what we did in 2.4, though we made this type the default and gave the real spinlocks a new name to be used in those few places where it was really needed. Of course, this resulted in a lot of places using a mutex where a spinlock would have been fine.

-Scott

i did not say latency sources, i said unpredictable latency sources. hardirq and softirq processing introduces near arbitrary latency at any (irqs-enabled) point in the kernel. Hence they make all kernel code unbound in essence - even the most trivial kernel code, sys_getpid().

by (optionally) moving softirqs and hardirqs to a process context we've removed this source of uncertainty by making all processing synchronous, and what remains are ordinary algorithmic properties of the kernel code
- which we can predict and control. I.e. with those two fixed we now have a _chance_ to guarantee latencies.

[the only remaining source of 'latency uncertainty' is the small asynchronous hardirq stub that would still remain. This has an effect that can be compared to e.g. cache effects and it cannot become unbound unless the CPU is bombarded with a very high number of interrupts.]

what are those few places where a spinlock was really needed?

I'm a bit uneasy about making mutexes the default not due to performance but due to e.g. some hardware being very timing-sensitive. I dont think we can make a blanket assumption that every code path is preemptable if all processing is synchronous and the exclusions are listened to.

Ingo

Places that inherently cannot sleep, such as inside the scheduler, the unthreadable part of the hard IRQ code, inside the mutex implementation, etc.

In practice, this didn't turn out to be an issue; most modern hardware seems to be pretty tolerant of that (and you already have to deal with things like interrupts getting in the way), and drivers which do local_irq_disable() or to ensure timing will still work.

Has this sort of problem been seen with RT-Linux and such, which would cause similar delays?

-Scott

Scott and Ingo,

Drivers that you might have to poll (technically a kind of hardware level spinlock multi-device concurrency problem... Those special spins need to be bounded by a preempt_{dis,en}able to prevent deadlocking) for completion since it can't do an async notify of some sort, the low level timer handling infrastructure, all places in the scheduler, all child functions/places that can sleep/block within a non-preemptable critical section must be demoted back to spinlocks and more stuff. The problem isn't trivial at all. The latter one on the list is something that requires progressive audit as minor kernel releases come out.

This is major project. kgdb needs to be ported to it, etc... and other things that slip my mind right now.

There are also other problem with moving to a largely sleeping mutex style kernel, dead lock detection becomes sorely needed. Current spinlock detection methods are probably going to be useless in a system like this. BSD/OS-FreeBSD have some of these facilites. The TimeSys mutexes have a read/write lock, akind to BSD/OS shared/exclusive locks, that has a depth first search cycle detector in them. My background is BSD/OS-FreeBSD.

The problem with FreeBSD is that their project is pretty much crap in that they have these ego-manics focused on cute little SMP mechanisms instead of actually doing the hard work of pushing locks down into lower level subsystems. That's why DragonFly-BSD split from them in addition to other multipule reasons. They also have tons more class and are nicer, smarter folks in general. :)

The good thing about this, Linux, is that many of the RTOS issues we're talking about now have a direct 1:1 relationship to SMP locking issues. The concurrency issues, in a mathematical manner, are the same. It's not just the trivial stuff with holding a non-preemptive lock such as BLK, but in the context of priority inheritance and contention where, I believe, the simple case use of priority inheritance should be considered a kind contention overload condition of the overall system.

The general purpose OS folks like FreeBSD and old versions Solaris have a sort of confused and backward notion of this problem by using priority inheritance as a substitute for fixing the contention problems in the first place. They abuse the scheduler to try and a get system that can respond regularly to priority centric schedulers, but what happens instead is they spread scheduling irregularities that effect the entire kernel in unknown, unpredictable and odd ways. RTOS folks are much more sensitive to the over and inappropriate use of things like this.

Linux is prime for some kind of RTOS conversion in that locks have been pushed down sufficiently that late/runtime detection logic with simple priority inheritance would rarely be triggered. That's basically a kind of lock contention maladaptation. There's a possibility of making Linux a top-notch RTOS if the right folks where working on that stuff.

Rant over... :)

BTW, this basically turning Linux into a kind of SGI IRIX style system.

bill

i have another worry with the 'everything is a mutex' concept. Currently we still do have a number of 'central' locks such as dcache_lock, or the SLAB locks. So even if all (but the scheduling) spinlocks are converted to sleeping mutexes what do you gain? A high-prio RT task will get to execute userspace instructions almost immediately, but any kernel functionality use of this RT thread might still be blocked by a priority inversion problem. So the same type of latency problems that we are detecting and solving currently will occur on a mutex-based system as well - if the RT application wants to use kernel functionality.

so why dont we keep the spinlocks [on UP, nonpreemptible sections] and just let the kernel finish its work and get to a fully lock-quiescent state ASAP where we can reschedule? It's not like that a high-prio RT task can avoid this situation with any guarantee, as long as these central locks remain. (in fact it would have to do this processing with higher overhead, because the lowprio thread that got preemption needs to be boosted, scheduled, unscheduled and the high-prio task needs to schedule again.)

i'd agree with turning most of the finegrained per-task (non-irq-safe) spinlocks into mutexes (or spin-mutexes). But the central locks that an RT task would likely hit need to remain spinlocks i believe.

plus there are central mutexes too that are in 'hiding' currently but could cause latencies just as much.

Ingo

The difference is that latency issues are isolated to code which uses the locks with bad critical sections. If some random driver holds an internal lock for a few milliseconds, it won't slow down anything that doesn't interact with the driver (either directly or by blocking on something else that interacts with the driver). Turning the spinlocks into mutexes doesn't eliminate the need for lock-breaking; it just lets the lock-breaking effort be concentrated on the core mutexes, so you don't need to fix *all* of the bad critical sections to see a reduction in worst case latency of common code.

Those critical sections where lock-breaking has been done can be converted back into spinlocks. Essentially, mutexes would be used for "untrusted" locks, as opposed to using spinlocks just where they're absolutely necessary. Over time, the set of trusted locks would presumably go up, though we'd have to be careful to make sure people know that they need to be especially careful of latency issues when they touch code that uses such locks.

One of the main benefits is that it significantly increases the RT guarantees for those users for whom the RT portion of their app can be verified as only using a limited, testable/auditable subset of kernel paths. Otherwise, you run the risk of some special code path (such as out-of-memory, perhaps) that didn't get hit in latency testing showing up and causing problems for a RT task that doesn't need memory, and doesn't go anywhere near the lock in question. How much this matters depends on how hard the RT one needs is.

Another is that the observed latencies of many apps is likely to go down faster than when squashing each individual latency in the system as it shows up. Said squashing can (and should) still occur, but at least some apps will not have to wait.

-Scott

ok, i see - this makes 100% sense. I'm wondering how intrusive such an all-preemptive patchset is? There are some problems with per-CPU data structures on SMP. Right now holding a spinlock means one can use smp_processor_id() and rely on it staying constant in the critical section. With a mutex in the same place all such assumptions would break. Is there some automatic way to deal with these issues (or to at least detect them reliably?).

Ingo