[patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Ingo Molnar]

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

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Alexander Batyrshin]

   Hi Ingo,
U9.3 (defconfig) died with trace:

------------[ cut here ]------------
kernel BUG at kernel/sched.c:784!
invalid operand: 0000 [#1]
PREEMPT SMP
Modules linked in:
CPU:    0
EIP:    0060:[<c011873d>]    Not tainted VLI
EFLAGS: 00010002   (2.6.9-rc4-mm1-RT-U9.3)
EIP is at resched_task+0x80/0x8a
eax: 00000001   ebx: c1674000   ecx: dfb578f0   edx: 00000000
esi: c16712c0   edi: 00000000   ebp: c167bc48   esp: c167bc3c
ds: 007b   es: 007b   ss: 0068   preempt: 00000003
Process ksoftirqd/0 (pid: 3, threadinfo=c167a000 task=c1670660)
Stack: c1403820 c1403820 00000000 c167bc94 c0118b78 c16712c0 c1433820 
00000000
        00000000 00000000 00000001 00000100 c1433820 c1433820 00000001 
00000000
        00000000 00000001 00000082 00000001 de9d3e60 00000001 c167bcd8 
c0133c7b
Call Trace:
  [<c0118b78>] try_to_wake_up+0x1f3/0x26b (20)
  [<c0133c7b>] autoremove_wake_function+0x2f/0x57 (76)
  [<c011a766>] __wake_up_common+0x3f/0x5e (28)
  [<c011a7d0>] __wake_up+0x4b/0x62 (40)
  [<c034e08c>] sock_def_readable+0x8e/0x90 (52)
  [<c0388dbe>] tcp_child_process+0xe6/0xec (28)
  [<c0384df7>] tcp_v4_do_rcv+0x123/0x162 (36)
  [<c0134079>] _mutex_lock+0x2c/0x3b (16)
  [<c0385513>] tcp_v4_rcv+0x6dd/0x92c (16)
  [<c03c0e30>] svc_revisit+0x27/0x154 (48)
  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (40)
  [<c0368609>] ip_local_deliver_finish+0xb6/0x1b2 (4)
  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (12)
  [<c035f607>] nf_hook_slow+0xdc/0x12e (20)
  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (28)
  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (28)
  [<c0367fcb>] ip_local_deliver+0x208/0x226 (4)
  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (24)
  [<c0368828>] ip_rcv_finish+0x123/0x2b3 (20)
  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (32)
  [<c035f607>] nf_hook_slow+0xdc/0x12e (20)
  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (28)
  [<c036846a>] ip_rcv+0x481/0x56a (32)
  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (24)
  [<c0354e68>] netif_receive_skb+0x117/0x1dd (28)
  [<c0354ff7>] process_backlog+0xc9/0x1cb (36)
  [<c03551b2>] net_rx_action+0xb9/0x1ed (48)
  [<c01242d9>] ___do_softirq+0xe1/0x130 (36)
  [<c0124923>] ksoftirqd+0x0/0xda (40)
  [<c01243fb>] _do_softirq+0x4b/0x4d (4)
  [<c01249c5>] ksoftirqd+0xa2/0xda (16)
  [<c013376d>] kthread+0xb7/0xbd (24)
  [<c01336b6>] kthread+0x0/0xbd (28)
  [<c0103375>] kernel_thread_helper+0x5/0xb (16)
preempt count: 00000004
. 4-level deep critical section nesting:
.. entry 1: _spin_lock_irqsave+0x1d/0xa5 [<00000000>] / (0x0 [<00000000>])
.. entry 2: _spin_lock+0x19/0x6d [<00000000>] / (0x0 [<00000000>])
.. entry 3: _spin_lock_irqsave+0x1d/0xa5 [<00000000>] / (0x0 [<00000000>])
.. entry 4: print_traces+0x17/0x4e [<00000000>] / (0x0 [<00000000>])

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Mark_H_Johnson]

>i have released the -U9.3 Real-Time Preemption patch, ...
>
It is getting hard to keep up with the updates....

This version built OK and since I noticed it includes fixes for the
parallel port, I added that back to my configuration and built / booted
without any problems. I still see the BUG from:

Oct 22 12:27:50 dws77 kernel: 8139too Fast Ethernet driver 0.9.27
Oct 22 12:27:50 dws77 kernel: eth0: RealTek RTL8139 at 0xdc00,
00:50:bf:39:11:fc, IRQ 11
Oct 22 12:27:50 dws77 kernel: BUG: atomic counter underflow at:
Oct 22 12:27:50 dws77 kernel:  [<c02b8f88>] qdisc_destroy+0x98/0xa0 (12)

I saw the messages about fixes for the other network drivers, but
don't forget this one.

Real time stress tests ran more smoothly this time with fewer
odd symptoms but a few new symptoms showed up too. I'll send the
boot log and traces separately. The following summarizes the tests
and results.

[1] X11 stress - very clean, max CPU delay was only 20 usec.

[2] proc stress - very clean, max CPU delay was only 30 usec.

[3] network output stress - only trace much worse than U9.2. An odd
pattern in the graph showing a delay of roughly 400 usec every 5
seconds with a much smaller delay following. There were also a couple
bursts of delays at 90-100 seconds, and 250-260 seconds. Did not
see this pattern on any other test.

[4] network input stress - very clean, max CPU delay was only 80 usec.

[5] disk write stress - very clean, max CPU delay only 70 usec.

[6] disk copy stress - very clean, max CPU delay only 90 usec.

[7] disk read stress - first 25 seconds, had a pattern of roughly 100 usec
CPU delays with a few peaks at 500 usec. After that, was very clean, almost
99.7% of the CPU delays were under 100 usec.

During these tests (total 25-30 minutes) had seven latency traces
over >200 usec. Summary follows:

00 - find_symbol, a single trace line over 400 usec as follows
preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U9.3
-------------------------------------------------------
 latency: 495 us, entries: 9 (9)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: modprobe/3643, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x1f/0x80 <c0314f4f>
 => ended at:   _spin_unlock_irq+0x1b/0x40 <c031538b>
=======>
00000001 0.000ms (+0.000ms): _spin_lock_irqsave (resolve_symbol)
00000001 0.000ms (+0.447ms): __find_symbol (resolve_symbol)
00010001 0.448ms (+0.000ms): do_nmi (__find_symbol)
00010001 0.448ms (+0.000ms): do_nmi (add_preempt_count)
00010001 0.449ms (+0.042ms): do_nmi (<00200093>)
00000001 0.491ms (+0.000ms): use_module (resolve_symbol)
00000001 0.492ms (+0.001ms): already_uses (use_module)
00000001 0.493ms (+0.000ms): kmem_cache_alloc (use_module)
00000001 0.494ms (+0.000ms): _spin_unlock_irq (resolve_symbol)

01, 02, 03, 05, 06 - flush_tlb
 latency: 1815 us, entries: 108 (108)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
 latency: 8959 us, entries: 180 (180)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
 latency: 175300 us, entries: 4000 (8116)   |   [VP:1 KP:1 SP:1 HP:1
#CPUS:2]
 latency: 80679 us, entries: 1545 (1545)   |   [VP:1 KP:1 SP:1 HP:1
#CPUS:2]
 latency: 76801 us, entries: 3561 (3561)   |   [VP:1 KP:1 SP:1 HP:1
#CPUS:2]

This is that symptom I reported before where something gets "stuck"
and one or more clock ticks later, it finally gets freed up. Note that
the real time application did not see any of these delays. It may
be interesting to do another test w/ two real time tasks to see if
these are real or a sampling artifact.

04 - avc_insert, a single > 200 usec trace entry.

preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U9.3
-------------------------------------------------------
 latency: 216 us, entries: 4 (4)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: fam/2933, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x1f/0x80 <c0314f4f>
 => ended at:   _spin_unlock_irqrestore+0x20/0x50 <c0315340>
=======>
00000001 0.000ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
00000001 0.000ms (+0.214ms): avc_insert (avc_has_perm_noaudit)
00000001 0.214ms (+0.000ms): memcpy (avc_has_perm_noaudit)
00000001 0.215ms (+0.000ms): _spin_unlock_irqrestore (avc_has_perm_noaudit)

  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[K.R. Foley]

Mark_H_Johnson@raytheon.com wrote:
>>i have released the -U9.3 Real-Time Preemption patch, ...
>>
> 
> It is getting hard to keep up with the updates....
> 
> This version built OK and since I noticed it includes fixes for the
> parallel port, I added that back to my configuration and built / booted
> without any problems. I still see the BUG from:
> 
> Oct 22 12:27:50 dws77 kernel: 8139too Fast Ethernet driver 0.9.27
> Oct 22 12:27:50 dws77 kernel: eth0: RealTek RTL8139 at 0xdc00,
> 00:50:bf:39:11:fc, IRQ 11
> Oct 22 12:27:50 dws77 kernel: BUG: atomic counter underflow at:
> Oct 22 12:27:50 dws77 kernel:  [<c02b8f88>] qdisc_destroy+0x98/0xa0 (12)
> 
> I saw the messages about fixes for the other network drivers, but
> don't forget this one.

I still get this also. This is not fixed by the network driver fix, but 
I don't think it was expected to be.

> 
> Real time stress tests ran more smoothly this time with fewer
> odd symptoms but a few new symptoms showed up too. I'll send the
> boot log and traces separately. The following summarizes the tests
> and results.
> 
> [1] X11 stress - very clean, max CPU delay was only 20 usec.
> 
> [2] proc stress - very clean, max CPU delay was only 30 usec.
> 
> [3] network output stress - only trace much worse than U9.2. An odd
> pattern in the graph showing a delay of roughly 400 usec every 5
> seconds with a much smaller delay following. There were also a couple
> bursts of delays at 90-100 seconds, and 250-260 seconds. Did not
> see this pattern on any other test.
> 
> [4] network input stress - very clean, max CPU delay was only 80 usec.
> 
> [5] disk write stress - very clean, max CPU delay only 70 usec.
> 
> [6] disk copy stress - very clean, max CPU delay only 90 usec.
> 
> [7] disk read stress - first 25 seconds, had a pattern of roughly 100 usec
> CPU delays with a few peaks at 500 usec. After that, was very clean, almost
> 99.7% of the CPU delays were under 100 usec.
> 
> During these tests (total 25-30 minutes) had seven latency traces
> over >200 usec. Summary follows:
> 
> 00 - find_symbol, a single trace line over 400 usec as follows
> preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U9.3
> -------------------------------------------------------
>  latency: 495 us, entries: 9 (9)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
>     -----------------
>     | task: modprobe/3643, uid:0 nice:-10 policy:0 rt_prio:0
>     -----------------
>  => started at: _spin_lock_irqsave+0x1f/0x80 <c0314f4f>
>  => ended at:   _spin_unlock_irq+0x1b/0x40 <c031538b>
> =======>
> 00000001 0.000ms (+0.000ms): _spin_lock_irqsave (resolve_symbol)
> 00000001 0.000ms (+0.447ms): __find_symbol (resolve_symbol)
> 00010001 0.448ms (+0.000ms): do_nmi (__find_symbol)
> 00010001 0.448ms (+0.000ms): do_nmi (add_preempt_count)
> 00010001 0.449ms (+0.042ms): do_nmi (<00200093>)
> 00000001 0.491ms (+0.000ms): use_module (resolve_symbol)
> 00000001 0.492ms (+0.001ms): already_uses (use_module)
> 00000001 0.493ms (+0.000ms): kmem_cache_alloc (use_module)
> 00000001 0.494ms (+0.000ms): _spin_unlock_irq (resolve_symbol)
> 
> 01, 02, 03, 05, 06 - flush_tlb
>  latency: 1815 us, entries: 108 (108)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
>  latency: 8959 us, entries: 180 (180)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
>  latency: 175300 us, entries: 4000 (8116)   |   [VP:1 KP:1 SP:1 HP:1
> #CPUS:2]
>  latency: 80679 us, entries: 1545 (1545)   |   [VP:1 KP:1 SP:1 HP:1
> #CPUS:2]
>  latency: 76801 us, entries: 3561 (3561)   |   [VP:1 KP:1 SP:1 HP:1
> #CPUS:2]
> 
> This is that symptom I reported before where something gets "stuck"
> and one or more clock ticks later, it finally gets freed up. Note that
> the real time application did not see any of these delays. It may
> be interesting to do another test w/ two real time tasks to see if
> these are real or a sampling artifact.
> 
> 04 - avc_insert, a single > 200 usec trace entry.
> 
> preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U9.3
> -------------------------------------------------------
>  latency: 216 us, entries: 4 (4)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
>     -----------------
>     | task: fam/2933, uid:0 nice:0 policy:0 rt_prio:0
>     -----------------
>  => started at: _spin_lock_irqsave+0x1f/0x80 <c0314f4f>
>  => ended at:   _spin_unlock_irqrestore+0x20/0x50 <c0315340>
> =======>
> 00000001 0.000ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
> 00000001 0.000ms (+0.214ms): avc_insert (avc_has_perm_noaudit)
> 00000001 0.214ms (+0.000ms): memcpy (avc_has_perm_noaudit)
> 00000001 0.215ms (+0.000ms): _spin_unlock_irqrestore (avc_has_perm_noaudit)
> 
>   --Mark
> 
> 

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Thomas Gleixner]

On Fri, 2004-10-22 at 13:49 -0500, K.R. Foley wrote:
> Mark_H_Johnson@raytheon.com wrote:
> >>i have released the -U9.3 Real-Time Preemption patch, ...
> >>
> > 
> > It is getting hard to keep up with the updates....
> > 
> > This version built OK and since I noticed it includes fixes for the
> > parallel port, I added that back to my configuration and built / booted
> > without any problems. I still see the BUG from:
> > 
> > Oct 22 12:27:50 dws77 kernel: 8139too Fast Ethernet driver 0.9.27
> > Oct 22 12:27:50 dws77 kernel: eth0: RealTek RTL8139 at 0xdc00,
> > 00:50:bf:39:11:fc, IRQ 11
> > Oct 22 12:27:50 dws77 kernel: BUG: atomic counter underflow at:
> > Oct 22 12:27:50 dws77 kernel:  [<c02b8f88>] qdisc_destroy+0x98/0xa0 (12)
> > 
> > I saw the messages about fixes for the other network drivers, but
> > don't forget this one.
> 
> I still get this also. This is not fixed by the network driver fix, but 
> I don't think it was expected to be.

No, the fix was for the missing pci shutdown in tulip.

This one is something weird, which has to do with kuzdu triggered
load,unload,reload of a module. Not sure what happens there. I would
need more detailed information. Maybe enabling some debug print of the
card driver would reviel whats going on.

tglx

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Mark_H_Johnson]

>No, the fix was for the missing pci shutdown in tulip.
I thought the two were related (since I get the failed to shutdown
message right after that traceback. Perhaps the 8139too needs
that same shutdown fix.

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

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Thomas Gleixner]

On Fri, 2004-10-22 at 14:40 -0500, Mark_H_Johnson@raytheon.com wrote:
> >No, the fix was for the missing pci shutdown in tulip.
> I thought the two were related (since I get the failed to shutdown
> message right after that traceback. Perhaps the 8139too needs
> that same shutdown fix.

The shutdown fix is neccecary, but it is not related to the other
problem. The shutdown message will also happen , if you unload the
module manualy. The patch below fixes only the shutdown warning. For the
other one I need more information.

tglx

---

diff -urN --exclude='*~' 2.6.9-mm1-U10/drivers/net/8139too.c
2.6.9-mm1-U10.work/drivers/net/8139too.c
--- 2.6.9-mm1-U10/drivers/net/8139too.c	2004-10-22 19:10:44.000000000
+0200
+++ 2.6.9-mm1-U10.work/drivers/net/8139too.c	2004-10-22
21:52:19.000000000 +0200
@@ -749,7 +749,7 @@
 	pci_release_regions (pdev);
 
 	free_netdev(dev);
-
+	pci_disable_dev (pdev);
 	pci_set_drvdata (pdev, NULL);
 }
 

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Ingo Molnar]

how about U10.3? That has the BKL fix too.

	Ingo

* Alexander Batyrshin <abatyrshin@ru.mvista.com> wrote:

>   Hi Ingo,
> U9.3 (defconfig) died with trace:
> 
> ------------[ cut here ]------------
> kernel BUG at kernel/sched.c:784!
> invalid operand: 0000 [#1]
> PREEMPT SMP
> Modules linked in:
> CPU:    0
> EIP:    0060:[<c011873d>]    Not tainted VLI
> EFLAGS: 00010002   (2.6.9-rc4-mm1-RT-U9.3)
> EIP is at resched_task+0x80/0x8a
> eax: 00000001   ebx: c1674000   ecx: dfb578f0   edx: 00000000
> esi: c16712c0   edi: 00000000   ebp: c167bc48   esp: c167bc3c
> ds: 007b   es: 007b   ss: 0068   preempt: 00000003
> Process ksoftirqd/0 (pid: 3, threadinfo=c167a000 task=c1670660)
> Stack: c1403820 c1403820 00000000 c167bc94 c0118b78 c16712c0 c1433820 
> 00000000
>        00000000 00000000 00000001 00000100 c1433820 c1433820 00000001 
> 00000000
>        00000000 00000001 00000082 00000001 de9d3e60 00000001 c167bcd8 
> c0133c7b
> Call Trace:
>  [<c0118b78>] try_to_wake_up+0x1f3/0x26b (20)
>  [<c0133c7b>] autoremove_wake_function+0x2f/0x57 (76)
>  [<c011a766>] __wake_up_common+0x3f/0x5e (28)
>  [<c011a7d0>] __wake_up+0x4b/0x62 (40)
>  [<c034e08c>] sock_def_readable+0x8e/0x90 (52)
>  [<c0388dbe>] tcp_child_process+0xe6/0xec (28)
>  [<c0384df7>] tcp_v4_do_rcv+0x123/0x162 (36)
>  [<c0134079>] _mutex_lock+0x2c/0x3b (16)
>  [<c0385513>] tcp_v4_rcv+0x6dd/0x92c (16)
>  [<c03c0e30>] svc_revisit+0x27/0x154 (48)
>  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (40)
>  [<c0368609>] ip_local_deliver_finish+0xb6/0x1b2 (4)
>  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (12)
>  [<c035f607>] nf_hook_slow+0xdc/0x12e (20)
>  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (28)
>  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (28)
>  [<c0367fcb>] ip_local_deliver+0x208/0x226 (4)
>  [<c0368553>] ip_local_deliver_finish+0x0/0x1b2 (24)
>  [<c0368828>] ip_rcv_finish+0x123/0x2b3 (20)
>  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (32)
>  [<c035f607>] nf_hook_slow+0xdc/0x12e (20)
>  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (28)
>  [<c036846a>] ip_rcv+0x481/0x56a (32)
>  [<c0368705>] ip_rcv_finish+0x0/0x2b3 (24)
>  [<c0354e68>] netif_receive_skb+0x117/0x1dd (28)
>  [<c0354ff7>] process_backlog+0xc9/0x1cb (36)
>  [<c03551b2>] net_rx_action+0xb9/0x1ed (48)
>  [<c01242d9>] ___do_softirq+0xe1/0x130 (36)
>  [<c0124923>] ksoftirqd+0x0/0xda (40)
>  [<c01243fb>] _do_softirq+0x4b/0x4d (4)
>  [<c01249c5>] ksoftirqd+0xa2/0xda (16)
>  [<c013376d>] kthread+0xb7/0xbd (24)
>  [<c01336b6>] kthread+0x0/0xbd (28)
>  [<c0103375>] kernel_thread_helper+0x5/0xb (16)
> preempt count: 00000004
> . 4-level deep critical section nesting:
> .. entry 1: _spin_lock_irqsave+0x1d/0xa5 [<00000000>] / (0x0 [<00000000>])
> .. entry 2: _spin_lock+0x19/0x6d [<00000000>] / (0x0 [<00000000>])
> .. entry 3: _spin_lock_irqsave+0x1d/0xa5 [<00000000>] / (0x0 [<00000000>])
> .. entry 4: print_traces+0x17/0x4e [<00000000>] / (0x0 [<00000000>])