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

From: Florian Schmidt
Date: Mon Nov 15 2004 - 10:18:30 EST


On Sun, 14 Nov 2004 15:15:51 +0100
Ingo Molnar <mingo@xxxxxxx> wrote:

>
> * Florian Schmidt <mista.tapas@xxxxxxx> wrote:
>
> > i just build and booted into 26-3 (w/o debugging stuff) and put a
> > little load on the system (find /'s plus kernel compile plus
> > rtc_wakeup -f 8192). Got this on the console:
> >
> > `IRQ 8` [14] is being piggy. need_resched=0, cpu=0
> >
> > and the machine locked. will build with debugging and try to
> > reproduce.
>
> hm, i tried and couldnt reproduce this, so i'm curious what your
> debugging build yields.

Ok, i found time to boot into it once more. Now i'm pretty certain that the
rtc triggers the lock. As this time the kernel ran fine again for ca. 30
minutes. and then it locked right at the moment of spitting one of the rtc
being piggy messages to the ocnsole (of which i get about 1 per minute or
so, so it still might have been coincidence, but i was busy typing atm and
right in the moment of the piggy message, keyboard stopped working).

The sys-rq-t didn't help so much as i only have 50lines on my vga console.
The only thing i got to see was a list of held locks. I wrote down the
unique ones:

lock held by aquired at
atomic_read bash read_char
gendev_rel_sem init init_hwif_data
serio_lock IRQ 1 serio_interrupt
&mm->mmap_sem rtc_wakeup do_page_fault
sysrq_key_table IRQ 1 __handle_sysrq

Btw: i do have access to another machine on the internet, but i connect to
the net it via ppp0, thus netconsole won't help, right? Would it maybe be
feasible to add some sort of netconsole support which just dumps prinkt's
over any net interface to any IP with the price of not being able to catch
very early printk's (i'm probably talking out of my ass here. you'll set me
straight :))

Flo

.config attached

And FYI: some latency traces from before the lock:

preemption latency trace v1.0.7 on 2.6.10-rc1-mm3-RT-V0.7.26-4-NORT
-------------------------------------------------------
latency: 985 us, entries: 19 (19) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1]
-----------------
| task: IRQ 0/2, uid:0 nice:0 policy:1 rt_prio:49
-----------------
=> started at: try_to_wake_up+0x5a/0x110 <c01148da>
=> ended at: finish_task_switch+0x51/0xc0 <c0114dc1>
=======>
5 80000000 0.000ms (+0.000ms): trace_start_sched_wakeup (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): (50) ((98))
5 80000000 0.000ms (+0.000ms): (2) ((5))
5 80000000 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): preempt_schedule (__do_IRQ)
5 80000000 0.000ms (+0.000ms): irq_exit (do_IRQ)
5 80000000 0.000ms (+0.000ms): do_softirq (irq_exit)
5 80000000 0.000ms (+0.983ms): __do_softirq (do_softirq)
5 00000000 0.983ms (+0.000ms): preempt_schedule (_mmx_memcpy)
5 80000000 0.984ms (+0.000ms): __schedule (preempt_schedule)
5 80000000 0.984ms (+0.000ms): profile_hit (__schedule)
5 80000000 0.984ms (+0.000ms): sched_clock (__schedule)
2 80000000 0.984ms (+0.000ms): __switch_to (__schedule)
2 80000000 0.984ms (+0.000ms): (5) ((2))
2 80000000 0.984ms (+0.000ms): (98) ((50))
2 80000000 0.985ms (+0.000ms): finish_task_switch (__schedule)
2 80000000 0.985ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
2 80000000 0.985ms (+0.003ms): (2) ((50))
2 80000000 0.989ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)


preemption latency trace v1.0.7 on 2.6.10-rc1-mm3-RT-V0.7.26-4-NORT
-------------------------------------------------------
latency: 1035 us, entries: 19 (19) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1]
-----------------
| task: IRQ 0/2, uid:0 nice:0 policy:1 rt_prio:49
-----------------
=> started at: try_to_wake_up+0x5a/0x110 <c01148da>
=> ended at: finish_task_switch+0x51/0xc0 <c0114dc1>
=======>
5 80000000 0.000ms (+0.000ms): trace_start_sched_wakeup (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): (50) ((98))
5 80000000 0.000ms (+0.000ms): (2) ((5))
5 80000000 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): preempt_schedule (__do_IRQ)
5 80000000 0.000ms (+0.000ms): irq_exit (do_IRQ)
5 80000000 0.000ms (+0.000ms): do_softirq (irq_exit)
5 80000000 0.000ms (+1.033ms): __do_softirq (do_softirq)
5 00000000 1.033ms (+0.000ms): preempt_schedule (_mmx_memcpy)
5 80000000 1.034ms (+0.000ms): __schedule (preempt_schedule)
5 80000000 1.034ms (+0.000ms): profile_hit (__schedule)
5 80000000 1.034ms (+0.000ms): sched_clock (__schedule)
2 80000000 1.034ms (+0.000ms): __switch_to (__schedule)
2 80000000 1.034ms (+0.000ms): (5) ((2))
2 80000000 1.035ms (+0.000ms): (98) ((50))
2 80000000 1.035ms (+0.000ms): finish_task_switch (__schedule)
2 80000000 1.035ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
2 80000000 1.035ms (+0.003ms): (2) ((50))
2 80000000 1.038ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)

preemption latency trace v1.0.7 on 2.6.10-rc1-mm3-RT-V0.7.26-4-NORT
-------------------------------------------------------
latency: 1048 us, entries: 19 (19) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1]
-----------------
| task: IRQ 0/2, uid:0 nice:0 policy:1 rt_prio:49
-----------------
=> started at: try_to_wake_up+0x5a/0x110 <c01148da>
=> ended at: finish_task_switch+0x51/0xc0 <c0114dc1>
=======>
5 80000000 0.000ms (+0.000ms): trace_start_sched_wakeup (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): (50) ((98))
5 80000000 0.000ms (+0.000ms): (2) ((5))
5 80000000 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): preempt_schedule (__do_IRQ)
5 80000000 0.000ms (+0.000ms): irq_exit (do_IRQ)
5 80000000 0.000ms (+0.000ms): do_softirq (irq_exit)
5 80000000 0.000ms (+1.046ms): __do_softirq (do_softirq)
5 00000000 1.046ms (+0.000ms): preempt_schedule (_mmx_memcpy)
5 80000000 1.047ms (+0.000ms): __schedule (preempt_schedule)
5 80000000 1.047ms (+0.000ms): profile_hit (__schedule)
5 80000000 1.047ms (+0.000ms): sched_clock (__schedule)
2 80000000 1.047ms (+0.000ms): __switch_to (__schedule)
2 80000000 1.047ms (+0.000ms): (5) ((2))
2 80000000 1.047ms (+0.000ms): (98) ((50))
2 80000000 1.048ms (+0.000ms): finish_task_switch (__schedule)
2 80000000 1.048ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
2 80000000 1.048ms (+0.002ms): (2) ((50))
2 80000000 1.050ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)


preemption latency trace v1.0.7 on 2.6.10-rc1-mm3-RT-V0.7.26-4-NORT
-------------------------------------------------------
latency: 56 us, entries: 19 (19) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1]
-----------------
| task: IRQ 8/14, uid:0 nice:-10 policy:1 rt_prio:98
-----------------
=> started at: try_to_wake_up+0x5a/0x110 <c01148da>
=> ended at: finish_task_switch+0x51/0xc0 <c0114dc1>
=======>
5 80000000 0.000ms (+0.000ms): trace_start_sched_wakeup (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): (1) ((98))
5 80000000 0.000ms (+0.000ms): (14) ((5))
5 80000000 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up)
5 80000000 0.000ms (+0.000ms): preempt_schedule (__do_IRQ)
5 80000000 0.000ms (+0.000ms): irq_exit (do_IRQ)
5 80000000 0.000ms (+0.000ms): do_softirq (irq_exit)
5 80000000 0.000ms (+0.054ms): __do_softirq (do_softirq)
5 00000000 0.055ms (+0.000ms): preempt_schedule (_mmx_memcpy)
5 80000000 0.055ms (+0.000ms): __schedule (preempt_schedule)
5 80000000 0.055ms (+0.000ms): profile_hit (__schedule)
5 80000000 0.055ms (+0.000ms): sched_clock (__schedule)
14 80000000 0.055ms (+0.000ms): __switch_to (__schedule)
14 80000000 0.056ms (+0.000ms): (5) ((14))
14 80000000 0.056ms (+0.000ms): (98) ((1))
14 80000000 0.056ms (+0.000ms): finish_task_switch (__schedule)
14 80000000 0.056ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
14 80000000 0.056ms (+0.003ms): (14) ((1))
14 80000000 0.059ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)

Attachment: .config
Description: Binary data