CONFIG_PREEMPT_REALTIME, 'Fully Preemptible Kernel', VP-2.6.9-rc4-mm1-T4

OK.

Now that the usb-storage crash has been ironed out, thanks to Thomas Gleixner's patch, I proceeded with some local experiments regarding the jackd -R issue.

The fact is jackd -R (realtime mode; SCHED_FIFO) hosing the system, and thats exposed as soon as some jack audio client application enters into the chain.

Running jackd non-realtime (SCHED_OTHER) does not expose this problem, so I think it's a scheduling related one.

With a default scenario, with all IRQ handlers under SCHED_OTHER scheduling class and default priority, running jackd -R freezes completely the system. Only a hard-reset or power-off is the way out.

Then I try tweaking the keyboard (IRQs 1,12), rtc (IRQ 8) and soundcard (IRQ 5) scheduling policies to SCHED_FIFO and priority to something higher than jackd's (e.g. chrt --fifo 60).

This way, running jack -R still hoses the system, in a somewhat less egoistic manner, but still seems that it's the only process running on the system taking full control of it. The evidence I could find was that jackd's verbose output keeps pumping, as it would usually, but all the rest poor things freeze to death. This time however, magic SysRq is of some use, barely thanks to the i8042 IRQ scheduling promotion.

So it all seems that jackd -R is not crashing, nor anything else, for this matter.

I really hate to say this, but this should be investigated for the RT patch sake, obviously because the only purpose I find to it is precisely running jackd -R, and I can swear it has been near perfection until U4 inclusive (think it was called VP back then :).

I hope I'm not the only one.

(IIRC Florian Schmidt was experiencing something similar, like system intermitence, pauses, whatever, while also running jackd -R.)

Strange enough, all this is running on another SMP/HT box of mine, without major issues. Guess that SMP makes the difference here.

But wait, now I remember to notice something there yet: running some jack clients (e.g. fluidsynth) is much more expensive than usual wrt.CPU usage, reaching very unusual levels above 40% sustained (this is actual CPU% as reported by procps tools, not the DSP usage as reported by jack itself). IMHO the SMP/HT effect just seems to mask the real trouble, as the increased cost affects only one of the (virtual) CPUs.

I wonder if this does ring some bell out there. :)

Cheers,

rncbc aka Rui Nuno Capela
[email protected]

i tried to pole jackd a little bit (just using things like jack_freewheel and jack_impulse_grabber - i dont even know what they do), and got jackd into some sort of userspace loop:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2558 root 16 0 27900 1852 2152 S 97.8 0.8 2:36.38 jackd

attaching gdb to it shows:

Loaded symbols for /usr/local/lib/jack/jack_oss.so 0xffffe410 in ?? ()
(gdb) bt

 #0  0xffffe410 in ?? ()
 #1  0xbffff7f8 in ?? ()
 #2  0x00000a67 in ?? ()
 #3  0x00000000 in ?? ()
 #4  0x4db8adf8 in pthread_join () from /lib/tls/libpthread.so.0
 #5  0xb77d6e66 in oss_driver_stop (driver=0x8055938) at  oss_driver.c:696
 #6  0x0804ba03 in jack_engine_delete (engine=0x805c308) at  engine.c:2466
 #7  0x0804ade7 in main (argc=3, argv=0xbffffb44) at jackd.c:207

(gdb)

it's looping somewhere in the pthread code, and it does no system-calls at all and thus no scheduling as well.

i dont know much about jackit, and it could easily be that something in this kernel broke its interaction with pthread, but it seems to me that this loop is in userspace and is only 'fatal' if the looping thread runs at SCHED_FIFO priority. Could someone with more jackit experience try to figure out what's going on here?

Ingo

ah ... i should have guessed that "jack_freewheel y" puts jackd into ... freewheeling mode. So this is by design.

i still suspect that it's some sort of userspace loop causing the jackd problems - just that under SCHED_OTHER you dont normally notice it, while with jack -R it's fatal.

Ingo

After some trial-and-error cycle, changing kernel configuration options, I come to believe the obvious, that this jackd -R nasty behavior seems to be present (only) if PREEMPT_REALTIME is set (Y).

When PREEMPT_REALTIME is not set (N), it just runs and I can throw any client at 'jackd -R' without hosing the whole system. However, I'm seeing plenty of these:

BUG: scheduling while atomic: jackd/0x00000002/3968
caller is schedule_timeout+0x5a/0xa8
 [<c0104ec8>] dump_stack+0x1e/0x20 (20)
 [<c02cd6d2>] __schedule+0x4c4/0x69e (76)
 [<c02ce45f>] schedule_timeout+0x5a/0xa8 (60)
 [<c0169c75>] do_poll+0x9b/0xb9 (48)
 [<c0169e02>] sys_poll+0x16f/0x225 (76)
 [<c010408d>] sysenter_past_esp+0x52/0x71 (-8124)

preempt count: 00000003
. 3-level deep critical section nesting:
.. entry 1: ipc_lock_writer+0x2f/0xae / (sys_shmctl+0x88/0x895) .. entry 2: ipc_lock_writer+0xa3/0xae / (sys_shmctl+0x88/0x895) .. entry 3: print_traces+0x16/0x4a / (dump_stack+0x1e/0x20)

BUG: sleeping function called from invalid context jackd(3968) at
mm/slab.c:2055
in_atomic():1 [00000002], irqs_disabled():0
 [<c0104ec8>] dump_stack+0x1e/0x20 (20)
 [<c011505f>] __might_sleep+0xb2/0xc5 (36)
 [<c013e7f8>] __kmalloc+0xa3/0xaa (28)
 [<c0169d60>] sys_poll+0xcd/0x225 (76)
 [<c010408d>] sysenter_past_esp+0x52/0x71 (-8124)

preempt count: 00000003
. 3-level deep critical section nesting:
.. entry 1: ipc_lock_writer+0x2f/0xae / (sys_shmctl+0x88/0x895) .. entry 2: ipc_lock_writer+0xa3/0xae / (sys_shmctl+0x88/0x895) .. entry 3: print_traces+0x16/0x4a / (dump_stack+0x1e/0x20)

OTOH, I do get in some trouble elsewhere, but not related to jackd. For example, the system hangs on udev, never managed to shutdown cleanly, and some system monitoring applications just keeps failing completely (e.g. gkrellm).

But I found this on late init:

BUG: Unable to handle kernel NULL pointer dereference at virtual address

00000000
printing eip:
c01cbb7d
*pde = 00000000

Oops: 0000 [#1]
PREEMPT
Modules linked in: realtime commoncap snd_seq_oss snd_seq_midi_event

snd_seq snd_pcm_oss snd_mixer_oss snd_usb_usx2y snd_usb_lib snd_rawmidi snd_seq_device snd_hwdep snd_ali5451 snd_ac97_codec snd_pcm snd_timer snd_page_alloc snd soundcore prism2_cs p80211 ds yenta_socket pcmcia_core natsemi crc32 loop subfs evdev ohci_hcd usbcore thermal processor fan button battery ac

CPU:    0
EIP:    0060:[<c01cbb7d>]    Not tainted VLI
EFLAGS: 00210246   (2.6.9-rc4-mm1-U9.2)

EIP is at acpi_os_signal_semaphore+0x30/0x4e
eax: df75b700 ebx: 00000001 ecx: 00000000 edx: 00000010
esi: c155c400 edi: 00000000 ebp: de48dd9c esp: de48dd98
ds: 007b es: 007b ss: 0068 preempt: 00000001
Process kdeinit (pid: 3862, threadinfo=de48c000 task=de5af400)

Stack: df750700 de48ddac c01d4b88 df74b160 00000001 de48ddc4 c01d67a2
df750700
       df750700 c155c400 c155c400 de48ddd8 c01d3abe df750700 c155c400
00000000
       de48ddf8 c01cd2e2 c155c400 00000000 c149c820 c155c400 c155c5ec
00000000
Call Trace:
 [<c0104e94>] show_stack+0x80/0x96 (28)
 [<c010502f>] show_registers+0x165/0x1de (56)
 [<c0105241>] die+0xf6/0x191 (64)
 [<c01123ab>] do_page_fault+0x483/0x6a4 (212)
 [<c0104af1>] error_code+0x2d/0x38 (72)
 [<c01d4b88>] acpi_ex_system_release_mutex+0x28/0x2a (16)
 [<c01d67a2>] acpi_ex_release_mutex+0x135/0x154 (24)
 [<c01d3abe>] acpi_ex_opcode_1A_0T_0R+0x2a/0x92 (20)
 [<c01cd2e2>] acpi_ds_exec_end_op+0xb4/0x28e (32)
 [<c01db23e>] acpi_ps_parse_loop+0x528/0x810 (40)
 [<c01db57d>] acpi_ps_parse_aml+0x57/0x1c2 (32)
 [<c01dbea5>] acpi_psx_execute+0x15d/0x1c4 (28)
 [<c01d914d>] acpi_ns_execute_control_method+0x41/0x51 (20)
 [<c01d90f2>] acpi_ns_evaluate_by_handle+0x74/0x8e (16)
 [<c01d8fed>] acpi_ns_evaluate_relative+0xa9/0xc5 (32)
 [<c01d88a5>] acpi_evaluate_object+0xfd/0x1ae (52)
 [<c01cbedd>] acpi_evaluate_integer+0x32/0x4f (52)
 [<e001a06c>] acpi_button_state_seq_show+0x27/0x64 [button] (32)
 [<c0175562>] seq_read+0xd3/0x2cf (60)
 [<c015461c>] vfs_read+0xc1/0x13a (44)
 [<c015490b>] sys_read+0x4b/0x75 (44)
 [<c010408d>] sysenter_past_esp+0x52/0x71 (-8124)

preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: die+0x3a/0x191 / (do_page_fault+0x483/0x6a4) .. entry 2: print_traces+0x16/0x4a / (show_stack+0x80/0x96)

Code: 4d 08 8b 5d 0c 85 c9 0f 94 c2 85 db 0f 94 c0 09 d0 ba 01 10 00 00 a8

01 75 28 83 fb 01 66 ba 10 00 77 1f ff 01 0f 8e d2 00 00 00 <8b> 01 48 7e 10 68 29 7e 2e c0 e8 5a c3 f4 ff 5b e8 18 93 f3 ff

As it seemed an ACPI issue, I turned it off and the troubles went away. Again, all this is happening with PREEMPT_REALTIME off.

Bye now.

rncbc aka Rui Nuno Capela
[email protected]

Grr. I got this -U8 mail *before* I got the -U7 mail.

All thruout these U# kernels, I get stalls in X(everything pauses, not sure if remote pings stop). Nothing shows in dmesg when this occurs.

I had been running rc kernels for awhile, without these problems. I had not run any mm kernels, but I have run all the U kernels(but not U7).

Compiling/rebooting.

Got some input on this.

Heavy disk and/or network i/o seems to cause the pauses. Doing a copy over nfs(writing to disk), or using scp gives me 1-2 MB/s. If I boot plain rc4, I get full network speed(10-11 MB/s with nfs, 5-8 MB/s with scp).

i have released the -U9 Real-Time Preemption patch, which can be downloaded from:

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

this too is a fixes-only release. It includes more driver fixes and improvements from Thomas Gleixner.

Changes since -U8.1:

- USB semaphore->completion conversion from Thomas Gleixner

- netconsole fixes from Michal Schmidt

- fbcon fixes

- added counted semaphores, this is now used by firewire, XFS and ACPI. This could fix the firewire breakage - but testing would be welcome.

- PREEMPT_ACTIVE irqs-enabled critical path removal.

- fixed irqs-off raw spinlock primitives on UP: they enabled irqs before enabling preemption, creating a window for an interrupt to slip in and increase the critical path.

- made the deadlock detector not crash the current process - it will just hang. This produces far nicer log output while still not endangering stability. Also, fixed a bug in the detector that happens if the trace buffer overflows.

- made the atomic-counter-underflow detector non-fatal as well, for the same reasons.

to create a -U9 tree from scratch, the patching order is:

http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.8.tar.bz2
+ http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.9-rc4.bz2
+ http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc4/2.6.9-rc4-mm1/2.6.9-rc4-mm1.bz2
+ http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U9

Ingo

impi watchdog conversion to completion api.

tglx

diff --exclude='*~' -urN 2.6.9-rc4-mm1-RT-U9/drivers/char/ipmi/ipmi_watchdog.c 2.6.9-rc4-mm1-U9-E0/drivers/char/ipmi/ipmi_watchdog.c
--- 2.6.9-rc4-mm1-RT-U9/drivers/char/ipmi/ipmi_watchdog.c 2004-10-21
15:47:23.000000000 +0200
+++ 2.6.9-rc4-mm1-U9-E0/drivers/char/ipmi/ipmi_watchdog.c 2004-10-21
15:41:53.000000000 +0200
@@ -386,16 +386,16 @@
when both messages are free. */
static atomic_t heartbeat_tofree = ATOMIC_INIT(0); static DECLARE_MUTEX(heartbeat_lock);
-static DECLARE_MUTEX(heartbeat_wait_lock); +static DECLARE_COMPLETION(heartbeat_received);
static void heartbeat_free_smi(struct ipmi_smi_msg *msg) {
if (atomic_dec_and_test(&heartbeat_tofree))
- up(&heartbeat_wait_lock);
+ complete(&heartbeat_received);
}
static void heartbeat_free_recv(struct ipmi_recv_msg *msg) {
if (atomic_dec_and_test(&heartbeat_tofree))
- up(&heartbeat_wait_lock);
+ complete(&heartbeat_received);
}
static struct ipmi_smi_msg heartbeat_smi_msg =
{
@@ -473,7 +473,7 @@
}

/* Wait for the heartbeat to be sent. */
- down(&heartbeat_wait_lock);
+ wait_for_completion(&heartbeat_received);

if (heartbeat_recv_msg.msg.data[0] != 0) {
/* Got an error in the heartbeat response. It was already

Sorry, I copied the wrong file to the correct place.

tglx

diff --exclude='*~' -urN 2.6.9-rc4-mm1-RT-U9/drivers/char/ipmi/ipmi_watchdog.c 2.6.9-rc4-mm1-U9-E0/drivers/char/ipmi/ipmi_watchdog.c
--- 2.6.9-rc4-mm1-RT-U9/drivers/char/ipmi/ipmi_watchdog.c 2004-10-21
15:47:23.000000000 +0200
+++ 2.6.9-rc4-mm1-U9-E0/drivers/char/ipmi/ipmi_watchdog.c 2004-10-21
16:25:14.000000000 +0200
@@ -47,6 +47,7 @@
#include <linux/reboot.h>
#include <linux/wait.h>
#include <linux/poll.h>
+#include <linux/completion.h>
#ifdef CONFIG_X86_LOCAL_APIC
#include <asm/apic.h>
#endif
@@ -386,16 +387,16 @@
when both messages are free. */
static atomic_t heartbeat_tofree = ATOMIC_INIT(0); static DECLARE_MUTEX(heartbeat_lock);
-static DECLARE_MUTEX(heartbeat_wait_lock); +static DECLARE_COMPLETION(heartbeat_received);
static void heartbeat_free_smi(struct ipmi_smi_msg *msg) {
if (atomic_dec_and_test(&heartbeat_tofree))
- up(&heartbeat_wait_lock);
+ complete(&heartbeat_received);
}
static void heartbeat_free_recv(struct ipmi_recv_msg *msg) {
if (atomic_dec_and_test(&heartbeat_tofree))
- up(&heartbeat_wait_lock);
+ complete(&heartbeat_received);
}
static struct ipmi_smi_msg heartbeat_smi_msg =
{
@@ -473,7 +474,7 @@
}

/* Wait for the heartbeat to be sent. */
- down(&heartbeat_wait_lock);
+ wait_for_completion(&heartbeat_received);

if (heartbeat_recv_msg.msg.data[0] != 0) {
/* Got an error in the heartbeat response. It was already
@@ -944,7 +945,6 @@
{
int rv;

- init_MUTEX_LOCKED(&heartbeat_wait_lock);
printk(KERN_INFO PFX "driver version "
IPMI_WATCHDOG_VERSION "\n");

The #ifdef is not right. Patch attached.

Michal

@@ -74,7 +74,7 @@ static void write_msg(struct console *co
 		return;
 
 	local_irq_save(flags);
-#ifdef PREEMPT_REALTIME
+#ifdef CONFIG_PREEMPT_REALTIME
 	/*
 	 * A bit hairy. Netconsole uses mutexes (indirectly) and
 	 * thus must have interrupts enabled:

indeed - i've added this to -U9.2 too.

Ingo

Hey,

The kernel booted now with my firewire card plugged in. However when i try to mount my reiser4 partition i get following error

BUG: semaphore recursion deadlock detected!
.. current task mount/10514 is already holding ccb5bb4c.
c022d6cb cf25d8f0 ccb5bae8 00002912 ccb5bb4c 00000000 ccb5bb48 ccb5a000
      ccb5bb4c cf25d8f0 00000000 ccb5bb48 c0344760 ccb5bb4c 0000019d 
ccb5bb50
      ccb5bb50 cf25d8f0 00000002 ccabdc00 ccb5bb4c d0b26a08 ccabdd4c 
c0120005
Call Trace:
[<c022d6cb>] __rwsem_deadlock+0xd9/0x12d (4)
[<c0344760>] down_write+0x103/0x1a6 (48)
[<d0b26a08>] kcond_wait+0xaa/0xac [reiser4] (36)
[<c0120005>] do_fork+0x133/0x18a (8)
[<c03443a8>] out_of_line_wait_on_bit+0x91/0x99 (32)
[<c0134273>] wake_bit_function+0x0/0x55 (28)
[<c0134c36>] check_preempt_timing+0x6e/0x1a4 (16)
[<c034471a>] down_write+0xbd/0x1a6 (56)
[<c034471a>] down_write+0xbd/0x1a6 (12)
[<d0b280b0>] start_ktxnmgrd+0x98/0x9a [reiser4] (36)
[<d0b33716>] reiser4_fill_super+0x3b/0x71 [reiser4] (28)
[<c0160854>] sb_set_blocksize+0x2e/0x5d (588)
[<c01603fd>] get_sb_bdev+0xf9/0x132 (24)
[<d0b2d569>] reiser4_get_sb+0x2f/0x33 [reiser4] (68)
[<d0b336db>] reiser4_fill_super+0x0/0x71 [reiser4] (20)
[<c016061a>] do_kern_mount+0x4f/0xc0 (4)
[<c0175945>] do_new_mount+0x9c/0xe1 (36)
[<c0175feb>] do_mount+0x145/0x194 (44)
[<c034471a>] down_write+0xbd/0x1a6 (48)
[<c0175e4d>] copy_mount_options+0x63/0xbc (32)
[<c0176459>] sys_mount+0x9f/0xe0 (32)
[<c01060b1>] sysenter_past_esp+0x52/0x71 (44)

preempt count: 00000003
. 3-level deep critical section nesting:
.. entry 1: down_write+0x1a1/0x1a6 / (0x0)
.. entry 2: down_write+0x6a/0x1a6 / (0x0)
.. entry 3: print_traces+0x17/0x50 / (0x0)

------------[ cut here ]------------
kernel BUG at lib/rwsem-generic.c:601!
invalid operand: 0000 [#1]
PREEMPT
Modules linked in: reiser4 airo_cs airo ohci_hcd ehci_hcd 8139cp mii ohci1394 ieee1394 snd_intel8x0 snd_ac97_codec usbhid uhci_hcd intel_agp agpgart snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_pcm snd_timer snd_page_alloc snd_mixer_oss snd usbcore vfat fat
CPU:    0
EIP:    0060:[<c022dc15>]    Not tainted VLI
EFLAGS: 00010202   (2.6.9-rc4-mm1-RT-U9.1)

EIP is at up_write+0x1dc/0x1e9
eax: cca0a000 ebx: ccb5bb48 ecx: 0000002f edx: cf25d8f0
esi: ccb5bb4c edi: ccabdc00 ebp: cf1ad970 esp: cca0bf84
ds: 007b es: 007b ss: 0068 preempt: 00000001
Process ktxnmgrd (pid: 10544, threadinfo=cca0a000 task=cf1ad970)

Stack: 00000001 cf1ad970 ccabdc00 cf1ad970 ccb5bb48 ccabdc00 ccabdc00 cf1ad970
      d0b26b9f ccabdc00 cdf87000 ccabdd4c d0b27de5 ccabdc00 c0105fda 
cf205260
      d0b27d4c 00000000 cc9d5400 00000000 00000000 00000000 cca0a000 
d0b27d4c
Call Trace:
[<d0b26b9f>] kcond_broadcast+0x23/0x46 [reiser4] (36)
[<d0b27de5>] ktxnmgrd+0x99/0x22c [reiser4] (16)
[<c0105fda>] ret_from_fork+0x6/0x14 (8)
[<d0b27d4c>] ktxnmgrd+0x0/0x22c [reiser4] (8)
[<d0b27d4c>] ktxnmgrd+0x0/0x22c [reiser4] (28)
[<c01042a9>] kernel_thread_helper+0x5/0xb (16)

preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: die+0x39/0x198 / (0x0)
.. entry 2: print_traces+0x17/0x50 / (0x0)

reiser4 has some pretty ugly locking abstraction called kcond, i took a look but it doesnt seem simple to convert it. Reiserfs should really use a normal Linux waitqueue and nothing more...

Ingo

It's fairly standard condition variable.

Why? Condition variable is very well known and widely used concept. In the area of their applicability (where predicate whose change is waited upon is protected by a single lock) they provide clean and easily recognizable synchronization device.

Real problem in this case is failure of "semaphore deadlock detection" to cope with perfectly legal semaphore usage (down() by thread T1, up() by thread T2). As one possible solution kcond can be re-written on top of beloved "normal Linux waitqueue".

Nikita.

sorry, but just look at the kcond code and compare the 'fastpath' with say the fastpath of Linux semaphores or waitqueue handling.

condition variables (here i dont mean your code specifically, but the general pthread concept) are simply trying to achieve too much via a single object, which increases their complexity quite significantly.

Separating out a few select atomic synchronization primitives that can be used for each appropriate purpose does the job equally well.

condition variables are fine if you 1) already know them from userspace and 2) want to use a single locking abstraction for everything. It is thus also a kitchen-sink primitive that is inevitably slow and complex. I still have to see a locking problem where condvars are the cleanest/simplest answer, and i've yet to see a locking problem where condvars are not the slowest answer ;)

of course this too is valid kernel code so i'm not complaining at all. It was simply too complex to be converted at first sight to PREEMPT_REALTIME.

Ingo

Agree completely. kcond implementation is very inefficient. But it's "obviously correct" at that. Idea was to optimize it later, when we would have time for this. Didn't happen so far.

This is quite questionable. Where is this complexity? Standard condition variable usage looks like

    spin_lock(&lock);
    while (!predicate)
        kcond_wait(&cond_var, &lock);
    /*
     * at this point predicate is true and @lock is held
     */

This can, of course, be implemented with wait-queues, but:

- condition variables are used idiomatically, and hence, contain strong hint about what code tries to achieve.

- their API is designed to match their (rather narrow) usage. For example, kcond_wait() takes lock as an argument and can (given proper debugging support in the spin-lock implementation) check that this lock is actually locked by the calling thread.

Difference between a condition variable and "atomic synchronization primitives" is like difference between a spin-lock and open-coded Dekker
algorithm: both provide you with mutual exclusion, but the former gives one distinct clue about what is going on.

Umm... I have better example: every algorithm can be coded without loop statements, with goto-s only. And (given proper programmer) goto produces better assembly than while(). Does this constitutes an argument in favor of throwing away all these wimpy loops that no Real Programmer should use?

A kernel daemon that waits for some work to do is an example.

(And just to fight what seems to be common misconception: condition variables were not introduced by POSIX committee, they are much older than that. As all synchronization primitives they originate from the kernel land.)

what type of work - could you be a bit more specific?

Ingo

Take a loop in fs/cifs/cifsfs.c:cifs_oplock_thread() (I won't copy it here to avoid you all going blind). It can be recoded as

    while(1) {
        spin_lock(&GlobalMid_Lock);
        while (list_empty(&GlobalOplock_Q)) {
             if (kcond_timedwait(&SomeCIFSCVAR, &GlobalMid_Lock, HZ) == -EINTR) {
                     spin_unlock(&GlobalMid_Lock);
                     complete_and_exit(&cifs_oplock_exited, 0);
             }
        }
        oplock_item = list_entry(GlobalOplock_Q.next, struct oplock_q_entry, qhead);
        /* do stuff with oplock_item ... */
        spin_unlock(&GlobalMid_Lock);
        ....
    }

Point is that this is very stylistic usage---easily recognizable.

Nikita.

in this particular case i'd use a workqueue, which would simplify this down to something like:

	workqueue_handler()
	{	
		spin_lock(&GlobalMid_Lock);
		oplock_item = list_entry(GlobalOplock_Q.next, ...);
		/* do stuff with oplock_item */
		spin_unlock(&GlobalMid_Lock);
	}

and instead of playing games with signals to exit the worker thread, i'd use destroy_workqueue().

Ingo

Got a second error, while compiling a new kernel my network connection got down

BUG: semaphore recursion deadlock detected!
.. current task eth0/10202 is already holding cc9345ac.
cc9345ac c03433b7 cfe51260 ccb5e000 cc9345ac cd11c740 ccb5ff8c ffffe000
      c034490c cc9345ac 000001d9 cc9345b0 cc9345b0 cd11c740 00000002 
cc9343e0
      ccb5e000 cc934644 ffffe000 d0a7a136 c5fcd280 cc934000 ccb5e000 
c0105fda
Call Trace:
[<c03433b7>] __sched_text_start+0x2e3/0x5e2 (8)
[<c034490c>] down_write_interruptible+0x109/0x243 (28)
[<d0a7a136>] airo_thread+0x82/0x2a0 [airo] (44)
[<c0105fda>] ret_from_fork+0x6/0x14 (16)
[<c011d046>] default_wake_function+0x0/0x12 (12)
[<d0a7a0b4>] airo_thread+0x0/0x2a0 [airo] (24)
[<c01042a9>] kernel_thread_helper+0x5/0xb (16)

preempt count: 00000003
. 3-level deep critical section nesting:
.. entry 1: down_write_interruptible+0x23e/0x243 / (0x0) .. entry 2: down_write_interruptible+0x6c/0x243 / (0x0) .. entry 3: print_traces+0x17/0x50 / (0x0)

tglx

diff --exclude='*~' -urN 2.6.9-rc4-mm1-RT-U9/kernel/sched.c 2.6.9-rc4-mm1-U9-E0/kernel/sched.c
--- 2.6.9-rc4-mm1-RT-U9/kernel/sched.c 2004-10-21 15:47:21.000000000
+0200
+++ 2.6.9-rc4-mm1-U9-E0/kernel/sched.c 2004-10-21 17:17:44.000000000
+0200
@@ -3185,9 +3185,9 @@
__set_current_state(TASK_UNINTERRUPTIBLE); spin_unlock_irq(&x->wait.lock); timeout = schedule_timeout(timeout);
+ spin_lock_irq(&x->wait.lock);
if (!timeout)
goto out;
- spin_lock_irq(&x->wait.lock);
} while (!x->done); __remove_wait_queue(&x->wait, &wait);
}
@@ -3250,8 +3250,10 @@
} __set_current_state(TASK_INTERRUPTIBLE); spin_unlock_irq(&x->wait.lock);
- schedule();
- spin_lock_irq(&x->wait.lock);
+ timeout = schedule_timeout(timeout);
+ spin_lock_irq(&x->wait.lock);
+ if (!timeout)
+ goto out;
} while (!x->done); __remove_wait_queue(&x->wait, &wait);
}

Finally a patch that I can get booted on my older SMP system at home again. More correctly it is U9.2. I have been having problems with these hanging after U5. Haven't had a ton of time to try to track down the problems and didn't want to report problems without having done enough troubleshooting. Anyway, I got this while booting U9.2.

kr

Oct 21 12:33:22 porky kernel: BUG: atomic counter underflow at:
Oct 21 12:33:22 porky kernel:  [<c0254dd8>] qdisc_destroy+0x98/0xa0 (12)
Oct 21 12:33:22 porky kernel:  [<c0254fed>] dev_shutdown+0x3d/0xa0 (16)
Oct 21 12:33:22 porky kernel:  [<c024773b>] unregister_netdevice+0x13b/0x280 (28)
Oct 21 12:33:22 porky netfs: Mounting other filesystems:  succeeded
Oct 21 12:33:22 porky kernel:  [<c0112fb0>] mcount+0x14/0x18 (12)
Oct 21 12:33:22 porky kernel:  [<e09a6160>] tulip_remove_one+0x0/0xa0 [tulip] (4)
Oct 21 12:33:22 porky kernel:  [<c02058de>] unregister_netdev+0x1e/0x30 (24)
Oct 21 12:33:22 porky kernel:  [<e09a618f>] tulip_remove_one+0x2f/0xa0 [tulip] (16)
Oct 21 12:33:22 porky kernel:  [<c01f2907>] device_release_driver+0x67/0x70 (8)
Oct 21 12:33:22 porky kernel:  [<c0112fb0>] mcount+0x14/0x18 (8)
Oct 21 12:33:22 porky kernel:  [<c01c4e26>] pci_device_remove+0x76/0x80 (20)
Oct 21 12:33:22 porky kernel:  [<c01f573b>] device_detach_shutdown+0xb/0x40 (12)
Oct 21 12:33:22 porky kernel:  [<c01f2907>] device_release_driver+0x67/0x70 (12)
Oct 21 12:33:22 porky kernel:  [<c01f293b>] driver_detach+0x2b/0x40 (24)
Oct 21 12:33:22 porky kernel:  [<c01f2daf>] bus_remove_driver+0x3f/0x70 (20)
Oct 21 12:33:22 porky kernel:  [<c01f32b9>] driver_unregister+0x19/0x30 (20)
Oct 21 12:33:22 porky kernel:  [<c01c50cc>] pci_unregister_driver+0x1c/0x30 (16)
Oct 21 12:33:22 porky kernel:  [<e09a7767>] tulip_cleanup+0x17/0x1b [tulip] (16)
Oct 21 12:33:22 porky kernel:  [<c0139801>] sys_delete_module+0x121/0x150 (12)
Oct 21 12:33:22 porky kernel:  [<c01531a1>] sys_munmap+0x51/0x60 (64)
Oct 21 12:33:22 porky kernel:  [<c0116a20>] do_page_fault+0x0/0x660 (16)
Oct 21 12:33:22 porky kernel:  [<c0106719>] sysenter_past_esp+0x52/0x71 (16)
Oct 21 12:33:22 porky kernel: preempt count: 00000001
Oct 21 12:33:22 porky kernel: . 1-level deep critical section nesting:
Oct 21 12:33:22 porky kernel: .. entry 1: print_traces+0x1d/0x60 / (dump_stack+0x23/0x30)
Oct 21 12:33:22 porky kernel: 
Oct 21 12:33:22 porky kernel: tulip 0000:04:0a.0: Device was removed without properly calling pci_disable_device(). This may need fixing.

I guess, you don't have a tulip network card in your box, as the module is removed.

The question is, if it got registered correctly before the removal.

tglx

Actually I do have the tulip card in the box and I am pulling this stuff from the logs over that connection now. Here are the next lines from the log that might help.

Oct 21 12:33:22 porky kernel: tulip 0000:04:0a.0: Device was removed without pro
perly calling pci_disable_device(). This may need fixing.
Oct 21 12:33:22 porky kernel: hda: ATAPI 48X CD-ROM CD-R/RW drive, 8192kB Cache,
 UDMA(33)
Oct 21 12:33:22 porky kernel: Uniform CD-ROM driver Revision: 3.20
Oct 21 12:33:22 porky kernel: hdc: ATAPI 48X CD-ROM drive, 120kB Cache, UDMA(33)
Oct 21 12:33:22 porky kernel: ip_tables: (C) 2000-2002 Netfilter core team
Oct 21 12:33:22 porky kernel: Linux Tulip driver version 1.1.13 (May 11, 2002)
Oct 21 12:33:22 porky kernel: PCI: Found IRQ 5 for device 0000:04:0a.0
Oct 21 12:33:22 porky kernel: PCI: Sharing IRQ 5 with 0000:04:05.1
Oct 21 12:33:22 porky kernel: tulip0:  EEPROM default media type Autosense.
Oct 21 12:33:22 porky kernel: tulip0:  Index #0 - Media MII (#11) described by a
 21140 MII PHY (1) block.
Oct 21 12:33:22 porky kernel: tulip0:  MII transceiver #3 config 3100 status 780
9 advertising 01e1.
Oct 21 12:33:22 porky kernel: eth0: Digital DS21140 Tulip rev 32 at 0xe480, 00:0

0:C0:7F:A0:E9, IRQ 5.

Not really. We must figure out, why sys_delete_module is called.

[<e09a7767>] tulip_cleanup+0x17/0x1b [tulip] (16)
[<c0139801>] sys_delete_module+0x121/0x150 (12)   <<--------
[<c01531a1>] sys_munmap+0x51/0x60 (64)
[<c0116a20>] do_page_fault+0x0/0x660 (16)
[<c0106719>] sysenter_past_esp+0x52/0x71 (16)

This one is a result of the BUG()

tglx

Understand. I did not mean the log would help figure it out, but that it would explain that the card really is present. :)

My guess is that it is prematurely unloading the driver before it's fully registered, like you said. The question is why? Also I am not in front of the system right now so I can't unload the module to see if it generates the error again, but I will try it when I get home.

More info on this:

As mentioned before, I get this on boot (every boot):

Oct 21 12:33:22 porky kernel: Linux Tulip driver version 1.1.13 (May 11, 2002)
Oct 21 12:33:22 porky kernel: PCI: Found IRQ 5 for device 0000:04:0a.0
Oct 21 12:33:22 porky kernel: PCI: Sharing IRQ 5 with 0000:04:05.1
Oct 21 12:33:22 porky kernel: tulip0:  EEPROM default media type Autosense.
Oct 21 12:33:22 porky kernel: tulip0:  Index #0 - Media MII (#11) described by a 21140 MII PHY (1) block.
Oct 21 12:33:22 porky kernel: tulip0:  MII transceiver #3 config 3100 status 7809 advertising 01e1.
Oct 21 12:33:22 porky kernel: eth0: Digital DS21140 Tulip rev 32 at 0xe480, 00:00:C0:7F:A0:E9, IRQ 5.
Oct 21 12:33:22 porky kernel: BUG: atomic counter underflow at:
Oct 21 12:33:22 porky kernel:  [<c0254dd8>] qdisc_destroy+0x98/0xa0 (12)
Oct 21 12:33:22 porky kernel:  [<c0254fed>] dev_shutdown+0x3d/0xa0 (16)
Oct 21 12:33:22 porky kernel:  [<c024773b>] unregister_netdevice+0x13b/0x280 (28)
Oct 21 12:33:22 porky netfs: Mounting other filesystems:  succeeded
Oct 21 12:33:22 porky kernel:  [<c0112fb0>] mcount+0x14/0x18 (12)
Oct 21 12:33:22 porky kernel:  [<e09a6160>] tulip_remove_one+0x0/0xa0 [tulip] (4)
Oct 21 12:33:22 porky kernel:  [<c02058de>] unregister_netdev+0x1e/0x30 (24)
Oct 21 12:33:22 porky kernel:  [<e09a618f>] tulip_remove_one+0x2f/0xa0 [tulip] (16)
Oct 21 12:33:22 porky kernel:  [<c01f2907>] device_release_driver+0x67/0x70 (8)
Oct 21 12:33:22 porky kernel:  [<c0112fb0>] mcount+0x14/0x18 (8)
Oct 21 12:33:22 porky kernel:  [<c01c4e26>] pci_device_remove+0x76/0x80 (20)
Oct 21 12:33:22 porky kernel:  [<c01f573b>] device_detach_shutdown+0xb/0x40 (12)
Oct 21 12:33:22 porky kernel:  [<c01f2907>] device_release_driver+0x67/0x70 (12)
Oct 21 12:33:22 porky kernel:  [<c01f293b>] driver_detach+0x2b/0x40 (24)
Oct 21 12:33:22 porky kernel:  [<c01f2daf>] bus_remove_driver+0x3f/0x70 (20)
Oct 21 12:33:22 porky kernel:  [<c01f32b9>] driver_unregister+0x19/0x30 (20)
Oct 21 12:33:22 porky kernel:  [<c01c50cc>] pci_unregister_driver+0x1c/0x30 (16)
Oct 21 12:33:22 porky kernel:  [<e09a7767>] tulip_cleanup+0x17/0x1b [tulip] (16)
Oct 21 12:33:22 porky kernel:  [<c0139801>] sys_delete_module+0x121/0x150 (12)
Oct 21 12:33:22 porky kernel:  [<c01531a1>] sys_munmap+0x51/0x60 (64)
Oct 21 12:33:22 porky kernel:  [<c0116a20>] do_page_fault+0x0/0x660 (16)
Oct 21 12:33:22 porky kernel:  [<c0106719>] sysenter_past_esp+0x52/0x71 (16)
Oct 21 12:33:22 porky kernel: preempt count: 00000001
Oct 21 12:33:22 porky kernel: . 1-level deep critical section nesting:
Oct 21 12:33:22 porky kernel: .. entry 1: print_traces+0x1d/0x60 / (dump_stack+0x23/0x30)
Oct 21 12:33:22 porky kernel:
Oct 21 12:33:22 porky kernel: tulip 0000:04:0a.0: Device was removed without properly calling pci_disable_device(). This may need fixing.

I am not sure why the tulip driver is being loaded,unloaded,reloaded every time on boot? Anyway, I wanted to check to see if I could generate the above bug on subsequent unloads of the module. I downed the network and the unloaded the tulip module. I did get the message below when unloading the module but no "BUG: atomic counter underflow" message.

Oct 22 05:43:33 porky kernel: tulip 0000:04:0a.0: Device was removed without properly calling pci_disable_device(). This may need fixing.
Oct 22 05:43:33 porky net.agent[921]: remove event not handled

kr

Can you please verify this against vanilla 2.6.9 and 2.6.9-mm1 ?

tglx

I will verify it against 2.6.9 when I get time. I did verify the "Device was removed without properly calling pci_disable_device(). This may need fixing." message is generated with 2.6.9-rc3-mm3 without preempt patches. Also thanks to Mark Johnson's suggestion I verified that the reason the driver is being loaded twice is because kudzu is loading it once then unloading it.

kr

--- 2.6.9-rc4-mm1/drivers/net/tulip/tulip_core.c 2004-10-12
09:41:27.000000000 +0200
+++ 2.6.9-rc4-mm1-U9-E0/drivers/net/tulip/tulip_core.c 2004-10-22
17:54:31.000000000 +0200
@@ -1784,6 +1784,7 @@
#endif
free_netdev (dev);
pci_release_regions (pdev);
+ pci_disable_device (pdev);
pci_set_drvdata (pdev, NULL);

/* pci_power_off (pdev, -1); */

Actually I do have the tulip card in the box and I am pulling this stuff from the logs over that connection now. Here are the next lines from the log that might help.

Sorry brainfart before completing that thought. It is not unusual for the tulip to get loaded, unloaded,loaded again when this system starts up. Not sure why. It has never really caused me any problems so I haven't bothered figuring it out.

kr

i think this is an upstream bug that the atomic-counter debugging assert triggers. Jeff, the assert above shows qdisc->refcnt underflowing from 0 to -1. So the qdisc_destroy() [or dev_shutdown()?] use is inbalanced. Plus rtl8139 is doing this too, see the log below. The upstream kernel does not notice this condition. Or is ->refcnt allowed to underflow?

Ingo

Oct 20 16:47:18 localhost kernel: BUG: atomic counter underflow at:
Oct 20 16:47:18 localhost kernel:  [<c02b8d88>] qdisc_destroy+0x98/0xa0 (12)
Oct 20 16:47:18 localhost kernel:  [<c02b8f9d>] dev_shutdown+0x3d/0xa0 (16)
Oct 20 16:47:18 localhost kernel:  [<c02aa38b>] unregister_netdevice+0x13b/0x280 (28)
Oct 20 16:47:18 localhost kernel:  [<c01148b0>] mcount+0x14/0x18 (8)
Oct 20 16:47:18 localhost kernel:  [<e0836b10>] rtl8139_remove_one+0x0/0xa0 [8139too] (4)
Oct 20 16:47:18 localhost kernel:  [<c0241f8e>] unregister_netdev+0x1e/0x30 (24)
Oct 20 16:47:18 localhost kernel:  [<e0836b3a>] rtl8139_remove_one+0x2a/0xa0 [8139too] (16)
Oct 20 16:47:18 localhost kernel:  [<c01148b0>] mcount+0x14/0x18 (12)
Oct 20 16:47:18 localhost kernel:  [<c01e4016>] pci_device_remove+0x76/0x80 (20)
Oct 20 16:47:18 localhost kernel:  [<c02306cb>] device_detach_shutdown+0xb/0x40 (12)
Oct 20 16:47:18 localhost kernel:  [<c022d817>] device_release_driver+0x67/0x70 (12)
Oct 20 16:47:18 localhost kernel:  [<c022d84b>] driver_detach+0x2b/0x40 (24)
Oct 20 16:47:18 localhost kernel:  [<c022dcbf>] bus_remove_driver+0x3f/0x70 (20)
Oct 20 16:47:18 localhost kernel:  [<c022e1c9>] driver_unregister+0x19/0x30 (20)
Oct 20 16:47:18 localhost kernel:  [<c01e42bc>] pci_unregister_driver+0x1c/0x30 (16)
Oct 20 16:47:18 localhost kernel:  [<e0838b07>] rtl8139_cleanup_module+0x17/0x1b [8139too] (16)
Oct 20 16:47:18 localhost kernel:  [<c013c8d1>] sys_delete_module+0x121/0x150 (12)
Oct 20 16:47:18 localhost kernel:  [<c01596a4>] sys_munmap+0x54/0x70 (64)
Oct 20 16:47:18 localhost kernel:  [<c0118560>] do_page_fault+0x0/0x6d0 (16)
Oct 20 16:47:18 localhost kernel:  [<c0107b49>] sysenter_past_esp+0x52/0x71 (16)

For those using kernel-package, I just submitted a patch to allow for uppercase versions.

http://bugs.debian.org/277680

I have a reproducible BUG which I first hit in -U9 and it's in -U9.2 too. It occurs always when a packet hits a REJECT rule in the INPUT chain of iptables. To reproduce: iptables -I INPUT 1 -p tcp --dport 666 -j REJECT
...and telnet your TCP port 666 from the network.

BUG: semaphore recursion deadlock detected!
.. current task ksoftirqd/0/2 is already holding f890a6d4.
c0414ec4 f7c27f64 0000012c 00000001 f7c26000 00000000 f7c27f9c c0121687
       c03c8118 c0121758 c0121ae4 0000000a c03c8118 f7c26000 f7c26000 
00000000
       f7c27fa4 c0121770 f7c27fbc c0121ae4 00000001 fffffff6 f7c26000 
f7c25f70
Call Trace:
 [<c0121687>] ___do_softirq+0x87/0xd0 (32)
 [<c0121758>] _do_softirq+0x8/0x30 (8)
 [<c0121ae4>] ksoftirqd+0x94/0xe0 (4)
 [<c0121770>] _do_softirq+0x20/0x30 (28)
 [<c0121ae4>] ksoftirqd+0x94/0xe0 (8)
 [<c013116a>] kthread+0xaa/0xb0 (24)
 [<c0121a50>] ksoftirqd+0x0/0xe0 (20)
 [<c01310c0>] kthread+0x0/0xb0 (12)
 [<c0103319>] kernel_thread_helper+0x5/0xc (16)

preempt count: 00000003
. 3-level deep critical section nesting:
.. entry 1: down_write+0x1a4/0x1b0 / (ipt_do_table+0x6a/0x330 [ip_tables]) .. entry 2: down_write+0x72/0x1b0 / (ipt_do_table+0x6a/0x330 [ip_tables]) .. entry 3: print_traces+0x1d/0x90 / (show_stack+0x83/0xa0)

Michal

i have released the -U9.3 Real-Time Preemption patch, which can be downloaded from:

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

this too is a fixes-only release.

Changes since -U9.2:

- tons more driver/mutex/completion conversion done by Thomas Gleixner
for: ppp, ipmi, parport/ieeee1284, scsi, hotplug, and more.

- iptables/netfilter deadlock fix, this should fix the bug reported by Michal Schmidt.

- .config housekeeping: disallow the turning off of PREEMPT_BKL when PREEMPT_REALTIME is on. This solves the build error reported by Matthew L Foster.

- print the full stacktrace of the current task in the deadlock detector and dont use show_stack(). This explains some of the weird partial stackdumps reported.

- some more minor updates to the case when the deadlock detector turns itself off due to reaching the limit. We kept the spinlock locked.

to create a -U9.3 tree from scratch, the patching order is:

http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.8.tar.bz2
+ http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.9-rc4.bz2
+ http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc4/2.6.9-rc4-mm1/2.6.9-rc4-mm1.bz2
+ http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U9.3

Ingo

i have released the -U10 Real-Time Preemption patch, which can be downloaded from:

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

this is purely a rebasing of -U9.3 to 2.6.9-mm1.

to create a -U10 tree from scratch, the patching order is:

http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
+ http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9/2.6.9-mm1/2.6.9-mm1.bz2
+ http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-U10

Ingo

As sort of the ultimate dummy test, I'm building this right now. The only oddments so far are a bunch of deprecated variable warnings, quite a few but many are dups.

I'll repost after I've tried it.

Cheers, Gene
"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)
99.28% setiathome rank, not too shabby for a WV hillbilly
Yahoo.com attorneys please note, additions to this message
by Gene Heskett are:
Copyright 2004 by Maurice Eugene Heskett, all rights reserved.

these warnings are present in -mm1 too.

Ingo

Hey Ingo,

Bite Me.

:-)

Jeff

Hey, Jeff,

This is a very high traffic list. If you have nothing constructive to say, don't say it. Many here are already not happy with your attitude already, you're not helping.

For my part, you're getting a shiny new procmail entry right to dave null. I'm sick of it.

Sorry, everyone else, for adding to the noise. But someone's gotta say it.

--Russell

Russell Miller - [email protected] - Le Mars, IA
Duskglow Consulting - Helping companies just like you to succeed for ~ 10 yrs.
http://www.duskglow.com - 712-546-5886

I'll stick to bugs from now own Russell. Please forward the same to Ingo ....

Jeff

Frankly Jeff, we'd best be afraid of food poisoning if we got that hungry.

Cheers, Gene
"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)
99.28% setiathome rank, not too shabby for a WV hillbilly
Yahoo.com attorneys please note, additions to this message
by Gene Heskett are:
Copyright 2004 by Maurice Eugene Heskett, all rights reserved.

i have released the -U10.2 Real-Time Preemption patch, which can be downloaded from:

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

this is a fixes-only release.

Changes since -U10:

- fixed a big bug present ever since: the BKL got dropped when a spinlock-mutex was acquired and it scheduled away. This reduced the locking efficiency of the BKL. A number of outstanding problems could be affected, in particular this should fix the tty locking breakage reported by Alexander Batyrshin and Adam Heath. UP and SMP systems are affected too, with SMP systems having a higher chance to trigger this condition.

- tulip.c breakage fix from Thomas Gleixner

- tg3 and 3c59x fixes.

- made the hardirq threads SCHED_FIFO by default. They get priorities between 25 and 50, depending on the irq #. (this is pretty random but i found no better scheme.) Made the softirq thread SCHED_FIFO by default as well, albeit this probably will have to change. These changes should make it easier to debug a hung system.

to create a -U10.2 tree from scratch, the patching order is:

http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
+ http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9/2.6.9-mm1/2.6.9-mm1.bz2
+ http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-U10.2

Ingo

Mmm, I get a 404 page not found. when I click on on thsi link.

Cheers, Gene
"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)
99.28% setiathome rank, not too shabby for a WV hillbilly
Yahoo.com attorneys please note, additions to this message
by Gene Heskett are:
Copyright 2004 by Maurice Eugene Heskett, all rights reserved.

Same here. The current version is 10.3:

http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-U10.3

I did not get an announcement, it looks like the listserv is backlogged, or Ingo did not announce it yet.

Lee

OK, U10.3 is the first since T3 for me that boots flawlessly. Latency numbers forthcoming...

Lee

had to do it in the last minute and didnt have time to announce it. -RT-U10.3 fixes a UP compilation error reported by John Gilbert.

Ingo

I'm seeing an odd build error in the -U10.3 patch to 2.6.9-mm1:

<snip>

AS arch/i386/boot/compressed/head.o
CC arch/i386/boot/compressed/misc.o
OBJCOPY arch/i386/boot/compressed/vmlinux.bin
BFD: Warning: Writing section `.bss' to huge (ie negative) file offset 0xc03ac000.
objcopy: arch/i386/boot/compressed/vmlinux.bin: File truncated make[2]: *** [arch/i386/boot/compressed/vmlinux.bin] Error 1
make[1]: *** [arch/i386/boot/compressed/vmlinux] Error 2
make: *** [bzImage] Error 2

[root@otaku linux-2.6.9]# objdump -f vmlinux

vmlinux: file format elf32-i386
architecture: i386, flags 0x00000112:
EXEC_P, HAS_SYMS, D_PAGED
start address 0x00100000

This appears a result of changes in:

arch/i386/kernel/vmlinux.lds.S

apparently for support of CONFIG_KERN_PHYS_OFFSET. This causes the kernel LMA start address to change from 0xc0100000 to 0x100000 and objcopy to gag. I rolled back to a 2.6.9-mm1 version of the above linker map file and did get the kernel to build and boot.

Anyone else seeing this? .config attached.

BTW, the -U10.2 patch seems to have disappeared
from:

http://people.redhat.com/mingo/realtime-preempt/older/

[email protected]

Hi,

Yes.

You probably need to upgrade your binutil package. The .bss LMA start address section is not dealt the way it should by ld.

An other (bad) way to work around this compile problem is to force the .bss LMA start address with the following OBJCOPYFLAGS at objcopy time.

OBJCOPYFLAGS := -O binary --change-section-lma .bss-0xc0000000 -R .note -R .comment -S

Hope this help,
Remi

Already tried a recent (2.15) version of objcopy
with the same results. But LD was the issue.
BTW the offending version of binutils was 2.13.

Thanks!

[email protected]

I got quite a few BUG traces this afternoon running this one on my workstation. I am just attaching the relevant chunk of the log because there are 7 or 8 of them.

kr

Oct 22 14:11:29 swdev14 kernel: NET: Registered protocol family 4
Oct 22 14:13:11 swdev14 ntpd[2865]: synchronized to 151.131.44.70, stratum=4
Oct 22 14:13:11 swdev14 ntpd[2865]: kernel time sync disabled 0041
Oct 22 14:26:00 swdev14 ntpd[2865]: kernel time sync enabled 0001
Oct 22 14:37:14 swdev14 kernel: BUG: sleeping function called from invalid context ksoftirqd/0(3) at kernel/mutex.c:37
Oct 22 14:37:14 swdev14 kernel: in_atomic():1 [00000001], irqs_disabled():0
Oct 22 14:37:14 swdev14 kernel:  [<c011ac3d>] __might_sleep+0xc4/0xd6 (12)
Oct 22 14:37:14 swdev14 kernel:  [<c0132ae8>] _mutex_lock+0x3e/0x63 (36)
Oct 22 14:37:14 swdev14 kernel:  [<e0a8b297>] ipxitf_find_using_phys+0x1e/0x4c [ipx] (28)
Oct 22 14:37:14 swdev14 kernel:  [<e0a8d5a6>] ipx_rcv+0xdc/0x1dd [ipx] (20)
Oct 22 14:37:14 swdev14 kernel:  [<c024050b>] snap_rcv+0x5f/0xe0 (32)
Oct 22 14:37:14 swdev14 kernel:  [<c023fadc>] llc_rcv+0x19b/0x2a3 (24)
Oct 22 14:37:14 swdev14 kernel:  [<c02325df>] netif_receive_skb+0x201/0x30c (32)
Oct 22 14:37:14 swdev14 kernel:  [<c0130400>] remove_from_abslist+0x6/0x64 (20)
Oct 22 14:37:14 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (8)
Oct 22 14:37:14 swdev14 kernel:  [<c0232780>] process_backlog+0x96/0x164 (28)
Oct 22 14:37:14 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (40)
Oct 22 14:37:14 swdev14 kernel:  [<c012299c>] ___do_softirq+0xb8/0x107 (40)
Oct 22 14:37:14 swdev14 kernel:  [<c013317c>] __mcount+0x1d/0x21 (12)
Oct 22 14:37:14 swdev14 kernel:  [<c0122a9b>] _do_softirq+0x20/0x22 (36)
Oct 22 14:37:14 swdev14 kernel:  [<c0122f85>] ksoftirqd+0xcd/0x105 (8)
Oct 22 14:37:14 swdev14 kernel:  [<c0132227>] kthread+0xbc/0xc1 (32)
Oct 22 14:37:14 swdev14 kernel:  [<c0122eb8>] ksoftirqd+0x0/0x105 (20)
Oct 22 14:37:14 swdev14 kernel:  [<c013216b>] kthread+0x0/0xc1 (12)
Oct 22 14:37:14 swdev14 kernel:  [<c01043b1>] kernel_thread_helper+0x5/0xb (16)
Oct 22 14:37:14 swdev14 kernel: preempt count: 00000002
Oct 22 14:37:14 swdev14 kernel: . 2-level deep critical section nesting:
Oct 22 14:37:14 swdev14 kernel: .. entry 1: snap_rcv+0x1b/0xe0 [<c023fadc>] / (llc_rcv+0x19b/0x2a3 [<c023fadc>])
Oct 22 14:37:14 swdev14 kernel: .. entry 2: print_traces+0x1d/0x59 [<c01070c3>] / (dump_stack+0x23/0x27 [<c01070c3>])
Oct 22 14:37:14 swdev14 kernel: 
Oct 22 14:37:16 swdev14 kernel: BUG: sleeping function called from invalid context ksoftirqd/0(3) at kernel/mutex.c:37
Oct 22 14:37:16 swdev14 kernel: in_atomic():1 [00000001], irqs_disabled():0
Oct 22 14:37:16 swdev14 kernel:  [<c011ac3d>] __might_sleep+0xc4/0xd6 (12)
Oct 22 14:37:16 swdev14 kernel:  [<c0132ae8>] _mutex_lock+0x3e/0x63 (36)
Oct 22 14:37:16 swdev14 kernel:  [<e0a8b297>] ipxitf_find_using_phys+0x1e/0x4c [ipx] (28)
Oct 22 14:37:16 swdev14 kernel:  [<e0a8d5a6>] ipx_rcv+0xdc/0x1dd [ipx] (20)
Oct 22 14:37:16 swdev14 kernel:  [<c024050b>] snap_rcv+0x5f/0xe0 (32)
Oct 22 14:37:16 swdev14 kernel:  [<c023fadc>] llc_rcv+0x19b/0x2a3 (24)
Oct 22 14:37:16 swdev14 kernel:  [<c02325df>] netif_receive_skb+0x201/0x30c (32)
Oct 22 14:37:16 swdev14 kernel:  [<c0130400>] remove_from_abslist+0x6/0x64 (20)
Oct 22 14:37:16 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (8)
Oct 22 14:37:16 swdev14 kernel:  [<c0232780>] process_backlog+0x96/0x164 (28)
Oct 22 14:37:16 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (40)
Oct 22 14:37:16 swdev14 kernel:  [<c012299c>] ___do_softirq+0xb8/0x107 (40)
Oct 22 14:37:16 swdev14 kernel:  [<c013317c>] __mcount+0x1d/0x21 (12)
Oct 22 14:37:16 swdev14 kernel:  [<c0122a9b>] _do_softirq+0x20/0x22 (36)
Oct 22 14:37:16 swdev14 kernel:  [<c0122f85>] ksoftirqd+0xcd/0x105 (8)
Oct 22 14:37:16 swdev14 kernel:  [<c0132227>] kthread+0xbc/0xc1 (32)
Oct 22 14:37:16 swdev14 kernel:  [<c0122eb8>] ksoftirqd+0x0/0x105 (20)
Oct 22 14:37:16 swdev14 kernel:  [<c013216b>] kthread+0x0/0xc1 (12)
Oct 22 14:37:16 swdev14 kernel:  [<c01043b1>] kernel_thread_helper+0x5/0xb (16)
Oct 22 14:37:16 swdev14 kernel: preempt count: 00000002
Oct 22 14:37:16 swdev14 kernel: . 2-level deep critical section nesting:
Oct 22 14:37:16 swdev14 kernel: .. entry 1: snap_rcv+0x1b/0xe0 [<c023fadc>] / (llc_rcv+0x19b/0x2a3 [<c023fadc>])
Oct 22 14:37:16 swdev14 kernel: .. entry 2: print_traces+0x1d/0x59 [<c01070c3>] / (dump_stack+0x23/0x27 [<c01070c3>])
Oct 22 14:37:16 swdev14 kernel: 
Oct 22 14:37:17 swdev14 kernel: BUG: sleeping function called from invalid context ksoftirqd/0(3) at kernel/mutex.c:37
Oct 22 14:37:17 swdev14 kernel: in_atomic():1 [00000001], irqs_disabled():0
Oct 22 14:37:17 swdev14 kernel:  [<c011ac3d>] __might_sleep+0xc4/0xd6 (12)
Oct 22 14:37:17 swdev14 kernel:  [<c0132ae8>] _mutex_lock+0x3e/0x63 (36)
Oct 22 14:37:17 swdev14 kernel:  [<e0a8b297>] ipxitf_find_using_phys+0x1e/0x4c [ipx] (28)
Oct 22 14:37:17 swdev14 kernel:  [<e0a8d5a6>] ipx_rcv+0xdc/0x1dd [ipx] (20)
Oct 22 14:37:17 swdev14 kernel:  [<c024050b>] snap_rcv+0x5f/0xe0 (32)
Oct 22 14:37:17 swdev14 kernel:  [<c023fadc>] llc_rcv+0x19b/0x2a3 (24)
Oct 22 14:37:17 swdev14 kernel:  [<c02325df>] netif_receive_skb+0x201/0x30c (32)
Oct 22 14:37:17 swdev14 kernel:  [<c0130400>] remove_from_abslist+0x6/0x64 (20)
Oct 22 14:37:17 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (8)
Oct 22 14:37:17 swdev14 kernel:  [<c0232780>] process_backlog+0x96/0x164 (28)
Oct 22 14:37:17 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (40)
Oct 22 14:37:17 swdev14 kernel:  [<c012299c>] ___do_softirq+0xb8/0x107 (40)
Oct 22 14:37:17 swdev14 kernel:  [<c013317c>] __mcount+0x1d/0x21 (12)
Oct 22 14:37:17 swdev14 kernel:  [<c0122a9b>] _do_softirq+0x20/0x22 (36)
Oct 22 14:37:17 swdev14 kernel:  [<c0122f85>] ksoftirqd+0xcd/0x105 (8)
Oct 22 14:37:17 swdev14 kernel:  [<c0132227>] kthread+0xbc/0xc1 (32)
Oct 22 14:37:17 swdev14 kernel:  [<c0122eb8>] ksoftirqd+0x0/0x105 (20)
Oct 22 14:37:17 swdev14 kernel:  [<c013216b>] kthread+0x0/0xc1 (12)
Oct 22 14:37:17 swdev14 kernel:  [<c01043b1>] kernel_thread_helper+0x5/0xb (16)
Oct 22 14:37:17 swdev14 kernel: preempt count: 00000002
Oct 22 14:37:17 swdev14 kernel: . 2-level deep critical section nesting:
Oct 22 14:37:17 swdev14 kernel: .. entry 1: snap_rcv+0x1b/0xe0 [<c023fadc>] / (llc_rcv+0x19b/0x2a3 [<c023fadc>])
Oct 22 14:37:17 swdev14 kernel: .. entry 2: print_traces+0x1d/0x59 [<c01070c3>] / (dump_stack+0x23/0x27 [<c01070c3>])
Oct 22 14:37:17 swdev14 kernel: 
Oct 22 14:37:17 swdev14 kernel: BUG: scheduling while atomic: ksoftirqd/0/0x10000001/3
Oct 22 14:37:17 swdev14 kernel: caller is cond_resched+0x64/0x78
Oct 22 14:37:17 swdev14 kernel:  [<c029dd88>] __sched_text_start+0xbdc/0xc2c (12)
Oct 22 14:37:17 swdev14 kernel:  [<c029e6da>] cond_resched+0x64/0x78 (8)
Oct 22 14:37:17 swdev14 kernel:  [<c01338ce>] check_preempt_timing+0x5d/0x289 (12)
Oct 22 14:37:17 swdev14 kernel:  [<c0133b40>] touch_preempt_timing+0x46/0x4a (4)
Oct 22 14:37:17 swdev14 kernel:  [<c029e69c>] cond_resched+0x26/0x78 (4)
Oct 22 14:37:17 swdev14 kernel:  [<c029deab>] preempt_schedule+0x11/0x6f (4)
Oct 22 14:37:17 swdev14 kernel:  [<c01070c3>] dump_stack+0x23/0x27 (4)
Oct 22 14:37:17 swdev14 kernel:  [<c0112038>] mcount+0x14/0x18 (8)
Oct 22 14:37:17 swdev14 kernel:  [<c0132aed>] _mutex_lock+0x43/0x63 (60)
Oct 22 14:37:17 swdev14 kernel:  [<c029e6da>] cond_resched+0x64/0x78 (20)
Oct 22 14:37:17 swdev14 kernel:  [<c0132aed>] _mutex_lock+0x43/0x63 (16)
Oct 22 14:37:17 swdev14 kernel:  [<e0a8b297>] ipxitf_find_using_phys+0x1e/0x4c [ipx] (28)
Oct 22 14:37:17 swdev14 kernel:  [<e0a8d5a6>] ipx_rcv+0xdc/0x1dd [ipx] (20)
Oct 22 14:37:17 swdev14 kernel:  [<c024050b>] snap_rcv+0x5f/0xe0 (32)
Oct 22 14:37:17 swdev14 kernel:  [<c023fadc>] llc_rcv+0x19b/0x2a3 (24)
Oct 22 14:37:17 swdev14 kernel:  [<c02325df>] netif_receive_skb+0x201/0x30c (32)
Oct 22 14:37:17 swdev14 kernel:  [<c0130400>] remove_from_abslist+0x6/0x64 (20)
Oct 22 14:37:17 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (8)
Oct 22 14:37:17 swdev14 kernel:  [<c0232780>] process_backlog+0x96/0x164 (28)
Oct 22 14:37:17 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (40)
Oct 22 14:37:17 swdev14 kernel:  [<c012299c>] ___do_softirq+0xb8/0x107 (40)
Oct 22 14:37:17 swdev14 kernel:  [<c013317c>] __mcount+0x1d/0x21 (12)
Oct 22 14:37:18 swdev14 kernel:  [<c0122a9b>] _do_softirq+0x20/0x22 (36)
Oct 22 14:37:18 swdev14 kernel:  [<c0122f85>] ksoftirqd+0xcd/0x105 (8)
Oct 22 14:37:18 swdev14 kernel:  [<c0132227>] kthread+0xbc/0xc1 (32)
Oct 22 14:37:18 swdev14 kernel:  [<c0122eb8>] ksoftirqd+0x0/0x105 (20)
Oct 22 14:37:18 swdev14 kernel:  [<c013216b>] kthread+0x0/0xc1 (12)
Oct 22 14:37:18 swdev14 kernel:  [<c01043b1>] kernel_thread_helper+0x5/0xb (16)
Oct 22 14:37:18 swdev14 kernel: preempt count: 10000002
Oct 22 14:37:18 swdev14 kernel: . 2-level deep critical section nesting:
Oct 22 14:37:18 swdev14 kernel: .. entry 1: snap_rcv+0x1b/0xe0 [<c023fadc>] / (llc_rcv+0x19b/0x2a3 [<c023fadc>])
Oct 22 14:37:18 swdev14 kernel: .. entry 2: print_traces+0x1d/0x59 [<c01070c3>] / (dump_stack+0x23/0x27 [<c01070c3>])
Oct 22 14:37:18 swdev14 kernel: 
Oct 22 15:22:47 swdev14 modprobe: FATAL: Error running install command for sound_slot_0 
Oct 22 15:22:47 swdev14 modprobe: FATAL: Error running install command for sound_slot_1 
Oct 22 15:22:47 swdev14 modprobe: FATAL: Error running install command for sound_slot_0 
Oct 22 15:22:47 swdev14 modprobe: FATAL: Error running install command for sound_slot_1 
Oct 22 15:22:47 swdev14 modprobe: FATAL: Error running install command for sound_slot_0 
Oct 22 15:22:47 swdev14 modprobe: FATAL: Error running install command for sound_slot_1 
Oct 22 15:22:47 swdev14 modprobe: FATAL: Error running install command for sound_slot_0 
Oct 22 15:22:47 swdev14 last message repeated 2 times
Oct 22 15:25:07 swdev14 su(pam_unix)[15830]: session opened for user root by aaektkf(uid=19990)
Oct 22 15:30:34 swdev14 kernel: BUG: sleeping function called from invalid context ksoftirqd/0(3) at kernel/mutex.c:37
Oct 22 15:30:34 swdev14 kernel: in_atomic():1 [00000001], irqs_disabled():0
Oct 22 15:30:34 swdev14 kernel:  [<c011ac3d>] __might_sleep+0xc4/0xd6 (12)
Oct 22 15:30:34 swdev14 kernel:  [<c0132ae8>] _mutex_lock+0x3e/0x63 (36)
Oct 22 15:30:34 swdev14 kernel:  [<e0a8b297>] ipxitf_find_using_phys+0x1e/0x4c [ipx] (28)
Oct 22 15:30:34 swdev14 kernel:  [<e0a8d5a6>] ipx_rcv+0xdc/0x1dd [ipx] (20)
Oct 22 15:30:34 swdev14 kernel:  [<c024050b>] snap_rcv+0x5f/0xe0 (32)
Oct 22 15:30:34 swdev14 kernel:  [<c023fadc>] llc_rcv+0x19b/0x2a3 (24)
Oct 22 15:30:34 swdev14 kernel:  [<c02325df>] netif_receive_skb+0x201/0x30c (32)
Oct 22 15:30:34 swdev14 kernel:  [<c0130400>] remove_from_abslist+0x6/0x64 (20)
Oct 22 15:30:34 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (8)
Oct 22 15:30:34 swdev14 kernel:  [<c0232780>] process_backlog+0x96/0x164 (28)
Oct 22 15:30:34 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (40)
Oct 22 15:30:34 swdev14 kernel:  [<c012299c>] ___do_softirq+0xb8/0x107 (40)
Oct 22 15:30:34 swdev14 kernel:  [<c013317c>] __mcount+0x1d/0x21 (12)
Oct 22 15:30:34 swdev14 kernel:  [<c0122a9b>] _do_softirq+0x20/0x22 (36)
Oct 22 15:30:34 swdev14 kernel:  [<c0122f85>] ksoftirqd+0xcd/0x105 (8)
Oct 22 15:30:34 swdev14 kernel:  [<c0132227>] kthread+0xbc/0xc1 (32)
Oct 22 15:30:34 swdev14 kernel:  [<c0122eb8>] ksoftirqd+0x0/0x105 (20)
Oct 22 15:30:34 swdev14 kernel:  [<c013216b>] kthread+0x0/0xc1 (12)
Oct 22 15:30:34 swdev14 kernel:  [<c01043b1>] kernel_thread_helper+0x5/0xb (16)
Oct 22 15:30:34 swdev14 kernel: preempt count: 00000002
Oct 22 15:30:34 swdev14 kernel: . 2-level deep critical section nesting:
Oct 22 15:30:34 swdev14 kernel: .. entry 1: snap_rcv+0x1b/0xe0 [<c023fadc>] / (llc_rcv+0x19b/0x2a3 [<c023fadc>])
Oct 22 15:30:34 swdev14 kernel: .. entry 2: print_traces+0x1d/0x59 [<c01070c3>] / (dump_stack+0x23/0x27 [<c01070c3>])
Oct 22 15:30:34 swdev14 kernel: 
Oct 22 15:30:35 swdev14 kernel: BUG: sleeping function called from invalid context ksoftirqd/0(3) at kernel/mutex.c:37
Oct 22 15:30:35 swdev14 kernel: in_atomic():1 [00000001], irqs_disabled():0
Oct 22 15:30:35 swdev14 kernel:  [<c011ac3d>] __might_sleep+0xc4/0xd6 (12)
Oct 22 15:30:35 swdev14 kernel:  [<c0132ae8>] _mutex_lock+0x3e/0x63 (36)
Oct 22 15:30:35 swdev14 kernel:  [<e0a8b297>] ipxitf_find_using_phys+0x1e/0x4c [ipx] (28)
Oct 22 15:30:35 swdev14 kernel:  [<e0a8d5a6>] ipx_rcv+0xdc/0x1dd [ipx] (20)
Oct 22 15:30:35 swdev14 kernel:  [<c024050b>] snap_rcv+0x5f/0xe0 (32)
Oct 22 15:30:35 swdev14 kernel:  [<c023fadc>] llc_rcv+0x19b/0x2a3 (24)
Oct 22 15:30:35 swdev14 kernel:  [<c02325df>] netif_receive_skb+0x201/0x30c (32)
Oct 22 15:30:35 swdev14 kernel:  [<c0130400>] remove_from_abslist+0x6/0x64 (20)
Oct 22 15:30:35 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (8)
Oct 22 15:30:35 swdev14 kernel:  [<c0232780>] process_backlog+0x96/0x164 (28)
Oct 22 15:30:35 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (40)
Oct 22 15:30:35 swdev14 kernel:  [<c012299c>] ___do_softirq+0xb8/0x107 (40)
Oct 22 15:30:35 swdev14 kernel:  [<c013317c>] __mcount+0x1d/0x21 (12)
Oct 22 15:30:35 swdev14 kernel:  [<c0122a9b>] _do_softirq+0x20/0x22 (36)
Oct 22 15:30:35 swdev14 kernel:  [<c0122f85>] ksoftirqd+0xcd/0x105 (8)
Oct 22 15:30:35 swdev14 kernel:  [<c0132227>] kthread+0xbc/0xc1 (32)
Oct 22 15:30:35 swdev14 kernel:  [<c0122eb8>] ksoftirqd+0x0/0x105 (20)
Oct 22 15:30:35 swdev14 kernel:  [<c013216b>] kthread+0x0/0xc1 (12)
Oct 22 15:30:35 swdev14 kernel:  [<c01043b1>] kernel_thread_helper+0x5/0xb (16)
Oct 22 15:30:35 swdev14 kernel: preempt count: 00000002
Oct 22 15:30:35 swdev14 kernel: . 2-level deep critical section nesting:
Oct 22 15:30:35 swdev14 kernel: .. entry 1: snap_rcv+0x1b/0xe0 [<c023fadc>] / (llc_rcv+0x19b/0x2a3 [<c023fadc>])
Oct 22 15:30:35 swdev14 kernel: .. entry 2: print_traces+0x1d/0x59 [<c01070c3>] / (dump_stack+0x23/0x27 [<c01070c3>])
Oct 22 15:30:35 swdev14 kernel: 
Oct 22 15:30:37 swdev14 kernel: BUG: sleeping function called from invalid context ksoftirqd/0(3) at kernel/mutex.c:37
Oct 22 15:30:37 swdev14 kernel: in_atomic():1 [00000001], irqs_disabled():0
Oct 22 15:30:37 swdev14 kernel:  [<c011ac3d>] __might_sleep+0xc4/0xd6 (12)
Oct 22 15:30:37 swdev14 kernel:  [<c0132ae8>] _mutex_lock+0x3e/0x63 (36)
Oct 22 15:30:37 swdev14 kernel:  [<e0a8b297>] ipxitf_find_using_phys+0x1e/0x4c [ipx] (28)
Oct 22 15:30:37 swdev14 kernel:  [<e0a8d5a6>] ipx_rcv+0xdc/0x1dd [ipx] (20)
Oct 22 15:30:37 swdev14 kernel:  [<c024050b>] snap_rcv+0x5f/0xe0 (32)
Oct 22 15:30:37 swdev14 kernel:  [<c023fadc>] llc_rcv+0x19b/0x2a3 (24)
Oct 22 15:30:37 swdev14 kernel:  [<c02325df>] netif_receive_skb+0x201/0x30c (32)
Oct 22 15:30:37 swdev14 kernel:  [<c0130400>] remove_from_abslist+0x6/0x64 (20)
Oct 22 15:30:37 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (8)
Oct 22 15:30:37 swdev14 kernel:  [<c0232780>] process_backlog+0x96/0x164 (28)
Oct 22 15:30:37 swdev14 kernel:  [<c02328ef>] net_rx_action+0xa1/0x178 (40)
Oct 22 15:30:37 swdev14 kernel:  [<c012299c>] ___do_softirq+0xb8/0x107 (40)
Oct 22 15:30:37 swdev14 kernel:  [<c013317c>] __mcount+0x1d/0x21 (12)
Oct 22 15:30:37 swdev14 kernel:  [<c0122a9b>] _do_softirq+0x20/0x22 (36)
Oct 22 15:30:37 swdev14 kernel:  [<c0122f85>] ksoftirqd+0xcd/0x105 (8)
Oct 22 15:30:37 swdev14 kernel:  [<c0132227>] kthread+0xbc/0xc1 (32)
Oct 22 15:30:37 swdev14 kernel:  [<c0122eb8>] ksoftirqd+0x0/0x105 (20)
Oct 22 15:30:37 swdev14 kernel:  [<c013216b>] kthread+0x0/0xc1 (12)
Oct 22 15:30:37 swdev14 kernel:  [<c01043b1>] kernel_thread_helper+0x5/0xb (16)
Oct 22 15:30:37 swdev14 kernel: preempt count: 00000002
Oct 22 15:30:37 swdev14 kernel: . 2-level deep critical section nesting:
Oct 22 15:30:37 swdev14 kernel: .. entry 1: snap_rcv+0x1b/0xe0 [<c023fadc>] / (llc_rcv+0x19b/0x2a3 [<c023fadc>])
Oct 22 15:30:37 swdev14 kernel: .. entry 2: print_traces+0x1d/0x59 [<c01070c3>] / (dump_stack+0x23/0x27 [<c01070c3>])
Oct 22 15:30:37 swdev14 kernel: 

does the patch below fix these?

Ingo

@@ -55,7 +55,7 @@ static int snap_rcv(struct sk_buff *skb,
 		.type = __constant_htons(ETH_P_SNAP),
 	};
 
-	rcu_read_lock();
+	rcu_read_lock_spin(&snap_lock);
 	proto = find_snap_client(skb->h.raw);
 	if (proto) {
 		/* Pass the frame on. */

@@ -68,7 +68,7 @@ static int snap_rcv(struct sk_buff *skb,
 		rc = 1;
 	}
 
-	rcu_read_unlock();
+	rcu_read_unlock_spin(&snap_lock);
 	return rc;
 }
 

I will try reproducing it here (at home). Otherwise it'll have to wait till Monday.

Regarding the jackd -R issue, I was trying to capture some debug data via netconsole on my laptop (P4/UP) running RT-U10.2, and when the system freezes as reported before, I was able to kick the SysRq+T. But, instead of a task trace list, I get the following:

SysRq : <3>BUG: sleeping function called from invalid context IRQ 1(776) at kernel/mutex.c:37
in_atomic():1 [00000001], irqs_disabled():1

 [<c0104ee4>] dump_stack+0x1e/0x20 (20)
 [<c0114a23>] __might_sleep+0xb2/0xc7 (36)
 [<c012c0f2>] _mutex_lock+0x39/0x5e (28)
 [<c012c13a>] _mutex_lock_irqsave+0x11/0x15 (12)
 [<c027f927>] refill_skbs+0x13/0x6d (20)
 [<c027fa4c>] find_skb+0x5d/0x9d (24)
 [<c027fb74>] netpoll_send_udp+0x3b/0x298 (48)
 [<e00ef047>] write_msg+0x47/0x5c [netconsole] (36)
 [<c0117804>] __call_console_drivers+0x51/0x60 (32)
 [<c0117910>] call_console_drivers+0x6d/0x147 (40)
 [<c0117caf>] release_console_sem+0x48/0x100 (36)
 [<c0117bd5>] vprintk+0x127/0x174 (36)
 [<c0117aac>] printk+0x18/0x1a (16)
 [<c01f4849>] __handle_sysrq+0x38/0xed (40)
 [<c01ee426>] kbd_event+0xeb/0xfa (40)
 [<c025f6a8>] input_event+0x160/0x3d4 (44)
 [<c02620b6>] atkbd_report_key+0x3b/0x95 (32)
 [<c026236c>] atkbd_interrupt+0x25c/0x590 (60)
 [<c01f6fd2>] serio_interrupt+0x4f/0xa5 (44)
 [<c01f78cb>] i8042_interrupt+0xb8/0x1b8 (40)
 [<c0131dbc>] handle_IRQ_event+0x48/0x79 (32)
 [<c01325dd>] do_hardirq+0x86/0x123 (40)
 [<c0132712>] do_irqd+0x98/0xc9 (36)
 [<c012b7d7>] kthread+0x9c/0xc9 (48)
 [<c0102305>] kernel_thread_helper+0x5/0xb (548454420)

preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __sysrq_lock_table+0x12/0x14 [<c01f482b>] / (__handle_sysrq+0x1a/0xed [<c01f482b>])
.. entry 2: print_traces+0x16/0x48 [<c0104ee4>] / (dump_stack+0x1e/0x20 [<c0104ee4>])

Other SysRq key combinations dumps similar.

Any suggestions?

rncbc aka Rui Nuno Capela
[email protected]

Just starting to test U10.3. So far no freezes but I do see problems with Jack kicking out Hydrogen from the graph and some xruns.

I see this on boot (athlon64 system):

ACPI: PCI interrupt 0000:00:0e.0[A] -> GSI 19 (level, low) -> IRQ 19
ohci1394: fw-host0: OHCI-1394 1.0 (PCI): IRQ=[19] MMIO=[cfffe000-cfffe7ff] Max Packet=[2048]
ohci1394 0000:00:0e.0: Device was removed without properly calling pci_disable_device(). This may need fixing.
r8169 Gigabit Ethernet driver 1.6LK loaded
ACPI: PCI interrupt 0000:00:0b.0[A] -> GSI 16 (level, low) -> IRQ 16
divert: allocating divert_blk for eth0
eth0: Identified chip type is 'RTL8169s/8110s'.
eth0: RTL8169 at 0xf88c8f00, 00:0c:76:b3:c2:43, IRQ 16

BUG: atomic counter underflow at:
 [<c02b99a1>] qdisc_destroy+0x91/0xa0 (8)
 [<c02b9b6f>] dev_shutdown+0x2f/0x90 (12)
 [<c030dfc7>] cond_resched+0x17/0x70 (8)
 [<c02acea5>] unregister_netdevice+0x125/0x250 (16)
 [<c030e6b2>] down_write+0xa2/0x1e0 (12)
 [<c01cd87a>] __up_write+0x11a/0x200 (4)
 [<c02476cf>] unregister_netdev+0xf/0x20 (16)
 [<f8b0163d>] rtl8169_remove_one+0x1d/0x50 [r8169] (8)
 [<c01d6c08>] pci_device_remove+0x68/0x70 (16)
 [<c0235cb6>] device_release_driver+0x56/0x60 (20)
 [<c0235cd8>] driver_detach+0x18/0x30 (12)
 [<c02360d9>] bus_remove_driver+0x29/0x50 (12)
 [<c02364eb>] driver_unregister+0xb/0x20 (8)
 [<c01d6e3b>] pci_unregister_driver+0xb/0x20 (8)
 [<c0137795>] sys_delete_module+0x105/0x130 (8)
 [<c0106019>] sysenter_past_esp+0x52/0x71 (80)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0xd/0x40 [<00000000>] / (0x0 [<00000000>])

divert: freeing divert_blk for eth0
ip_tables: (C) 2000-2002 Netfilter core team
ip_conntrack version 2.1 (8192 buckets, 65536 max) - 300 bytes per conntrack
r8169 Gigabit Ethernet driver 1.6LK loaded
ACPI: PCI interrupt 0000:00:0b.0[A] -> GSI 16 (level, low) -> IRQ 16
divert: allocating divert_blk for eth0
eth0: Identified chip type is 'RTL8169s/8110s'.
eth0: RTL8169 at 0xf8af4f00, 00:0c:76:b3:c2:43, IRQ 16 IRQ#16 thread RT prio: 49.
r8169: eth0: link up

-- Fernando

does the patch below help?

Ingo

@@ -252,7 +252,7 @@ static struct sysrq_key_op sysrq_kill_op
 
 
 /* Key Operations table and lock */
-static DECLARE_RAW_SPINLOCK(sysrq_key_table_lock);
+static DECLARE_SPINLOCK(sysrq_key_table_lock);
 #define SYSRQ_KEY_TABLE_LENGTH 36
 static struct sysrq_key_op *sysrq_key_table[SYSRQ_KEY_TABLE_LENGTH] = {
 /* 0 */	&sysrq_loglevel_op,

interrupts are disabled. You used a -RT-U10.2/3 kernel, and have CONFIG_REALTIME enabled, right? Do you have this in drivers/net/netconsole.c, line 77:

 #ifdef PREEMPT_REALTIME
         /*
          * A bit hairy. Netconsole uses mutexes (indirectly) and
          * thus must have interrupts enabled:
          */
         local_irq_enable();

#endif

correct? Could you do this a few lines below:

                WARN_ON_RT(irqs_disabled());
                netpoll_send_udp(&np, msg, frag);
                WARN_ON_RT(irqs_disabled());

to figure out who disables interrupts. Also, could you add the same two lines to net/core/netpoll.c, line 83:

        WARN_ON_RT(irqs_disabled());
        np->dev->poll_controller(np->dev);
        WARN_ON_RT(irqs_disabled());

and send me either the full bootlog, or the _first_ such BUG message you'll be getting. Which network controller is this?

Ingo

OK. All affirmative. NIC is natsemi.

Here it is:

SysRq : IRQ 1/776: BUG in write_msg at drivers/net/netconsole.c:87

 [<c0104ee4>] dump_stack+0x1e/0x20 (20)
 [<e00ef0ab>] write_msg+0xab/0xf4 [netconsole] (52)
 [<c0117804>] __call_console_drivers+0x51/0x60 (32)
 [<c0117910>] call_console_drivers+0x6d/0x147 (40)
 [<c0117caf>] release_console_sem+0x48/0x100 (36)
 [<c0117bd5>] vprintk+0x127/0x174 (36)
 [<c0117aac>] printk+0x18/0x1a (16)
 [<c01f4835>] __handle_sysrq+0x38/0xed (40)
 [<c01ee426>] kbd_event+0xeb/0xfa (40)
 [<c025f694>] input_event+0x160/0x3d4 (44)
 [<c02620a2>] atkbd_report_key+0x3b/0x95 (32)
 [<c0262358>] atkbd_interrupt+0x25c/0x590 (60)
 [<c01f6fbe>] serio_interrupt+0x4f/0xa5 (44)
 [<c01f78b7>] i8042_interrupt+0xb8/0x1b8 (40)
 [<c0131dbc>] handle_IRQ_event+0x48/0x79 (32)
 [<c01325dd>] do_hardirq+0x86/0x123 (40)
 [<c0132712>] do_irqd+0x98/0xc9 (36)
 [<c012b7d7>] kthread+0x9c/0xc9 (48)
 [<c0102305>] kernel_thread_helper+0x5/0xb (548454420)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x16/0x48 [<c0104ee4>] / (dump_stack+0x1e/0x20 [<c0104ee4>])

BUG: sleeping function called from invalid context IRQ 1(776) at
kernel/mutex.c:37
in_atomic():0 [00000000], irqs_disabled():1
 [<c0104ee4>] dump_stack+0x1e/0x20 (20)
 [<c0114a23>] __might_sleep+0xb2/0xc7 (36)
 [<c012c0f2>] _mutex_lock+0x39/0x5e (28)
 [<c012c13a>] _mutex_lock_irqsave+0x11/0x15 (12)
 [<c027f9bc>] refill_skbs+0x13/0x6d (20)
 [<c027fae1>] find_skb+0x5d/0x9d (24)
 [<c027fc09>] netpoll_send_udp+0x3b/0x298 (48)
 [<e00ef050>] write_msg+0x50/0xf4 [netconsole] (52)
 [<c0117804>] __call_console_drivers+0x51/0x60 (32)
 [<c0117910>] call_console_drivers+0x6d/0x147 (40)
 [<c0117caf>] release_console_sem+0x48/0x100 (36)
 [<c0117bd5>] vprintk+0x127/0x174 (36)
 [<c0117aac>] printk+0x18/0x1a (16)
 [<c01f4835>] __handle_sysrq+0x38/0xed (40)
 [<c01ee426>] kbd_event+0xeb/0xfa (40)
 [<c025f694>] input_event+0x160/0x3d4 (44)
 [<c02620a2>] atkbd_report_key+0x3b/0x95 (32)
 [<c0262358>] atkbd_interrupt+0x25c/0x590 (60)
 [<c01f6fbe>] serio_interrupt+0x4f/0xa5 (44)
 [<c01f78b7>] i8042_interrupt+0xb8/0x1b8 (40)
 [<c0131dbc>] handle_IRQ_event+0x48/0x79 (32)
 [<c01325dd>] do_hardirq+0x86/0x123 (40)
 [<c0132712>] do_irqd+0x98/0xc9 (36)
 [<c012b7d7>] kthread+0x9c/0xc9 (48)
 [<c0102305>] kernel_thread_helper+0x5/0xb (548454420)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x16/0x48 [<c0104ee4>] / (dump_stack+0x1e/0x20 [<c0104ee4>])

Bye.

rncbc aka Rui Nuno Capela
[email protected]

doh! Go to line 77 and spot the bug. (yes, the PREEMPT_REALTIME needs to become CONFIG_PREEMPT_REALTIME) With that fixed does it work for you?

Ingo

OK again. And found another place where PREEMPT_REALTIME is in place of CONFIG_PREEMPT_REALTIME, on drivers/ide/ide-taskfile.c, lines 287 and 308 (see appended diffs).

Anyway, back to my jackd -R issue. I tell you that things are really different now: hitting SysRq+T, just about when it all gets frozen, I see nothing on netconsole capture end, only this single line:

SysRq : Show State

and nothing more.

rncbc aka Rui Nuno Capela
[email protected]

@@ -74,7 +74,7 @@
 		return;
 
 	local_irq_save(flags);
-#ifdef PREEMPT_REALTIME
+#ifdef CONFIG_PREEMPT_REALTIME
 	/*
 	 * A bit hairy. Netconsole uses mutexes (indirectly) and
 	 * thus must have interrupts enabled:

@@ -284,7 +284,7 @@
 	u8 *buf;
 
 	page = sg[hwif->cursg].page;
-#if defined(CONFIG_HIGHMEM) && !defined(PREEMPT_REALTIME)
+#if defined(CONFIG_HIGHMEM) && !defined(CONFIG_PREEMPT_REALTIME)
 	local_irq_save(flags);
 #endif
 	buf = kmap_atomic(page, KM_BIO_SRC_IRQ) +

@@ -305,7 +305,7 @@
 		taskfile_input_data(drive, buf, SECTOR_WORDS);
 
 	kunmap_atomic(page, KM_BIO_SRC_IRQ);
-#if defined(CONFIG_HIGHMEM) && !defined(PREEMPT_REALTIME)
+#if defined(CONFIG_HIGHMEM) && !defined(CONFIG_PREEMPT_REALTIME)
 	local_irq_restore(flags);
 #endif
 }

The current version is -U10.3

Find below a patch against -U10.3. It contains a couple of smaller fixes including the network driver bootup BUG.

<Dislaimer>
I'm trying to start a serious discussion on that. It's not my intention to start a flamewar.
</Disclaimer>

The network driver load/unload problem, which was reported from a couple of testers, is related to Ingo's check inside of atomic_dec_and_test().

        if (!atomic_read(v)) {
                printk("BUG: atomic counter underflow at:\n");
                dump_stack();
        }

The unmodified atomic_dec_and_test() returns 0 in all cases except for the case when the counter is 0 after the decrement. This implementation covers automatically the case, where atomic_dec_and_test() is called with counter == 0.

The network code uses atomic_dec_and_test() in qdisk_destroy to check, if the caller owns the last reference to the qdisc. This covers also the case when no reference is there when this is called. I fixed this for now with a check for 0 before calling qdisk_destroy().

Thats a fix, but not an answer to the following question.

The question is whether the atomic implementation is intended to allow counter values less than 0 or not. Reviewing the usage it seems not to be the case. The qdisc_destroy code is the only place I recognized so far, which makes use of that implementation detail.

Assume count = 0, call atomic_dec_test() and you have count = -1. At a differemt places the check is if (!atomic_read(v)){...} If count = -1 it signals, that data or whatever is available.

I don't think there is code which is actually failing on that, but as a design rule it might turn out that Ingo's check and the implied rule "count must be >= 0" is appropriate.

tglx
---

diff --exclude='*~' -urN 2.6.9-mm1-U10.3/drivers/net/8139too.c 2.6.9-mm1-U10.work/drivers/net/8139too.c
--- 2.6.9-mm1-U10.3/drivers/net/8139too.c 2004-10-23 01:59:14.000000000
+0200
+++ 2.6.9-mm1-U10.work/drivers/net/8139too.c 2004-10-22
23:18:32.000000000 +0200
@@ -749,7 +749,7 @@
pci_release_regions (pdev);

free_netdev(dev);
-
+ pci_disable_device (pdev);
pci_set_drvdata (pdev, NULL);
}

diff --exclude='*~' -urN 2.6.9-mm1-U10.3/drivers/pci/hotplug/cpci_hotplug_core.c 2.6.9-mm1-U10.work/drivers/pci/hotplug/cpci_hotplug_core.c
--- 2.6.9-mm1-U10.3/drivers/pci/hotplug/cpci_hotplug_core.c 2004-10-23
01:59:15.000000000 +0200
+++ 2.6.9-mm1-U10.work/drivers/pci/hotplug/cpci_hotplug_core.c

2004-10-22 19:06:47.000000000 +0200

@@ -598,7 +598,7 @@
msleep(100);
}
dbg("poll thread signals exit");
- up(&thread_exit);
+ complete(&thread_exit);
return 0;
}

diff --exclude='*~' -urN 2.6.9-mm1-U10.3/net/sched/sch_generic.c 2.6.9-mm1-U10.work/net/sched/sch_generic.c
--- 2.6.9-mm1-U10.3/net/sched/sch_generic.c 2004-10-23
01:59:12.000000000 +0200
+++ 2.6.9-mm1-U10.work/net/sched/sch_generic.c 2004-10-23
02:45:58.000000000 +0200
@@ -584,7 +584,9 @@
qdisc = dev->qdisc_sleeping;
dev->qdisc = &noop_qdisc;
dev->qdisc_sleeping = &noop_qdisc;
- qdisc_destroy(qdisc);
+
+ if (atomic_read(&qdisc->refcnt))
+ qdisc_destroy(qdisc);
#if defined(CONFIG_NET_SCH_INGRESS) ||
defined(CONFIG_NET_SCH_INGRESS_MODULE)

         if ((qdisc = dev->qdisc_ingress) != NULL) {

dev->qdisc_ingress = NULL;
diff --exclude='*~' -urN 2.6.9-mm1-U10.3/drivers/pcmcia/yenta_socket.c 2.6.9-mm1-U10.work/drivers/pcmcia/yenta_socket.c
--- 2.6.9-mm1-U10.3/drivers/pcmcia/yenta_socket.c 2004-10-22
16:52:26.000000000 +0200
+++ 2.6.9-mm1-U10.work/drivers/pcmcia/yenta_socket.c 2004-10-22
21:26:15.000000000 +0200
@@ -653,6 +653,7 @@
yenta_free_resources(sock);

pci_release_regions(dev);
+ pci_disable_device(dev);
pci_set_drvdata(dev, NULL);
}

On realtime-preempt-2.6.9-mm1-U10.3:

o In rcupdate.h, I believe that the:

+# define rcu_read_unlock_nort() rcu_read_lock_nort()

should instead be:

+# define rcu_read_unlock_nort() rcu_read_unlock()

It looks to me like the current definition would cause preemption to be permanently disabled in a kernel with CONFIG_PREEMPT but without CONFIG_PREEMPT_REALTIME, at least if one used SysV IPC.

o The rcu_read_lock_spin(), rcu_read_lock_read(),
rcu_read_lock_bh_read(), rcu_read_lock_sem(), and rcu_read_lock_bh_spin() APIs cannot be called recursively. But you probably already knew that. ;-)

I don't understand why the rcu_read_lock_sem() API gets its own #ifdef.

o Some recent RCU patches acquire the update-side lock
under rcu_read_lock(), which I believe will deadlock here. Since the same CPU/task is acquiring the same lock twice, I don't believe that the mutex mods help, but could easily be mistaken. Then again, this may well be why there are all the emails on this thread advising that SELinux be disabled.

Thanx, Paul

Oh no! That would explain a lot... the typical report is it works fine until people go to use the network :-P

Lee

Yes and No !

The wrong define is in the #else path of CONFIG_PREEMPT_REALTIME, so it affects the kernel only when it is built with PREEMPT_REALTIME disabled.

The network problem with PREEMPT_REALTIME enabled is a subtle race, which I have nearly tracked down. I know the scenario, but I have not yet identified the culprit. (:

tglx

yeah, correct - fortunately this is a non-default path, but still a nice fix.

actually, rcu_read_lock_read() is the variant that _can_ be called recursively and which i used in the networking code quite extensively. The others are only useful if the locking is 'flat' in the original code, or if the locking is extensively rewritten. (I havent tried to convert the IPC code back from the 'flat' locking to the original 'nested' locking, but i've done it for the networking code.)

which codepaths do you mean? Things are looking pretty good in -U10.3 so far.

Ingo

OK, sorry for my confusion. I still don't see why rcu_read_lock_sem() is segregated, but it will clearly work either way.

The one that I am aware of has not yet hit mainline -- Kaigai Kohei's scalability changes to Linux. See:

	http://marc.theaimsgroup.com/?l=linux-kernel&m=109628285418353&w=2

The function avc_update_cache() does an rcu_read_lock(), then invokes avc_update_node(), which acquires the update-side lock. No problem under conventional RCU, in the case where one might realize that an update is needed during what is a read-only search in the common case, but would be problematic given real-time preemption.

Thanx, Paul

I get following error with 10.3 on kernel 2.6.9-mm1

Device 'i823650' does not have a release() function, it is broken and must be fixed. swapper/1: BUG in device_release at drivers/base/core.c:85

[<c0238aeb>] kobject_cleanup+0x9a/0x9c (8)
[<c0238b15>] kobject_put+0x1e/0x22 (24)
[<c0238aed>] kobject_release+0x0/0xa (8)
[<c045cecf>] init_i82365+0x1f2/0x208 (4)
[<c02487b6>] pci_register_driver+0x94/0xa6 (8)
[<c044286c>] do_initcalls+0x54/0xb6 (32)
[<c010040b>] init+0x0/0x10d (16)
[<c010043f>] init+0x34/0x10d (12)
[<c01042a8>] kernel_thread_helper+0x0/0xb (12)
[<c01042ad>] kernel_thread_helper+0x5/0xb (4)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x14/0x45 [<00000000>] / (0x0 [<00000000>])

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

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

NOTE: this is a highly experimental release, a more experimental one than -U10.3.

the big change in the '-V' series of the patchset is that i have converted the last couple of non-preemptible kernel subsystems to fully-preemptible mutex-based locking. These subsystems are:

- the SLAB allocator
- the buddy page allocator
- waitqueue handling
- soft-timer subsystem
- security/selinux
- workqueues
- the random driver

this is probably the last 'big leap forward' in terms of the scope of the patch. (having reached the ultimate scope: it now encompasses everything ;)

But as an inevitable result of this big leap it will likely break in a couple of places. Unfortunately these subsystems were largely interdependent so it's an all-or-nothing step with not much middle ground between the locking done in -U10.3 and in -V0.

another result of these changes is that the number of critical sections in -V0 is roughly 30% of that in -U10.3. Now we only have the scheduler and very lowlevel IRQ-hardware locks as raw spinlocks. (plus the lone holdout vga_lock - which i will probably make a mutex too in the near future)

[ NOTE: there's one known bug in this release: selinux on one of my testsystems broke, it hangs during bootup. With CONFIG_SECURITY disabled it works fine. I'm working on the fix. So please keep CONFIG_SECURITY disabled for the time being. ]

other changes in -V0:

- build fixes: more driver fixes from Thomas Gleixner

- crash fix: fixed a bug found by Thomas Gleixner: rwsem runtime initialization was racy.

- deadlock fix: fixed lockup bug caused by __schedule clearing PREEMPT_ACTIVE. The need_resched loop is now outside of __schedule(). This might solve lockups/slowdowns reported by some people.

- latency fix: made keventd SCHED_FIFO - this could fix the mouse related delays reported by a number of people.

- latency fix: fixed SMP lock-break mechanism of mutexes.

- usability feature: hard-interrupts get decreasing SCHED_FIFO priority starting at prio 49 and stopping at prio 25. This should give a good default.

- debug feature: implemented SysRq-D to show the list of tasks with locks blocked on, if RW_SEM_DEADLOCK_DETECTION is enabled.

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

http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
+ http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9/2.6.9-mm1/2.6.9-mm1.bz2
+ http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-V0

Ingo

Does this include all models of security or just the selinux stuff?

i have only tried selinux. (which is installed/enabled by default on FC3 so it's easy for me to test on an out of box distro.)

Ingo

Well I will know when it boots, or doesn't. :) I will report back when I know.

kr

i think i found the bug - now selinux boots fine. I've uploaded -V0.1 with the fix included. This fix could solve a number of other complaints as well.

Ingo

hi, i saw these during boot (config and complete dmesg attached):

Freeing unused kernel memory: 348k freed
Adding 289160k swap on /dev/hda3. Priority:-1 extents:1 EXT3 FS on hdc1, internal journal
IRQ#8 thread RT prio: 45.

BUG: sleeping function called from invalid context modprobe(116) at kernel/mutex.c:28
in_atomic():1 [00000001], irqs_disabled():1
 [<c0117182>] __might_sleep+0xc2/0xe0 (12)
 [<c0134989>] resolve_symbol+0xb9/0xc0 (24)
 [<c01309f8>] _mutex_lock+0x38/0x50 (12)
 [<c0144995>] kmem_cache_alloc+0x45/0x100 (24)
 [<c0134989>] resolve_symbol+0xb9/0xc0 (8)
 [<c0133cfc>] use_module+0x4c/0x160 (4)
 [<c0133d50>] use_module+0xa0/0x160 (20)
 [<f08414f0>] unregister_sound_special+0x0/0x40 [soundcore] (12)
 [<c0134989>] resolve_symbol+0xb9/0xc0 (16)
 [<c0134fe2>] simplify_symbols+0xb2/0x120 (48)
 [<c0135cc3>] load_module+0x573/0xa90 (44)
 [<c013100d>] __mcount+0x1d/0x20 (48)
 [<c0136236>] sys_init_module+0x56/0x260 (112)
 [<c010617b>] syscall_call+0x7/0xb (28)

preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: resolve_symbol+0x21/0xc0 [<c01348f1>] / (simplify_symbols+0xb2/0x120 [<c0134fe2>]) .. entry 2: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

PCI: Found IRQ 3 for device 0000:00:0f.0
sis900.c: v1.08.07 11/02/2003

[...]

EXT3-fs: mounted filesystem with ordered data mode.
eth0: Media Link On 100mbps full-duplex IRQ#5 thread RT prio: 44.
ip_tables: (C) 2000-2002 Netfilter core team

BUG: sleeping function called from invalid context modprobe(591) at kernel/mutex.c:28
in_atomic():1 [00000001], irqs_disabled():1
 [<c0117182>] __might_sleep+0xc2/0xe0 (12)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (24)
 [<c01309f8>] _mutex_lock+0x38/0x50 (12)
 [<c0144995>] kmem_cache_alloc+0x45/0x100 (24)
 [<c0134989>] resolve_symbol+0xb9/0xc0 (8)
 [<c0133cfc>] use_module+0x4c/0x160 (4)
 [<c0133d50>] use_module+0xa0/0x160 (20)
 [<f0914030>] ipt_do_table+0x0/0x320 [ip_tables] (12)
 [<c0134989>] resolve_symbol+0xb9/0xc0 (16)
 [<c0134fe2>] simplify_symbols+0xb2/0x120 (48)
 [<c0135cc3>] load_module+0x573/0xa90 (44)
 [<c01ef27b>] __up_write+0x13b/0x320 (48)
 [<c0136236>] sys_init_module+0x56/0x260 (112)
 [<c010617b>] syscall_call+0x7/0xb (28)

preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: resolve_symbol+0x21/0xc0 [<c01348f1>] / (simplify_symbols+0xb2/0x120 [<c0134fe2>]) .. entry 2: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

ip_conntrack version 2.1 (6144 buckets, 49152 max) - 452 bytes per conntrack

Module                  Size  Used by
ipt_addrtype            2112  1 
ipt_state               1920  1 
ip_conntrack           51096  1 ipt_state
iptable_filter          3136  1 
ip_tables              19584  3 ipt_addrtype,ipt_state,iptable_filter
bsd_comp                5952  0 
ppp_deflate             6272  0 
zlib_deflate           22360  1 ppp_deflate
ppp_async              13784  1 
ppp_generic            34276  7 bsd_comp,ppp_deflate,ppp_async
slhc                    8320  1 ppp_generic
crc_ccitt               2112  1 ppp_async
sis900                 20036  0 
crc32                   4352  1 sis900
snd_cs46xx             84168  1 
snd_rawmidi            26592  1 snd_cs46xx
snd_seq_device          8972  1 snd_rawmidi
snd_ac97_codec         77472  1 snd_cs46xx
snd_pcm               100600  2 snd_cs46xx,snd_ac97_codec
snd_timer              27612  1 snd_pcm
snd                    57668  8 snd_cs46xx,snd_rawmidi,snd_seq_device,snd_ac97_codec,snd_pcm,snd_timer
soundcore              10688  1 snd
snd_page_alloc         10244  2 snd_cs46xx,snd_pcm
gameport                4992  1 snd_cs46xx

flo

does the patch below fix this?

Ingo

@@ -53,7 +53,7 @@
 #define INIT_OFFSET_MASK (1UL << (BITS_PER_LONG-1))
 
 /* Protects module list */
-static DECLARE_RAW_SPINLOCK(modlist_lock);
+static DECLARE_SPINLOCK(modlist_lock);
 
 /* List of modules, protected by module_mutex AND modlist_lock */
 static DECLARE_MUTEX(module_mutex);

looks like it. they didn't show on first boot of the new kernel with patch applied.

Btw: i still experience some "pauses". They are different now though. It seems i can trigger them by reloading a page in mozilla (not always). This BUG definetly looks related. Dunno, when exactly it happened (related to what i did at that moment), but it's the only one in dmesg output on this bootup. Each of the pauses is accompanied by a high cpu usage of ksoftirqd. I cannot retrigger the BUG though.

mozilla-bin/763: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (64)
 [<c01ef17b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef17b>] __up_write+0x13b/0x320 (4)
 [<c02b94d3>] down_read+0xd3/0x2b0 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01eef11>] up_read+0x111/0x240 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01eef11>] up_read+0x111/0x240 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (104)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

Here's the syslog entry:

Oct 25 15:56:31 mango kernel: mozilla-bin/763: BUG in futex_wait at kernel/futex.c:542
Oct 25 15:56:31 mango kernel:  [futex_requeue+162/608] futex_wait+0x192/0x1a0 (12)
Oct 25 15:56:31 mango kernel:  [print_name_offset+149/160] sub_preempt_count+0x65/0xd0 (64)
Oct 25 15:56:31 mango kernel:  [zlib_inflateReset+43/128] __up_write+0x13b/0x320 (8)
Oct 25 15:56:31 mango kernel:  [kfifo_alloc+216/240] check_preempt_timing+0x58/0x290 (8)
Oct 25 15:56:31 mango kernel:  [print_name_offset+149/160] sub_preempt_count+0x65/0xd0 (4)
Oct 25 15:56:31 mango kernel:  [zlib_inflateReset+43/128] __up_write+0x13b/0x320 (4)
Oct 25 15:56:31 mango kernel:  [__func__.0+318/987] down_read+0xd3/0x2b0 (8)
Oct 25 15:56:31 mango kernel:  [print_name_offset+149/160] sub_preempt_count+0x65/0xd0 (4)
Oct 25 15:56:31 mango kernel:  [zlib_inflate_fast+465/1024] up_read+0x111/0x240 (8)
Oct 25 15:56:31 mango kernel:  [kfifo_alloc+216/240] check_preempt_timing+0x58/0x290 (8)
Oct 25 15:56:31 mango kernel:  [print_name_offset+149/160] sub_preempt_count+0x65/0xd0 (4)
Oct 25 15:56:31 mango kernel:  [zlib_inflate_fast+465/1024] up_read+0x111/0x240 (4)
Oct 25 15:56:31 mango kernel:  [wake_up_process+32/48] default_wake_function+0x0/0x20 (104)
Oct 25 15:56:31 mango kernel:  [wake_up_process+32/48] default_wake_function+0x0/0x20 (32)
Oct 25 15:56:31 mango kernel:  [unqueue_me+103/256] do_futex+0x47/0xa0 (40)
Oct 25 15:56:31 mango kernel:  [futex_wait+176/400] sys_futex+0xf0/0x100 (40)
Oct 25 15:56:31 mango kernel:  [irq_entries_start+107/128] syscall_call+0x7/0xb (68)
Oct 25 15:56:31 mango kernel: preempt count: 00000001
Oct 25 15:56:31 mango kernel: . 1-level deep critical section nesting:
Oct 25 15:56:31 mango kernel: .. entry 1: print_traces+0x17/0x90 [update_max_trace+23/160] / (dump_stack+0x23/0x30 [show_registers+131/464])

ok, i've added it and uploaded -V0.2 together with another fix: there was a scheduler recursion possible via the delayed-put mechanism using workqueues - now it's using its own separate lists and per-CPU threads.

please try -V0.2 - maybe the delayed-put fix is somehow related. (but only maybe...)

Ingo

-V0.2 seems to behave quite well on my testboxes - i'm unable to reproduce the selinux boot hang anymore.

Ingo

OK. RT-V0.2 boots on my laptop (P4/UP), sometimes ;)

I know that my early impressions are illusive, rather subjective, but I do feel overall behavior is getting worst, when regarding low-latency audio work with jackd -R.

To put things straight with RT-V0.2, I get trouble with much less load than even before.

I noticed that something is, now and then, topping the cpu to 99%, leaving the system to a crawl, eventually returning back to normal. Can't figure out who or what, just because ps or top are stalling to silence, only returning results after when the crawl ends, which are of no useful evidence. When I'm lucky enough to let top (and gkrellm) telling me something, it does look like that most of the time is spent on kernel mode (sys time) and none of the running processes are at stake. Puzzled. It's just like you're about to loose confidence on the procps tools.

OTOH, jackd -R xruns are awfully back, even thought I (re)prioritize the relevant IRQ thread handlers to be always higher than jackd's. This just doesn't seem like an improvement, not at all :( IMO, given the xrun rate I'm experiencing with RT-V0.2, it all seems that I'm running on vanilla 2.6.9, with pretty much instability added to the picture.

About that jackd -R issue, which has been hosing the complete system occasionally, is still an annoyance on RT-V0.2. On this same laptop (P4/UP), it does happen only if PREEMPT_REALTIME is set. However, I think I've narrowed it's reproducibility: loading more than two fluidsynth instances was the easiest way to get the box frozen in less than one minute, at least on RT-U10.3. With RT-V0.2 is even easier, with just two fluidsynth instances, or even one.

Sorry for this kind of rant, but I had to distress myself, somehow ;)

Nevertheless, I'll keep on going with my user level trials... and let you informed, of course.

Cheers,

rncbc aka Rui Nuno Capela
[email protected]

Actually they should be lower, except the soundcard. I was only able to get the xrun free behavior of T3 by setting all IRQ threads except the soundcard to SCHED_OTHER. Especially important was setting ksoftirqd to SCHED_OTHER, this actually may have been the only one necessary.

The relative priorities of jackd and the soundcard irq do not matter as these two should never contend (aka they are never both runnable at the same time).

Lee

Not being familiar with jack, does it use rtc?

kr

No it normally uses the soundcard for timing. For testing there is a dummy backend that just usleep()s. This makes a pretty useful latency tester.

Lee

Just wondered. I am writing an email right now about my results with V0.2, one of which happens to be that amlat will kill any of my systems running it.

kr

What happens when one is blessed with a laptop where everything is sharing an interrupt?

$ cat /proc/interrupts
           CPU0
  0:    2372239          XT-PIC  timer  0/72239
  1:       5362          XT-PIC  i8042  0/5362
  2:          0          XT-PIC  cascade  0/0
  8:          1          XT-PIC  rtc  0/1
  9:     616176          XT-PIC  acpi, uhci_hcd, uhci_hcd, uhci_hcd,
eth0, yenta, yenta, Intel 82801CA-ICH3, radeon@PCI:1:0:0  0/16176
11:         37          XT-PIC  sonypi  0/35
12:      28392          XT-PIC  i8042  0/28392
14:      21078          XT-PIC  ide0  0/21078
15:        472          XT-PIC  ide1  0/472
NMI:          0
LOC:          0
ERR:          0
MIS:          0

I'm running U10.3 and I'm consistently seeing xruns when Jack clients start and stop, something I would not see before (I have not tried the latest V series yet). I have tried changing the priority of IRQ9 and the scheduler but I still see the xruns. Yesterday I tried enabling preempt_thresh to a low value but did not see hits when the xruns occurred. Maybe I'm missing something I need to do...

-- Fernando

Ugh, why would _anyone_ design a laptop like that? You have 4 perfectly good interrupts that you are not using at all. Is it really cheaper to put everything on the same irq? Does this work better under Windows or something?

AFAIK there is nothing you can do - any other irq that fires on 9 will mask out all the others until it completes.

I am increasingly convinced that the vast majority of laptops are horribly broken and completely unsuitable for low latency audio work.

Lee

Yes, except I did not see all these xruns running 2.4.26 + lowlat + preempt (same machine). Things got better with 2.6.x up to, perhaps, S7, although I would have to retest to make sure. Now they seem to be worse than before.

-- Fernando

Hmm, interesting. Anyway T3 is the last version that was stable for me, this is the xrun-free standard that I compare the later ones to.

Lee

<shameless plug>
Maybe this program will be useful. It is designed to give you overall system statistics without the need to scan entire /proc/NNN forest. Together with nice -20, it will hopefully not stall.

Compiled with dietlibc. If you will have trouble compiling it, binary is attached too.

Latest version is 0.9 but it seems I forgot it in my home box :( </shameless plug>
--
vda

// Based on nanotop.c from floppyfw project
// Released under GPL
// Contact me: [email protected]

//TODO:
// simplify code
// /proc/locks
// /proc/stat:
// disk_io: (3,0):(22272,17897,410702,4375,54750)
// btime 1059401962

//#include <ctype.h>
#include <sys/time.h> // gettimeofday
#include <string.h> // strstr etc
#include <stdarg.h> // f(...)
#include <fcntl.h> // O_RDONLY

#define VERSION_STR "0.7"
#define DELIM_CHAR ' '

//==============
#define NL "\n"
typedef unsigned long long ullong;
typedef unsigned long ulong;

typedef ulong sample_t;

//==============
#define proc_file_size 4096

typedef struct proc_file {
    char *name;
    int gen;
    char *file;
} proc_file;

proc_file proc_stat = { "/proc/stat", -1 }; proc_file proc_net_dev = { "/proc/net/dev", -1 }; proc_file proc_meminfo = { "/proc/meminfo", -1 }; proc_file proc_diskstats = { "/proc/diskstats", -1 }; struct timeval tv;
int gen=-1;
int is26=0;

//==============
#if 0
#include <stdio.h>

void dprintf(const char *fmt, ...) {
    va_list ap;
    va_start(ap, fmt);
    vprintf(fmt, ap);
    va_end(ap);
}

#else
extern void dprintf(const char *fmt, ...) {}
#endif

//==============
char outbuf[4096];
char *cur_outbuf = outbuf;

extern inline void reset_outbuf() {
    cur_outbuf = outbuf;
}

extern inline int outbuf_count() {
    return cur_outbuf-outbuf;
}

extern inline void print_outbuf() {
    if(cur_outbuf>outbuf) {
	write(1, outbuf, cur_outbuf-outbuf);
	cur_outbuf = outbuf;
    }
}

void put(const char *s) {
    int sz = strlen(s);
    if(sz > (outbuf+sizeof(outbuf))-cur_outbuf)
	sz = (outbuf+sizeof(outbuf))-cur_outbuf;
    memcpy(cur_outbuf, s, sz);
    cur_outbuf += sz;
}

void put_c(char c) {
if(cur_outbuf < outbuf+sizeof(outbuf))
*cur_outbuf++ = c;
}

//==============
char* simple_itoa(char *s, int sz, unsigned long v, int pad) { //==============

    s += sz;
    *--s = '\0';
    while (--sz > 0) {
        *--s = "0123456789"[v%10];
        pad--;
        v /= 10;
        if(!v && pad<=0) break;
    }
    return s;
}

//==============
int readfile_z(char *buf, int sz, const char* fname) { //==============

    int fd;
    fd=open(fname,O_RDONLY);
    if(fd<0) return 1;
    sz = read(fd,buf,sz-1);
    close(fd);
    if(sz<0) {
	buf[0]='\0';
	return 1;
    }
    buf[sz]='\0';
    return 0;
}

//==============
int rdval(const char* p, const char* key, sample_t *vec, ...) { //==============

    va_list arg_ptr;
    int indexline;
    int indexnext;

    p = strstr(p,key);
    if(!p) return 1;
	
    p += strlen(key);
    va_start(arg_ptr, vec);
    indexline = 1;
    indexnext = va_arg(arg_ptr, int);
    while(1) {
    	while(*p==' ' || *p=='\t') p++;
	if(*p=='\n' || *p=='\0') break;

        if(indexline == indexnext) { // read this value
            *vec++ = strtoul(p, NULL, 10);
            indexnext = va_arg(arg_ptr, int);
        }
    	while(*p > ' ') p++; // skip over value
        indexline++;
    }
    va_end(arg_ptr);
    return 0;
}

//==============
int rdval_diskstats(const char* p, sample_t *vec) {

//   1    2 3   4     5     6(rd)  7      8     9     10(wr) 11      12 13    14
//   3    0 hda 51292 14441 841783 926052 25717 79650 843256 3029804 0 148459 3956933
//   3    1 hda1 0 0 0 0 <- ignore if only 4 fields
//==============
    sample_t rd;
    int indexline = 0;
    vec[0] = 0;
    vec[1] = 0;
    while(1) {
        indexline++;
        while(*p==' ' || *p=='\t') p++;
        if(*p=='\0') break;
        if(*p=='\n') {
            indexline = 0;
	    p++;
            continue;
        }
        if(indexline == 6) {
            rd = strtoul(p, NULL, 10);
        } else
        if(indexline == 10) {
            vec[0] += rd;  // TODO: *sectorsize (don't know how to find out sectorsize)
            vec[1] += strtoul(p, NULL, 10);
    	    while(*p!='\n' && *p!='\0') p++;
	    continue;
        }
        while(*p > ' ') p++; // skip over value
    }
    return 0;
}

//==============
void scale(sample_t ul) {
//==============

    char buf[5];
    int index = 0;
    ul *= 10;
    if(ul>9999*10) { // do not scale if 9999 or less
	while(ul >= 10000) {
	    ul /= 1024;
	    index++;
	}
    }

    if(!index) {/* use 1234 format */
	buf[0] = " 123456789"[ul/10000];
	if(buf[0]== ' ') buf[1] = " 123456789"[ul/1000%10];
	            else buf[1] = "0123456789"[ul/1000%10];
	if(buf[1]== ' ') buf[2] = " 123456789"[ul/100%10];
                    else buf[2] = "0123456789"[ul/100%10];
	buf[3] = "0123456789"[ul/10%10];
    } else if(ul>=100) { /* use 123k format */
	if( (buf[0]= " 123456789"[ul/1000]) == ' ')
	    buf[1] = " 123456789"[ul/100%10];
	else
	    buf[1] = "0123456789"[ul/100%10];
	buf[2] = "0123456789"[ul/10%10];
	buf[3] = " kMGTEP"[index];
    } else { /* use 1.2M format */
	buf[0] = "0123456789"[ul/10];
	buf[1] = '.';
	buf[2] = "0123456789"[ul%10];
	buf[3] = " kMGTEP"[index];
    }
    buf[4] = 0;
    put(buf);
}

//==============

const char* prepare(proc_file *pf) {
    if(!pf->file) pf->file = (char*)malloc(proc_file_size);
    if(pf->gen != gen) {
	pf->gen = gen;
	readfile_z(pf->file, proc_file_size, pf->name);
    }
    return pf->file;
}

//==============
#define S_STAT(a) \

typedef struct a { \
    struct s_stat *next; \
    int (*collect)(struct a *s); \
    const char *label; \
    int width;

S_STAT(s_stat)
} s_stat;

#define MALLOC_STAT(type,var) type *var = (type*)malloc(sizeof(type))

//==============
S_STAT(cpu_stat)

    sample_t old[4];
    int bar_sz;
    char *bar;
} cpu_stat;

//==============
int collect_cpu(cpu_stat *s) {
//==============

    sample_t data[4];
    sample_t frac[4];
    sample_t all = 0;
    int norm_all = 0;
    int bar_sz = s->bar_sz;
    char *bar = s->bar;
    int i;

    if(rdval(prepare(&proc_stat), "cpu ", data, 1, 2, 3, 4))
	return 1;
    
    put_c('[');

//dprintf("data1:");
    for(i=0; i<4; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
        s->old[i] = data[i];
        all += (data[i] -= old);
//dprintf(" %lu",data[i]);
    }

//dprintf(" all %lu\n",all);

    if(all) {
//dprintf("data2:");
	for(i=0; i<4; i++) {
	    ullong t = bar_sz*(ullong)data[i];
	    norm_all += data[i] = t / all;
	    frac[i] = t % all;
//dprintf(" %lu/%lu",data[i],frac[i]);
	}
//dprintf(" norm_all %lu\n",norm_all);
    
	while(norm_all<bar_sz) {
	    sample_t max=frac[0]; int pos=0;
	    //for(i=1; i<4; i++) if(frac[i]>=max) max=frac[i], pos=i;
	    if(frac[1]>=max) max=frac[1], pos=1;
	    if(frac[2]>=max) max=frac[2], pos=2;
	    if(frac[3]>=max) max=frac[3], pos=3;
	    frac[pos]=0;	//avoid bumping same value twice
	    data[pos]++;
//dprintf("bumped %i\n",pos);
	    norm_all++;
        }

//dprintf("bar_sz %i\n",bar_sz);
//dprintf("sys %i\n",data[2]);
//dprintf("usr %i\n",data[0]);

//dprintf("nice %i\n",data[1]);
	memset(bar,'.',bar_sz);
	memset(bar,'S',data[2]); bar+=data[2]; //sys
	memset(bar,'U',data[0]); bar+=data[0]; //usr
	memset(bar,'N',data[1]); bar+=data[1]; //nice
    } else {
	memset(bar,'?',bar_sz);
    }
    put(s->bar);
    put_c(']');
    return 0;
}

//==============
s_stat* init_cpu(const char *param) {
//==============

    int sz;
    MALLOC_STAT(cpu_stat,s);
    s->collect = collect_cpu;
    s->label = "cpu ";
    s->width = 4;

    sz = strtol(param, NULL, 0);
    if(sz<10) sz=10;
    if(sz>1000) sz=1000;

    s->bar = (char*)malloc(sz+1);
    s->bar[sz]=0;
    s->bar_sz = sz;
    s->width = sz+2;
    return (s_stat*)s;
}

//==============
S_STAT(int_stat)

    sample_t old;
    int no;
    char numlabel[6];
} int_stat;

//==============
int collect_int(int_stat *s) {
//==============

    sample_t data[1];

    if(rdval(prepare(&proc_stat), "intr", data, s->no))
	return 1;

    sample_t old = s->old;
    if(data[0] < old) old = data[0];	//sanitize
    s->old = data[0];
    scale(data[0] - old);
    return 0;
}

//==============
s_stat* init_int(const char *param) {
//==============

    MALLOC_STAT(int_stat,s);
    s->collect = collect_int;
    s->width = 4;
    if(param[0]=='\0') {
	s->no = 1;
	s->label = "int ";
    } else {
	int n = strtoul(param, NULL, 0);
	s->no = n+2;
	s->label = s->numlabel;
	s->numlabel[0]='i';
	s->numlabel[1]='n';
	s->numlabel[2]='t';
	s->numlabel[3]=(n<=9 ? '0'+n : n+('A'-10));
	s->numlabel[4]=' ';
	s->numlabel[5]='\0';
    }
    return (s_stat*)s;
}

//==============
S_STAT(ctx_stat)

    sample_t old;
} ctx_stat;

//==============
int collect_ctx(ctx_stat *s) {
//==============

    sample_t data[1];

    if(rdval(prepare(&proc_stat), "ctxt", data, 1))
	return 1;

    sample_t old = s->old;
    if(data[0] < old) old = data[0];	//sanitize
    s->old = data[0];
    scale(data[0] - old);
    return 0;
}

//==============
s_stat* init_ctx(const char *param) {
//==============

    MALLOC_STAT(ctx_stat,s);
    s->collect = collect_ctx;
    s->label = "ctx ";
    s->width = 4;
    return (s_stat*)s;
}

//==============
S_STAT(blk_stat)

    const char* lookfor;
    sample_t old[2];
} blk_stat;

//==============
int collect_blk24(blk_stat *s) {
//==============

    sample_t data[2];
    int i;
    if(rdval(prepare(&proc_stat), s->lookfor, data, 1, 2))
    	return 1;

    for(i=0; i<2; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
	s->old[i] = data[i];
	data[i] -= old;
    }
    scale(data[0]*1024);
    put_c(' ');
    scale(data[1]*1024);
    return 0;
}

//==============
int collect_blk26(blk_stat *s) {
//==============

    sample_t data[2];
    int i;
    if(rdval_diskstats(prepare(&proc_diskstats), data))
	return 1;

    for(i=0; i<2; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
	s->old[i] = data[i];
	data[i] -= old;
    }
    scale(data[0]*512);
    put_c(' ');
    scale(data[1]*512);
    return 0;
}

//==============
int collect_blk(blk_stat *s) {
//==============

    if(is26) return collect_blk26(s);
    return collect_blk24(s);
}

//==============
s_stat* init_blk(const char *param) {
//==============

    MALLOC_STAT(blk_stat,s);
    s->collect = collect_blk;
    if(param[0]=='s') {
	s->label = "sio ";
	s->lookfor = "swap";
    } else {
	s->label = "bio ";
	s->lookfor = "page";
    }
    s->width = 9;
    return (s_stat*)s;
}

//==============
S_STAT(fork_stat)

    sample_t old;
} fork_stat;

//==============
int collect_fork(fork_stat *s) {
//==============

    sample_t data[1];

    if(rdval(prepare(&proc_stat), "processes", data, 1))
	return 1;

    sample_t old = s->old;
    if(data[0] < old) old = data[0];	//sanitize
    s->old = data[0];
    scale(data[0] - old);
    return 0;
}

//==============
s_stat* init_fork(const char *param) {
//==============

    MALLOC_STAT(fork_stat,s);
    s->collect = collect_fork;
    s->label = "fork";  // no trailing space: there usually <1000 forks,
    s->width = 4;       // we trade usual "fork    3" for rare "fork1234"
    return (s_stat*)s;
}

//==============
S_STAT(if_stat)

    sample_t old[4];
    const char *device;
    char *device_colon;
} if_stat;

//==============
int collect_if(if_stat *s) {
//==============

    sample_t data[4];
    int i;

    if(rdval(prepare(&proc_net_dev), s->device_colon, data, 1, 3, 9, 11))
	return 1;

    //dprintf("data1:");
    for(i=0; i<4; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
        s->old[i] = data[i];
        data[i] -= old;
	//dprintf(" %lu",data[i]);
    }
    //dprintf("\n");
    
    put_c(data[1] ? '*' : ' ');
    scale(data[0]);
    put_c(data[3] ? '*' : ' ');
    scale(data[2]);
    return 0;
}

//==============
s_stat* init_if(const char *device) {
//==============

    MALLOC_STAT(if_stat,s);
    s->collect = collect_if;
    s->label = device;
    s->width = 10;
    
    s->device = device;
    s->device_colon = (char*)malloc(strlen(device)+2);
    strcpy(s->device_colon,device);
    strcat(s->device_colon,":");
    return (s_stat*)s;
}

//==============
S_STAT(mem_stat)

    char opt;
} mem_stat;

//==============
int collect_mem(mem_stat *s) {
//==============
// total: used: free: shared: buffers: cached:
//Mem: 29306880 21946368 7360512 0 2101248 11956224
//Swap: 100655104 10207232 90447872
//MemTotal: 28620 kB
//MemFree: 7188 kB
//MemShared: 0 kB <-- ?

//Buffers:          2052 kB
//Cached:           9080 kB
//SwapCached:       2596 kB  <-- ?

    // Not available in 2.6:
    //if(rdval(prepare(&proc_meminfo), "Mem:", data, 1, 2, 5, 6))
    //    return 1;
    sample_t m_total;
    sample_t m_free;
    sample_t m_bufs;
    sample_t m_cached;
    if(rdval(prepare(&proc_meminfo), "MemTotal:", &m_total , 1)) return 1;
    if(rdval(prepare(&proc_meminfo), "MemFree:",  &m_free  , 1)) return 1;
    if(rdval(prepare(&proc_meminfo), "Buffers:",  &m_bufs  , 1)) return 1;
    if(rdval(prepare(&proc_meminfo), "Cached:",   &m_cached, 1)) return 1;
    switch(s->opt) {
    case 'f':
        scale((m_free + m_bufs + m_cached)<<10); break;
    case 't':
        scale(m_total<<10); break;
    default:
        scale((m_total - m_free - m_bufs - m_cached)<<10); break;
    }
    return 0;
}

//==============
s_stat* init_mem(const char *param) {
//==============

    MALLOC_STAT(mem_stat,s);
    s->collect = collect_mem;
    s->width = 4;
    s->opt=param[0];
    switch(param[0]) {
    case 'f':
	s->label = "free "; break;
    case 't':
	s->label = "tot "; break;
    default:
	s->label = "mem "; break;
    }
    return (s_stat*)s;
}

//==============
S_STAT(swp_stat)
} swp_stat;

//==============
int collect_swp(swp_stat *s) {
//==============

    sample_t data[1];
    if(rdval(prepare(&proc_meminfo), "Swap:", data, 2))
	return 1;
	
    scale(data[0]);
    return 0;
}

//==============
s_stat* init_swp(const char *param) {
//==============

    MALLOC_STAT(swp_stat,s);
    s->collect = collect_swp;
    s->label = "swp ";
    s->width = 4;
    return (s_stat*)s;
}

//==============
S_STAT(fd_stat)
} fd_stat;

//==============
int collect_fd(fd_stat *s) {
//==============

    char file[4096];
    sample_t data[2];

    readfile_z(file, sizeof(file), "/proc/sys/fs/file-nr");
    if(rdval(file, "", data, 1, 2))
	return 1;

    scale(data[0]-data[1]);
    return 0;
}

//==============
s_stat* init_fd(const char *param) {
//==============

    MALLOC_STAT(fd_stat,s);
    s->collect = collect_fd;
    s->label = "fd ";
    s->width = 4;
    return (s_stat*)s;
}

//==============
S_STAT(time_stat)

    int prec;
    int scale;
} time_stat;

//==============
int collect_time(time_stat *s) {
//==============

    char buf[16];	// 12:34:56.123456<eol>
			// 1234567890123456
    simple_itoa(buf, 3, tv.tv_sec/(60*60)%24, 2);
    buf[2] = ':';
    simple_itoa(buf+3, 3, tv.tv_sec/60%60, 2);
    buf[5] = ':';
    simple_itoa(buf+6, 3, tv.tv_sec%60, 2);
    
    if(s->prec) {
	buf[8] = '.';
	//simple_itoa(buf+9, s->prec+1, (tv.tv_usec + s->scale/2) / s->scale, s->prec);
	// (fixme: round up seconds too!)
	// so... rounding omitted! just use more prec if you need it! ;)
	simple_itoa(buf+9, s->prec+1, tv.tv_usec / s->scale, s->prec);
    }
    put(buf);
    return 0;
}

//==============
s_stat* init_time(const char *param) {
//==============

    int prec;
    MALLOC_STAT(time_stat,s);
    s->collect = collect_time;
    s->label = "";
    prec = param[0]-'0';
    if(prec<0) prec = 0;
    else if(prec>6) prec = 6;
    s->width = 8+prec + (prec!=0);
    s->prec = prec;
    s->scale = 1;
    while(prec++ < 6)
	s->scale *= 10;
    return (s_stat*)s;
}

//==============
S_STAT(extern_stat)

    int ifd,ofd;
    char *buf;
    char *cur;
} extern_stat;

#define WIDTH

//==============
int collect_extern(extern_stat *s) {
//==============

    int sz;
    char *p;
    int buffered = s->cur - s->buf;
    
    s->buf[40] = 0;
    p = strchr(s->buf,'\n');
    if(!p || p > s->cur) {
	do {
	    sz = read(s->ofd,s->cur,40 - buffered);
	    if(sz<0) exit(1);
	    buffered += sz;
	    p = strchr(s->cur,'\n');
	    s->cur = s->buf+buffered;
	    if(p > s->cur) p=0;
	} while(!p && buffered<40);
	if(!p) p=s->buf+40;
    }
    
    *p++ = 0;
    put(s->buf);
    s->cur = s->buf;
    while(p < s->buf+buffered) {
	put_c('=');
	*s->cur++ = *p++;
    }
    while(p <= s->buf+40) {
	put_c('='); p++;
    }
    return 0;
}

//#include <stdio.h>

void myexec(void *param) {
    char **argv = (char **)param;
    execv(argv[0], argv);
}

int start_child(int *i,int *o,void (*f)(void*),void *param) {
    int pid;
//printf("execv(%s, argv);\n",((char**)param)[0]);
    {
	int in[2];
	int out[2];
	pipe(in);
	pipe(out);
	pid = fork();
	switch(pid) {
	case -1: /* error */
	    return -1;
	case 0: /* child */
	    dup2(in[0],0); close(in[0]); close(in[1]);
	    dup2(out[1],1); close(out[0]); close(out[1]);
	    f(param);
	    exit(1);
	default: /* parent */
	    close(in[0]);
	    if(i) *i=in[1]; else close(in[1]);
	    if(o) *o=out[0]; else close(out[0]);
	    close(out[1]); 
	    return pid;
	}
    }
}

//==============
s_stat* init_extern(const char *param) {
//==============

    int pid;
    char *argv[] = { (char*)param, 0 };
    MALLOC_STAT(extern_stat,s);
    s->collect = collect_extern;
    s->label = "extern ";
    s->width = 40;
    s->buf = (char*)malloc(41);
    s->cur = s->buf;
    pid = start_child(&s->ifd, &s->ofd, myexec, argv);
    if(pid<0) exit(1);
//printf("pid,i,o=%d %d %d\n",pid,s->ifd,s->ofd);
    return (s_stat*)s;
}

//==============
char *header;
//==============
void build_n_put_hdr(s_stat *s) {
//==============

    while(s) {
	int l = 0;
        if(s->label[0]!=' ') {
    	    put(s->label);
	    l = strlen(s->label);
	}
	while(l <= s->width) {
	    put_c(' ');	
	    l++;
	}
        s = s->next;
    }
    put_c('\n');

    header = (char*)malloc(outbuf_count()+1);
    memcpy(header, outbuf, outbuf_count());
    header[outbuf_count()] = '\0';
    //print_outbuf();
}

//==============
void put_hdr(s_stat *s) {
//==============

    if(!header) build_n_put_hdr(s);
    else {
	put(header);
	//print_outbuf();
    }
}

//==============
void run_once(s_stat *s, int without_headers) {
//==============

    gen++;
    int first = 1;
    while(s) {
	if(s->label[0]!=' ') {		// "[prev ][LABEL]data
	    if(!first) put_c(DELIM_CHAR);
    	    if(!without_headers) put(s->label);
	} else {			// "prevLABELdata
	    put(s->label+1);
	}
        if(s->collect(s)) {
	    int w = s->width;
	    while(w-- > 0)
		put_c('?');
	}
        s = s->next;
	first = 0;
    }
}

//==============
typedef s_stat* init_func(const char *param);

const char options[] = "ncmsfixptbe";
init_func* init_functions[] = {
init_if,
init_cpu,
init_mem,
init_swp,
init_fd,
init_int,
init_ctx,
init_fork,
init_time,
init_blk,
init_extern,
};

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

    struct timezone tz;
    s_stat *first = 0;
    s_stat *last = 0;
    s_stat *s;
    int delta = 1000000;
    int deltanz = 1000000;
    int print_headers = 0;
    char *final_str = "\n";
    char *p;
    int fd;
    int i;
    
    if(argc==1) {
	put(
	"nmeter " VERSION_STR " allows you to monitor your system in real time" NL
	NL
	"Options:" NL
	"c[N]	monitor CPU. N - bar size, default 10" NL
	"nIFACE	monitor network interface IFACE" NL
	"m[f/t]	monitor allocated/free/total memory" NL
	"s	monitor allocated swap" NL
	"f	monitor number of used filedescriptors" NL
	"i[NN]	monitor total/specific IRQ rate" NL
	"x	monitor context switch rate" NL
	"p	monitor process creation rate" NL
	"b[s]	monitor block io (swap io)" NL
	"t[N]	show time (with N decimal points)" NL
	"d[N]	milliseconds between updates. Default 1000" NL
	"h[N]	print headers above numbers (each N lines, default once)" NL
	"lLABEL	specify label for previous item" NL
	"LLABEL	same + label will be printed without surrounding blanks" NL
	"r	print <cr> instead of <lf> at EOL. Try it ;)" NL
	);
	print_outbuf();
	return 0;
    }

    fd = open("/proc/version",O_RDONLY);
    if(fd>=0) {
	char buf[32];
	if(0<read(fd,buf,sizeof(buf)))
	    is26 = (strstr(buf,"Linux version 2.6.")!=NULL);
	close(fd);
    }
    for(i=1; i<argc; i++) {
	p = strchr(options,argv[i][0]);
	if(p) {
	    s = init_functions[p-options](argv[i]+1);
	    if(s) {
		s->next = 0;
		if(!first)
		    first = s;
		else
		    last->next = s;
		last = s;
	    }
	}

// You have to see it... gcc 3.2 coded switch() as 40 element jump table // OH NO! >>>:^O
/*
#define SW(a) switch(a) {
#define ENDSW }
#define CASE(a,b) case (b): {
#define ENDCASE }
*/
#define SW(a) do {
#define ENDSW } while(0);
#define CASE(a,b) if((a)==(b)) {

#define ENDCASE }
	SW(argv[i][0])
	CASE(argv[i][0],'r')
	    final_str = "\r";
	    break;
	ENDCASE
	CASE(argv[i][0],'d')
	    delta = strtol(argv[i]+1, NULL, 0)*1000;
	    deltanz = delta>0? delta : 1;
	    break;
	ENDCASE
	CASE(argv[i][0],'h')
	    if(argv[i][1]=='\0')
		print_headers = -1;
	    else
		print_headers = strtol(argv[i]+1, NULL, 0);
	    break;
	ENDCASE
	CASE(argv[i][0],'l')
	    if(last)
		last->label=argv[i]+1;
	    break;
	ENDCASE
	CASE(argv[i][0],'L')
	    if(last) {
		argv[i][0]=' ';
		last->label=argv[i];
	    }
	    break;
	ENDCASE
	ENDSW
    }
	
    if(print_headers == -1) {
	build_n_put_hdr(first);
	print_outbuf();
    }
    run_once(first, print_headers);
    reset_outbuf();
    if(delta>=0) {
	//gettimeofday(&tv,0);
	gettimeofday(&tv,&tz); //
	usleep(delta>1000000 ? 1000000 : delta-tv.tv_usec%deltanz);
    }
    while(1) {
	gettimeofday(&tv,&tz);
        tv.tv_sec -= tz.tz_minuteswest*60;

	if(print_headers > 0 && gen%print_headers == 0)
	    put_hdr(first);
	run_once(first, print_headers);
	put(final_str);
	print_outbuf();

	// Negative delta -> no usleep at all
	// This will hog the CPU but you can have REALLY GOOD
	// time resolution ;)
	// TODO: detect and avoid useless updates
	// (like: nothing happens except time)
        if(delta>=0) {
	    int rem = delta - ((ullong)tv.tv_sec*1000000+tv.tv_usec)%deltanz;
	    // Sometimes kernel wakes us up just a tiny bit earlier than asked
	    // Do not go to very short sleep in this case
	    if(rem < delta/128) {
		rem += delta;
	    }
	    usleep(rem);
	}
    }

    return 0;
}

</shameless plug>

Thanks for nmeter. I have changed a couple of little bits to build with gcc-3.4 here (see diff attached).

Indeed, it says 0.7 as its version string. What's up on 0.9?

rncbc aka Rui Nuno Capela
[email protected]

@@ -59,15 +59,15 @@
 char outbuf[4096];
 char *cur_outbuf = outbuf;
 
-extern inline void reset_outbuf() {
+inline void reset_outbuf() {
     cur_outbuf = outbuf;
 }
 
-extern inline int outbuf_count() {
+inline int outbuf_count() {
     return cur_outbuf-outbuf;
 }
 
-extern inline void print_outbuf() {
+inline void print_outbuf() {
     if(cur_outbuf>outbuf) {
 	write(1, outbuf, cur_outbuf-outbuf);
 	cur_outbuf = outbuf;

Hmm will it compile on 3.4 with "static inline"?

Here it is.
--
vda

// Based on nanotop.c from floppyfw project
// Released under GPL
// Contact me: [email protected]

//TODO:
// simplify code
// /proc/locks
// /proc/stat:
// disk_io: (3,0):(22272,17897,410702,4375,54750)
// btime 1059401962

#include <time.h> // timezone (global var)
#include <sys/time.h> // gettimeofday
#include <string.h> // strstr etc
#include <stdarg.h> // f(...)
#include <fcntl.h> // O_RDONLY

#define VERSION_STR "0.9"
#define DELIM_CHAR ' '

//==============
#define NL "\n"
typedef unsigned long long ullong;
typedef unsigned long ulong;

typedef ulong sample_t;

//==============
#define proc_file_size 4096

typedef struct proc_file {
    char *name;
    int gen;
    char *file;
} proc_file;

proc_file proc_stat = { "/proc/stat", -1 }; proc_file proc_net_dev = { "/proc/net/dev", -1 }; proc_file proc_meminfo = { "/proc/meminfo", -1 }; proc_file proc_diskstats = { "/proc/diskstats", -1 }; struct timeval tv;
int gen=-1;
int is26=0;

//==============
#if 0
#include <stdio.h>

void dprintf(const char *fmt, ...) {
    va_list ap;
    va_start(ap, fmt);
    vprintf(fmt, ap);
    va_end(ap);
}

#else
extern void dprintf(const char *fmt, ...) {}
#endif

//==============
char outbuf[4096];
char *cur_outbuf = outbuf;
int delta = 1000000;
int deltanz = 1000000;

static inline void reset_outbuf() {
    cur_outbuf = outbuf;
}

static inline int outbuf_count() {
    return cur_outbuf-outbuf;
}

static inline void print_outbuf() {
    if(cur_outbuf>outbuf) {
	write(1, outbuf, cur_outbuf-outbuf);
	cur_outbuf = outbuf;
    }
}

void put(const char *s) {
    int sz = strlen(s);
    if(sz > (outbuf+sizeof(outbuf))-cur_outbuf)
	sz = (outbuf+sizeof(outbuf))-cur_outbuf;
    memcpy(cur_outbuf, s, sz);
    cur_outbuf += sz;
}

void put_c(char c) {
if(cur_outbuf < outbuf+sizeof(outbuf))
*cur_outbuf++ = c;
}

//==============
char* simple_itoa(char *s, int sz, unsigned long v, int pad) { //==============

    s += sz;
    *--s = '\0';
    while (--sz > 0) {
        *--s = "0123456789"[v%10];
        pad--;
        v /= 10;
        if(!v && pad<=0) break;
    }
    return s;
}

//==============
int readfile_z(char *buf, int sz, const char* fname) { //==============

    int fd;
    fd=open(fname,O_RDONLY);
    if(fd<0) return 1;
    sz = read(fd,buf,sz-1);
    close(fd);
    if(sz<0) {
	buf[0]='\0';
	return 1;
    }
    buf[sz]='\0';
    return 0;
}

//==============
int rdval(const char* p, const char* key, sample_t *vec, ...) { //==============

    va_list arg_ptr;
    int indexline;
    int indexnext;

    p = strstr(p,key);
    if(!p) return 1;
	
    p += strlen(key);
    va_start(arg_ptr, vec);
    indexline = 1;
    indexnext = va_arg(arg_ptr, int);
    while(1) {
    	while(*p==' ' || *p=='\t') p++;
	if(*p=='\n' || *p=='\0') break;

        if(indexline == indexnext) { // read this value
            *vec++ = strtoul(p, NULL, 10);
            indexnext = va_arg(arg_ptr, int);
        }
    	while(*p > ' ') p++; // skip over value
        indexline++;
    }
    va_end(arg_ptr);
    return 0;
}

//==============
int rdval_diskstats(const char* p, sample_t *vec) {

//   1    2 3   4     5     6(rd)  7      8     9     10(wr) 11      12 13    14
//   3    0 hda 51292 14441 841783 926052 25717 79650 843256 3029804 0 148459 3956933
//   3    1 hda1 0 0 0 0 <- ignore if only 4 fields
//==============
    sample_t rd;
    int indexline = 0;
    vec[0] = 0;
    vec[1] = 0;
    while(1) {
        indexline++;
        while(*p==' ' || *p=='\t') p++;
        if(*p=='\0') break;
        if(*p=='\n') {
            indexline = 0;
	    p++;
            continue;
        }
        if(indexline == 6) {
            rd = strtoul(p, NULL, 10);
        } else
        if(indexline == 10) {
            vec[0] += rd;  // TODO: *sectorsize (don't know how to find out sectorsize)
            vec[1] += strtoul(p, NULL, 10);
    	    while(*p!='\n' && *p!='\0') p++;
	    continue;
        }
        while(*p > ' ') p++; // skip over value
    }
    return 0;
}

//==============
void scale(sample_t ul) {
//==============

    char buf[5];
    int index = 0;
    ul *= 10;
    if(ul>9999*10) { // do not scale if 9999 or less
	while(ul >= 10000) {
	    ul /= 1024;
	    index++;
	}
    }

    if(!index) {/* use 1234 format */
	buf[0] = " 123456789"[ul/10000];
	if(buf[0]== ' ') buf[1] = " 123456789"[ul/1000%10];
	            else buf[1] = "0123456789"[ul/1000%10];
	if(buf[1]== ' ') buf[2] = " 123456789"[ul/100%10];
                    else buf[2] = "0123456789"[ul/100%10];
	buf[3] = "0123456789"[ul/10%10];
    } else if(ul>=100) { /* use 123k format */
	if( (buf[0]= " 123456789"[ul/1000]) == ' ')
	    buf[1] = " 123456789"[ul/100%10];
	else
	    buf[1] = "0123456789"[ul/100%10];
	buf[2] = "0123456789"[ul/10%10];
	buf[3] = " kMGTEP"[index];
    } else { /* use 1.2M format */
	buf[0] = "0123456789"[ul/10];
	buf[1] = '.';
	buf[2] = "0123456789"[ul%10];
	buf[3] = " kMGTEP"[index];
    }
    buf[4] = 0;
    put(buf);
}

//==============

const char* prepare(proc_file *pf) {
    if(!pf->file) pf->file = (char*)malloc(proc_file_size);
    if(pf->gen != gen) {
	pf->gen = gen;
	readfile_z(pf->file, proc_file_size, pf->name);
    }
    return pf->file;
}

//==============
#define S_STAT(a) \

typedef struct a { \
    struct s_stat *next; \
    int (*collect)(struct a *s); \
    const char *label; \
    int width;

S_STAT(s_stat)
} s_stat;

#define MALLOC_STAT(type,var) type *var = (type*)malloc(sizeof(type))

//==============
// user nice system idle iowait irq softirq (last 3 only in 2.6)
//cpu 649369 0 341297 4336769 11640 7122 1183
//cpuN 649369 0 341297 4336769 11640 7122 1183
#define N 7
S_STAT(cpu_stat)

    sample_t old[N];
    int bar_sz;
    char *bar;
} cpu_stat;

//==============
int collect_cpu(cpu_stat *s) {
//==============

    sample_t data[N] = {0,0,0,0,0,0,0};
    sample_t frac[N] = {0,0,0,0,0,0,0};
    sample_t all = 0;
    int norm_all = 0;
    int bar_sz = s->bar_sz;
    char *bar = s->bar;
    int i;

    if(rdval(prepare(&proc_stat), "cpu ", data, 1, 2, 3, 4, 5, 6 ,7))
	return 1;
    
    put_c('[');

    for(i=0; i<N; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
        s->old[i] = data[i];
        all += (data[i] -= old);
    }

    if(all) {
//dprintf("data2:");
	for(i=0; i<N; i++) {
	    ullong t = bar_sz*(ullong)data[i];
	    norm_all += data[i] = t / all;
	    frac[i] = t % all;
//dprintf(" %lu/%lu",data[i],frac[i]);
	}
//dprintf(" norm_all %lu\n",norm_all);
    
	while(norm_all<bar_sz) {
	    sample_t max=frac[0]; int pos=0;
	    //for(i=1; i<4; i++) if(frac[i]>=max) max=frac[i], pos=i;
	    for(i=1; i<N; i++) {
		if(frac[i]>=max) max=frac[i], pos=i;
	    }
	    frac[pos]=0;	//avoid bumping same value twice
	    data[pos]++;
//dprintf("bumped %i\n",pos);
	    norm_all++;
        }

//dprintf("bar_sz %i\n",bar_sz);
//dprintf("sys %i\n",data[2]);
//dprintf("usr %i\n",data[0]);

//dprintf("nice %i\n",data[1]);
	memset(bar,'.',bar_sz);
	memset(bar,'S',data[2]); bar+=data[2]; //sys
	memset(bar,'U',data[0]); bar+=data[0]; //usr
	memset(bar,'N',data[1]); bar+=data[1]; //nice
	memset(bar,'D',data[4]); bar+=data[4]; //iowait
	memset(bar,'I',data[5]); bar+=data[5]; //irq
	memset(bar,'i',data[6]); bar+=data[6]; //softirq
    } else {
	memset(bar,'?',bar_sz);
    }
    put(s->bar);
    put_c(']');
    return 0;
}

//==============
s_stat* init_cpu(const char *param) {
//==============

    int sz;
    MALLOC_STAT(cpu_stat,s);
    s->collect = collect_cpu;
    s->label = "cpu ";
    s->width = 4;

    sz = strtol(param, NULL, 0);
    if(sz<10) sz=10;
    if(sz>1000) sz=1000;

    s->bar = (char*)malloc(sz+1);
    s->bar[sz]=0;
    s->bar_sz = sz;
    s->width = sz+2;
    return (s_stat*)s;
}

//==============
S_STAT(int_stat)

    sample_t old;
    int no;
    char numlabel[6];
} int_stat;

//==============
int collect_int(int_stat *s) {
//==============

    sample_t data[1];

    if(rdval(prepare(&proc_stat), "intr", data, s->no))
	return 1;

    sample_t old = s->old;
    if(data[0] < old) old = data[0];	//sanitize
    s->old = data[0];
    scale(data[0] - old);
    return 0;
}

//==============
s_stat* init_int(const char *param) {
//==============

    MALLOC_STAT(int_stat,s);
    s->collect = collect_int;
    s->width = 4;
    if(param[0]=='\0') {
	s->no = 1;
	s->label = "int ";
    } else {
	int n = strtoul(param, NULL, 0);
	s->no = n+2;
	s->label = s->numlabel;
	s->numlabel[0]='i';
	s->numlabel[1]='n';
	s->numlabel[2]='t';
	s->numlabel[3]=(n<=9 ? '0'+n : n+('A'-10));
	s->numlabel[4]=' ';
	s->numlabel[5]='\0';
    }
    return (s_stat*)s;
}

//==============
S_STAT(ctx_stat)

    sample_t old;
} ctx_stat;

//==============
int collect_ctx(ctx_stat *s) {
//==============

    sample_t data[1];

    if(rdval(prepare(&proc_stat), "ctxt", data, 1))
	return 1;

    sample_t old = s->old;
    if(data[0] < old) old = data[0];	//sanitize
    s->old = data[0];
    scale(data[0] - old);
    return 0;
}

//==============
s_stat* init_ctx(const char *param) {
//==============

    MALLOC_STAT(ctx_stat,s);
    s->collect = collect_ctx;
    s->label = "ctx ";
    s->width = 4;
    return (s_stat*)s;
}

//==============
S_STAT(blk_stat)

    const char* lookfor;
    sample_t old[2];
} blk_stat;

//==============
int collect_blk24(blk_stat *s) {
//==============

    sample_t data[2];
    int i;
    if(rdval(prepare(&proc_stat), s->lookfor, data, 1, 2))
    	return 1;

    for(i=0; i<2; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
	s->old[i] = data[i];
	data[i] -= old;
    }
    scale(data[0]*1024);
    put_c(' ');
    scale(data[1]*1024);
    return 0;
}

//==============
int collect_blk26(blk_stat *s) {
//==============

    sample_t data[2];
    int i;
    if(rdval_diskstats(prepare(&proc_diskstats), data))
	return 1;

    for(i=0; i<2; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
	s->old[i] = data[i];
	data[i] -= old;
    }
    scale(data[0]*512);
    put_c(' ');
    scale(data[1]*512);
    return 0;
}

//==============
int collect_blk(blk_stat *s) {
//==============

    if(is26) return collect_blk26(s);
    return collect_blk24(s);
}

//==============
s_stat* init_blk(const char *param) {
//==============

    MALLOC_STAT(blk_stat,s);
    s->collect = collect_blk;
//    if(param[0]=='s') {
//	s->label = "sio ";
//	s->lookfor = "swap";
//    } else {
	s->label = "bio ";
	s->lookfor = "page";
//    }
    s->width = 9;
    return (s_stat*)s;
}

//==============
S_STAT(fork_stat)

    sample_t old;
} fork_stat;

//==============
int collect_fork(fork_stat *s) {
//==============

    sample_t data[1];

    if(rdval(prepare(&proc_stat), "processes", data, 1))
	return 1;

    sample_t old = s->old;
    if(data[0] < old) old = data[0];	//sanitize
    s->old = data[0];
    scale(data[0] - old);
    return 0;
}

//==============
s_stat* init_fork(const char *param) {
//==============

    MALLOC_STAT(fork_stat,s);
    s->collect = collect_fork;
    s->label = "fork";  // no trailing space: there usually <1000 forks,
    s->width = 4;       // we trade usual "fork    3" for rare "fork1234"
    return (s_stat*)s;
}

//==============
S_STAT(if_stat)

    sample_t old[4];
    const char *device;
    char *device_colon;
} if_stat;

//==============
int collect_if(if_stat *s) {
//==============

    sample_t data[4];
    int i;

    if(rdval(prepare(&proc_net_dev), s->device_colon, data, 1, 3, 9, 11))
	return 1;

    for(i=0; i<4; i++) {
	sample_t old = s->old[i];
	if(data[i] < old) old = data[i];	//sanitize
        s->old[i] = data[i];
        data[i] -= old;
    }
    put_c(data[1] ? '*' : ' ');
    scale(data[0]);
    put_c(data[3] ? '*' : ' ');
    scale(data[2]);
    return 0;
}

//==============
s_stat* init_if(const char *device) {
//==============

    MALLOC_STAT(if_stat,s);
    s->collect = collect_if;
    s->label = device;
    s->width = 10;
    
    s->device = device;
    s->device_colon = (char*)malloc(strlen(device)+2);
    strcpy(s->device_colon,device);
    strcat(s->device_colon,":");
    return (s_stat*)s;
}

//==============
S_STAT(mem_stat)

    char opt;
} mem_stat;

//==============
int collect_mem(mem_stat *s) {
//==============
// total: used: free: shared: buffers: cached:
//Mem: 29306880 21946368 7360512 0 2101248 11956224
//Swap: 100655104 10207232 90447872
//MemTotal: 28620 kB
//MemFree: 7188 kB
//MemShared: 0 kB <-- ?

//Buffers:          2052 kB
//Cached:           9080 kB
//SwapCached:       2596 kB  <-- ?

    // Not available in 2.6:
    //if(rdval(prepare(&proc_meminfo), "Mem:", data, 1, 2, 5, 6))
    //    return 1;
    sample_t m_total;
    sample_t m_free;
    sample_t m_bufs;
    sample_t m_cached;
    if(rdval(prepare(&proc_meminfo), "MemTotal:", &m_total , 1)) return 1;
    if(rdval(prepare(&proc_meminfo), "MemFree:",  &m_free  , 1)) return 1;
    if(rdval(prepare(&proc_meminfo), "Buffers:",  &m_bufs  , 1)) return 1;
    if(rdval(prepare(&proc_meminfo), "Cached:",   &m_cached, 1)) return 1;
    switch(s->opt) {
    case 'f':
        scale((m_free + m_bufs + m_cached)<<10); break;
    case 't':
        scale(m_total<<10); break;
    default:
        scale((m_total - m_free - m_bufs - m_cached)<<10); break;
    }
    return 0;
}

//==============
s_stat* init_mem(const char *param) {
//==============

    MALLOC_STAT(mem_stat,s);
    s->collect = collect_mem;
    s->width = 4;
    s->opt=param[0];
    switch(param[0]) {
    case 'f':
	s->label = "free "; break;
    case 't':
	s->label = "tot "; break;
    default:
	s->label = "mem "; break;
    }
    return (s_stat*)s;
}

//==============
S_STAT(swp_stat)
} swp_stat;

//==============
int collect_swp(swp_stat *s) {
//==============

    sample_t data[1];
    if(rdval(prepare(&proc_meminfo), "Swap:", data, 2))
	return 1;
	
    scale(data[0]);
    return 0;
}

//==============
s_stat* init_swp(const char *param) {
//==============

    MALLOC_STAT(swp_stat,s);
    s->collect = collect_swp;
    s->label = "swp ";
    s->width = 4;
    return (s_stat*)s;
}

//==============
S_STAT(fd_stat)
} fd_stat;

//==============
int collect_fd(fd_stat *s) {
//==============

    char file[4096];
    sample_t data[2];

    readfile_z(file, sizeof(file), "/proc/sys/fs/file-nr");
    if(rdval(file, "", data, 1, 2))
	return 1;

    scale(data[0]-data[1]);
    return 0;
}

//==============
s_stat* init_fd(const char *param) {
//==============

    MALLOC_STAT(fd_stat,s);
    s->collect = collect_fd;
    s->label = "fd ";
    s->width = 4;
    return (s_stat*)s;
}

//==============
S_STAT(time_stat)

    int prec;
    int scale;
} time_stat;

//==============
int collect_time(time_stat *s) {
//==============

    char buf[16];	// 12:34:56.123456<eol>
			// 1234567890123456
    simple_itoa(buf, 3, tv.tv_sec/(60*60)%24, 2);
    buf[2] = ':';
    simple_itoa(buf+3, 3, tv.tv_sec/60%60, 2);
    buf[5] = ':';
    simple_itoa(buf+6, 3, tv.tv_sec%60, 2);
    
    if(s->prec) {
	buf[8] = '.';
	//simple_itoa(buf+9, s->prec+1, (tv.tv_usec + s->scale/2) / s->scale, s->prec);
	// (fixme: round up seconds too!)
	// so... rounding omitted! just use more prec if you need it! ;)
	simple_itoa(buf+9, s->prec+1, tv.tv_usec / s->scale, s->prec);
    }
    put(buf);
    return 0;
}

//==============
s_stat* init_time(const char *param) {
//==============

    int prec;
    MALLOC_STAT(time_stat,s);
    s->collect = collect_time;
    s->label = "";
    prec = param[0]-'0';
    if(prec<0) prec = 0;
    else if(prec>6) prec = 6;
    s->width = 8+prec + (prec!=0);
    s->prec = prec;
    s->scale = 1;
    while(prec++ < 6)
	s->scale *= 10;
    return (s_stat*)s;
}

//==============
char *header;
//==============
void build_n_put_hdr(s_stat *s) {
//==============

    while(s) {
	int l = 0;
        if(s->label[0]!=' ') {
    	    put(s->label);
	    l = strlen(s->label);
	}
	while(l <= s->width) {
	    put_c(' ');	
	    l++;
	}
        s = s->next;
    }
    put_c('\n');

    header = (char*)malloc(outbuf_count()+1);
    memcpy(header, outbuf, outbuf_count());
    header[outbuf_count()] = '\0';
    //print_outbuf();
}

//==============
void put_hdr(s_stat *s) {
//==============

    if(!header) build_n_put_hdr(s);
    else {
	put(header);
	//print_outbuf();
    }
}

//==============
void run_once(s_stat *s, int without_headers) {
//==============

    gen++;
    int first = 1;
    while(s) {
	if(s->label[0]!=' ') {		// "[prev ][LABEL]data
	    if(!first) put_c(DELIM_CHAR);
    	    if(!without_headers) put(s->label);
	} else {			// "prevLABELdata
	    put(s->label+1);
	}
        if(s->collect(s)) {
	    int w = s->width;
	    while(w-- > 0)
		put_c('?');
	}
        s = s->next;
	first = 0;
    }
}

//==============
typedef s_stat* init_func(const char *param);

const char options[] = "ncmsfixptb";
init_func* init_functions[] = {
init_if,
init_cpu,
init_mem,
init_swp,
init_fd,
init_int,
init_ctx,
init_fork,
init_time,
init_blk,
};

//#include <signal.h>
//static void setup_signals() {
// sigset_t ss;
//

//    sigemptyset(&ss);
//    sigaddset(&ss, SIGPIPE);	
//    sigprocmask(SIG_BLOCK, &ss, NULL);

//}

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

    s_stat *first = 0;
    s_stat *last = 0;
    s_stat *s;
    int print_headers = 0;
    char *final_str = "\n";
    char *p;
    int fd;
    int i;

    //setup_signals();

    { // this incredibly ugly code is used only for timezone brain damage
	time_t tmp=0;
	// used only for a side effect of setting global timezone var:
	localtime(&tmp); 
    }
    
    if(argc==1) {
	put(
	"Nmeter " VERSION_STR " allows you to monitor your system in real time" NL
	NL
	"Options:" NL
	"c[N]	monitor CPU. N - bar size, default 10" NL
	"	(legend: S:system U:user N:niced D:iowait I:irq i:softirq)" NL
	"nIFACE	monitor network interface IFACE" NL
	"m[f/t]	monitor allocated/free/total memory" NL
	"s	monitor allocated swap" NL
	"f	monitor number of used filedescriptors" NL
	"i[NN]	monitor total/specific IRQ rate" NL
	"x	monitor context switch rate" NL
	"p	monitor process creation rate" NL
	"b	monitor block io" NL
	//"b[s]	monitor block io (swap io)" NL
	"t[N]	show time (with N decimal points)" NL
	"d[N]	milliseconds between updates. Default 1000" NL
	"h[N]	print headers above numbers (each N lines, default once)" NL
	"lLABEL	specify label for previous item" NL
	"LLABEL	same + label will be printed without surrounding blanks" NL
	"r	print <cr> instead of <lf> at EOL" NL
	);
	print_outbuf();
	return 0;
    }

    fd = open("/proc/version",O_RDONLY);
    if(fd>=0) {
	char buf[32];
	if(0<read(fd,buf,sizeof(buf)))
	    is26 = (strstr(buf,"Linux version 2.6.")!=NULL);
	close(fd);
    }
    for(i=1; i<argc; i++) {
	p = strchr(options,argv[i][0]);
	if(p) {
	    s = init_functions[p-options](argv[i]+1);
	    if(s) {
		s->next = 0;
		if(!first)
		    first = s;
		else
		    last->next = s;
		last = s;
	    }
	}

// You have to see it... gcc 3.2 coded switch() as 40 element jump table // OH NO! >>>:^O
/*
#define SW(a) switch(a) {
#define ENDSW }
#define CASE(a,b) case (b): {
#define ENDCASE }
*/
#define SW(a) do {
#define ENDSW } while(0);
#define CASE(a,b) if((a)==(b)) {

#define ENDCASE }
	SW(argv[i][0])
	CASE(argv[i][0],'r')
	    final_str = "\r";
	    break;
	ENDCASE
	CASE(argv[i][0],'d')
	    delta = strtol(argv[i]+1, NULL, 0)*1000;
	    deltanz = delta>0? delta : 1;
	    break;
	ENDCASE
	CASE(argv[i][0],'h')
	    if(argv[i][1]=='\0')
		print_headers = -1;
	    else
		print_headers = strtol(argv[i]+1, NULL, 0);
	    break;
	ENDCASE
	CASE(argv[i][0],'l')
	    if(last)
		last->label=argv[i]+1;
	    break;
	ENDCASE
	CASE(argv[i][0],'L')
	    if(last) {
		argv[i][0]=' ';
		last->label=argv[i];
	    }
	    break;
	ENDCASE
	ENDSW
    }
	
    if(print_headers == -1) {
	build_n_put_hdr(first);
	print_outbuf();
    }
    run_once(first, print_headers);
    reset_outbuf();
    if(delta>=0) {
	gettimeofday(&tv,0);
	usleep(delta>1000000 ? 1000000 : delta-tv.tv_usec%deltanz);
    }
    while(1) {
	gettimeofday(&tv,0);
	tv.tv_sec -= timezone;

	if(print_headers > 0 && gen%print_headers == 0)
	    put_hdr(first);
	run_once(first, print_headers);
	put(final_str);
	print_outbuf();

	// Negative delta -> no usleep at all
	// This will hog the CPU but you can have REALLY GOOD
	// time resolution ;)
	// TODO: detect and avoid useless updates
	// (like: nothing happens except time)
        if(delta>=0) {
	    int rem = delta - ((ullong)tv.tv_sec*1000000+tv.tv_usec)%deltanz;
	    // Sometimes kernel wakes us up just a tiny bit earlier than asked
	    // Do not go to very short sleep in this case
	    if(rem < delta/128) {
		rem += delta;
	    }
	    usleep(rem);
	}
    }

    return 0;
}

Yes, it now compiles on gcc-3.4.1 out of the box.

Thanks for this nice little utility.

Cheers.

rncbc aka Rui Nuno Capela
[email protected]

doesn't seem so. V0.2 doesn't fix this for me. This time i got a BUG storm again in syslog (it kinda seems related to starting playback in xmms plus loading pages in mozilla. will boot again to verify):

Oct 25 16:53:42 mango kernel: IRQ#3 thread RT prio: 43.
Oct 25 16:53:52 mango kernel: mozilla-bin/741: BUG in futex_wait at kernel/futex.c:542
Oct 25 16:53:52 mango kernel:  [add_preempt_count+130/224] futex_wait+0x192/0x1a0 (12)
Oct 25 16:53:52 mango kernel:  [zlib_inflate_blocks+1352/3088] __up_write+0x148/0x320 (100)
Oct 25 16:53:52 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (16)
Oct 25 16:53:52 mango kernel:  [__func__.13+351/922] down_write+0xd5/0x250 (8)
Oct 25 16:53:52 mango kernel:  [kthread_create+120/208] check_preempt_timing+0x58/0x290 (8)
Oct 25 16:53:52 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:52 mango kernel:  [__func__.13+351/922] down_write+0xd5/0x250 (4)
Oct 25 16:53:52 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (8)
Oct 25 16:53:52 mango kernel:  [zlib_inflate_blocks+1352/3088] __up_write+0x148/0x320 (8)
Oct 25 16:53:52 mango kernel:  [kthread_create+120/208] check_preempt_timing+0x58/0x290 (8)
Oct 25 16:53:52 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [zlib_inflate_blocks+1352/3088] __up_write+0x148/0x320 (4)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (72)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (32)
Oct 25 16:53:56 mango kernel:  [print_last_trace+247/256] do_futex+0x47/0xa0 (40)
Oct 25 16:53:56 mango kernel:  [get_futex_key+128/448] sys_futex+0xf0/0x100 (40)
Oct 25 16:53:56 mango kernel:  [syscall_fault+35/40] syscall_call+0x7/0xb (68)
Oct 25 16:53:56 mango kernel: preempt count: 00000001
Oct 25 16:53:56 mango kernel: . 1-level deep critical section nesting:
Oct 25 16:53:56 mango kernel: .. entry 1: print_traces+0x1d/0x70 [__kfifo_put+157/208] / (dump_stack+0x23/0x30 [show_registers+3/464])
Oct 25 16:53:56 mango kernel:
Oct 25 16:53:56 mango kernel: kernel/futex.c:542
Oct 25 16:53:56 mango kernel:  [add_preempt_count+130/224] futex_wait+0x192/0x1a0 (12)
Oct 25 16:53:56 mango kernel:  [dequeue_task+24/64] effective_prio+0x8/0x60 (80)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+136/624] recalc_task_prio+0x98/0x190 (8)
Oct 25 16:53:56 mango kernel:  [task_rq_lock+98/112] enqueue_task+0x12/0x50 (24)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+487/624] activate_task+0x67/0x80 (16)
Oct 25 16:53:56 mango kernel:  [__mon_yday+161/268] preempt_schedule+0x11/0x80 (12)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (16)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (8)
Oct 25 16:53:56 mango kernel:  [kthread_create+120/208] check_preempt_timing+0x58/0x290 (8)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (4)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (60)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (12)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (20)
Oct 25 16:53:56 mango kernel:  [print_last_trace+247/256] do_futex+0x47/0xa0 (40)
Oct 25 16:53:56 mango kernel:  [get_futex_key+128/448] sys_futex+0xf0/0x100 (40)
Oct 25 16:53:56 mango kernel:  [syscall_fault+35/40] syscall_call+0x7/0xb (68)
Oct 25 16:53:56 mango kernel: preempt count: 00000001
Oct 25 16:53:56 mango kernel: . 1-level deep critical section nesting:
Oct 25 16:53:56 mango kernel: .. entry 1: print_traces+0x1d/0x70 [__kfifo_put+157/208] / (dump_stack+0x23/0x30 [show_registers+3/464])
Oct 25 16:53:56 mango kernel:
Oct 25 16:53:56 mango kernel: mozilla-bin/741: BUG in futex_wait at kernel/futex.c:542
Oct 25 16:53:56 mango kernel:  [add_preempt_count+130/224] futex_wait+0x192/0x1a0 (12)
Oct 25 16:53:56 mango kernel:  [dequeue_task+24/64] effective_prio+0x8/0x60 (80)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+136/624] recalc_task_prio+0x98/0x190 (8)
Oct 25 16:53:56 mango kernel:  [task_rq_lock+98/112] enqueue_task+0x12/0x50 (24)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+487/624] activate_task+0x67/0x80 (16)
Oct 25 16:53:56 mango kernel:  [__mon_yday+161/268] preempt_schedule+0x11/0x80 (12)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (16)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (8)
Oct 25 16:53:56 mango kernel:  [kthread_create+120/208] check_preempt_timing+0x58/0x290 (8)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (4)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (60)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (12)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (20)
Oct 25 16:53:56 mango kernel:  [print_last_trace+247/256] do_futex+0x47/0xa0 (40)
Oct 25 16:53:56 mango kernel:  [get_futex_key+128/448] sys_futex+0xf0/0x100 (40)
Oct 25 16:53:56 mango kernel:  [syscall_fault+35/40] syscall_call+0x7/0xb (68)
Oct 25 16:53:56 mango kernel: preempt count: 00000001
Oct 25 16:53:56 mango kernel: . 1-level deep critical section nesting:
Oct 25 16:53:56 mango kernel: .. entry 1: print_traces+0x1d/0x70 [__kfifo_put+157/208] / (dump_stack+0x23/0x30 [show_registers+3/464])
Oct 25 16:53:56 mango kernel:
Oct 25 16:53:56 mango kernel: mozilla-bin/741: BUG in futex_wait at kernel/futex.c:542
Oct 25 16:53:56 mango kernel:  [add_preempt_count+130/224] futex_wait+0x192/0x1a0 (12)
Oct 25 16:53:56 mango kernel:  [dequeue_task+24/64] effective_prio+0x8/0x60 (80)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+136/624] recalc_task_prio+0x98/0x190 (8)
Oct 25 16:53:56 mango kernel:  [task_rq_lock+98/112] enqueue_task+0x12/0x50 (24)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+487/624] activate_task+0x67/0x80 (16)
Oct 25 16:53:56 mango kernel:  [__mon_yday+161/268] preempt_schedule+0x11/0x80 (12)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (16)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (8)
Oct 25 16:53:56 mango kernel:  [kthread_create+120/208] check_preempt_timing+0x58/0x290 (8)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (4)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (60)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (12)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (20)
Oct 25 16:53:56 mango kernel:  [print_last_trace+247/256] do_futex+0x47/0xa0 (40)
Oct 25 16:53:56 mango kernel:  [get_futex_key+128/448] sys_futex+0xf0/0x100 (40)
Oct 25 16:53:56 mango kernel:  [syscall_fault+35/40] syscall_call+0x7/0xb (68)
Oct 25 16:53:56 mango kernel: preempt count: 00000001
Oct 25 16:53:56 mango kernel: . 1-level deep critical section nesting:
Oct 25 16:53:56 mango kernel: .. entry 1: print_traces+0x1d/0x70 [__kfifo_put+157/208] / (dump_stack+0x23/0x30 [show_registers+3/464])
Oct 25 16:53:56 mango kernel:
Oct 25 16:53:56 mango kernel: mozilla-bin/741: BUG in futex_wait at kernel/futex.c:542
Oct 25 16:53:56 mango kernel:  [add_preempt_count+130/224] futex_wait+0x192/0x1a0 (12)
Oct 25 16:53:56 mango kernel:  [dequeue_task+24/64] effective_prio+0x8/0x60 (80)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+136/624] recalc_task_prio+0x98/0x190 (8)
Oct 25 16:53:56 mango kernel:  [task_rq_lock+98/112] enqueue_task+0x12/0x50 (24)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+487/624] activate_task+0x67/0x80 (16)
Oct 25 16:53:56 mango kernel:  [__mon_yday+161/268] preempt_schedule+0x11/0x80 (12)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (16)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (8)
Oct 25 16:53:56 mango kernel:  [kthread_create+120/208] check_preempt_timing+0x58/0x290 (8)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (4)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (60)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (12)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (20)
Oct 25 16:53:56 mango kernel:  [print_last_trace+247/256] do_futex+0x47/0xa0 (40)
Oct 25 16:53:56 mango kernel:  [get_futex_key+128/448] sys_futex+0xf0/0x100 (40)
Oct 25 16:53:56 mango kernel:  [syscall_fault+35/40] syscall_call+0x7/0xb (68)
Oct 25 16:53:56 mango kernel: preempt count: 00000001
Oct 25 16:53:56 mango kernel: . 1-level deep critical section nesting:
Oct 25 16:53:56 mango kernel: .. entry 1: print_traces+0x1d/0x70 [__kfifo_put+157/208] / (dump_stack+0x23/0x30 [show_registers+3/464])
Oct 25 16:53:56 mango kernel:
Oct 25 16:53:56 mango kernel: mozilla-bin/741: BUG in futex_wait at kernel/futex.c:542
Oct 25 16:53:56 mango kernel:  [add_preempt_count+130/224] futex_wait+0x192/0x1a0 (12)
Oct 25 16:53:56 mango kernel:  [dequeue_task+24/64] effective_prio+0x8/0x60 (80)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+136/624] recalc_task_prio+0x98/0x190 (8)
Oct 25 16:53:56 mango kernel:  [task_rq_lock+98/112] enqueue_task+0x12/0x50 (24)
Oct 25 16:53:56 mango kernel:  [decay_avgs_and_calculate_rates+487/624] activate_task+0x67/0x80 (16)
Oct 25 16:53:56 mango kernel:  [__mon_yday+161/268] preempt_schedule+0x11/0x80 (12)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (16)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (8)
Oct 25 16:53:56 mango kernel:  [kthread_create+120/208] check_preempt_timing+0x58/0x290 (8)
Oct 25 16:53:56 mango kernel:  [wake_bit_function+5/96] sub_preempt_count+0x65/0xd0 (4)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (4)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (60)
Oct 25 16:53:56 mango kernel:  [__func__.5+7/19] preempt_schedule_irq+0x6f/0xa0 (12)
Oct 25 16:53:56 mango kernel:  [deactivate_task+0/64] default_wake_function+0x0/0x20 (20)
Oct 25 16:53:56 mango kernel:  [print_last_trace+247/256] do_futex+0x47/0xa0 (40)
Oct 25 16:53:56 mango kernel:  [get_futex_key+128/448] sys_futex+0xf0/0x100 (40)
Oct 25 16:53:56 mango kernel:  [syscall_fault+35/40] syscall_call+0x7/0xb (68)
Oct 25 16:53:56 mango kernel: preempt count: 00000001
Oct 25 16:53:56 mango kernel: . 1-level deep critical section nesting:
Oct 25 16:53:56 mango kernel: .. entry 1: print_traces+0x1d/0x70 [__kfifo_put+157/208] / (dump_stack+0x23/0x30 [show_registers+3/464])
Oct 25 16:53:56 mango kernel:

[gazillions more]

flo

Well I have now gotten a couple of these now too (with V0.2). They all seem to be generated by firefox or thunderbird and the traces are all identical except for the offending process.

Oct 25 11:22:11 swdev14 kernel:
Oct 25 11:22:20 swdev14 kernel: thunderbird-bin/3946: BUG in futex_wait at kernel/futex.c:542
Oct 25 11:22:20 swdev14 kernel:  [<c0136389>] futex_wait+0x192/0x19c (12)
Oct 25 11:22:20 swdev14 kernel:  [<c0135646>] sub_preempt_count+0x75/0xd8 (72)
Oct 25 11:22:20 swdev14 kernel:  [<c02aa9f2>] _spin_unlock+0x1a/0x34 (4)
Oct 25 11:22:20 swdev14 kernel:  [<c02aa9f2>] _spin_unlock+0x1a/0x34 (84)
Oct 25 11:22:20 swdev14 kernel:  [<c01120ac>] mcount+0x14/0x18 (4)
Oct 25 11:22:20 swdev14 kernel:  [<c02aa9f2>] _spin_unlock+0x1a/0x34 (20)
Oct 25 11:22:20 swdev14 kernel:  [<c0118e15>] default_wake_function+0x0/0x1c (60)
Oct 25 11:22:20 swdev14 kernel:  [<c0118e15>] default_wake_function+0x0/0x1c (32)
Oct 25 11:22:20 swdev14 kernel:  [<c0136777>] sys_futex+0xf0/0xfc (12)
Oct 25 11:22:20 swdev14 kernel:  [<c01120ac>] mcount+0x14/0x18 (8)
Oct 25 11:22:20 swdev14 kernel:  [<c0136637>] do_futex+0x47/0x97 (20)
Oct 25 11:22:20 swdev14 kernel:  [<c0136777>] sys_futex+0xf0/0xfc (40)
Oct 25 11:22:20 swdev14 kernel:  [<c010623d>] sysenter_past_esp+0x52/0x71 (68)
Oct 25 11:22:20 swdev14 kernel: preempt count: 00000001
Oct 25 11:22:20 swdev14 kernel: . 1-level deep critical section nesting:
Oct 25 11:22:20 swdev14 kernel: .. entry 1: print_traces+0x1d/0x59 [<c0135a28>] / (dump_stack+0x23/0x27 [<c01070db>])
Oct 25 11:22:20 swdev14 kernel:

I see a lot of similar traces too on V0.2 (also either from firefox or thunderbird):

Oct 26 10:20:57 eran kernel: thunderbird-bin/4285: BUG in futex_wait at kernel/futex.c:542
Oct 26 10:20:57 eran kernel:  [<c01338d9>] futex_wait+0x1b9/0x1c0 (8)
Oct 26 10:20:57 eran kernel:  [<c0132b84>] check_preempt_timing+0x64/0x190 (80)
Oct 26 10:20:57 eran kernel:  [<c0132b84>] check_preempt_timing+0x64/0x190 (4)
Oct 26 10:20:57 eran kernel:  [<c01191f7>] recalc_task_prio+0xa7/0x1a0 (12)
Oct 26 10:20:57 eran kernel:  [<c0119785>] finish_task_switch+0x35/0xb0 (8)
Oct 26 10:20:57 eran kernel:  [<c011941a>] try_to_wake_up+0x8a/0xc0 (8)
Oct 26 10:20:57 eran kernel:  [<c01191f7>] recalc_task_prio+0xa7/0x1a0 (12)
Oct 26 10:20:57 eran kernel:  [<c01191f7>] recalc_task_prio+0xa7/0x1a0 (12)
Oct 26 10:20:57 eran kernel:  [<c01191f7>] recalc_task_prio+0xa7/0x1a0 (8)
Oct 26 10:20:57 eran kernel:  [<c0119785>] finish_task_switch+0x35/0xb0 (12)
Oct 26 10:20:57 eran kernel:  [<c01191f7>] recalc_task_prio+0xa7/0x1a0 (20)
Oct 26 10:20:57 eran kernel:  [<c0119785>] finish_task_switch+0x35/0xb0 (12)
Oct 26 10:20:57 eran kernel:  [<c0119e20>] default_wake_function+0x0/0x10 (64)
Oct 26 10:20:57 eran kernel:  [<c0119e20>] default_wake_function+0x0/0x10 (32)
Oct 26 10:20:57 eran kernel:  [<c0108609>] do_IRQ+0x39/0x60 (20)
Oct 26 10:20:57 eran kernel:  [<c0133b55>] do_futex+0x35/0x90 (20)
Oct 26 10:20:57 eran kernel:  [<c022cf3c>] copy_from_user+0x5c/0x90 (8)
Oct 26 10:20:57 eran kernel:  [<c0133c9a>] sys_futex+0xea/0x100 (16)
Oct 26 10:20:57 eran kernel:  [<c01060f9>] sysenter_past_esp+0x52/0x71 (56)
Oct 26 10:20:57 eran kernel: preempt count: 00000001
Oct 26 10:20:57 eran kernel: . 1-level deep critical section nesting:
Oct 26 10:20:57 eran kernel: .. entry 1: print_traces+0xd/0x40 [<c0132f8d>] / (0x0 [<00000000>])

I also get these errors from 'tail -f /var/log/messages':
tail: cannot read realtime clock: Unknown error 516
(it seems to happen at the same time as the above traces, though less often).

Eran Mann
MRV International
Tel: 972-4-9936297
Fax: 972-4-9890430
www.mrv.com

some more:

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

mozilla-bin/753: BUG in futex_wait at kernel/futex.c:542

 [<c0132962>] futex_wait+0x192/0x1a0 (12)
 [<c01ef27b>] __up_write+0x13b/0x320 (84)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (16)
 [<c02b9880>] down_write+0xd0/0x2b0 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c02b9880>] down_write+0xd0/0x2b0 (4)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (8)
 [<c01ef27b>] __up_write+0x13b/0x320 (8)
 [<c0131788>] check_preempt_timing+0x58/0x290 (8)
 [<c0131c55>] sub_preempt_count+0x65/0xd0 (4)
 [<c01ef27b>] __up_write+0x13b/0x320 (4)
 [<c0115f60>] default_wake_function+0x0/0x20 (72)
 [<c0115f60>] default_wake_function+0x0/0x20 (32)
 [<c0132c17>] do_futex+0x47/0xa0 (40)
 [<c0132d60>] sys_futex+0xf0/0x100 (40)
 [<c010617b>] syscall_call+0x7/0xb (68)

preempt count: 00000001
. 1-level deep critical section nesting:
.. entry 1: print_traces+0x17/0x90 [<c0131fc7>] / (dump_stack+0x23/0x30 [<c0106733>])

[snip]

i forgot to mention these were from the same session as the previous one. also i think i missed the first ones, so the reports in this mail are probably useless(?).

flo

i think the futex assert is a separate problem not triggered by the module.c warnings.

Ingo

Actually pertaining to V0.2. I just got my UP system booted up on V0.2 and got this in the log. I did notice that this is not new to this release. It has been here at least since U10.3. Sorry I didn't catch it sooner.

Oct 25 13:31:56 daffy kernel: IRQ#11 thread RT prio: 43.
Oct 25 13:31:56 daffy kernel: ip/2432: BUG in enable_irq at kernel/irq/manage.c:112
Oct 25 13:31:56 daffy kernel:  [<c01396ab>] enable_irq+0xfb/0x100 (12)
Oct 25 13:31:56 daffy kernel:  [<d0975614>] e100_up+0x114/0x200 [e100] (48)
Oct 25 13:31:56 daffy kernel:  [<d0976a20>] e100_open+0x30/0x80 [e100] (48)
Oct 25 13:31:56 daffy kernel:  [<c0113154>] mcount+0x14/0x18 (12)
Oct 25 13:31:56 daffy kernel:  [<c0265d98>] dev_open+0x88/0xa0 (20)
Oct 25 13:31:56 daffy kernel:  [<c02677cd>] dev_change_flags+0x5d/0x140 (28)
Oct 25 13:31:56 daffy kernel:  [<c02653ee>] __dev_get_by_name+0xe/0xd0 (8)
Oct 25 13:31:56 daffy kernel:  [<c02af3d7>] devinet_ioctl+0x277/0x6c0 (28)
Oct 25 13:31:56 daffy kernel:  [<c02b1894>] inet_ioctl+0x64/0xb0 (108)
Oct 25 13:31:56 daffy kernel:  [<c025c048>] sock_ioctl+0xc8/0x250 (28)
Oct 25 13:31:56 daffy kernel:  [<c0171cf7>] sys_ioctl+0xf7/0x260 (32)
Oct 25 13:31:56 daffy kernel:  [<c01064ed>] sysenter_past_esp+0x52/0x71 (48)
Oct 25 13:31:56 daffy kernel: preempt count: 00000002
Oct 25 13:31:56 daffy kernel: . 2-level deep critical section nesting:
Oct 25 13:31:56 daffy kernel: .. entry 1: enable_irq+0x33/0x100 [<c01395e3>] / (e100_up+0x114/0x200 [e100] [<d0975614>])
Oct 25 13:31:56 daffy kernel: .. entry 2: print_traces+0x1d/0x60 [<c0132ecd>] / (dump_stack+0x23/0x30 [<c0106b23>])
Oct 25 13:31:56 daffy kernel:

this is pretty harmless and has been happening in -mm for some time. The e100 device will work fine afterwards.

Ingo

Several things in regard to V0.2:

1) Interactive responsiveness seems to be noticably sluggish at times on all three of the systems I have tested this on.
2) My 450MHz UP system is definitely the worst by far. Scrolling through the syslog in a telnet session produces pauses every few seconds for about a second, that is while it's still responding. These problems seem to be network related, but there are no indications of what the problem is. This system also at times will just stop responding to network requests.
3) Both of the SMP systems are lacking the snappy responsiveness in X that I have become accustomed to with previous patches, but the 2.6GHz Xeon (w/HT) is worse than the 933MHz Xeon. Again no indications of problems in the logs.
4) Using amlat to run the RTC at 1kHz will kill any of these systems very quickly.

kr

yeah, something's seriously buggered in V0.2 - dont bother testing its latencies, the bug hides all the benefits.

Ingo

could you try this with -V0.3 too? I believe most of these problems should be solved.

Ingo

Sure will. It's building on two of the systems now (V0.3.1).

kr

I've repeated the above on the dual 933 Xeon:

Still problems with interactive behavior. Running KDE, with top running in xterm, scrolling through the menus I get some pauses. When the pauses occur I see kdeinit hit the top of the list and sometimes consuming 90% or more of a CPU and idle usage drops to 30-40%. I do see some latency traces (not really high ones) in the log that were generated by kdeinit but I think they were generated prior to when these pauses occurred, most likely when logging in.

Running amlat still hard locks the system. The last time this happened I got this in the log:

 Oct 26 21:43:56 porky kernel: BUG: sleeping function called from 
invalid context amlat(3963) at kernel/mutex.c:28
Oct 26 21:43:56 porky kernel: in_atomic():1 [00000001], irqs_disabled():1
Oct 26 21:43:56 porky kernel:  [<c011c7da>] __might_sleep+0xca/0xe0 (12)
Oct 26 21:43:56 porky kernel:  [<c0137d89>] _mutex_lock+0x39/0x50 (36)
Oct 26 21:43:56 porky kernel:  [<c0137df6>] _mutex_lock_irqsave+0x16/0x20 (24)
Oct 26 21:43:56 porky kernel:  [<c012977d>] __mod_timer+0x4d/0x1f0 (12)
Oct 26 21:43:56 porky kernel:  [<c01f6535>] rtc_do_ioctl+0x185/0x970 (44)
Oct 26 21:43:56 porky kernel:  [<c013838d>] __mcount+0x1d/0x30 (136)
Oct 26 21:43:56 porky kernel:  [<c01f6d2b>] rtc_ioctl+0xb/0x30 (4)
Oct 26 21:43:56 porky kernel:  [<c0179367>] sys_ioctl+0xe7/0x250 (4)
Oct 26 21:43:56 porky kernel:  [<c01131f8>] mcount+0x14/0x18 (8)
Oct 26 21:43:56 porky kernel:  [<c01f6d2b>] rtc_ioctl+0xb/0x30 (20)
Oct 26 21:43:56 porky kernel:  [<c0179367>] sys_ioctl+0xe7/0x250 (20)
Oct 26 21:43:56 porky kernel:  [<c0106739>] sysenter_past_esp+0x52/0x71 (48)
Oct 26 21:43:56 porky kernel: preempt count: 00000002
Oct 26 21:43:56 porky kernel: . 2-level deep critical section nesting:
Oct 26 21:43:56 porky kernel: .. entry 1: _spin_lock_irqsave+0x22/0x80 [<c02c71c2>] / (rtc_do_ioctl+0x158/0x970 [<c01f6508>])
Oct 26 21:43:56 porky kernel: .. entry 2: print_traces+0x1d/0x60 [<c01394bd>] / (dump_stack+0x23/0x30 [<c0107613>])
Oct 26 21:43:56 porky kernel:
Oct 26 21:43:56 porky kernel: BUG: scheduling while atomic: IRQ 8/0x00000001/672
Oct 26 21:43:56 porky kernel: caller is schedule+0x30/0xe0
Oct 26 21:43:57 porky kernel:  [<c02c58c1>] __schedule+0x771/0x7d0 (12)
Oct 26 21:43:57 porky kernel:  [<c02c5950>] schedule+0x30/0xe0 (8)
Oct 26 21:43:57 porky kernel:  [<c013838d>] __mcount+0x1d/0x30 (60)
Oct 26 21:43:57 porky kernel:  [<c02c592e>] schedule+0xe/0xe0 (4)
Oct 26 21:43:57 porky kernel:  [<c02c6c4d>] down_write_mutex+0x12d/0x1e0 (4)
Oct 26 21:43:57 porky kernel:  [<c01131f8>] mcount+0x14/0x18 (8)
Oct 26 21:43:57 porky kernel:  [<c02c5950>] schedule+0x30/0xe0 (20)
Oct 26 21:43:57 porky kernel:  [<c01131f8>] mcount+0x14/0x18 (4)
Oct 26 21:43:57 porky kernel:  [<c02c74ea>] _spin_unlock+0x1a/0x40 (20)
Oct 26 21:43:57 porky kernel:  [<c02c6c4d>] down_write_mutex+0x12d/0x1e0 (12)

Working on booting the 450 right now.

kr

does the quick hack below help?

Ingo

@@ -238,11 +238,11 @@ irqreturn_t rtc_interrupt(int irq, void 
 		rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);
 	}
 
+	spin_unlock (&rtc_lock);
+
 	if (rtc_status & RTC_TIMER_ON)
 		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
 
-	spin_unlock (&rtc_lock);
-
 	/* Now do the rest of the actions */
 	spin_lock(&rtc_task_lock);
 	if (rtc_callback)

@@ -1094,10 +1094,6 @@ static void rtc_dropped_irq(unsigned lon
 		return;
 	}
 
-	/* Just in case someone disabled the timer from behind our back... */
-	if (rtc_status & RTC_TIMER_ON)
-		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
-
 	rtc_irq_data += ((rtc_freq/HZ)<<8);
 	rtc_irq_data &= ~0xff;
 	rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);	/* restart */

@@ -1106,6 +1102,10 @@ static void rtc_dropped_irq(unsigned lon
 
 	spin_unlock_irq(&rtc_lock);
 
+	/* Just in case someone disabled the timer from behind our back... */
+	if (rtc_status & RTC_TIMER_ON)
+		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
+
 	printk(KERN_WARNING "rtc: lost some interrupts at %ldHz.\n", freq);
 
 	/* Now we have new data */

here's a more complete fix.

Ingo

@@ -177,7 +177,7 @@ static unsigned long rtc_max_user_freq =
 /*
  * rtc_task_lock nests inside rtc_lock.
  */
-static DECLARE_SPINLOCK(rtc_task_lock);
+static DECLARE_RAW_SPINLOCK(rtc_task_lock);
 static rtc_task_t *rtc_callback = NULL;
 #endif
 

@@ -238,10 +238,17 @@ irqreturn_t rtc_interrupt(int irq, void 
 		rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);
 	}
 
-	if (rtc_status & RTC_TIMER_ON)
+	if (rtc_status & RTC_TIMER_ON) {
+		spin_unlock (&rtc_lock);
+		/*
+		 * We do the mod_timer outside of the lock because
+		 * it may reschedule under PREEMPT_REALTIME. As long
+		 * as we read the flag race-free it is not a problem
+		 * if two mod_timer()s race:
+		 */
 		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
-
-	spin_unlock (&rtc_lock);
+	} else
+		spin_unlock (&rtc_lock);
 
 	/* Now do the rest of the actions */
 	spin_lock(&rtc_task_lock);

@@ -1094,17 +1101,19 @@ static void rtc_dropped_irq(unsigned lon
 		return;
 	}
 
-	/* Just in case someone disabled the timer from behind our back... */
-	if (rtc_status & RTC_TIMER_ON)
-		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
-
 	rtc_irq_data += ((rtc_freq/HZ)<<8);
 	rtc_irq_data &= ~0xff;
 	rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);	/* restart */
 
 	freq = rtc_freq;
 
-	spin_unlock_irq(&rtc_lock);
+	/* Just in case someone disabled the timer from behind our back... */
+	if (rtc_status & RTC_TIMER_ON) {
+		spin_unlock_irq(&rtc_lock);
+		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
+	} else
+		spin_unlock_irq(&rtc_lock);
+
 
 	printk(KERN_WARNING "rtc: lost some interrupts at %ldHz.\n", freq);
 

third time lucky?

Ingo

@@ -177,7 +177,7 @@ static unsigned long rtc_max_user_freq =
 /*
  * rtc_task_lock nests inside rtc_lock.
  */
-static DECLARE_SPINLOCK(rtc_task_lock);
+static DECLARE_RAW_SPINLOCK(rtc_task_lock);
 static rtc_task_t *rtc_callback = NULL;
 #endif
 

@@ -238,10 +238,17 @@ irqreturn_t rtc_interrupt(int irq, void 
 		rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);
 	}
 
-	if (rtc_status & RTC_TIMER_ON)
+	if (rtc_status & RTC_TIMER_ON) {
+		spin_unlock (&rtc_lock);
+		/*
+		 * We do the mod_timer outside of the lock because
+		 * it may reschedule under PREEMPT_REALTIME. As long
+		 * as we read the flag race-free it is not a problem
+		 * if two mod_timer()s race:
+		 */
 		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
-
-	spin_unlock (&rtc_lock);
+	} else
+		spin_unlock (&rtc_lock);
 
 	/* Now do the rest of the actions */
 	spin_lock(&rtc_task_lock);

@@ -404,8 +411,8 @@ static int rtc_do_ioctl(unsigned int cmd
 		if (rtc_status & RTC_TIMER_ON) {
 			spin_lock_irq (&rtc_lock);
 			rtc_status &= ~RTC_TIMER_ON;
-			del_timer(&rtc_irq_timer);
 			spin_unlock_irq (&rtc_lock);
+			del_timer(&rtc_irq_timer); // FIXME
 		}
 		return 0;
 	}

@@ -730,9 +737,10 @@ static int rtc_release(struct inode *ino
 	}
 	if (rtc_status & RTC_TIMER_ON) {
 		rtc_status &= ~RTC_TIMER_ON;
-		del_timer(&rtc_irq_timer);
-	}
-	spin_unlock_irq(&rtc_lock);
+		spin_unlock_irq(&rtc_lock);
+		del_timer(&rtc_irq_timer); // FIXME
+	} else
+		spin_unlock_irq(&rtc_lock);
 
 	if (file->f_flags & FASYNC) {
 		rtc_fasync (-1, file, 0);

@@ -808,6 +816,7 @@ int rtc_unregister(rtc_task_t *task)
 	return -EIO;
 #else
 	unsigned char tmp;
+	int rm_timer;
 
 	spin_lock_irq(&rtc_lock);
 	spin_lock(&rtc_task_lock);

@@ -827,13 +836,16 @@ int rtc_unregister(rtc_task_t *task)
 		CMOS_WRITE(tmp, RTC_CONTROL);
 		CMOS_READ(RTC_INTR_FLAGS);
 	}
+	rm_timer = 0;
 	if (rtc_status & RTC_TIMER_ON) {
 		rtc_status &= ~RTC_TIMER_ON;
-		del_timer(&rtc_irq_timer);
+		rm_timer = 1;
 	}
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock(&rtc_task_lock);
 	spin_unlock_irq(&rtc_lock);
+	if (rm_timer)
+		del_timer(&rtc_irq_timer);
 	return 0;
 #endif
 }

@@ -1094,17 +1106,19 @@ static void rtc_dropped_irq(unsigned lon
 		return;
 	}
 
-	/* Just in case someone disabled the timer from behind our back... */
-	if (rtc_status & RTC_TIMER_ON)
-		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
-
 	rtc_irq_data += ((rtc_freq/HZ)<<8);
 	rtc_irq_data &= ~0xff;
 	rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);	/* restart */
 
 	freq = rtc_freq;
 
-	spin_unlock_irq(&rtc_lock);
+	/* Just in case someone disabled the timer from behind our back... */
+	if (rtc_status & RTC_TIMER_ON) {
+		spin_unlock_irq(&rtc_lock);
+		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
+	} else
+		spin_unlock_irq(&rtc_lock);
+
 
 	printk(KERN_WARNING "rtc: lost some interrupts at %ldHz.\n", freq);
 

there was one more piece missing...

i've also uploaded -RT-V0.3.2 with this fix included.

Ingo

@@ -177,7 +177,7 @@ static unsigned long rtc_max_user_freq =
 /*
  * rtc_task_lock nests inside rtc_lock.
  */
-static DECLARE_SPINLOCK(rtc_task_lock);
+static DECLARE_RAW_SPINLOCK(rtc_task_lock);
 static rtc_task_t *rtc_callback = NULL;
 #endif
 

@@ -217,6 +217,8 @@ static inline unsigned char rtc_is_updat
 
 irqreturn_t rtc_interrupt(int irq, void *dev_id, struct pt_regs *regs)
 {
+	unsigned long flags;
+
 	/*
 	 *	Can be an alarm interrupt, update complete interrupt,
 	 *	or a periodic interrupt. We store the status in the

@@ -224,7 +226,7 @@ irqreturn_t rtc_interrupt(int irq, void 
 	 *	the last read in the remainder of rtc_irq_data.
 	 */
 
-	spin_lock (&rtc_lock);
+	spin_lock_irqsave(&rtc_lock, flags);
 	rtc_irq_data += 0x100;
 	rtc_irq_data &= ~0xff;
 	if (is_hpet_enabled()) {

@@ -238,16 +240,23 @@ irqreturn_t rtc_interrupt(int irq, void 
 		rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);
 	}
 
-	if (rtc_status & RTC_TIMER_ON)
+	if (rtc_status & RTC_TIMER_ON) {
+		spin_unlock_irqrestore(&rtc_lock, flags);
+		/*
+		 * We do the mod_timer outside of the lock because
+		 * it may reschedule under PREEMPT_REALTIME. As long
+		 * as we read the flag race-free it is not a problem
+		 * if two mod_timer()s race:
+		 */
 		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
-
-	spin_unlock (&rtc_lock);
+	} else
+		spin_unlock_irqrestore(&rtc_lock, flags);
 
 	/* Now do the rest of the actions */
-	spin_lock(&rtc_task_lock);
+	spin_lock_irqsave(&rtc_task_lock, flags);
 	if (rtc_callback)
 		rtc_callback->func(rtc_callback->private_data);
-	spin_unlock(&rtc_task_lock);
+	spin_unlock_irqrestore(&rtc_task_lock, flags);
 	wake_up_interruptible(&rtc_wait);	
 
 	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);

@@ -404,8 +413,8 @@ static int rtc_do_ioctl(unsigned int cmd
 		if (rtc_status & RTC_TIMER_ON) {
 			spin_lock_irq (&rtc_lock);
 			rtc_status &= ~RTC_TIMER_ON;
-			del_timer(&rtc_irq_timer);
 			spin_unlock_irq (&rtc_lock);
+			del_timer(&rtc_irq_timer); // FIXME
 		}
 		return 0;
 	}

@@ -422,10 +431,9 @@ static int rtc_do_ioctl(unsigned int cmd
 
 		if (!(rtc_status & RTC_TIMER_ON)) {
 			spin_lock_irq (&rtc_lock);
-			rtc_irq_timer.expires = jiffies + HZ/rtc_freq + 2*HZ/100;
-			add_timer(&rtc_irq_timer);
 			rtc_status |= RTC_TIMER_ON;
 			spin_unlock_irq (&rtc_lock);
+			mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
 		}
 		set_rtc_irq_bit(RTC_PIE);
 		return 0;

@@ -730,9 +738,10 @@ static int rtc_release(struct inode *ino
 	}
 	if (rtc_status & RTC_TIMER_ON) {
 		rtc_status &= ~RTC_TIMER_ON;
-		del_timer(&rtc_irq_timer);
-	}
-	spin_unlock_irq(&rtc_lock);
+		spin_unlock_irq(&rtc_lock);
+		del_timer(&rtc_irq_timer); // FIXME
+	} else
+		spin_unlock_irq(&rtc_lock);
 
 	if (file->f_flags & FASYNC) {
 		rtc_fasync (-1, file, 0);

@@ -808,6 +817,7 @@ int rtc_unregister(rtc_task_t *task)
 	return -EIO;
 #else
 	unsigned char tmp;
+	int rm_timer;
 
 	spin_lock_irq(&rtc_lock);
 	spin_lock(&rtc_task_lock);

@@ -827,13 +837,16 @@ int rtc_unregister(rtc_task_t *task)
 		CMOS_WRITE(tmp, RTC_CONTROL);
 		CMOS_READ(RTC_INTR_FLAGS);
 	}
+	rm_timer = 0;
 	if (rtc_status & RTC_TIMER_ON) {
 		rtc_status &= ~RTC_TIMER_ON;
-		del_timer(&rtc_irq_timer);
+		rm_timer = 1;
 	}
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock(&rtc_task_lock);
 	spin_unlock_irq(&rtc_lock);
+	if (rm_timer)
+		del_timer(&rtc_irq_timer);
 	return 0;
 #endif
 }

@@ -1094,17 +1107,19 @@ static void rtc_dropped_irq(unsigned lon
 		return;
 	}
 
-	/* Just in case someone disabled the timer from behind our back... */
-	if (rtc_status & RTC_TIMER_ON)
-		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
-
 	rtc_irq_data += ((rtc_freq/HZ)<<8);
 	rtc_irq_data &= ~0xff;
 	rtc_irq_data |= (CMOS_READ(RTC_INTR_FLAGS) & 0xF0);	/* restart */
 
 	freq = rtc_freq;
 
-	spin_unlock_irq(&rtc_lock);
+	/* Just in case someone disabled the timer from behind our back... */
+	if (rtc_status & RTC_TIMER_ON) {
+		spin_unlock_irq(&rtc_lock);
+		mod_timer(&rtc_irq_timer, jiffies + HZ/rtc_freq + 2*HZ/100);
+	} else
+		spin_unlock_irq(&rtc_lock);
+
 
 	printk(KERN_WARNING "rtc: lost some interrupts at %ldHz.\n", freq);
 

note that if you are running amlat/realfeel then you should do something like this after starting realfeel:

chrt -f 99 -p pidof 'IRQ 8'
chrt -f 98 -p pidof realfeel

because by default IRQ 8 has a lower RT priority than realfeel.

Ingo

Hi,

V0.3.2 builds and boots fine here. It seems to run ok, too. Uptime 25 minutes and no BUG's [yay! 25 minutes already! ;)]. Well anyways, preempt_max_thresh is at 38us after running several concurrent find's plus jackd.

There's a problem though with jackd performance. Read on below if it is of any interest at this point.

Soundcard IRQ is 3:

mango:~# cat /proc/interrupts 
           CPU0       
  0:    1331024          XT-PIC  timer  0/31024
  1:       3494          XT-PIC  i8042  0/3494
  2:          0          XT-PIC  cascade  0/0
  3:     781428          XT-PIC  CS46XX  0/81428
  5:       1811          XT-PIC  eth0  0/1811
  8:          4          XT-PIC  rtc  0/4
 12:      71236          XT-PIC  i8042  1/71236
 14:       5163          XT-PIC  ide0  0/5163
 15:      50392          XT-PIC  ide1  0/50392
NMI:          0 
ERR:          0

I set the irq handler thread to prio 99:

mango:~# chrt -p `pidof "IRQ 3"`
pid 118's current scheduling policy: SCHED_FIFO
pid 118's current scheduling priority: 99

jackd runs with a period size of 128 frames (48000hz samplerate) and with SCHED_FIFO with prios from 60 to 70 (ps output is somewhat broken):

mango:~# ps -cmL `pidof jackd`
  PID   LWP CLS PRI TTY      STAT   TIME COMMAND
 1286     - -     - ?        -      0:28 /usr/bin/jackd -R -P60 -t20000 -dalsa -
    -  1286 TS   20 -        SLsl   0:00 -
    -  1287 TS   23 -        SLsl   0:00 -
    -  1288 FF  110 -        SLsl   0:00 -
    -  1289 FF  100 -        SLsl   0:27 -

~$ chrt -p 1286
pid 1286's current scheduling policy: SCHED_OTHER
pid 1286's current scheduling priority: 0
~$ chrt -p 1287
pid 1287's current scheduling policy: SCHED_OTHER
pid 1287's current scheduling priority: 0
~$ chrt -p 1288
pid 1288's current scheduling policy: SCHED_FIFO
pid 1288's current scheduling priority: 70
~$ chrt -p 1289
pid 1289's current scheduling policy: SCHED_FIFO
pid 1289's current scheduling priority: 60

Anyways i get xruns like crazy under load (like 200 in 10 minutes). It seems the scheduling class and high priority don't matter really as wiggling windows around on the screen or doing a "find /" can easily provoke xruns.

flo

just curious, are these two important to the latency path of jackd, or are they lowprio things and are thus at SCHED_OTHER intentionally?

yeah, i'm hunting a quite similar bug: i can see 'realfeel' latencies generated by simple window scrolling. It is most likely a logic bug somewhere - a missing reschedule check, irqs left disabled accidentally, or something like that. Since some other workloads dont trigger it i dont think i broke RT scheduling by itself - it is most likely some non-core code somewhere missing a resched. Which doesnt make it less of a problem, but it makes it harder to find :-|

Ingo

the latter. jackd has one RT thread for doing the grunt work and one which acts as a watchdog. The other two are SCHED_OTHER by design.

Hmm, you're right. It seems that diskload alone doesn't trigger the problem. it rather looks like graphics output/activity is the problem.

Anyways i'm back in U3 w/o PREEMPT_REALTIME as V0.3.2 just hardlocked on me when i pressed ctrl-d in a root shell (in an xterm) to exit. Nothing has made it to the log. I haven't found out yet whether it's possible to use my old zx81 as serial console, so i can't help with OOPS/BUG output.

flo

[snip]

anyways, i still see the mysterious pauses which do not show up in the preempt_max_thresh.

ah, and btw: what does the /proc/sys/kernel/kernel_preemption tunable do with PREEMPT_REALTIME enabled?

mango:~# cat /proc/sys/kernel/kernel_preemption 
1

[all the other VP tunables are not available anymore]

mango:~# cat /proc/sys/kernel/voluntary_preemption
cat: /proc/sys/kernel/voluntary_preemption: No such file or directory
mango:~# cat /proc/sys/kernel/hardirq_preemption
cat: /proc/sys/kernel/hardirq_preemption: No such file or directory
mango:~# cat /proc/sys/kernel/softirq_preemption
cat: /proc/sys/kernel/softirq_preemption: No such file or directory

flo

it's pretty pointless to offer this tunable, agreed. In theory one could try to turn off involuntary preemption but what's the point?

right - the PREEMPT_REALTIME kernel is only correct if all asynchronous processing is done in a process context, so i removed those tunables.

Ingo

is this 90% or more CPU time system (kernel) overhead or userspace overhead?

Ingo

another thing to watch for is the context-switch rate in vmstat. -V0.3 patches include a hack that include involuntary context-switches (mutex context switches) in the context-switch stat as well. (previously those were reported in a separate field which vmstat didnt pick up.)

So if the context-switch rate shots up to above say 100K/sec that is a sure sign of some mutex badness. The livelock scenarios i solved in -V0.3 occasionally generated a more than 500K/sec context-switch rate on a 2GHz box. Having just a couple of thousand per sec isnt by itself a sign of anything unusual.

Ingo

It appears that most of the time is being consumed in system (~50% vs. ~6%).

As for the context-switch, I do see this jump up to ~10-11K/sec from ~4-5K/sec and I see this only when I trigger the pauses.

kr

btw., to get good 'realfeel' results i had to apply the attached patch. Especially when running realfeel over the network it can easily happen that it's delayed for some time and gets out of sync with the RTC. So after a new maximum latency has triggered the code now waits 10 periods to wait for the timings to recover.

this does not hurt the latency measurements in any way - latencies that occur after these 10 ticks (~5 msecs) are over are still fully measured and reported.

amlat produces weird output for me, continuously increasing latency values:

latency = 2967939 milliseconds
latency = 2967950 milliseconds
sigint
max jitter = 0 microseconds

maybe some /dev/rtc API detail changed? Or is this the normal output?

Ingo

@@ -91,7 +91,7 @@ int set_realtime_priority(void)
 	 * set the process to realtime privs
 	 */
 	memset(&schp, 0, sizeof(schp));
-	schp.sched_priority = sched_get_priority_max(SCHED_FIFO);
+	schp.sched_priority = sched_get_priority_max(SCHED_FIFO) - 1;
 	
 	if (sched_setscheduler(0, SCHED_FIFO, &schp) != 0) {
 		perror("sched_setscheduler");

@@ -191,8 +191,19 @@ int main(int argc, char *argv[])
 		now = rdtsc();
 		delay = secondsPerTick * (now - last);
 		if (delay > max_delay) {
+			int i;
+
 			max_delay = delay;
 			printf("%.3f msec\n", 1e3 * (ideal - delay));
+			/*
+			 * To make sure that the delay due to the printf
+			 * is not counted we skip the next period:
+			 */
+			for (i = 0; i < 10; i++)
+				if (read(fd, &data, sizeof(data)) == -1)
+					fatal("blocking read failed");
+			last = rdtsc();
+			continue;
 		}
 		ms = (-(ideal - delay) + 1.0/20000.0) * 10000;
 		if (ms < 0)

Well to produce useful results, amlat requires Andrew's rtc-debug patch that modifies the rtc driver as well as traps so that timings are kept when the isr gets run and when the rtc device is read to track scheduling latencies. Also if this patch was applied the value being read by amlat from the rtc device would be the last interrupt time instead of the interrupt info that rtc normally produces. So the latency values being spit out are bogus, but it's good enough to exercise the rtc.

I use the rtc-debug and amlat to generate histograms of latencies which is what I was trying to do when I found the rtc problem the first time. I believe that rtc-debug/amlat is much more accurate for generating histograms of latencies than realfeel is because the instrumentation is in the kernel rather than a userspace program.

kr

ah, ok - nice. So rtc-debug+amlat is the only known-reliable way to produce latency histograms?

Btw., rtc-debug's latency results could now be cross-validated with -V0.4's wakeup tracer (and vice versa), because the two are totally independent mechanisms.

Ingo

Don't know that for sure, but it is the most reliable way that I am aware of.

Agreed. :)

kr

Yes, I think it is the most reliable way because the measurement is done in the kernel. At least, this is what AM's notes say. There are any number of ways to generate these with userspace programs (jackd, realfeel, etc).

Here is a more up to date version of the rtc-debug patch:

http://lkml.org/lkml/2004/9/9/307

There is still a bit of 2.4 cruft in there but it works well. Maybe this could be included in future patches.

Lee

the most natural point of inclusion would be Andrew's -mm tree i think :-)

Ingo

Well I suspect from looking at the comments :-) that he would not include it in its current form due to the way it just checks whether the process opening the RTC is called "amlat" and updates the RTC histogram if so. I am not sure what a clean way to do this would be, maybe an ioctl()?

Anyway I am generating a cleaned up version of the patch agaqinst 2.6.9-mm1.

Lee

Actually if you are cleaning it up anyway, could you fix it to work with Ingo's changes to rtc.c? If not I will be glad to do it. Up until one of the last couple of versions of RT PREEMPT it applied cleanly, but I just tried it and it failed.

kr

Yup, here it is against 2.6.9-mm1-V0.4.1. Not yet tested (building now) but should work. I took out the show_trace_smp part because that never worked, I always get "Stack pointer is garbage". So now the patch is smaller and only touches rtc.c.

@@ -86,6 +86,18 @@
 #include <asm/hpet.h>
 #endif
 
+static unsigned long long last_interrupt_time;
+
+#include <asm/timex.h>
+
+
+#define CPU_MHZ	(cpu_khz / 1000)
+#define HISTSIZE	10000
+static int histogram[HISTSIZE];
+
+int rtc_debug;
+int rtc_running;
+
 #ifdef __sparc__
 #include <linux/pci.h>
 #include <asm/ebus.h>

@@ -191,6 +203,14 @@
 static const unsigned char days_in_mo[] = 
 {0, 31, 28, 31, 30, 31, 30, 31, 31, 30, 31, 30, 31};
 
+static int rtc_state;
+
+enum rtc_states {
+	S_IDLE,			/* Waiting for an interrupt */
+	S_WAITING_FOR_READ,	/* Signal delivered. waiting for rtc_read() */
+	S_READ_MISSED,		/* Signal delivered, read() deadline missed */
+};
+
 /*
  * Returns true if a clock update is in progress
  */

@@ -259,7 +279,36 @@
 	spin_unlock_irqrestore(&rtc_task_lock, flags);
 	wake_up_interruptible(&rtc_wait);	
 
-	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+	if (!(rtc_status & RTC_IS_OPEN))
+		goto tata;
+
+	switch (rtc_state) {
+	case S_IDLE:			/* Waiting for an interrupt */
+		rdtscll(last_interrupt_time);
+		kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+		rtc_state = S_WAITING_FOR_READ;
+		break;
+	case S_WAITING_FOR_READ:	/* Signal has been delivered. waiting for rtc_read() */
+		/*
+		 * Well foo.  The usermode application didn't schedule and read in time.
+		 */
+		rtc_state = S_READ_MISSED;
+		if (strcmp(current->comm, "amlat") != 0) {
+			printk("`%s'[%d] is being piggy.  "
+					"need_resched=%d, cpu=%d\n",
+				current->comm, current->pid,
+				need_resched(), smp_processor_id());
+			/* show_trace_smp(); */
+		}
+		break;
+	case S_READ_MISSED:		/* Signal has been delivered, read() deadline was missed */
+		/*
+		 * Not much we can do here.  We're waiting for the usermode
+		 * application to read the rtc
+		 */
+		break;
+	}
+tata:
 
 	return IRQ_HANDLED;
 }

@@ -319,8 +368,74 @@
  *	Now all the various file operations that we export.
  */
 
-static ssize_t rtc_read(struct file *file, char __user *buf,
-			size_t count, loff_t *ppos)
+static ssize_t ll_rtc_read(struct file *file, char *buf,
+				size_t count, loff_t *ppos)
+{
+	ssize_t retval;
+	unsigned long long now;
+
+	rdtscll(now);
+
+	switch (rtc_state) {
+	case S_IDLE:			/* Waiting for an interrupt */
+		/*
+		 * err...  This can't be happening
+		 */
+		printk("ll_rtc_read(): called in state S_IDLE!\n");
+		break;
+	case S_WAITING_FOR_READ:	/*
+					 * Signal has been delivered.
+					 * waiting for rtc_read()
+					 */
+		/*
+		 * Well done
+		 */
+	case S_READ_MISSED:		/*
+					 * Signal has been delivered, read()
+					 * deadline was missed
+					 */
+		/*
+		 * So, you finally got here.
+		 */
+		if (last_interrupt_time == 0)
+			printk("ll_rtc_read(): we screwed up.  "
+					"last_interrupt_time = 0\n");
+		rtc_state = S_IDLE;
+		{
+			unsigned long long latency = now - last_interrupt_time;
+			unsigned long delta;	/* Nocroseconds */
+
+			delta = latency;
+			delta /= CPU_MHZ;
+			if (delta > 1000 * 1000) {
+				printk("rtc: eek\n");
+			} else {
+				unsigned long slot = delta;
+				if (slot >= HISTSIZE)
+					slot = HISTSIZE - 1;
+				histogram[slot]++;
+				if (delta > 2000)
+					printk("wow!  That was a "
+							"%ld millisec bump\n",
+						delta / 1000);
+			}
+		}
+		rtc_state = S_IDLE;
+		break;
+	}
+
+	if (count < sizeof(last_interrupt_time))
+		return -EINVAL;
+
+	retval = -EIO;
+	if (copy_to_user(buf, &last_interrupt_time,
+				sizeof(last_interrupt_time)) == 0)
+		retval = sizeof(last_interrupt_time);
+	return retval;
+}
+
+static ssize_t orig_rtc_read(struct file *file, char *buf,
+  			size_t count, loff_t *ppos)
 {
 #ifndef RTC_IRQ
 	return -EIO;

@@ -375,6 +490,19 @@
 #endif
 }
 
+/*
+ * If anyone reads this, please send me an email describing
+ * the superlative elegance of this conception
+ */
+static ssize_t rtc_read(struct file *file, char *buf,
+			size_t count, loff_t *ppos)
+{
+	if (strcmp(current->comm, "amlat") == 0)
+		return ll_rtc_read(file, buf, count, ppos);
+	else
+		return orig_rtc_read(file, buf, count, ppos);
+}
+
 static int rtc_do_ioctl(unsigned int cmd, unsigned long arg, int kernel)
 {
 	struct rtc_time wtime; 

@@ -692,6 +820,8 @@
  * needed here. Or anywhere else in this driver. */
 static int rtc_open(struct inode *inode, struct file *file)
 {
+	int i;
+
 	spin_lock_irq (&rtc_lock);
 
 	if(rtc_status & RTC_IS_OPEN)

@@ -699,7 +829,16 @@
 
 	rtc_status |= RTC_IS_OPEN;
 
-	rtc_irq_data = 0;
+	if (strcmp(current->comm, "amlat") == 0) {
+		last_interrupt_time = 0;
+		rtc_state = S_IDLE;
+		rtc_irq_data = 0;
+	}
+
+	rtc_running = 1;
+	for (i = 0; i < HISTSIZE; i++)
+		histogram[i] = 0;
+
 	spin_unlock_irq (&rtc_lock);
 	return 0;
 

@@ -753,6 +892,19 @@
 	rtc_irq_data = 0;
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock_irq (&rtc_lock);
+	{
+		int i = 0;
+		unsigned long total = 0;
+		printk("rtc histogram:\n");
+		for (i = 0; i < HISTSIZE; i++) {
+			if (histogram[i]) {
+				total += histogram[i];
+				printk("%d %d\n", i, histogram[i]);
+			}
+		}
+		printk("\nTotal samples: %lu\n", total);
+		rtc_running = 0;
+	}
 	return 0;
 }
 

@@ -1127,6 +1279,7 @@
 	wake_up_interruptible(&rtc_wait);
 
 	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+	return;
 }
 #endif
 

OH! And thanks. :)

kr

Well I tried it and it does not seem to work exactly right. This might be because I enabled the HPET so the RTC is not getting used. When I run amlat for a few minutes I get a histogram with only 38 samples. Does this work for you?

Lee