Messages in this thread | | | Subject | Re: [patch] voluntary-preempt-2.6.8.1-P1 | From | Thomas Charbonnel <> | Date | Mon, 16 Aug 2004 13:13:40 +0200 |
| |
Ingo Molnar wrote : > * Lee Revell <rlrevell@joe-job.com> wrote: > > > Anyway, the change to sched.c fixes the mlockall bug, it works > > perfectly now. Thanks! > > great! This fix also means that we've got one more lock-break in the > ext3 journalling code and one more lock-break in dcache.c. I've released > -P1 with the fix included: > > http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8.1-P1 > > Ingo
Tested P1. The biggest offender on my system is still reiserfs' search_by_key. The trace is made of a very long loop of : 0.016ms (+0.000ms): reiserfs_in_journal (scan_bitmap_block) 0.016ms (+0.000ms): find_next_zero_bit (scan_bitmap_block) (...) 0.977ms (+0.000ms): reiserfs_in_journal (scan_bitmap_block) 0.977ms (+0.000ms): find_next_zero_bit (scan_bitmap_block) with interrupts showing up in the trace from time to time. Do you have plans to fix this, or should I switch to ext3 ?
Another point was the ACPI induced latency I was experiencing. I think that P1 could help track this down. After a fresh boot on an ACPI enabled kernel, once the initialization-related latency spikes are over, I reset /proc/sys/kernel/preempt_max_latency to 100, and then I get a 100us latency_trace attributed to swapper/1:
preemption latency trace v1.0 ----------------------------- latency: 100 us, entries: 4000 (14253) process: swapper/1, uid: 0 nice: 0, policy: 0, rt_priority: 0 =======> 0.000ms (+0.000ms): startup_8259A_irq (probe_irq_on) 0.000ms (+0.000ms): enable_8259A_irq (startup_8259A_irq) 0.001ms (+0.001ms): startup_8259A_irq (probe_irq_on) 0.001ms (+0.000ms): enable_8259A_irq (startup_8259A_irq) 0.002ms (+0.001ms): startup_8259A_irq (probe_irq_on) 0.002ms (+0.000ms): enable_8259A_irq (startup_8259A_irq) (...)
but the weird thing is that the latency sum goes way above those 100us, the culprit being do_IRQ, regularly chewing up to 1ms !
(...) 0.009ms (+0.000ms): enable_8259A_irq (startup_8259A_irq) 0.011ms (+0.001ms): startup_8259A_irq (probe_irq_on) 0.011ms (+0.000ms): enable_8259A_irq (startup_8259A_irq) 0.954ms (+0.943ms): do_IRQ (common_interrupt) -------------^ 0.954ms (+0.000ms): mask_and_ack_8259A (do_IRQ) 0.956ms (+0.002ms): generic_redirect_hardirq (do_IRQ) 0.956ms (+0.000ms): generic_handle_IRQ_event (do_IRQ) 0.957ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event) 0.957ms (+0.000ms): mark_offset_tsc (timer_interrupt) 0.962ms (+0.005ms): do_timer (timer_interrupt) (...) 119.027ms (+0.000ms): preempt_schedule (timer_interrupt) 119.027ms (+0.000ms): preempt_schedule (timer_interrupt) 119.027ms (+0.000ms): generic_note_interrupt (do_IRQ) 119.027ms (+0.000ms): end_8259A_irq (do_IRQ) 119.028ms (+0.000ms): enable_8259A_irq (do_IRQ) 119.028ms (+0.000ms): preempt_schedule (do_IRQ) 119.029ms (+0.000ms): preempt_schedule (do_IRQ) 119.029ms (+0.000ms): do_softirq (do_IRQ) 119.029ms (+0.000ms): __do_softirq (do_softirq) 120.017ms (+0.987ms): do_IRQ (common_interrupt) ---------------^ 120.017ms (+0.000ms): mask_and_ack_8259A (do_IRQ) 120.019ms (+0.002ms): preempt_schedule (do_IRQ) 120.019ms (+0.000ms): generic_redirect_hardirq (do_IRQ) 120.019ms (+0.000ms): preempt_schedule (do_IRQ) 120.020ms (+0.000ms): generic_handle_IRQ_event (do_IRQ) (...)
You can find the full trace here : http://www.undata.org/~thomas/swapper.trace
Do you have an idea of what's happening here ?
Thomas
- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
| |