Messages in this thread | | | Date | Mon, 15 Nov 2004 16:15:32 +0100 | From | Florian Schmidt <> | Subject | Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.25-1 |
| |
On Sun, 14 Nov 2004 15:15:51 +0100 Ingo Molnar <mingo@elte.hu> wrote:
> > * Florian Schmidt <mista.tapas@gmx.net> 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)
[unhandled content-type:application/octet-stream] | |