Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Mark_H_Johnson]

>i've released the -T3 VP patch:

I ran another series of tests, this time without using threaded IRQ's. Both
/proc/sys/kernel/softirq_preemption and
/proc/sys/kernel/hardirq_preemption
were zero.

The results were somewhat similar to what I saw yesterday when both types
of
IRQ's were threaded. The number of latencies > 200 usec was higher:
  threaded IRQ's -  47
unthreaded IRQ's - 128

However, the application level overhead (as measured by latencytest)
appears to be less without threaded IRQ's than with. For example,
during the X11 stress test:

                            CPU task   samples within 0.1 msec
nominal duration:          1.16 msec     n/a
Max with threaded IRQ's:   1.38 msec     99.97%
Max with unthreaded IRQ's: 1.25 msec    100.00%

The green line in the chart is MUCH thinner in the unthreaded test
as well indicating much less overhead with unthreaded IRQ's. Please
note that in both tests, the audio IRQ was not threaded (all others
were...).

This trend continued until the disk tests were performed. In those
cases, the threaded overhead was less but I believe that is due to
the setting of the audio IRQ to be non-threaded.

The types of latency traces I saw are summarized as follows. Some
details are at the end and if anyone wants full traces, please let
me know. The numbers that follow refer to the trace numbers.

[1] rt_check_expire - hundreds of traces of _spin_lock and _spin_unlock
with the preempt count >1
00 02 78 82 87 92 101 110 126

[2] do_wait - preempt count bounces up / down many cycles
01

[3] do_IRQ - appears to be chaining of hard and soft IRQ's without any
opportunity for preemption. May also have timer tick as well. A few
different ways to start this symptom. Most traces are like one of these.
03... 37 39... 73 76 79 81 83... 86 88 89 94 96 97 99 100 102 103 106 107
109 111 114 119 122 123

[4] rt_run_flush - a VERY long trace (> 4000 samples)
38 106

[5] rcu / cache actions
74 75 77 90 95 113 124

[6] prune_icache - an interrupt causes some delays
80 91 98

[7] clear_page_tables - also seen without threaded IRQ's
92 108 112 115 ... 118 120 121 125 127

[8] avc_insert - a long delay at one step...
105

  --Mark

[1] rt_check_expire

The following is typical of this kind of trace.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 295 us, entries: 882 (882)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: X/2815, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: smp_apic_timer_interrupt+0x43/0xf0
 => ended at:   irq_exit+0x33/0x50
=======>
00010000 0.000ms (+0.000ms): smp_apic_timer_interrupt
(apic_timer_interrupt)
00010000 0.000ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010000 0.000ms (+0.000ms): profile_hook (profile_tick)
00010000 0.000ms (+0.000ms): _read_lock (profile_hook)
00010001 0.001ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.001ms (+0.000ms): _read_unlock (profile_tick)
00010000 0.001ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010000 0.001ms (+0.000ms): update_one_process (update_process_times)
00010000 0.002ms (+0.000ms): run_local_timers (update_process_times)
00010000 0.002ms (+0.000ms): raise_softirq (update_process_times)
00010000 0.002ms (+0.000ms): scheduler_tick (update_process_times)
00010000 0.002ms (+0.000ms): sched_clock (scheduler_tick)
00010000 0.003ms (+0.000ms): _spin_lock (scheduler_tick)
00010001 0.003ms (+0.000ms): _spin_unlock (scheduler_tick)
00010000 0.003ms (+0.000ms): rebalance_tick (scheduler_tick)
00010000 0.004ms (+0.000ms): irq_exit (smp_apic_timer_interrupt)
00000001 0.004ms (+0.000ms): do_softirq (irq_exit)
00000001 0.004ms (+0.000ms): __do_softirq (do_softirq)
00000101 0.004ms (+0.000ms): ___do_softirq (__do_softirq)
00000101 0.005ms (+0.000ms): run_timer_softirq (___do_softirq)
00000101 0.005ms (+0.000ms): _spin_lock_irq (run_timer_softirq)
00000101 0.005ms (+0.000ms): _spin_lock_irqsave (run_timer_softirq)
00000102 0.006ms (+0.000ms): _spin_unlock_irq (run_timer_softirq)
00000101 0.006ms (+0.000ms): peer_check_expire (run_timer_softirq)
00000101 0.007ms (+0.000ms): cleanup_once (peer_check_expire)
00000101 0.007ms (+0.000ms): _spin_lock_bh (cleanup_once)
00000101 0.008ms (+0.000ms): _spin_lock_irqsave (_spin_lock_bh)
00000202 0.008ms (+0.000ms): _spin_unlock_bh (cleanup_once)
00000201 0.008ms (+0.000ms): local_bh_enable (cleanup_once)
00000101 0.009ms (+0.000ms): __mod_timer (peer_check_expire)
00000101 0.009ms (+0.000ms): _spin_lock_irqsave (__mod_timer)
00000102 0.010ms (+0.000ms): _spin_lock (__mod_timer)
00000103 0.010ms (+0.000ms): internal_add_timer (__mod_timer)
00000103 0.011ms (+0.000ms): _spin_unlock (__mod_timer)
00000102 0.011ms (+0.000ms): _spin_unlock_irqrestore (__mod_timer)
00000101 0.012ms (+0.000ms): cond_resched_all (run_timer_softirq)
00000101 0.012ms (+0.000ms): cond_resched_softirq (run_timer_softirq)
00000101 0.012ms (+0.000ms): _spin_lock_irq (run_timer_softirq)
00000101 0.012ms (+0.000ms): _spin_lock_irqsave (run_timer_softirq)
00000102 0.013ms (+0.000ms): _spin_unlock_irq (run_timer_softirq)
00000101 0.013ms (+0.000ms): rt_check_expire (run_timer_softirq)
00000101 0.014ms (+0.000ms): _spin_lock (rt_check_expire)
00000102 0.014ms (+0.000ms): _spin_unlock (rt_check_expire)
00000101 0.015ms (+0.000ms): _spin_lock (rt_check_expire)
00000102 0.015ms (+0.000ms): _spin_unlock (rt_check_expire)
... MANY repetitions ...
00000101 0.151ms (+0.000ms): _spin_lock (rt_check_expire)
00000102 0.152ms (+0.000ms): _spin_unlock (rt_check_expire)
00000101 0.152ms (+0.001ms): _spin_lock (rt_check_expire)
00000102 0.153ms (+0.000ms): rt_may_expire (rt_check_expire)
00000102 0.153ms (+0.000ms): _spin_unlock (rt_check_expire)
00000101 0.154ms (+0.000ms): _spin_lock (rt_check_expire)
00000102 0.154ms (+0.000ms): _spin_unlock (rt_check_expire)
... MANY more repetitions ...
00000101 0.289ms (+0.000ms): _spin_lock (rt_check_expire)
00000102 0.289ms (+0.000ms): _spin_unlock (rt_check_expire)
00000101 0.290ms (+0.000ms): mod_timer (rt_check_expire)
00000101 0.290ms (+0.000ms): __mod_timer (rt_check_expire)
00000101 0.290ms (+0.000ms): _spin_lock_irqsave (__mod_timer)
00000102 0.291ms (+0.000ms): _spin_lock (__mod_timer)
00000103 0.291ms (+0.000ms): internal_add_timer (__mod_timer)
00000103 0.291ms (+0.000ms): _spin_unlock (__mod_timer)
00000102 0.292ms (+0.000ms): _spin_unlock_irqrestore (__mod_timer)
00000101 0.292ms (+0.000ms): cond_resched_all (run_timer_softirq)
00000101 0.292ms (+0.000ms): cond_resched_softirq (run_timer_softirq)
00000101 0.292ms (+0.000ms): _spin_lock_irq (run_timer_softirq)
00000101 0.292ms (+0.000ms): _spin_lock_irqsave (run_timer_softirq)
00000102 0.293ms (+0.000ms): _spin_unlock_irq (run_timer_softirq)
00000101 0.293ms (+0.000ms): __wake_up (run_timer_softirq)
00000101 0.293ms (+0.000ms): _spin_lock_irqsave (__wake_up)
00000102 0.293ms (+0.000ms): __wake_up_common (__wake_up)
00000102 0.294ms (+0.000ms): _spin_unlock_irqrestore (run_timer_softirq)
00000101 0.294ms (+0.000ms): cond_resched_all (___do_softirq)
00000101 0.294ms (+0.000ms): cond_resched_softirq (___do_softirq)
00000001 0.295ms (+0.000ms): sub_preempt_count (irq_exit)
00000001 0.295ms (+0.000ms): update_max_trace (check_preempt_timing)

[2] do_wait

Another example of several cycles up / down from preempt 1 to 2 to 1 ...

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 228 us, entries: 572 (572)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: init/1, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _read_lock+0x1b/0x80
 => ended at:   _read_unlock+0x1a/0x40
=======>
00000001 0.000ms (+0.000ms): _read_lock (do_wait)
00000001 0.000ms (+0.001ms): eligible_child (do_wait)
00000001 0.002ms (+0.000ms): selinux_task_wait (eligible_child)
00000001 0.003ms (+0.000ms): task_has_perm (selinux_task_wait)
00000001 0.004ms (+0.000ms): avc_has_perm (task_has_perm)
00000001 0.004ms (+0.000ms): avc_has_perm_noaudit (avc_has_perm)
00000001 0.004ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
00000002 0.005ms (+0.000ms): avc_lookup (avc_has_perm_noaudit)
00000002 0.006ms (+0.000ms): _spin_unlock_irqrestore (avc_has_perm_noaudit)
00000001 0.007ms (+0.000ms): security_compute_av (avc_has_perm_noaudit)
00000001 0.007ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
00000002 0.007ms (+0.000ms): avc_insert (avc_has_perm_noaudit)
00000002 0.008ms (+0.000ms): memcpy (avc_has_perm_noaudit)
00000002 0.008ms (+0.000ms): _spin_unlock_irqrestore (avc_has_perm_noaudit)
00000001 0.009ms (+0.000ms): avc_audit (avc_has_perm)
00000001 0.009ms (+0.000ms): eligible_child (do_wait)
00000001 0.010ms (+0.000ms): selinux_task_wait (eligible_child)
00000001 0.010ms (+0.000ms): task_has_perm (selinux_task_wait)
00000001 0.011ms (+0.000ms): avc_has_perm (task_has_perm)
00000001 0.011ms (+0.000ms): avc_has_perm_noaudit (avc_has_perm)
00000001 0.012ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
...
00000001 0.221ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
00000002 0.221ms (+0.000ms): memcpy (avc_has_perm_noaudit)
00000002 0.221ms (+0.000ms): _spin_unlock_irqrestore (avc_has_perm_noaudit)
00000001 0.222ms (+0.000ms): avc_audit (avc_has_perm)
00000001 0.222ms (+0.000ms): eligible_child (do_wait)
00000001 0.222ms (+0.000ms): selinux_task_wait (eligible_child)
00000001 0.223ms (+0.000ms): task_has_perm (selinux_task_wait)
00000001 0.223ms (+0.000ms): avc_has_perm (task_has_perm)
00000001 0.223ms (+0.000ms): avc_has_perm_noaudit (avc_has_perm)
00000001 0.224ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
00000002 0.224ms (+0.000ms): memcpy (avc_has_perm_noaudit)
00000002 0.224ms (+0.000ms): _spin_unlock_irqrestore (avc_has_perm_noaudit)
00000001 0.224ms (+0.000ms): avc_audit (avc_has_perm)
00000001 0.225ms (+0.000ms): wait_task_zombie (do_wait)
00000001 0.226ms (+0.000ms): _spin_lock_irq (wait_task_zombie)
00000001 0.226ms (+0.000ms): _spin_lock_irqsave (wait_task_zombie)
00000002 0.227ms (+0.000ms): _spin_unlock_irq (wait_task_zombie)
00000001 0.227ms (+0.000ms): _read_unlock (wait_task_zombie)
00000001 0.228ms (+0.000ms): sub_preempt_count (_read_unlock)
00000001 0.228ms (+0.000ms): update_max_trace (check_preempt_timing)

[3] do_IRQ

Several traces look similar to those I reported previously, just have
some additional latency at the start & end. For example:


preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 450 us, entries: 898 (898)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: cpu_burn/13771, uid:0 nice:10 policy:0 rt_prio:0
    -----------------
 => started at: do_IRQ+0x19/0x90
 => ended at:   irq_exit+0x33/0x50
=======>
00010000 0.000ms (+0.000ms): do_IRQ (common_interrupt)
00010000 0.000ms (+0.000ms): do_IRQ (<08048340>)
00010000 0.000ms (+0.000ms): do_IRQ (<0000000b>)
00010000 0.000ms (+0.000ms): _spin_lock (__do_IRQ)
00010001 0.000ms (+0.000ms): mask_and_ack_level_ioapic_irq (__do_IRQ)
...
00020000 0.041ms (+0.000ms): irq_exit (do_IRQ)
00010000 0.041ms (+0.000ms): rtl8139_interrupt (handle_IRQ_event)
00010000 0.041ms (+0.001ms): _spin_lock (rtl8139_interrupt)
00010001 0.042ms (+0.000ms): _spin_unlock (rtl8139_interrupt)
00010000 0.043ms (+0.000ms): _spin_lock (__do_IRQ)
00010001 0.043ms (+0.000ms): note_interrupt (__do_IRQ)
00010001 0.043ms (+0.000ms): end_level_ioapic_irq (__do_IRQ)
00010001 0.043ms (+0.000ms): unmask_IO_APIC_irq (__do_IRQ)
00010001 0.044ms (+0.000ms): _spin_lock_irqsave (unmask_IO_APIC_irq)
00010002 0.044ms (+0.000ms): __unmask_IO_APIC_irq (unmask_IO_APIC_irq)
00010002 0.044ms (+0.013ms): __modify_IO_APIC_irq (__unmask_IO_APIC_irq)
00010002 0.058ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ)
00010001 0.058ms (+0.000ms): _spin_unlock (__do_IRQ)
00010000 0.058ms (+0.000ms): irq_exit (do_IRQ)
00000001 0.059ms (+0.000ms): do_softirq (irq_exit)
00000001 0.059ms (+0.000ms): __do_softirq (do_softirq)
00000101 0.059ms (+0.000ms): ___do_softirq (__do_softirq)
00000101 0.059ms (+0.000ms): net_rx_action (___do_softirq)
... if I read this right, 60 usec was taken prior to getting to
the soft IRQ w/o any preemption opportunities ...
... many more traces ...
00010101 0.427ms (+0.000ms): rtl8139_interrupt (handle_IRQ_event)
00010101 0.427ms (+0.001ms): _spin_lock (rtl8139_interrupt)
00010102 0.429ms (+0.000ms): rtl8139_tx_interrupt (rtl8139_interrupt)
00010102 0.430ms (+0.000ms): _spin_unlock (rtl8139_interrupt)
00010101 0.430ms (+0.000ms): preempt_schedule (rtl8139_interrupt)
00010101 0.431ms (+0.000ms): _spin_lock (__do_IRQ)
00010102 0.431ms (+0.000ms): note_interrupt (__do_IRQ)
00010102 0.431ms (+0.000ms): end_level_ioapic_irq (__do_IRQ)
00010102 0.431ms (+0.000ms): unmask_IO_APIC_irq (__do_IRQ)
00010102 0.432ms (+0.000ms): _spin_lock_irqsave (unmask_IO_APIC_irq)
00010103 0.432ms (+0.000ms): __unmask_IO_APIC_irq (unmask_IO_APIC_irq)
00010103 0.432ms (+0.013ms): __modify_IO_APIC_irq (__unmask_IO_APIC_irq)
00010103 0.446ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ)
00010102 0.446ms (+0.000ms): preempt_schedule (__do_IRQ)
00010102 0.447ms (+0.000ms): _spin_unlock (__do_IRQ)
00010101 0.447ms (+0.000ms): preempt_schedule (__do_IRQ)
00010101 0.447ms (+0.000ms): irq_exit (do_IRQ)
00000101 0.448ms (+0.000ms): __wake_up (run_timer_softirq)
00000101 0.448ms (+0.000ms): _spin_lock_irqsave (__wake_up)
00000102 0.448ms (+0.000ms): __wake_up_common (__wake_up)
00000102 0.448ms (+0.000ms): _spin_unlock_irqrestore (run_timer_softirq)
00000101 0.449ms (+0.000ms): preempt_schedule (run_timer_softirq)
00000101 0.449ms (+0.000ms): cond_resched_all (___do_softirq)
00000101 0.449ms (+0.001ms): cond_resched_softirq (___do_softirq)
00000001 0.450ms (+0.000ms): sub_preempt_count (irq_exit)
00000001 0.450ms (+0.000ms): update_max_trace (check_preempt_timing)

[not quite sure if the same symptom but has many of the same
features as above...]

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 507 us, entries: 609 (609)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: rcp/13989, uid:2711 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x1f/0x80
 => ended at:   local_bh_enable+0x3f/0xb0

[16 - ditto, providing some detail]

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 474 us, entries: 919 (919)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: klogd/1953, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: schedule+0x43/0x810
 => ended at:   schedule+0x412/0x810
=======>
00000001 0.000ms (+0.000ms): schedule (work_resched)
00000001 0.000ms (+0.000ms): sched_clock (schedule)
00000001 0.001ms (+0.000ms): _spin_lock_irq (schedule)
00000001 0.001ms (+0.001ms): _spin_lock_irqsave (schedule)
00000002 0.002ms (+0.000ms): dequeue_task (schedule)
00000002 0.003ms (+0.000ms): recalc_task_prio (schedule)
00000002 0.003ms (+0.000ms): effective_prio (recalc_task_prio)
00000002 0.003ms (+0.005ms): enqueue_task (schedule)
00000002 0.008ms (+0.001ms): __switch_to (schedule)
00000002 0.010ms (+0.000ms): finish_task_switch (schedule)
00000002 0.010ms (+0.001ms): _spin_unlock_irq (finish_task_switch)
00000002 0.011ms (+0.000ms): smp_apic_timer_interrupt (_spin_unlock_irq)
00010002 0.012ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010002 0.013ms (+0.000ms): profile_hook (profile_tick)
00010002 0.013ms (+0.001ms): _read_lock (profile_hook)
00010003 0.014ms (+0.000ms): notifier_call_chain (profile_hook)
00010003 0.015ms (+0.000ms): _read_unlock (profile_tick)
00010002 0.015ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010002 0.016ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010002 0.017ms (+0.001ms): update_one_process (update_process_times)
00010002 0.018ms (+0.000ms): run_local_timers (update_process_times)
00010002 0.018ms (+0.000ms): raise_softirq (update_process_times)
00010002 0.019ms (+0.000ms): scheduler_tick (update_process_times)
00010002 0.019ms (+0.002ms): sched_clock (scheduler_tick)
00010002 0.021ms (+0.000ms): _spin_lock (scheduler_tick)
00010003 0.022ms (+0.000ms): task_timeslice (scheduler_tick)
00010003 0.022ms (+0.001ms): __bitmap_weight (scheduler_tick)
00010003 0.024ms (+0.000ms): __bitmap_weight (scheduler_tick)
00010003 0.024ms (+0.000ms): dequeue_task (scheduler_tick)
00010003 0.024ms (+0.000ms): effective_prio (scheduler_tick)
00010003 0.025ms (+0.000ms): enqueue_task (scheduler_tick)
00010003 0.025ms (+0.000ms): _spin_unlock (scheduler_tick)
00010002 0.025ms (+0.000ms): preempt_schedule (scheduler_tick)
00010002 0.025ms (+0.000ms): rebalance_tick (scheduler_tick)
00010002 0.026ms (+0.000ms): irq_exit (smp_apic_timer_interrupt)
00000003 0.026ms (+0.000ms): do_softirq (irq_exit)
00000003 0.027ms (+0.000ms): __do_softirq (do_softirq)
00000103 0.027ms (+0.000ms): ___do_softirq (__do_softirq)
00010103 0.028ms (+0.000ms): do_IRQ (___do_softirq)
00010103 0.028ms (+0.000ms): do_IRQ (<0000000b>)
00010103 0.029ms (+0.000ms): _spin_lock (__do_IRQ)
00010104 0.029ms (+0.000ms): mask_and_ack_level_ioapic_irq (__do_IRQ)
00010104 0.029ms (+0.000ms): mask_IO_APIC_irq
(mask_and_ack_level_ioapic_irq)
00010104 0.030ms (+0.000ms): _spin_lock_irqsave (mask_IO_APIC_irq)
00010105 0.030ms (+0.000ms): __mask_IO_APIC_irq (mask_IO_APIC_irq)
00010105 0.030ms (+0.014ms): __modify_IO_APIC_irq (__mask_IO_APIC_irq)
00010105 0.045ms (+0.000ms): _spin_unlock_irqrestore
(mask_and_ack_level_ioapic_irq)
00010104 0.045ms (+0.000ms): preempt_schedule
(mask_and_ack_level_ioapic_irq)
00010104 0.045ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010104 0.045ms (+0.000ms): _spin_unlock (__do_IRQ)
00010103 0.046ms (+0.000ms): preempt_schedule (__do_IRQ)
00010103 0.046ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010103 0.047ms (+0.000ms): rtl8139_interrupt (handle_IRQ_event)
... pretty deep nesting ...
00000109 0.464ms (+0.000ms): activate_task (try_to_wake_up)
00000109 0.465ms (+0.000ms): sched_clock (activate_task)
00000109 0.465ms (+0.000ms): recalc_task_prio (activate_task)
00000109 0.465ms (+0.000ms): effective_prio (recalc_task_prio)
00000109 0.466ms (+0.000ms): enqueue_task (activate_task)
00000109 0.466ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up)
00000108 0.466ms (+0.000ms): preempt_schedule (try_to_wake_up)
00000108 0.466ms (+0.000ms): _spin_unlock_irqrestore
(sk_stream_write_space)
00000107 0.467ms (+0.000ms): preempt_schedule (sk_stream_write_space)
00000107 0.467ms (+0.000ms): _spin_unlock (tcp_v4_rcv)
00000106 0.467ms (+0.000ms): preempt_schedule (tcp_v4_rcv)
00000105 0.468ms (+0.000ms): preempt_schedule (ip_local_deliver)
00000104 0.468ms (+0.000ms): preempt_schedule (netif_receive_skb)
00000104 0.469ms (+0.001ms): rtl8139_isr_ack (rtl8139_rx)
00000104 0.470ms (+0.000ms): _spin_unlock (rtl8139_poll)
00000103 0.471ms (+0.000ms): preempt_schedule (rtl8139_poll)
00000103 0.471ms (+0.000ms): cond_resched_all (___do_softirq)
00000103 0.471ms (+0.001ms): cond_resched_softirq (___do_softirq)
00000001 0.473ms (+0.001ms): preempt_schedule (finish_task_switch)
00000001 0.474ms (+0.000ms): sub_preempt_count (schedule)
00000001 0.474ms (+0.000ms): update_max_trace (check_preempt_timing)

[79 - ditto, different way to get started]

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 209 us, entries: 275 (275)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: sleep/15758, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: unmap_vmas+0x12e/0x280
 => ended at:   _spin_unlock+0x2d/0x60


[4] rt_run_flush

The trace buffer filled up before this completed so I don't have
the sequence that stopped the trace.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 2586 us, entries: 4000 (12487)   |   [VP:1 KP:1 SP:0 HP:0
#CPUS:2]
    -----------------
    | task: cpu_burn/13771, uid:0 nice:10 policy:0 rt_prio:0
    -----------------
 => started at: smp_apic_timer_interrupt+0x43/0xf0
 => ended at:   irq_exit+0x33/0x50
=======>
00010000 0.000ms (+0.000ms): smp_apic_timer_interrupt
(apic_timer_interrupt)
00010000 0.000ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010000 0.000ms (+0.000ms): profile_hook (profile_tick)
00010000 0.000ms (+0.000ms): _read_lock (profile_hook)
00010001 0.001ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.001ms (+0.000ms): _read_unlock (profile_tick)
00010000 0.001ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010000 0.001ms (+0.000ms): update_one_process (update_process_times)
00010000 0.002ms (+0.000ms): run_local_timers (update_process_times)
00010000 0.002ms (+0.000ms): raise_softirq (update_process_times)
00010000 0.002ms (+0.000ms): scheduler_tick (update_process_times)
00010000 0.002ms (+0.000ms): sched_clock (scheduler_tick)
00010000 0.003ms (+0.000ms): _spin_lock (scheduler_tick)
00010001 0.003ms (+0.000ms): _spin_unlock (scheduler_tick)
00010000 0.003ms (+0.000ms): rebalance_tick (scheduler_tick)
00010000 0.004ms (+0.000ms): irq_exit (smp_apic_timer_interrupt)
00000001 0.004ms (+0.000ms): do_softirq (irq_exit)
00000001 0.004ms (+0.000ms): __do_softirq (do_softirq)
00000101 0.004ms (+0.000ms): ___do_softirq (__do_softirq)
00000101 0.005ms (+0.000ms): run_timer_softirq (___do_softirq)
00000101 0.005ms (+0.000ms): _spin_lock_irq (run_timer_softirq)
00000101 0.005ms (+0.000ms): _spin_lock_irqsave (run_timer_softirq)
00000102 0.005ms (+0.000ms): _spin_unlock_irq (run_timer_softirq)
00000101 0.006ms (+0.000ms): rt_secret_rebuild (run_timer_softirq)
00000101 0.006ms (+0.000ms): rt_cache_flush (rt_secret_rebuild)
00000101 0.007ms (+0.000ms): _spin_lock_bh (rt_cache_flush)
00000101 0.007ms (+0.000ms): _spin_lock_irqsave (_spin_lock_bh)
00000202 0.007ms (+0.000ms): del_timer (rt_cache_flush)
00000202 0.008ms (+0.000ms): _spin_unlock_bh (rt_cache_flush)
00000201 0.008ms (+0.000ms): local_bh_enable (rt_cache_flush)
00000101 0.009ms (+0.000ms): rt_run_flush (rt_secret_rebuild)
00000101 0.009ms (+0.000ms): get_random_bytes (rt_run_flush)
00000101 0.009ms (+0.000ms): extract_entropy (get_random_bytes)
00000101 0.009ms (+0.000ms): _spin_lock_irqsave (extract_entropy)
00000102 0.010ms (+0.000ms): __wake_up (extract_entropy)
00000102 0.010ms (+0.000ms): _spin_lock_irqsave (__wake_up)
00000103 0.010ms (+0.000ms): __wake_up_common (__wake_up)
00000103 0.010ms (+0.000ms): _spin_unlock_irqrestore (extract_entropy)
00000102 0.011ms (+0.000ms): _spin_unlock_irqrestore (extract_entropy)
00000101 0.011ms (+0.000ms): SHATransform (extract_entropy)
00000101 0.011ms (+0.002ms): memcpy (SHATransform)
00000101 0.014ms (+0.000ms): add_entropy_words (extract_entropy)
00000101 0.014ms (+0.000ms): _spin_lock_irqsave (add_entropy_words)
00000102 0.014ms (+0.000ms): _spin_unlock_irqrestore (extract_entropy)
00000101 0.015ms (+0.000ms): SHATransform (extract_entropy)
00000101 0.015ms (+0.002ms): memcpy (SHATransform)
00000101 0.018ms (+0.000ms): add_entropy_words (extract_entropy)
00000101 0.018ms (+0.000ms): _spin_lock_irqsave (add_entropy_words)
00000102 0.018ms (+0.000ms): _spin_unlock_irqrestore (extract_entropy)
00000101 0.019ms (+0.000ms): _spin_lock_bh (rt_run_flush)
00000101 0.019ms (+0.000ms): _spin_lock_irqsave (_spin_lock_bh)
00000202 0.020ms (+0.000ms): _spin_unlock_bh (rt_run_flush)
00000201 0.020ms (+0.000ms): local_bh_enable (rt_run_flush)
00000101 0.020ms (+0.000ms): cond_resched_all (rt_run_flush)
00000101 0.020ms (+0.000ms): cond_resched_softirq (rt_run_flush)
00000101 0.021ms (+0.000ms): _spin_lock_bh (rt_run_flush)
00000101 0.021ms (+0.000ms): _spin_lock_irqsave (_spin_lock_bh)
00000202 0.021ms (+0.000ms): _spin_unlock_bh (rt_run_flush)
00000201 0.021ms (+0.000ms): local_bh_enable (rt_run_flush)
... this kind of cycle repeats a VERY long time and the watchdog
provides this piece of information ...
00000101 0.769ms (+0.000ms): _spin_lock_irqsave (_spin_lock_bh)
00000202 0.770ms (+0.000ms): _spin_unlock_bh (rt_run_flush)
00000201 0.770ms (+0.000ms): local_bh_enable (rt_run_flush)
00000101 0.770ms (+0.000ms): cond_resched_all (rt_run_flush)
00000101 0.771ms (+0.000ms): do_nmi (___trace)
00010101 0.771ms (+0.002ms): do_nmi (<08049b20>)
00010101 0.773ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010101 0.773ms (+464353.452ms): nmi_watchdog_tick (default_do_nmi)
00000002 464354.226ms (+12313.439ms): _spin_unlock (release_console_sem)
00010101 0.774ms (+0.000ms): do_IRQ (___trace)
00010101 0.774ms (+0.000ms): do_IRQ (<00000000>)
00010101 0.774ms (+0.000ms): _spin_lock (__do_IRQ)
00010102 0.775ms (+0.000ms): ack_edge_ioapic_irq (__do_IRQ)
00010102 0.775ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010102 0.775ms (+0.000ms): _spin_unlock (__do_IRQ)
00010101 0.776ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010101 0.776ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010101 0.776ms (+0.000ms): _spin_lock (timer_interrupt)
00010102 0.776ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010102 0.777ms (+0.000ms): _spin_lock (mark_offset_tsc)
00010103 0.777ms (+0.010ms): _spin_lock (mark_offset_tsc)
00010104 0.787ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010103 0.788ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010102 0.788ms (+0.003ms): _spin_lock (timer_interrupt)
00010103 0.792ms (+0.000ms): _spin_unlock (timer_interrupt)
00010102 0.792ms (+0.000ms): do_timer (timer_interrupt)
00010102 0.792ms (+0.000ms): update_wall_time (do_timer)
... more traces ...
00000101 1.023ms (+0.000ms): cond_resched_all (rt_run_flush)
00000101 1.023ms (+0.000ms): cond_resched_softirq (rt_run_flush)
00000101 1.023ms (+0.000ms): _spin_lock_bh (rt_run_flush)
00000101 1.024ms (+0.000ms): _spin_lock_irqsave (_spin_lock_bh)
00000202 1.024ms (+0.000ms): _spin_unlock_bh (rt_run_flush)
00000201 1.024ms (+0.000ms): local_bh_enable (rt_run_flush)
00000101 1.025ms (+0.000ms): cond_resched_all (rt_run_flush)
00000101 1.025ms (+0.000ms): cond_resched_softirq (rt_run_flush)
00000101 1.025ms (+0.000ms): _spin_lock_bh (rt_run_flush)
00000101 1.025ms (+0.000ms): _spin_lock_irqsave (_spin_lock_bh)
00000202 1.026ms (+0.000ms): _spin_unlock_bh (rt_run_flush)
00000201 1.026ms (+0.000ms): local_bh_enable (rt_run_flush)
00000101 1.026ms (+0.000ms): cond_resched_all (rt_run_flush)
00000101 1.026ms (+2915178.859ms): cond_resched_softirq (rt_run_flush)
[not sure why the odd values shown in some of the traces either]

[5] rcu / cache actions

May be a false positive due to latency tracing overhead.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 207 us, entries: 431 (431)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: kswapd0/72, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched_lock+0x24/0xf0
 => ended at:   cond_resched_lock+0x60/0xf0
=======>
00000001 0.000ms (+0.000ms): touch_preempt_timing (cond_resched_lock)
00000001 0.000ms (+0.000ms): smp_apic_timer_interrupt
(touch_preempt_timing)
00010001 0.000ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 0.000ms (+0.000ms): profile_hook (profile_tick)
00010001 0.001ms (+0.000ms): _read_lock (profile_hook)
00010002 0.001ms (+0.000ms): notifier_call_chain (profile_hook)
00010002 0.001ms (+0.000ms): _read_unlock (profile_tick)
00010001 0.001ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 0.002ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 0.002ms (+0.000ms): update_one_process (update_process_times)
00010001 0.002ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.002ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.003ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.003ms (+0.000ms): sched_clock (scheduler_tick)
00010001 0.003ms (+0.000ms): rcu_check_callbacks (scheduler_tick)
00010001 0.003ms (+0.000ms): idle_cpu (rcu_check_callbacks)
00010001 0.004ms (+0.000ms): __tasklet_schedule (scheduler_tick)
00010001 0.004ms (+0.000ms): _spin_lock (scheduler_tick)
00010002 0.004ms (+0.000ms): task_timeslice (scheduler_tick)
00010002 0.004ms (+0.000ms): __bitmap_weight (scheduler_tick)
00010002 0.005ms (+0.000ms): _spin_unlock (scheduler_tick)
00010001 0.005ms (+0.000ms): rebalance_tick (scheduler_tick)
00010001 0.005ms (+0.000ms): irq_exit (smp_apic_timer_interrupt)
00000002 0.006ms (+0.000ms): do_softirq (irq_exit)
00000002 0.006ms (+0.000ms): __do_softirq (do_softirq)
00000102 0.006ms (+0.000ms): ___do_softirq (__do_softirq)
00000102 0.006ms (+0.000ms): run_timer_softirq (___do_softirq)
00000102 0.006ms (+0.000ms): _spin_lock_irq (run_timer_softirq)
00000102 0.007ms (+0.000ms): _spin_lock_irqsave (run_timer_softirq)
00000103 0.007ms (+0.000ms): _spin_unlock_irq (run_timer_softirq)
00000102 0.007ms (+0.000ms): __wake_up (run_timer_softirq)
00000102 0.007ms (+0.000ms): _spin_lock_irqsave (__wake_up)
00000103 0.008ms (+0.000ms): __wake_up_common (__wake_up)
00000103 0.008ms (+0.000ms): _spin_unlock_irqrestore (run_timer_softirq)
00000102 0.008ms (+0.000ms): cond_resched_all (___do_softirq)
00000102 0.008ms (+0.000ms): cond_resched_softirq (___do_softirq)
00000102 0.009ms (+0.000ms): tasklet_action (___do_softirq)
00000102 0.009ms (+0.000ms): rcu_process_callbacks (tasklet_action)
00000102 0.009ms (+0.000ms): __rcu_process_callbacks
(rcu_process_callbacks)
00000102 0.010ms (+0.000ms): _spin_lock (__rcu_process_callbacks)
00000103 0.010ms (+0.000ms): rcu_start_batch (__rcu_process_callbacks)
00000103 0.010ms (+0.000ms): _spin_unlock (__rcu_process_callbacks)
00000102 0.010ms (+0.000ms): rcu_check_quiescent_state
(__rcu_process_callbacks)
00000102 0.011ms (+0.000ms): rcu_do_batch (rcu_process_callbacks)
00000102 0.012ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.012ms (+0.001ms): kmem_cache_free (d_callback)
00000102 0.013ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.014ms (+0.000ms): kmem_cache_free (d_callback)
00000102 0.014ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.015ms (+0.000ms): kmem_cache_free (d_callback)
00000102 0.016ms (+0.000ms): cache_flusharray (kmem_cache_free)
00000102 0.016ms (+0.001ms): _spin_lock (cache_flusharray)
00000103 0.017ms (+0.003ms): free_block (cache_flusharray)
00000103 0.021ms (+0.000ms): _spin_unlock (cache_flusharray)
00000102 0.021ms (+0.000ms): memmove (cache_flusharray)
00000102 0.021ms (+0.000ms): memcpy (memmove)
00000102 0.022ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.022ms (+0.000ms): kmem_cache_free (d_callback)
00000102 0.022ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.023ms (+0.000ms): kmem_cache_free (d_callback)
00000102 0.023ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.024ms (+0.000ms): kmem_cache_free (d_callback)
00000102 0.024ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.025ms (+0.000ms): kmem_cache_free (d_callback)
...
00000102 0.190ms (+0.000ms): cache_flusharray (kmem_cache_free)
00000102 0.190ms (+0.000ms): _spin_lock (cache_flusharray)
00000103 0.191ms (+0.003ms): free_block (cache_flusharray)
00000103 0.194ms (+0.000ms): _spin_unlock (cache_flusharray)
00000102 0.194ms (+0.000ms): memmove (cache_flusharray)
00000102 0.195ms (+0.000ms): memcpy (memmove)
00000102 0.195ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.195ms (+0.000ms): kmem_cache_free (d_callback)
00000102 0.196ms (+0.000ms): __tasklet_schedule (rcu_process_callbacks)
00000102 0.196ms (+0.000ms): __rcu_process_callbacks
(rcu_process_callbacks)
00000102 0.197ms (+0.000ms): rcu_check_quiescent_state
(__rcu_process_callbacks)
00000102 0.197ms (+0.000ms): cond_resched_all (___do_softirq)
00000102 0.197ms (+0.000ms): cond_resched_softirq (___do_softirq)
00000102 0.198ms (+0.000ms): wake_up_process (__do_softirq)
00000102 0.198ms (+0.000ms): try_to_wake_up (wake_up_process)
00000102 0.199ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000102 0.199ms (+0.001ms): _spin_lock (task_rq_lock)
00000103 0.201ms (+0.000ms): activate_task (try_to_wake_up)
00000103 0.201ms (+0.000ms): sched_clock (activate_task)
00000103 0.202ms (+0.001ms): recalc_task_prio (activate_task)
00000103 0.203ms (+0.000ms): effective_prio (recalc_task_prio)
00000103 0.203ms (+0.001ms): enqueue_task (activate_task)
00000103 0.204ms (+0.000ms): resched_task (try_to_wake_up)
00000103 0.205ms (+0.001ms): _spin_unlock_irqrestore (try_to_wake_up)
00000102 0.206ms (+0.001ms): preempt_schedule (try_to_wake_up)
00000001 0.207ms (+0.000ms): sub_preempt_count (cond_resched_lock)
00000001 0.208ms (+0.000ms): update_max_trace (check_preempt_timing)

[6] prune_icache

If I read this right, an operation that should have taken 100 usec or
so, was preempted by an even longer duration series of operations.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 263 us, entries: 597 (597)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: kswapd0/72, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock+0x1f/0x70
 => ended at:   _spin_unlock+0x2d/0x60
=======>
00000001 0.000ms (+0.000ms): _spin_lock (prune_icache)
00000001 0.000ms (+0.000ms): inode_has_buffers (prune_icache)
00000001 0.001ms (+0.000ms): inode_has_buffers (prune_icache)
00000001 0.001ms (+0.000ms): inode_has_buffers (prune_icache)
00000001 0.002ms (+0.000ms): inode_has_buffers (prune_icache)
...
00000001 0.075ms (+0.000ms): smp_apic_timer_interrupt (prune_icache)
00010001 0.075ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 0.075ms (+0.000ms): profile_hook (profile_tick)
00010001 0.075ms (+0.000ms): _read_lock (profile_hook)
00010002 0.076ms (+0.000ms): notifier_call_chain (profile_hook)
00010002 0.076ms (+0.000ms): _read_unlock (profile_tick)
00010001 0.076ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 0.077ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 0.077ms (+0.000ms): update_one_process (update_process_times)
00010001 0.078ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.078ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.078ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.078ms (+0.000ms): sched_clock (scheduler_tick)
00010001 0.079ms (+0.000ms): rcu_check_callbacks (scheduler_tick)
00010001 0.080ms (+0.000ms): idle_cpu (rcu_check_callbacks)
... it then runs later ...
00000102 0.097ms (+0.001ms): tasklet_action (___do_softirq)
00000102 0.098ms (+0.000ms): rcu_process_callbacks (tasklet_action)
00000102 0.098ms (+0.000ms): __rcu_process_callbacks
(rcu_process_callbacks)
00000102 0.099ms (+0.000ms): rcu_check_quiescent_state
(__rcu_process_callbacks)
00000102 0.100ms (+0.000ms): rcu_do_batch (rcu_process_callbacks)
00000102 0.100ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.101ms (+0.000ms): kmem_cache_free (d_callback)
00000102 0.101ms (+0.000ms): d_callback (rcu_do_batch)
00000102 0.102ms (+0.000ms): kmem_cache_free (d_callback)
... finally getting back to the original work ...
00000103 0.237ms (+0.000ms): resched_task (try_to_wake_up)
00000103 0.238ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up)
00000102 0.238ms (+0.001ms): preempt_schedule (try_to_wake_up)
00000001 0.239ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.240ms (+0.000ms): inode_has_buffers (prune_icache)
00000001 0.241ms (+0.000ms): inode_has_buffers (prune_icache)
...
00000001 0.262ms (+0.000ms): inode_has_buffers (prune_icache)
00000001 0.263ms (+0.001ms): _spin_unlock (prune_icache)
00000001 0.264ms (+0.000ms): sub_preempt_count (_spin_unlock)
00000001 0.264ms (+0.000ms): update_max_trace (check_preempt_timing)

[7] clear_page_tables

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 208 us, entries: 67 (67)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: get_ltrace.sh/16132, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: unmap_vmas+0x12e/0x280
 => ended at:   _spin_unlock+0x2d/0x60
=======>
00000001 0.000ms (+0.000ms): touch_preempt_timing (unmap_vmas)
00000001 0.000ms (+0.000ms): __bitmap_weight (unmap_vmas)
00000001 0.000ms (+0.000ms): unmap_page_range (unmap_vmas)
00000001 0.000ms (+0.000ms): zap_pmd_range (unmap_page_range)
00000001 0.000ms (+0.000ms): zap_pte_range (zap_pmd_range)
00000001 0.001ms (+0.000ms): kmap_atomic (zap_pte_range)
00000002 0.001ms (+0.001ms): page_address (zap_pte_range)
00000002 0.002ms (+0.000ms): set_page_dirty (zap_pte_range)
00000002 0.002ms (+0.000ms): page_remove_rmap (zap_pte_range)
00000002 0.002ms (+0.000ms): set_page_dirty (zap_pte_range)
00000002 0.003ms (+0.000ms): page_remove_rmap (zap_pte_range)
00000002 0.003ms (+0.000ms): set_page_dirty (zap_pte_range)
00000002 0.003ms (+0.000ms): page_remove_rmap (zap_pte_range)
00000002 0.004ms (+0.000ms): kunmap_atomic (zap_pte_range)
00000001 0.004ms (+0.002ms): vm_acct_memory (exit_mmap)
00000001 0.007ms (+0.181ms): clear_page_tables (exit_mmap)
00000001 0.189ms (+0.000ms): flush_tlb_mm (exit_mmap)
...

[8] avc_insert

The watchdog timer woke this up but avc_insert appears to be
the long step.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 248 us, entries: 35 (35)   |   [VP:1 KP:1 SP:0 HP:0 #CPUS:2]
    -----------------
    | task: fam/2929, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x1f/0x80
 => ended at:   _spin_unlock_irqrestore+0x32/0x70
=======>
00000001 0.000ms (+0.000ms): _spin_lock_irqsave (avc_has_perm_noaudit)
00000001 0.000ms (+0.020ms): avc_insert (avc_has_perm_noaudit)
00010001 0.020ms (+0.001ms): do_nmi (avc_insert)
00010001 0.022ms (+0.005ms): do_nmi (<08049b20>)
00010001 0.027ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010001 0.027ms (+0.185ms): nmi_watchdog_tick (default_do_nmi)
00000001 0.213ms (+0.000ms): memcpy (avc_has_perm_noaudit)
00000001 0.213ms (+0.000ms): _spin_unlock_irqrestore (avc_has_perm_noaudit)
00010001 0.214ms (+0.000ms): do_IRQ (_spin_unlock_irqrestore)
00010001 0.214ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.215ms (+0.000ms): _spin_lock (__do_IRQ)
00010002 0.215ms (+0.000ms): ack_edge_ioapic_irq (__do_IRQ)
00010002 0.216ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010002 0.216ms (+0.000ms): _spin_unlock (__do_IRQ)
00010001 0.216ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010001 0.217ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.217ms (+0.000ms): _spin_lock (timer_interrupt)
00010002 0.218ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010002 0.218ms (+0.000ms): _spin_lock (mark_offset_tsc)
00010003 0.219ms (+0.013ms): _spin_lock (mark_offset_tsc)
00010004 0.232ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010003 0.233ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010002 0.234ms (+0.007ms): _spin_lock (timer_interrupt)
00010003 0.242ms (+0.000ms): _spin_unlock (timer_interrupt)
00010002 0.242ms (+0.000ms): do_timer (timer_interrupt)
00010002 0.243ms (+0.000ms): update_wall_time (do_timer)
00010002 0.243ms (+0.003ms): update_wall_time_one_tick (update_wall_time)
00010002 0.246ms (+0.000ms): _spin_unlock (timer_interrupt)
00010001 0.247ms (+0.000ms): _spin_lock (__do_IRQ)
00010002 0.247ms (+0.000ms): note_interrupt (__do_IRQ)
00010002 0.247ms (+0.000ms): end_edge_ioapic_irq (__do_IRQ)
00010002 0.247ms (+0.000ms): _spin_unlock (__do_IRQ)
00010001 0.248ms (+0.001ms): irq_exit (do_IRQ)
00000001 0.249ms (+0.001ms): sub_preempt_count (_spin_unlock_irqrestore)
00000001 0.250ms (+0.000ms): update_max_trace (check_preempt_timing)

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Sid Boyce]

Config for HPET not correctly set in arch/x86_64/Kconfig. 
CONFIG_HPET_TIMER=y
CONFIG_HPET_EMULATE_RTC=y are the only ones to appear and it doesn't 
build hpet.o, build also fails with # CONFIG_HPET_TIMER is not set.
     CHK     include/linux/version.h
make[1]: `arch/x86_64/kernel/asm-offsets.s' is up to date.
   CHK     include/linux/compile.h
   GEN_INITRAMFS_LIST usr/initramfs_list
Using shipped usr/initramfs_list
   GEN     .version
   CHK     include/linux/compile.h
   UPD     include/linux/compile.h
   CC      init/version.o
   LD      init/built-in.o
   LD      .tmp_vmlinux1
arch/x86_64/kernel/built-in.o(.init.text+0x1dc1): In function 
`late_hpet_init':
: undefined reference to `hpet_alloc'
--------------------------------------
x86 builds OK with:-

CONFIG_HPET_TIMER=y
CONFIG_HPET_EMULATE_RTC=y
CONFIG_HPET=y
# CONFIG_HPET_RTC_IRQ is not set
CONFIG_HPET_MMAP=y
Regards
Sid.
-- 
Sid Boyce .... Hamradio G3VBV and keen Flyer
=====LINUX ONLY USED HERE=====

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Mark_H_Johnson]

>i've released the -T3 VP patch: [snip]

Thanks. This fixes the USB boot time problem / USB mouse does not work.
I do not have the problem others have reported with audio - audio works
just fine for me.

I've made two runs using latencytest for the real time task / generating
audio. To recap, I have a dual 866 Mhz Pentium III w/ 512 M memory,
Ensonic audio, 8139too network interface, and IDE disk. The IDE is set
to use udma2. Both tests run with both hard IRQ and soft IRQ threads
(except for the audio IRQ).

The first run, I set a limit of 500 usec and had no latencies longer than
that. Very good.

The second run, I set the limit to 200 usec and had 47 traces > 200 usec
in a 20-30 minute period. Two were VERY long, one was about 1.7 msec and
the other was over 50 msec. The material at the end summarizes the types
of traces I had. I will send the detailed traces separately.

  --Mark

To summarize, the symptoms w/ trace numbers following:
[1] VERY long latencies
04 27
[2] Long traces, USB related
00 32 42 43 44
[3] Long traces, network related
03 05... 24 28 46
[4] Pruning icache
25 26
[5] clear_page_tables
01 02 29 30 31 33... 41 45

[1] VERY long latencies

This appears to be disk related, IRQ 14 is ide0.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 53418 us, entries: 226 (226)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: IRQ 14/203, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x1f/0x80
 => ended at:   _spin_unlock+0x2d/0x60
=======>
00000001 0.000ms (+0.000ms): _spin_lock_irqsave (ide_intr)
00000001 0.000ms (+0.000ms): drive_is_ready (ide_intr)
00000001 0.001ms (+0.000ms): __ide_dma_test_irq (drive_is_ready)
00000001 0.002ms (+0.000ms): ide_inb (__ide_dma_test_irq)
00000001 0.002ms (+0.000ms): del_timer (ide_intr)
00000001 0.003ms (+0.422ms): _spin_lock_irqsave (del_timer)
00010002 0.425ms (+0.000ms): do_nmi (sub_preempt_count)
00010002 0.426ms (+0.003ms): do_nmi (___trace)
00010002 0.429ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 0.430ms (+0.993ms): nmi_watchdog_tick (default_do_nmi)
00010002 1.423ms (+0.000ms): do_nmi (_spin_lock_irqsave)
00010002 1.424ms (+0.001ms): do_nmi (___trace)
00010002 1.425ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 1.425ms (+0.996ms): nmi_watchdog_tick (default_do_nmi)
00010001 2.422ms (+0.000ms): do_nmi (_spin_lock_irqsave)
00010001 2.422ms (+0.001ms): do_nmi (check_preempt_timing)
00010001 2.424ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010001 2.424ms (+0.996ms): nmi_watchdog_tick (default_do_nmi)
00010002 3.420ms (+0.000ms): do_nmi (_spin_lock_irqsave)
00010002 3.420ms (+0.001ms): do_nmi (check_preempt_timing)
00010002 3.422ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 3.422ms (+0.996ms): nmi_watchdog_tick (default_do_nmi)
00010002 4.418ms (+0.000ms): do_nmi (_spin_lock_irqsave)
00010002 4.419ms (+0.003ms): do_nmi (___trace)
00010002 4.422ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 4.422ms (+0.994ms): nmi_watchdog_tick (default_do_nmi)
...
00010001 49.345ms (+0.996ms): nmi_watchdog_tick (default_do_nmi)
00010002 50.341ms (+0.000ms): do_nmi (_spin_lock_irqsave)
00010002 50.341ms (+0.001ms): do_nmi (___trace)
00010002 50.343ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 50.343ms (+0.996ms): nmi_watchdog_tick (default_do_nmi)
00010002 51.339ms (+0.000ms): do_nmi (add_preempt_count)
00010002 51.340ms (+0.003ms): do_nmi (cycles_to_usecs)
00010002 51.343ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 51.343ms (+0.994ms): nmi_watchdog_tick (default_do_nmi)
00010002 52.338ms (+0.000ms): do_nmi (_spin_lock_irqsave)
00010002 52.338ms (+0.003ms): do_nmi (touch_preempt_timing)
00010002 52.342ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 52.342ms (+0.994ms): nmi_watchdog_tick (default_do_nmi)
00010002 53.336ms (+0.000ms): do_nmi (add_preempt_count)
00010002 53.336ms (+0.003ms): do_nmi (check_preempt_timing)
00010002 53.340ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 53.340ms (+0.076ms): nmi_watchdog_tick (default_do_nmi)
00000002 53.417ms (+0.000ms): _spin_unlock_irqrestore (del_timer)
00000001 53.417ms (+0.000ms): _spin_unlock (ide_intr)
00000001 53.418ms (+0.000ms): sub_preempt_count (_spin_unlock)
00000001 53.419ms (+0.000ms): update_max_trace (check_preempt_timing)

Here is the other one, same basic symptom but just not as long duration.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 1715 us, entries: 18 (18)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: IRQ 14/203, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x1f/0x80
 => ended at:   _spin_unlock+0x2d/0x60
=======>
00000001 0.000ms (+0.000ms): _spin_lock_irqsave (ide_intr)
00000001 0.000ms (+0.000ms): drive_is_ready (ide_intr)
00000001 0.001ms (+0.000ms): __ide_dma_test_irq (drive_is_ready)
00000001 0.001ms (+0.000ms): ide_inb (__ide_dma_test_irq)
00000001 0.002ms (+0.000ms): del_timer (ide_intr)
00000001 0.002ms (+0.022ms): _spin_lock_irqsave (del_timer)
00010002 0.024ms (+0.000ms): do_nmi (sub_preempt_count)
00010002 0.025ms (+0.001ms): do_nmi (check_preempt_timing)
00010002 0.026ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 0.027ms (+0.996ms): nmi_watchdog_tick (default_do_nmi)
00010002 1.023ms (+0.000ms): do_nmi (sub_preempt_count)
00010002 1.023ms (+0.003ms): do_nmi (check_preempt_timing)
00010002 1.027ms (+0.000ms): notifier_call_chain (default_do_nmi)
00010002 1.027ms (+0.688ms): nmi_watchdog_tick (default_do_nmi)
00000002 1.715ms (+0.000ms): _spin_unlock_irqrestore (del_timer)
00000001 1.715ms (+0.000ms): _spin_unlock (ide_intr)
00000001 1.716ms (+0.000ms): sub_preempt_count (_spin_unlock)
00000001 1.716ms (+0.000ms): update_max_trace (check_preempt_timing)

[2] Long traces, USB related

I had several traces with hundreds of lines of tracing data. This set
appear to be related to USB processing (moving the mouse).

This one is typical.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 365 us, entries: 320 (320)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: X/2815, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x1f/0x80
 => ended at:   _spin_unlock_irqrestore+0x32/0x70

[3] Long traces, network related

Similar to the previous one, and a symptom I have reported before.
I don't see any obvious fixes for this type of problem and the overhead
of tracing may introduce a significant delay to make the problem look
much worse than it really is.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 203 us, entries: 401 (401)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: ksoftirqd/0/3, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock+0x1f/0x70
 => ended at:   rtl8139_rx+0x217/0x340

OR

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 222 us, entries: 562 (562)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: rcp/7416, uid:2711 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: tcp_prequeue_process+0x49/0xb0
 => ended at:   local_bh_enable+0x3f/0xb0


[4] Pruning icache

Don't recall seeing this one before. It was long enough to have a clock
tick come in, but with only 25 usec overhead, the clock overhead was not
significant.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 274 us, entries: 165 (165)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: kswapd0/72, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock+0x1f/0x70
 => ended at:   _spin_unlock+0x2d/0x60
=======>
00000001 0.000ms (+0.002ms): _spin_lock (prune_icache)
00000001 0.002ms (+0.005ms): inode_has_buffers (prune_icache)
00000001 0.007ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.009ms (+0.002ms): inode_has_buffers (prune_icache)
00000001 0.011ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.013ms (+0.002ms): inode_has_buffers (prune_icache)
...
00000001 0.263ms (+0.002ms): inode_has_buffers (prune_icache)
00000001 0.265ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.266ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.268ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.269ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.271ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.272ms (+0.000ms): inode_has_buffers (prune_icache)
00000001 0.273ms (+0.002ms): _spin_unlock (prune_icache)
00000001 0.275ms (+0.000ms): sub_preempt_count (_spin_unlock)
00000001 0.276ms (+0.000ms): update_max_trace (check_preempt_timing)

[5] clear_page_tables

Usually short (<50-100 lines) but taking significant time to perform.
You can see the big hit at clear_page_tables in this one.

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 234 us, entries: 38 (38)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: get_ltrace.sh/7082, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: unmap_vmas+0x12e/0x280
 => ended at:   _spin_unlock+0x2d/0x60
=======>
00000001 0.000ms (+0.000ms): touch_preempt_timing (unmap_vmas)
00000001 0.000ms (+0.000ms): __bitmap_weight (unmap_vmas)
00000001 0.000ms (+0.000ms): unmap_page_range (unmap_vmas)
00000001 0.000ms (+0.000ms): zap_pmd_range (unmap_page_range)
00000001 0.000ms (+0.000ms): zap_pte_range (zap_pmd_range)
00000001 0.001ms (+0.000ms): kmap_atomic (zap_pte_range)
00000002 0.001ms (+0.000ms): page_address (zap_pte_range)
00000002 0.001ms (+0.000ms): set_page_dirty (zap_pte_range)
00000002 0.001ms (+0.000ms): page_remove_rmap (zap_pte_range)
00000002 0.002ms (+0.000ms): set_page_dirty (zap_pte_range)
00000002 0.002ms (+0.000ms): page_remove_rmap (zap_pte_range)
00000002 0.002ms (+0.000ms): kunmap_atomic (zap_pte_range)
00000001 0.003ms (+0.001ms): vm_acct_memory (exit_mmap)
00000001 0.004ms (+0.217ms): clear_page_tables (exit_mmap)
00000001 0.221ms (+0.003ms): flush_tlb_mm (exit_mmap)
00000001 0.225ms (+0.000ms): free_pages_and_swap_cache (exit_mmap)
00000001 0.225ms (+0.000ms): lru_add_drain (free_pages_and_swap_cache)
00000001 0.226ms (+0.000ms): release_pages (free_pages_and_swap_cache)
00000001 0.227ms (+0.000ms): _spin_lock_irq (release_pages)
00000001 0.227ms (+0.001ms): _spin_lock_irqsave (release_pages)
00000002 0.228ms (+0.000ms): _spin_unlock_irq (release_pages)
00000001 0.228ms (+0.000ms): __pagevec_free (release_pages)
00000001 0.228ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.229ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.229ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.230ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.230ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.230ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.231ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.231ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.232ms (+0.000ms): _spin_lock_irq (release_pages)
00000001 0.232ms (+0.000ms): _spin_lock_irqsave (release_pages)
00000002 0.232ms (+0.000ms): _spin_unlock_irq (release_pages)
00000001 0.233ms (+0.000ms): __pagevec_free (release_pages)
00000001 0.233ms (+0.000ms): free_hot_cold_page (__pagevec_free)
00000001 0.233ms (+0.001ms): _spin_unlock (exit_mmap)
00000001 0.235ms (+0.001ms): sub_preempt_count (_spin_unlock)
00000001 0.236ms (+0.000ms): update_max_trace (check_preempt_timing)

Re: BKL backtraces - was: Re: [patch] voluntary-preempt-2.6.9-rc2-mm1-S1

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 1569 bytes --]


* K.R. Foley <kr@cybsft.com> wrote:

> All of these were generated while booting:
> 
> Sep 20 19:45:10 porky kernel: using smp_processor_id() in preemptible 
> code: modprobe/1019
> Sep 20 19:45:10 porky kernel:  [<c011c58e>] smp_processor_id+0x8e/0xa0
> Sep 20 19:45:10 porky kernel:  [<c013ace6>] module_unload_init+0x46/0x70
> Sep 20 19:45:10 porky kernel:  [<c013ce58>] load_module+0x598/0xb10
> Sep 20 19:45:10 porky kernel:  [<c013d438>] sys_init_module+0x68/0x280
> Sep 20 19:45:10 porky kernel:  [<c01066b9>] sysenter_past_esp+0x52/0x71
> 
> The above one of course repeats on each module load.

ok, this is a harmless false positive - the attached patch fixes it.

> Sep 20 19:45:10 porky kernel: using smp_processor_id() in preemptible 
> code: X/1017
> Sep 20 19:45:10 porky kernel:  [<c011c58e>] smp_processor_id+0x8e/0xa0
> Sep 20 19:45:10 porky kernel:  [<c01d6c15>] add_timer_randomness+0x125/0x150
> Sep 20 19:45:10 porky kernel:  [<c01d6c9e>] add_mouse_randomness+0x1e/0x30
> Sep 20 19:45:10 porky kernel:  [<c022b835>] input_event+0x55/0x3f0

> Sep 20 19:45:10 porky kernel:  [<c01e1390>] vt_ioctl+0x0/0x1ad0
> Sep 20 19:45:10 porky kernel:  [<c01dc08b>] tty_ioctl+0x37b/0x4d0
> Sep 20 19:45:10 porky kernel:  [<c0175034>] sys_ioctl+0xe4/0x240
> Sep 20 19:45:10 porky kernel:  [<c01066b9>] sysenter_past_esp+0x52/0x71
> 
> The X one above repeats once also.

aha! This is a real one, fixed by the second patch. This piece of code
relied on add_timer_randomness() always being called with preemption
disabled.

these fixes will show up in -S2.

	Ingo

[-- Attachment #2: 1 --]
[-- Type: text/plain, Size: 441 bytes --]

--- linux/kernel/module.c.orig	
+++ linux/kernel/module.c	
@@ -394,7 +394,7 @@ static void module_unload_init(struct mo
 	for (i = 0; i < NR_CPUS; i++)
 		local_set(&mod->ref[i].count, 0);
 	/* Hold reference count during initialization. */
-	local_set(&mod->ref[smp_processor_id()].count, 1);
+	local_set(&mod->ref[_smp_processor_id()].count, 1);
 	/* Backwards compatibility macros put refcount during init. */
 	mod->waiter = current;
 }

[-- Attachment #3: 2 --]
[-- Type: text/plain, Size: 698 bytes --]

--- linux/drivers/char/random.c.orig	
+++ linux/drivers/char/random.c	
@@ -807,10 +807,11 @@ static void add_timer_randomness(struct 
 	long		delta, delta2, delta3;
 	int		entropy = 0;
 
+	preempt_disable();
 	/* if over the trickle threshold, use only 1 in 4096 samples */
 	if ( random_state->entropy_count > trickle_thresh &&
 	     (__get_cpu_var(trickle_count)++ & 0xfff))
-		return;
+		goto out;
 
 	/*
 	 * Use get_cycles() if implemented, otherwise fall back to
@@ -861,6 +862,8 @@ static void add_timer_randomness(struct 
 		entropy = int_ln_12bits(delta);
 	}
 	batch_entropy_store(num, time, entropy);
+out:
+	preempt_enable();
 }
 
 void add_keyboard_randomness(unsigned char scancode)

[patch] voluntary-preempt-2.6.9-rc2-mm1-S2

[Ingo Molnar]

i've released the -S2 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm1-S2

Changes since -S1:

 - added the swapspace-layout patch to fix the get_swap_page()
   latencies. (sw-suspend wont compile but everything else should work
   fine.)

 - fixed the random.c BKL non-preemptability assumption

 - export smp_processor_id() to fix modules

 - module init smp_processor_id()-debug false positive fix

To get a 2.6.9-rc2-mm1-VP-S2 kernel, 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-rc2.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc2/2.6.9-rc2-mm1/2.6.9-rc2-mm1.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm1-S2

	Ingo

[patch] voluntary-preempt-2.6.9-rc2-mm1-S3

[Ingo Molnar]

i've released the -S3 VP patch:

   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm1-S3

most importantly, -S3 fixes the SMP+PREEMPT bug reported by K.R. Foley. 
It was a bug in BKL-preemption: forced preemption still caused automatic
dropping of the BKS - this is bad and broke fs/locks.c. (The race could
occur on UP+PREEMPT too but it has never been reproduced there.)

other changes since -S2:

 - introduced a CONFIG_PREEMPT_BKL - just in case there are other
   problems. This can be used to turn BKL preemption on/off. Can be 
   useful for performance tests as well.

 - fixed a couple of more smp_processor_id() false positives.

 - cleaned up hardirq.c some more

To get a 2.6.9-rc2-mm1-VP-S3 kernel, 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-rc2.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc2/2.6.9-rc2-mm1/2.6.9-rc2-mm1.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm1-S3

	Ingo

[patch] voluntary-preempt-2.6.9-rc2-mm1-S4

[Ingo Molnar]

i've released the -S4 VP patch:

   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm2-S4

-S4 fixes a softirq latency processing bug introduced in -S3. The
symptoms of this bug can be erratic mouse/keyboard behavior, higher
networking latencies, and similar things. (If CONFIG_PREEMPT is disabled
then another effect of this bug can lead to crashes.)

-S4 is also a merge to 2.6.9-rc2-mm2.

To get a 2.6.9-rc2-mm2-VP-S4 kernel, 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-rc2.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc2/2.6.9-rc2-mm2/2.6.9-rc2-mm2.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm2-S4

	Ingo

[patch] voluntary-preempt-2.6.9-rc2-mm3-S5

[Ingo Molnar]

i've released the -S5 VP patch:
 
   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm3-S5

this iteration fixes the jackd lockup reported by Rui Nuno Capela.

since Andrew has not released -mm3 yet i've uploaded his latest
intermediate tree plus two additional fixes that will likely show up in
the real -mm3, and unrolled some of the more experimental scheduler
stuff. 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-rc2.bz2
 + http://redhat.com/~mingo/voluntary-preempt/2.6.9-rc2-pre-mm3-mingo.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm3-S5

	Ingo

[patch] voluntary-preempt-2.6.9-rc2-mm3-S6

[Ingo Molnar]

i've released the -S6 VP patch:

   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm3-S6

this iteration fixes the 'dropped tcp connections' problem reported and
fixed by K.R. Foley.

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-rc2.bz2
 + http://redhat.com/~mingo/voluntary-preempt/2.6.9-rc2-pre-mm3-mingo.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm3-S6
 
	Ingo

[patch] voluntary-preempt-2.6.9-rc2-mm4-S7

[Ingo Molnar]

i've released the -S7 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm4-S7

this iteration is mainly a merge to -mm4. (-mm4 includes PREEMPT_BKL so
the -VP patch got smaller again - at least until -mm carries it.) The
patch undoes some more experimental scheduler patches that -mm includes.

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-rc2.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc2/2.6.9-rc2-mm4/2.6.9-rc2-mm4.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc2-mm4-S7

	Ingo

[patch] voluntary-preempt-2.6.9-rc3-mm1-S8

[Ingo Molnar]

i've released the -S8 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm1-S8

this iteration is mainly a merge to -rc3-mm1. The -rc3-mm1 tree now
includes the generic-irq-subsystem patch which is a prerequisite of the
threaded-irqs feature in the -VP patch. As a result of this the -VP
patch got significantly smaller, down from 224K to 89K.

also part of the patch are further refinements of the preempt-bkl
feature and a couple of bugfixes, reported for the -mm tree but not
included in -rc3-mm1 yet. (All of these were sent to Andrew too so they
should show up in -mm2.)

to build an -S8 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-rc3.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc3/2.6.9-rc3-mm1/2.6.9-rc3-mm1.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm1-S8

	Ingo

[patch] voluntary-preempt-2.6.9-rc3-mm1-S9

[Ingo Molnar]

i've released the -S9 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm2-S9

Changes since -S8:

 - merge to -mm2. mm2 includes another latency breaker: Hugh Dickins'
   vmtruncate rework that should fix the bash-shared-mapping latency.

 - fix the x64 compilation bug reported by thewade

 - fix the menuconfig duplicate entry bug noticed by Florian Schmidt

 - (fix two preempt bugs in -mm2 - will be in -mm3)

to build an -S9 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-rc3.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc3/2.6.9-rc3-mm2/2.6.9-rc3-mm2.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm2-S9

	Ingo

[patch] voluntary-preempt-2.6.9-rc3-mm2-T1

[Ingo Molnar]

i've released the -T1 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm2-T1

Changes since -T0:

 - added the read-lock fix from Hugh that affects SMP systems. This 
   could fix Rui's problem - i've checked -T1 on a P4/HT box and saw no 
   problems, BYMMV.

 - compilation fixes (for those who downloaded T0 early)

 - small tracer improvement

to build a -T1 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-rc3.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc3/2.6.9-rc3-mm2/2.6.9-rc3-mm2.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm2-T1

	Ingo

[patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Ingo Molnar]

i've released the -T3 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3

Changes since -T1 (-T2 was not announced):

 - rebased to -rc3-mm3. This should fix the build problems and further 
   shrinks the -VP patch. Also, people who had USB problems please
   re-test -T3 as -mm3 is supposed to have much of those problems fixed.
   Also, the dvb-bt8xx.c build problem should be fixed in -mm3 too, plus
   a number of smp_processor_id() warnings were debugged and fixed as
   well.

 - fixed SWSUSPEND compilation. Could someone who uses swsuspend check
   whether sw-suspension works fine?

 - improved CONFIG_DEBUG_PREEMPT - this could help debug any potentially
   remaining unbalanced preemption counts that were reported. (but
   the fixes in -mm3 could fix them as well.)

to build a -T3 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-rc3.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc3/2.6.9-rc3-mm3/2.6.9-rc3-mm3.bz2
 + http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Ingo Molnar]

* Hanno Meyer-Thurow <h.mth@web.de> wrote:

> > i've released the -T3 VP patch:
> > 
> >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 
> i get this on compile:
> 
> init/built-in.o(.text+0x18b): In function `rest_init':
> : undefined reference to `sub_preempt_count'

ok, this happens if PREEMPT_TIMING is not enabled. I've re-uploaded the
new -T3 patch, please re-download it.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Hanno Meyer-Thurow]

On Thu, 7 Oct 2004 13:44:34 +0200
Ingo Molnar <mingo@elte.hu> wrote:

> ok, this happens if PREEMPT_TIMING is not enabled. I've re-uploaded the
> new -T3 patch, please re-download it.
> 
> 	Ingo

great! it works, thanks :)

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Rui Nuno Capela]

Hi Ingo,
>
> i've released the -T3 VP patch:
>
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
>

Didn't try this yet on my desktop (where those USB troubles roared), but
on my laptop there's already a showstopper with while trying to start
beloved jackd -R:

---
Unable to handle kernel paging request at virtual address 00010024
 printing eip:
c011995f
*pde = 00000000
Oops: 0002 [#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 ohci1394 ieee1394 loop subfs evdev ohci_hcd usbcore thermal
processor fan button battery ac
CPU:    0
EIP:    0060:[<c011995f>]    Not tainted VLI
EFLAGS: 00010086   (2.6.9-rc3-mm3-T3.0)
EIP is at profile_hit+0x2f/0x33
eax: 00010024   ebx: de1f8510   ecx: 00000000   edx: 00000000
esi: 00000001   edi: ffffffea   ebp: db32ef88   esp: db32ef88
ds: 007b   es: 007b   ss: 0068   preempt: 00000003
Process jackd (pid: 6519, threadinfo=db32e000 task=dec4fa00)
Stack: db32efbc c0115431 00000002 c0104231 00000004 c0398460 c0102d2f
007d0f00
       00000046 0000001e 00001979 b75a1bb0 b7fa5a4c db32e000 c0104231
00001979
       00000001 b75a1dac b75a1bb0 b7fa5a4c bfffb9b8 0000009c 0000007b
0000007b
Call Trace:
 [<c0115431>] setscheduler+0xc4/0x254
 [<c0104231>] sysenter_past_esp+0x52/0x71
 [<c0102d2f>] sys_clone+0x40/0x42
 [<c0104231>] sysenter_past_esp+0x52/0x71
Code: b8 60 ff ff 8b 0d ec 16 3a c0 8b 15 e8 16 3a c0 8b 45 0c 83 ea 01 2d
28 02 10 c0 d3 e8 39 c2 0f 46 c2 8b 15 e4 16 3a c0 8d 04 82 <ff> 00 5d c3
55 89 e5 e8 85 60 ff ff b8 da ff ff ff 5d c3 55 89
 <6>note: jackd[6519] exited with preempt_count 2
Debug: sleeping function called from invalid context jackd(6519) at
kernel/fork.c:421
in_atomic():1, irqs_disabled():0
 [<c0116385>] __might_sleep+0xb5/0xc5
 [<c011921c>] vprintk+0x135/0x182
 [<c0116927>] mm_release+0x72/0xcf
 [<c01190e5>] printk+0x1d/0x1f
 [<c011b3a6>] do_exit+0x85/0x506
 [<c0112f0e>] do_page_fault+0x0/0x67e
 [<c0105539>] do_divide_error+0x0/0x13a
 [<c0112f0e>] do_page_fault+0x0/0x67e
 [<c01190e5>] printk+0x1d/0x1f
 [<c01133a7>] do_page_fault+0x499/0x67e
 [<c01c54dd>] __copy_from_user_ll+0x11/0x76
 [<c012efbc>] check_preempt_timing+0x18f/0x1fb
 [<c012f1ce>] sub_preempt_count+0x5c/0x8b
 [<c0117869>] copy_process+0x610/0xcfe
 [<c010eca6>] sched_clock+0x14/0x8d
 [<c012f1ce>] sub_preempt_count+0x5c/0x8b
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c012efbc>] check_preempt_timing+0x18f/0x1fb
 [<c012f1ce>] sub_preempt_count+0x5c/0x8b
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c0117869>] copy_process+0x610/0xcfe
 [<c0117869>] copy_process+0x610/0xcfe
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c0112f0e>] do_page_fault+0x0/0x67e
 [<c0104c8d>] error_code+0x2d/0x38
 [<c011995f>] profile_hit+0x2f/0x33
 [<c0115431>] setscheduler+0xc4/0x254
 [<c0104231>] sysenter_past_esp+0x52/0x71
 [<c0102d2f>] sys_clone+0x40/0x42
 [<c0104231>] sysenter_past_esp+0x52/0x71
scheduling while atomic: jackd/0x04000002/6519
 [<c02d21cc>] schedule+0x554/0x5f5
 [<c02d27f4>] cond_resched+0x5f/0x7f
 [<c011692c>] mm_release+0x77/0xcf
 [<c01190e5>] printk+0x1d/0x1f
 [<c011b3a6>] do_exit+0x85/0x506
 [<c0112f0e>] do_page_fault+0x0/0x67e
 [<c0105539>] do_divide_error+0x0/0x13a
 [<c0112f0e>] do_page_fault+0x0/0x67e
 [<c01190e5>] printk+0x1d/0x1f
 [<c01133a7>] do_page_fault+0x499/0x67e
 [<c01c54dd>] __copy_from_user_ll+0x11/0x76
 [<c012efbc>] check_preempt_timing+0x18f/0x1fb
 [<c012f1ce>] sub_preempt_count+0x5c/0x8b
 [<c0117869>] copy_process+0x610/0xcfe
 [<c010eca6>] sched_clock+0x14/0x8d
 [<c012f1ce>] sub_preempt_count+0x5c/0x8b
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c012efbc>] check_preempt_timing+0x18f/0x1fb
 [<c012f1ce>] sub_preempt_count+0x5c/0x8b
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c0117869>] copy_process+0x610/0xcfe
 [<c0117869>] copy_process+0x610/0xcfe
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c01146c3>] wake_up_new_task+0x142/0x190
 [<c0112f0e>] do_page_fault+0x0/0x67e
 [<c0104c8d>] error_code+0x2d/0x38
 [<c011995f>] profile_hit+0x2f/0x33
 [<c0115431>] setscheduler+0xc4/0x254
 [<c0104231>] sysenter_past_esp+0x52/0x71
 [<c0102d2f>] sys_clone+0x40/0x42
 [<c0104231>] sysenter_past_esp+0x52/0x71
---

This jackd crash seems to show up due to CONFIG_DEBUG_PREEMPT being set
on, but not sure yet.

CU
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Rui Nuno Capela]

>
> please re-download it, this is another bug i've fixed in the re-uploaded
> version. Does the new patch work?
>

OK. Now it works fine. Thanks Ingo.

Maybe I'm just a plain idiot, but wouldn't it be welcome to add another
dot number or whatever to the VP filename label? IMHO that should clear
things of what actual patch release are we really applying.

The crash with jackd wasn't the only one, some other sound apps also failed
with similar kernel oopses dumps.

And, just out of curiosity, I've also tested "vanilla" 2.6.9-rc3-mm3 and
it looks like suffering from the same illness. So this has to be yet
another "feature" of the -mm line ;)

I'm glad this time VP came to the rescue :)

Take care.
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Rui Nuno Capela]

Ingo Molnar wrote:
>
>>
>> i've released the -T3 VP patch:
>>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
>>
>

OK. Just to let you know, both of my personal machines are now running on
bleeding-edge 2.6.9-rc3-mm3-T3, and very happily may I assure :)

- my laptop, Mandrake 10.1c: P4@2.5GHz UP
- my desktop, SUSE 9.1 Pro: P4@2.8GHz HT/SMP

USB is fine and so is jackd, only to mention my recently known annoyances.

Even my Wacom Graphire USB is working without anything else but the kernel
supplied stuff. Most of the previous kernel installs I had to pullover
from linuxwacom.sf.net the mousedev, evdev and wacom modules, just to get
this tablet working straight on X, but now it seems pretty native :)

Good times are we living, eh?

Take care.
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Thu, 2004-10-07 at 19:26, Rui Nuno Capela wrote:
> Ingo Molnar wrote:
> >
> >>
> >> i've released the -T3 VP patch:
> >>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> >>
> >
> 
> OK. Just to let you know, both of my personal machines are now running on
> bleeding-edge 2.6.9-rc3-mm3-T3, and very happily may I assure :)

This actually feels a _lot_ snappier than mm2, which seemed prone to
weird stalls.  I don't have any numbers to back this up yet.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Con Kolivas]

Lee Revell wrote:
> On Thu, 2004-10-07 at 19:26, Rui Nuno Capela wrote:
> 
>>Ingo Molnar wrote:
>>
>>>>i've released the -T3 VP patch:
>>>>  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
>>>>
>>>
>>OK. Just to let you know, both of my personal machines are now running on
>>bleeding-edge 2.6.9-rc3-mm3-T3, and very happily may I assure :)
> 
> 
> This actually feels a _lot_ snappier than mm2, which seemed prone to
> weird stalls.  I don't have any numbers to back this up yet.

mm2 had a completely different cpu scheduler so no meaningful comparison 
can be made. Try comparing to mm3 vanilla.

Cheers,
Con

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Fri, 2004-10-08 at 02:49, Con Kolivas wrote:
> Lee Revell wrote:
> > On Thu, 2004-10-07 at 19:26, Rui Nuno Capela wrote:
> > 
> >>Ingo Molnar wrote:
> >>
> >>>>i've released the -T3 VP patch:
> >>>>  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> >>>>
> >>>
> >>OK. Just to let you know, both of my personal machines are now running on
> >>bleeding-edge 2.6.9-rc3-mm3-T3, and very happily may I assure :)
> > 
> > 
> > This actually feels a _lot_ snappier than mm2, which seemed prone to
> > weird stalls.  I don't have any numbers to back this up yet.
> 
> mm2 had a completely different cpu scheduler so no meaningful comparison 
> can be made. Try comparing to mm3 vanilla.

Well, I figured the change from -mm2 to -mm3 was responsible, as I have
never seen the VP patches make a perceptible difference in system
response time.  The VP effect only becomes apparent when you do
something that really needs millisecond or sub-ms latency.  I guess a
bug in the VP patch could cause performance regressions though.  However
no one reported sluggishness with mm2+S7, but it's apparent when you try
mm3+T3 that it feels a lot more responsive.

Anyway I was just wondering if there was an obvious change that would
cause this.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> On Thu, 2004-10-07 at 19:26, Rui Nuno Capela wrote:
> > Ingo Molnar wrote:
> > >
> > >>
> > >> i've released the -T3 VP patch:
> > >>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> > >>
> > >
> > 
> > OK. Just to let you know, both of my personal machines are now running on
> > bleeding-edge 2.6.9-rc3-mm3-T3, and very happily may I assure :)
> 
> This actually feels a _lot_ snappier than mm2, which seemed prone to
> weird stalls.  I don't have any numbers to back this up yet.

yeah, -mm is back to the development branch of the stock scheduler. 
(i.e. the scheduler changes destined for 2.6.10.)

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Peter Williams]

Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> 
>>On Thu, 2004-10-07 at 19:26, Rui Nuno Capela wrote:
>>
>>>Ingo Molnar wrote:
>>>
>>>>>i've released the -T3 VP patch:
>>>>>  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
>>>>>
>>>>
>>>OK. Just to let you know, both of my personal machines are now running on
>>>bleeding-edge 2.6.9-rc3-mm3-T3, and very happily may I assure :)
>>
>>This actually feels a _lot_ snappier than mm2, which seemed prone to
>>weird stalls.  I don't have any numbers to back this up yet.
> 
> 
> yeah, -mm is back to the development branch of the stock scheduler. 
> (i.e. the scheduler changes destined for 2.6.10.)

It's also got a fix for the cache hot timing bug which was causing havoc 
with the load balancer.

Peter
-- 
Peter Williams                                   pwil3058@bigpond.net.au

"Learning, n. The kind of ignorance distinguishing the studious."
  -- Ambrose Bierce

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Fri, 2004-10-08 at 03:36, Peter Williams wrote:
> Ingo Molnar wrote:
> > * Lee Revell <rlrevell@joe-job.com> wrote:
> > 
> > 
> >>On Thu, 2004-10-07 at 19:26, Rui Nuno Capela wrote:
> >>
> >>>Ingo Molnar wrote:
> >>>
> >>>>>i've released the -T3 VP patch:
> >>>>>  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> >>>>>
> >>>>
> >>>OK. Just to let you know, both of my personal machines are now running on
> >>>bleeding-edge 2.6.9-rc3-mm3-T3, and very happily may I assure :)
> >>
> >>This actually feels a _lot_ snappier than mm2, which seemed prone to
> >>weird stalls.  I don't have any numbers to back this up yet.
> > 
> > 
> > yeah, -mm is back to the development branch of the stock scheduler. 
> > (i.e. the scheduler changes destined for 2.6.10.)
> 
> It's also got a fix for the cache hot timing bug which was causing havoc 
> with the load balancer.

Wouldn't this only be an issue on SMP?  I am on a UP system.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[K.R. Foley]

Ingo Molnar wrote:
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 

For me, this one wants to panic on boot when trying to find the root 
filesystem. Acts like either the aic7xxx module is missing (which I 
don't think is the case) or hosed, or it's having trouble with the label 
for the root partition (Fedora system). Will investigate further when I 
get home tonight, unless something jumps out at anyone.

kr

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[K.R. Foley]

K.R. Foley wrote:
> Ingo Molnar wrote:
> 
>> i've released the -T3 VP patch:
>>
>>   
>> http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3 
>>
>>
> 
> For me, this one wants to panic on boot when trying to find the root 
> filesystem. Acts like either the aic7xxx module is missing (which I 
> don't think is the case) or hosed, or it's having trouble with the label 
> for the root partition (Fedora system). Will investigate further when I 
> get home tonight, unless something jumps out at anyone.
> 
> kr

For clarification: This appears to be a problem in 2.6.9-rc3-mm3 also.

kr

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Ingo Molnar]

* K.R. Foley <kr@cybsft.com> wrote:

> >For me, this one wants to panic on boot when trying to find the root 
> >filesystem. Acts like either the aic7xxx module is missing (which I 
> >don't think is the case) or hosed, or it's having trouble with the label 
> >for the root partition (Fedora system). Will investigate further when I 
> >get home tonight, unless something jumps out at anyone.
> >
> >kr
> 
> For clarification: This appears to be a problem in 2.6.9-rc3-mm3 also.

try root=/dev/sda3 (or whereever your root fs is) instead of
root=LABEL=/, in /etc/grub.conf.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[K.R. Foley]

Ingo Molnar wrote:
> * K.R. Foley <kr@cybsft.com> wrote:
> 
> 
>>>For me, this one wants to panic on boot when trying to find the root 
>>>filesystem. Acts like either the aic7xxx module is missing (which I 
>>>don't think is the case) or hosed, or it's having trouble with the label 
>>>for the root partition (Fedora system). Will investigate further when I 
>>>get home tonight, unless something jumps out at anyone.
>>>
>>>kr
>>
>>For clarification: This appears to be a problem in 2.6.9-rc3-mm3 also.
> 
> 
> try root=/dev/sda3 (or whereever your root fs is) instead of
> root=LABEL=/, in /etc/grub.conf.
> 
> 	Ingo
> 

Thanks. Tried that just to be sure. However, I don't seem to be the only 
one having this problem with aic7xxx.

kr

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Ingo Molnar]

* K.R. Foley <kr@cybsft.com> wrote:

> Ingo Molnar wrote:
> >* K.R. Foley <kr@cybsft.com> wrote:
> >
> >
> >>>For me, this one wants to panic on boot when trying to find the root 
> >>>filesystem. Acts like either the aic7xxx module is missing (which I 
> >>>don't think is the case) or hosed, or it's having trouble with the label 
> >>>for the root partition (Fedora system). Will investigate further when I 
> >>>get home tonight, unless something jumps out at anyone.
> >>>
> >>>kr
> >>
> >>For clarification: This appears to be a problem in 2.6.9-rc3-mm3 also.
> >
> >
> >try root=/dev/sda3 (or whereever your root fs is) instead of
> >root=LABEL=/, in /etc/grub.conf.
> >
> >	Ingo
> >
> 
> Thanks. Tried that just to be sure. However, I don't seem to be the
> only one having this problem with aic7xxx.

could you send me the following info:

  - full log of a failed boot
  - full log of a successful boot
  - the output of 'mount'

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[K.R. Foley]

[-- Attachment #1: Type: text/plain, Size: 2152 bytes --]

Ingo Molnar wrote:
> * K.R. Foley <kr@cybsft.com> wrote:
> 
> 
>>Ingo Molnar wrote:
>>
>>>* K.R. Foley <kr@cybsft.com> wrote:
>>>
>>>
>>>
>>>>>For me, this one wants to panic on boot when trying to find the root 
>>>>>filesystem. Acts like either the aic7xxx module is missing (which I 
>>>>>don't think is the case) or hosed, or it's having trouble with the label 
>>>>>for the root partition (Fedora system). Will investigate further when I 
>>>>>get home tonight, unless something jumps out at anyone.
>>>>>
>>>>>kr
>>>>
>>>>For clarification: This appears to be a problem in 2.6.9-rc3-mm3 also.
>>>
>>>
>>>try root=/dev/sda3 (or whereever your root fs is) instead of
>>>root=LABEL=/, in /etc/grub.conf.
>>>
>>>	Ingo
>>>
>>
>>Thanks. Tried that just to be sure. However, I don't seem to be the
>>only one having this problem with aic7xxx.
> 
> 

Ingo,

First let me say that, in case you haven't been following the other 
thread about this "2.6.9-rc3-mm3 fails to detect aic7xxx", I resolved 
this by backing out the bk-scsi.patch and bk-scsi-target.patch. Without 
those everything works fine.

> could you send me the following info:
> 
>   - full log of a failed boot

I would like to be able to be able to send you this, but it doesn't get 
to the point of logging. It dies trying to find the / device. On the 
screen it displays the parameters for the chosen option in grub.conf, 
says its uncompressing, then displays the Nash version info, then 
displays a panic message about not finding the root device. Something on 
the order of:

Kernel panic - not syncing: VFS: Unable to mount root fs on 
unknown-block(0,0)

Do you think that I would actually get to see more info out of this if I 
connect a serial console?

>   - full log of a successful boot

Attached.

>   - the output of 'mount'

[root@porky root]# mount
/dev/sda2 on / type ext3 (rw)
none on /proc type proc (rw)
none on /sys type sysfs (rw)
none on /dev/pts type devpts (rw,gid=5,mode=620)
/dev/sda1 on /boot type ext3 (rw)
/dev/sdb1 on /proj1 type ext3 (rw)
none on /dev/shm type tmpfs (rw)
sunrpc on /var/lib/nfs/rpc_pipefs type rpc_pipefs (rw)

> 
> 	Ingo
> 

thanks,

kr


[-- Attachment #2: bootlog.ok --]
[-- Type: text/plain, Size: 23743 bytes --]

Oct  8 06:48:42 porky syslogd 1.4.1: restart.
Oct  8 06:48:42 porky syslog: syslogd startup succeeded
Oct  8 06:48:42 porky syslog: klogd startup succeeded
Oct  8 06:48:42 porky kernel: klogd 1.4.1, log source = /proc/kmsg started.
Oct  8 06:48:42 porky kernel: Linux version 2.6.9-rc3-mm3-VP-T3 (kr@porky.cybersoft.int) (gcc version 3.3.3 20040412 (Red Hat Linux 3.3.3-7)) #8 SMP Thu Oct 7 23:07:40 CDT 2004
Oct  8 06:48:42 porky kernel: BIOS-provided physical RAM map:
Oct  8 06:48:42 porky kernel:  BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
Oct  8 06:48:42 porky kernel:  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
Oct  8 06:48:42 porky kernel:  BIOS-e820: 0000000000100000 - 000000001ff9e000 (usable)
Oct  8 06:48:42 porky kernel:  BIOS-e820: 000000001ff9e000 - 0000000020000000 (reserved)
Oct  8 06:48:42 porky kernel:  BIOS-e820: 00000000fec00000 - 00000000fec10000 (reserved)
Oct  8 06:48:42 porky kernel:  BIOS-e820: 00000000fee00000 - 00000000fee10000 (reserved)
Oct  8 06:48:42 porky kernel:  BIOS-e820: 00000000ffb00000 - 0000000100000000 (reserved)
Oct  8 06:48:42 porky kernel: 0MB HIGHMEM available.
Oct  8 06:48:42 porky kernel: 511MB LOWMEM available.
Oct  8 06:48:42 porky kernel: found SMP MP-table at 000fe710
Oct  8 06:48:42 porky kernel: DMI 2.3 present.
Oct  8 06:48:42 porky irqbalance: irqbalance startup succeeded
Oct  8 06:48:42 porky kernel: ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
Oct  8 06:48:42 porky kernel: Processor #0 6:8 APIC version 17
Oct  8 06:48:42 porky kernel: ACPI: LAPIC (acpi_id[0x02] lapic_id[0x01] enabled)
Oct  8 06:48:42 porky kernel: Processor #1 6:8 APIC version 17
Oct  8 06:48:42 porky kernel: ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
Oct  8 06:48:42 porky kernel: ACPI: LAPIC_NMI (acpi_id[0x02] high edge lint[0x1])
Oct  8 06:48:42 porky kernel: Using ACPI for processor (LAPIC) configuration information
Oct  8 06:48:42 porky kernel: Intel MultiProcessor Specification v1.4
Oct  8 06:48:42 porky kernel:     Virtual Wire compatibility mode.
Oct  8 06:48:42 porky kernel: OEM ID: DELL     Product ID: WS 620       APIC at: 0xFEE00000
Oct  8 06:48:42 porky kernel: I/O APIC #2 Version 32 at 0xFEC00000.
Oct  8 06:48:42 porky kernel: Enabling APIC mode:  Flat.  Using 1 I/O APICs
Oct  8 06:48:42 porky kernel: Processors: 2
Oct  8 06:48:42 porky portmap: portmap startup succeeded
Oct  8 06:48:42 porky kernel: Built 1 zonelists
Oct  8 06:48:42 porky kernel: Initializing CPU#0
Oct  8 06:48:43 porky kernel: Kernel command line: ro root=LABEL=/ rhgb quiet noapic
Oct  8 06:48:43 porky kernel: (swapper/0): new 196391 us maximum-latency critical section.
Oct  8 06:48:43 porky kernel:  => started at: <start_kernel+0x48/0x1e0>
Oct  8 06:48:43 porky kernel:  => ended at:   <cond_resched+0x25/0x80>
Oct  8 06:48:43 porky kernel:  [<c0137a38>] touch_preempt_timing+0x48/0x50
Oct  8 06:48:43 porky kernel:  [<c0137952>] check_preempt_timing+0x162/0x200
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:43 porky kernel:  [<c0137a38>] touch_preempt_timing+0x48/0x50
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:43 porky rpc.statd[2435]: Version 1.0.6 Starting
Oct  8 06:48:43 porky kernel:  [<c0138e58>] register_cpu_notifier+0x18/0x60
Oct  8 06:48:43 porky kernel:  [<c0133688>] rcu_cpu_notify+0x38/0x40
Oct  8 06:48:43 porky kernel:  [<c0381d0d>] rcu_init+0x6d/0x80
Oct  8 06:48:43 porky kernel:  [<c037097c>] start_kernel+0xbc/0x1e0
Oct  8 06:48:43 porky nfslock: rpc.statd startup succeeded
Oct  8 06:48:43 porky kernel:  [<c0370440>] unknown_bootoption+0x0/0x190
Oct  8 06:48:43 porky kernel: PID hash table entries: 2048 (order: 11, 32768 bytes)
Oct  8 06:48:43 porky kernel: (swapper/0): new 205265 us maximum-latency critical section.
Oct  8 06:48:43 porky kernel:  => started at: <cond_resched+0x25/0x80>
Oct  8 06:48:43 porky kernel:  => ended at:   <cond_resched+0x25/0x80>
Oct  8 06:48:43 porky kernel:  [<c0137a38>] touch_preempt_timing+0x48/0x50
Oct  8 06:48:43 porky kernel:  [<c0137952>] check_preempt_timing+0x162/0x200
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:43 porky kernel:  [<c0137a38>] touch_preempt_timing+0x48/0x50
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:43 porky kernel:  [<c0138e58>] register_cpu_notifier+0x18/0x60
Oct  8 06:48:43 porky kernel:  [<c012b21b>] timer_cpu_notify+0x2b/0x30
Oct  8 06:48:43 porky kernel:  [<c03819d5>] init_timers+0x35/0x60
Oct  8 06:48:43 porky kernel:  [<c037098b>] start_kernel+0xcb/0x1e0
Oct  8 06:48:43 porky kernel:  [<c0370440>] unknown_bootoption+0x0/0x190
Oct  8 06:48:43 porky kernel: Detected 931.130 MHz processor.
Oct  8 06:48:43 porky kernel: Using tsc for high-res timesource
Oct  8 06:48:43 porky kernel: (swapper/0): new 502992 us maximum-latency critical section.
Oct  8 06:48:43 porky kernel:  => started at: <cond_resched+0x25/0x80>
Oct  8 06:48:43 porky kernel:  => ended at:   <cond_resched+0x25/0x80>
Oct  8 06:48:43 porky kernel:  [<c0137a38>] touch_preempt_timing+0x48/0x50
Oct  8 06:48:43 porky kernel:  [<c0137952>] check_preempt_timing+0x162/0x200
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:43 porky kernel:  [<c0137a38>] touch_preempt_timing+0x48/0x50
Oct  8 06:48:43 porky rpcidmapd: rpc.idmapd startup succeeded
Oct  8 06:48:43 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:44 porky kernel:  [<c02b67b5>] cond_resched+0x25/0x80
Oct  8 06:48:44 porky kernel:  [<c01212fb>] acquire_console_sem+0x2b/0x60
Oct  8 06:48:44 porky kernel:  [<c038a4e3>] con_init+0x13/0x2b0
Oct  8 06:48:44 porky kernel:  [<c0114df0>] mcount+0x14/0x18
Oct  8 06:48:44 porky kernel:  [<c0389a12>] console_init+0x42/0x50
Oct  8 06:48:44 porky kernel:  [<c037099a>] start_kernel+0xda/0x1e0
Oct  8 06:48:44 porky kernel:  [<c0370440>] unknown_bootoption+0x0/0x190
Oct  8 06:48:44 porky kernel: Console: colour VGA+ 80x25
Oct  8 06:48:44 porky random: Initializing random number generator:  succeeded
Oct  8 06:48:44 porky kernel: Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Oct  8 06:48:44 porky kernel: Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Oct  8 06:48:44 porky kernel: Memory: 513384k/523896k available (1762k kernel code, 9892k reserved, 725k data, 284k init, 0k highmem)
Oct  8 06:48:44 porky kernel: Checking if this processor honours the WP bit even in supervisor mode... Ok.
Oct  8 06:48:44 porky kernel: Security Scaffold v1.0.0 initialized
Oct  8 06:48:44 porky kernel: Capability LSM initialized
Oct  8 06:48:44 porky kernel: Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
Oct  8 06:48:44 porky rc: Starting pcmcia:  succeeded
Oct  8 06:48:44 porky kernel: CPU: L1 I cache: 16K, L1 D cache: 16K
Oct  8 06:48:44 porky kernel: CPU: L2 cache: 256K
Oct  8 06:48:44 porky kernel: Intel machine check architecture supported.
Oct  8 06:48:44 porky kernel: Intel machine check reporting enabled on CPU#0.
Oct  8 06:48:44 porky kernel: Enabling fast FPU save and restore... done.
Oct  8 06:48:44 porky kernel: Enabling unmasked SIMD FPU exception support... done.
Oct  8 06:48:44 porky kernel: Checking 'hlt' instruction... OK.
Oct  8 06:48:44 porky kernel: CPU0: Intel Pentium III (Coppermine) stepping 06
Oct  8 06:48:44 porky kernel: per-CPU timeslice cutoff: 731.28 usecs.
Oct  8 06:48:39 porky sysctl: kernel.sysrq = 0 
Oct  8 06:48:44 porky kernel: task migration cache decay timeout: 1 msecs.
Oct  8 06:48:39 porky sysctl: kernel.core_uses_pid = 1 
Oct  8 06:48:44 porky kernel: Booting processor 1/1 eip 2000
Oct  8 06:48:39 porky network: Setting network parameters:  succeeded 
Oct  8 06:48:44 porky kernel: Initializing CPU#1
Oct  8 06:48:39 porky network: Bringing up loopback interface:  succeeded 
Oct  8 06:48:44 porky netfs: Mounting other filesystems:  succeeded
Oct  8 06:48:44 porky kernel: CPU: L1 I cache: 16K, L1 D cache: 16K
Oct  8 06:48:44 porky kernel: CPU: L2 cache: 256K
Oct  8 06:48:44 porky kernel: Intel machine check architecture supported.
Oct  8 06:48:44 porky kernel: Intel machine check reporting enabled on CPU#1.
Oct  8 06:48:44 porky kernel: CPU1: Intel Pentium III (Coppermine) stepping 06
Oct  8 06:48:44 porky kernel: Total of 2 processors activated (3682.30 BogoMIPS).
Oct  8 06:48:44 porky kernel: checking TSC synchronization across 2 CPUs: passed.
Oct  8 06:48:44 porky kernel: ksoftirqd started up.
Oct  8 06:48:44 porky kernel: Brought up 2 CPUs
Oct  8 06:48:44 porky kernel: ksoftirqd started up.
Oct  8 06:48:44 porky kernel: checking if image is initramfs...it isn't (no cpio magic); looks like an initrd
Oct  8 06:48:44 porky kernel: Freeing initrd memory: 355k freed
Oct  8 06:48:44 porky kernel: NET: Registered protocol family 16
Oct  8 06:48:44 porky autofs: automount startup succeeded
Oct  8 06:48:44 porky kernel: PCI: PCI BIOS revision 2.10 entry at 0xfc03e, last bus=4
Oct  8 06:48:44 porky kernel: PCI: Using configuration type 1
Oct  8 06:48:44 porky kernel: mtrr: v2.0 (20020519)
Oct  8 06:48:44 porky kernel: Linux Plug and Play Support v0.97 (c) Adam Belay
Oct  8 06:48:44 porky kernel: PCI: Probing PCI hardware
Oct  8 06:48:44 porky kernel: PCI: Probing PCI hardware (bus 00)
Oct  8 06:48:44 porky kernel: PCI: Transparent bridge - 0000:00:1e.0
Oct  8 06:48:44 porky kernel: PCI: Using IRQ router PIIX/ICH [8086/2410] at 0000:00:1f.0
Oct  8 06:48:45 porky smartd[2575]: smartd version 5.21 Copyright (C) 2002-3 Bruce Allen 
Oct  8 06:48:45 porky kernel: PCI: Failed to allocate mem resource #0:1000@0 for 0000:03:00.0
Oct  8 06:48:45 porky smartd[2575]: Home page is http://smartmontools.sourceforge.net/  
Oct  8 06:48:45 porky kernel: apm: BIOS version 1.2 Flags 0x03 (Driver version 1.16ac)
Oct  8 06:48:45 porky smartd[2575]: Opened configuration file /etc/smartd.conf 
Oct  8 06:48:45 porky kernel: apm: disabled - APM is not SMP safe.
Oct  8 06:48:45 porky smartd[2575]: Configuration file /etc/smartd.conf parsed. 
Oct  8 06:48:45 porky kernel: Starting balanced_irq
Oct  8 06:48:45 porky smartd[2575]: Device: /dev/hda, opened 
Oct  8 06:48:45 porky kernel: VFS: Disk quotas dquot_6.5.1
Oct  8 06:48:45 porky smartd[2575]: Device: /dev/hda, unable to read Device Identity Structure 
Oct  8 06:48:45 porky kernel: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Oct  8 06:48:45 porky smartd[2575]: Unable to register ATA device /dev/hda at line 30 of file /etc/smartd.conf 
Oct  8 06:48:45 porky kernel: Initializing Cryptographic API
Oct  8 06:48:45 porky smartd[2575]: Unable to register device /dev/hda (no Directive -d removable). Exiting. 
Oct  8 06:48:45 porky kernel: vesafb: probe of vesafb0 failed with error -6
Oct  8 06:48:45 porky kernel: isapnp: Scanning for PnP cards...
Oct  8 06:48:45 porky smartd: smartd startup failed
Oct  8 06:48:45 porky kernel: isapnp: No Plug & Play device found
Oct  8 06:48:45 porky kernel: requesting new irq thread for IRQ8...
Oct  8 06:48:45 porky kernel: Real Time Clock Driver v1.12
Oct  8 06:48:45 porky kernel: requesting new irq thread for IRQ12...
Oct  8 06:48:45 porky kernel: serio: i8042 AUX port at 0x60,0x64 irq 12
Oct  8 06:48:45 porky kernel: serio: i8042 KBD port at 0x60,0x64 irq 1
Oct  8 06:48:45 porky kernel: io scheduler noop registered
Oct  8 06:48:45 porky kernel: io scheduler anticipatory registered
Oct  8 06:48:45 porky kernel: io scheduler deadline registered
Oct  8 06:48:45 porky kernel: io scheduler cfq registered
Oct  8 06:48:45 porky kernel: RAMDISK driver initialized: 16 RAM disks of 8192K size 1024 blocksize
Oct  8 06:48:45 porky kernel: Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
Oct  8 06:48:45 porky kernel: ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
Oct  8 06:48:45 porky kernel: ICH: IDE controller at PCI slot 0000:00:1f.1
Oct  8 06:48:45 porky kernel: ICH: chipset revision 2
Oct  8 06:48:45 porky kernel: ICH: not 100%% native mode: will probe irqs later
Oct  8 06:48:45 porky kernel:     ide0: BM-DMA at 0xffa0-0xffa7, BIOS settings: hda:DMA, hdb:pio
Oct  8 06:48:45 porky kernel:     ide1: BM-DMA at 0xffa8-0xffaf, BIOS settings: hdc:DMA, hdd:pio
Oct  8 06:48:45 porky kernel: hda: SAMSUNG CD-R/RW SW-248F, ATAPI CD/DVD-ROM drive
Oct  8 06:48:45 porky kernel: requesting new irq thread for IRQ14...
Oct  8 06:48:45 porky kernel: elevator: using anticipatory as default io scheduler
Oct  8 06:48:45 porky kernel: ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Oct  8 06:48:45 porky kernel: hdc: Lite-On LTN483S 48x Max, ATAPI CD/DVD-ROM drive
Oct  8 06:48:45 porky kernel: requesting new irq thread for IRQ15...
Oct  8 06:48:45 porky kernel: ide1 at 0x170-0x177,0x376 on irq 15
Oct  8 06:48:46 porky kernel: mice: PS/2 mouse device common for all mice
Oct  8 06:48:46 porky kernel: IRQ#12 thread started up.
Oct  8 06:48:46 porky kernel: requesting new irq thread for IRQ1...
Oct  8 06:48:46 porky kernel: IRQ#1 thread started up.
Oct  8 06:48:46 porky kernel: input: AT Translated Set 2 keyboard on isa0060/serio0
Oct  8 06:48:46 porky kernel: input: ImPS/2 Generic Wheel Mouse on isa0060/serio1
Oct  8 06:48:46 porky kernel: md: md driver 0.90.0 MAX_MD_DEVS=256, MD_SB_DISKS=27
Oct  8 06:48:46 porky kernel: NET: Registered protocol family 2
Oct  8 06:48:46 porky kernel: IP: routing cache hash table of 2048 buckets, 32Kbytes
Oct  8 06:48:46 porky kernel: TCP: Hash tables configured (established 16384 bind 21845)
Oct  8 06:48:46 porky kernel: NET: Registered protocol family 1
Oct  8 06:48:46 porky kernel: NET: Registered protocol family 17
Oct  8 06:48:46 porky kernel: NET: Registered protocol family 8
Oct  8 06:48:46 porky kernel: NET: Registered protocol family 20
Oct  8 06:48:46 porky kernel: md: Autodetecting RAID arrays.
Oct  8 06:48:46 porky kernel: md: autorun ...
Oct  8 06:48:46 porky rc: Starting hpoj:  succeeded
Oct  8 06:48:46 porky kernel: md: ... autorun DONE.
Oct  8 06:48:46 porky kernel: RAMDISK: Compressed image found at block 0
Oct  8 06:48:46 porky kernel: VFS: Mounted root (ext2 filesystem).
Oct  8 06:48:46 porky kernel: SCSI subsystem initialized
Oct  8 06:48:46 porky kernel: PCI: Found IRQ 10 for device 0000:04:05.0
Oct  8 06:48:46 porky kernel: PCI: Sharing IRQ 10 with 0000:00:1f.3
Oct  8 06:48:47 porky kernel: requesting new irq thread for IRQ10...
Oct  8 06:48:47 porky kernel: PCI: Found IRQ 5 for device 0000:04:05.1
Oct  8 06:48:47 porky kernel: PCI: Sharing IRQ 5 with 0000:04:0a.0
Oct  8 06:48:47 porky kernel: requesting new irq thread for IRQ5...
Oct  8 06:48:47 porky kernel: scsi0 : Adaptec AIC7XXX EISA/VLB/PCI SCSI HBA DRIVER, Rev 6.2.36
Oct  8 06:48:47 porky kernel:         <Adaptec aic7899 Ultra160 SCSI adapter>
Oct  8 06:48:47 porky kernel:         aic7899: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs
Oct  8 06:48:47 porky kernel: 
Oct  8 06:48:47 porky kernel: IRQ#10 thread started up.
Oct  8 06:48:47 porky kernel: (scsi0:A:0): 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit)
Oct  8 06:48:47 porky kernel:   Vendor: QUANTUM   Model: ATLAS10K2-TY092L  Rev: DA40
Oct  8 06:48:47 porky kernel:   Type:   Direct-Access                      ANSI SCSI revision: 03
Oct  8 06:48:48 porky kernel: scsi0:A:0:0: Tagged Queuing enabled.  Depth 32
Oct  8 06:48:48 porky kernel: SCSI device sda: 17783239 512-byte hdwr sectors (9105 MB)
Oct  8 06:48:48 porky kernel: SCSI device sda: drive cache: write back
Oct  8 06:48:48 porky kernel:  sda: sda1 sda2 sda3
Oct  8 06:48:48 porky kernel: Attached scsi disk sda at scsi0, channel 0, id 0, lun 0
Oct  8 06:48:48 porky kernel: scsi1 : Adaptec AIC7XXX EISA/VLB/PCI SCSI HBA DRIVER, Rev 6.2.36
Oct  8 06:48:48 porky kernel:         <Adaptec aic7899 Ultra160 SCSI adapter>
Oct  8 06:48:48 porky kernel:         aic7899: Ultra160 Wide Channel B, SCSI Id=7, 32/253 SCBs
Oct  8 06:48:48 porky kernel: 
Oct  8 06:48:48 porky kernel: IRQ#5 thread started up.
Oct  8 06:48:48 porky kernel: (scsi1:A:0): 20.000MB/s transfers (20.000MHz, offset 15)
Oct  8 06:48:48 porky kernel:   Vendor: SEAGATE   Model: SX118273LC        Rev: 6679
Oct  8 06:48:48 porky kernel:   Type:   Direct-Access                      ANSI SCSI revision: 02
Oct  8 06:48:48 porky kernel: scsi1:A:0:0: Tagged Queuing enabled.  Depth 32
Oct  8 06:48:48 porky kernel: SCSI device sdb: 35566480 512-byte hdwr sectors (18210 MB)
Oct  8 06:48:48 porky kernel: SCSI device sdb: drive cache: write through
Oct  8 06:48:48 porky kernel:  sdb: sdb1
Oct  8 06:48:48 porky kernel: Attached scsi disk sdb at scsi1, channel 0, id 0, lun 0
Oct  8 06:48:48 porky kernel: EXT3-fs: mounted filesystem with ordered data mode.
Oct  8 06:48:48 porky kernel: kjournald starting.  Commit interval 5 seconds
Oct  8 06:48:48 porky kernel: Freeing unused kernel memory: 284k freed
Oct  8 06:48:48 porky kernel: NET: Registered protocol family 10
Oct  8 06:48:48 porky kernel: IPv6 over IPv4 tunneling driver
Oct  8 06:48:48 porky kernel: IRQ#8 thread started up.
Oct  8 06:48:48 porky kernel: usbcore: registered new driver usbfs
Oct  8 06:48:48 porky kernel: usbcore: registered new driver hub
Oct  8 06:48:48 porky kernel: USB Universal Host Controller Interface driver v2.2
Oct  8 06:48:48 porky kernel: PCI: Found IRQ 11 for device 0000:00:1f.2
Oct  8 06:48:48 porky kernel: uhci_hcd 0000:00:1f.2: Intel Corp. 82801AA USB
Oct  8 06:48:48 porky kernel: requesting new irq thread for IRQ11...
Oct  8 06:48:48 porky kernel: uhci_hcd 0000:00:1f.2: irq 11, io base 0xff80
Oct  8 06:48:48 porky kernel: uhci_hcd 0000:00:1f.2: new USB bus registered, assigned bus number 1
Oct  8 06:48:48 porky kernel: hub 1-0:1.0: USB hub found
Oct  8 06:48:48 porky kernel: hub 1-0:1.0: 2 ports detected
Oct  8 06:48:48 porky kernel: EXT3 FS on sda2, internal journal
Oct  8 06:48:48 porky kernel: device-mapper: 4.1.0-ioctl (2003-12-10) initialised: dm@uk.sistina.com
Oct  8 06:48:48 porky kernel: Adding 1044216k swap on /dev/sda3.  Priority:-1 extents:1
Oct  8 06:48:48 porky kernel: program scsi_unique_id is using a deprecated SCSI ioctl, please convert it to SG_IO
Oct  8 06:48:49 porky last message repeated 11 times
Oct  8 06:48:49 porky kernel: kjournald starting.  Commit interval 5 seconds
Oct  8 06:48:49 porky kernel: EXT3 FS on sda1, internal journal
Oct  8 06:48:49 porky kernel: EXT3-fs: mounted filesystem with ordered data mode.
Oct  8 06:48:49 porky kernel: kjournald starting.  Commit interval 5 seconds
Oct  8 06:48:49 porky kernel: EXT3 FS on sdb1, internal journal
Oct  8 06:48:49 porky kernel: EXT3-fs: mounted filesystem with ordered data mode.
Oct  8 06:48:49 porky kernel: IA-32 Microcode Update Driver: v1.14 <tigran@veritas.com>
Oct  8 06:48:49 porky kernel: microcode: CPU0 already at revision 0x2 (current=0x2)
Oct  8 06:48:49 porky kernel: microcode: CPU1 already at revision 0x2 (current=0x2)
Oct  8 06:48:49 porky kernel: microcode: No suitable data for CPU0
Oct  8 06:48:49 porky kernel: microcode: No suitable data for CPU1
Oct  8 06:48:49 porky kernel: parport0: PC-style at 0x378 (0x778) [PCSPP,TRISTATE,EPP]
Oct  8 06:48:49 porky kernel: parport0: irq 7 detected
Oct  8 06:48:49 porky kernel: Attached scsi generic sg0 at scsi0, channel 0, id 0, lun 0,  type 0
Oct  8 06:48:49 porky kernel: Attached scsi generic sg1 at scsi1, channel 0, id 0, lun 0,  type 0
Oct  8 06:48:49 porky kernel: inserting floppy driver for 2.6.9-rc3-mm3-VP-T3
Oct  8 06:48:49 porky kernel: Floppy drive(s): fd0 is 1.44M
Oct  8 06:48:49 porky kernel: requesting new irq thread for IRQ6...
Oct  8 06:48:49 porky kernel: IRQ#6 thread started up.
Oct  8 06:48:49 porky kernel: FDC 0 is a National Semiconductor PC87306
Oct  8 06:48:49 porky kernel: Linux Tulip driver version 1.1.13 (May 11, 2002)
Oct  8 06:48:49 porky kernel: PCI: Found IRQ 5 for device 0000:04:0a.0
Oct  8 06:48:49 porky kernel: PCI: Sharing IRQ 5 with 0000:04:05.1
Oct  8 06:48:49 porky kernel: tulip0:  EEPROM default media type Autosense.
Oct  8 06:48:49 porky kernel: tulip0:  Index #0 - Media MII (#11) described by a 21140 MII PHY (1) block.
Oct  8 06:48:49 porky kernel: tulip0:  MII transceiver #3 config 3100 status 7809 advertising 01e1.
Oct  8 06:48:49 porky kernel: eth0: Digital DS21140 Tulip rev 32 at 0xe480, 00:00:C0:7F:A0:E9, IRQ 5.
Oct  8 06:48:49 porky kernel: tulip 0000:04:0a.0: Device was removed without properly calling pci_disable_device(). This may need fixing.
Oct  8 06:48:49 porky kernel: IRQ#14 thread started up.
Oct  8 06:48:49 porky kernel: hda: ATAPI 48X CD-ROM CD-R/RW drive, 8192kB Cache, UDMA(33)
Oct  8 06:48:49 porky kernel: Uniform CD-ROM driver Revision: 3.20
Oct  8 06:48:49 porky kernel: IRQ#15 thread started up.
Oct  8 06:48:49 porky kernel: hdc: ATAPI 48X CD-ROM drive, 120kB Cache, UDMA(33)
Oct  8 06:48:49 porky kernel: ip_tables: (C) 2000-2002 Netfilter core team
Oct  8 06:48:49 porky kernel: Linux Tulip driver version 1.1.13 (May 11, 2002)
Oct  8 06:48:49 porky kernel: PCI: Found IRQ 5 for device 0000:04:0a.0
Oct  8 06:48:49 porky kernel: PCI: Sharing IRQ 5 with 0000:04:05.1
Oct  8 06:48:49 porky kernel: tulip0:  EEPROM default media type Autosense.
Oct  8 06:48:49 porky kernel: tulip0:  Index #0 - Media MII (#11) described by a 21140 MII PHY (1) block.
Oct  8 06:48:49 porky kernel: tulip0:  MII transceiver #3 config 3100 status 7809 advertising 01e1.
Oct  8 06:48:49 porky kernel: eth0: Digital DS21140 Tulip rev 32 at 0xe480, 00:00:C0:7F:A0:E9, IRQ 5.
Oct  8 06:48:49 porky kernel: ip_tables: (C) 2000-2002 Netfilter core team
Oct  8 06:48:49 porky kernel: eth0: Setting full-duplex based on MII#3 link partner capability of 05e1.
Oct  8 06:48:49 porky kernel: parport0: PC-style at 0x378 (0x778) [PCSPP,TRISTATE,EPP]
Oct  8 06:48:49 porky kernel: parport0: irq 7 detected
Oct  8 06:48:49 porky kernel: lp0: using parport0 (polling).
Oct  8 06:48:50 porky cups: cupsd startup succeeded
Oct  8 06:48:50 porky sshd:  succeeded
Oct  8 06:48:50 porky xinetd: xinetd startup succeeded
Oct  8 06:48:50 porky ntpdate[2906]: step time server 192.168.36.1 offset -0.498488 sec
Oct  8 06:48:50 porky ntpd:  succeeded
Oct  8 06:48:50 porky ntpd[2910]: ntpd 4.2.0@1.1161-r Thu Mar 11 11:46:39 EST 2004 (1)
Oct  8 06:48:50 porky ntpd: ntpd startup succeeded
Oct  8 06:48:50 porky ntpd[2910]: precision = 1.000 usec
Oct  8 06:48:50 porky ntpd[2910]: kernel time sync status 0040
Oct  8 06:48:50 porky ntpd[2910]: frequency initialized 16.655 PPM from /var/lib/ntp/drift
Oct  8 06:48:50 porky ntpd[2910]: configure: keyword "authenticate" unknown, line ignored
Oct  8 06:48:50 porky vsftpd: vsftpd vsftpd succeeded
Oct  8 06:48:50 porky sendmail: sendmail startup succeeded
Oct  8 06:48:50 porky sendmail: sm-client startup succeeded
Oct  8 06:48:50 porky gpm[2959]: *** info [startup.c(95)]: 
Oct  8 06:48:50 porky gpm[2959]: Started gpm successfully. Entered daemon mode.
Oct  8 06:48:50 porky xinetd[2896]: xinetd Version 2.3.13 started with libwrap loadavg options compiled in.
Oct  8 06:48:50 porky xinetd[2896]: Started working: 2 available services
Oct  8 06:48:51 porky gpm[2959]: *** info [mice.c(1766)]: 
Oct  8 06:48:51 porky gpm[2959]: imps2: Auto-detected intellimouse PS/2
Oct  8 06:48:51 porky gpm: gpm startup succeeded
Oct  8 06:48:51 porky crond: crond startup succeeded
Oct  8 06:48:51 porky xfs: xfs startup succeeded
Oct  8 06:48:52 porky anacron: anacron startup succeeded
Oct  8 06:48:52 porky atd: atd startup succeeded
Oct  8 06:48:52 porky readahead: Starting background readahead: 
Oct  8 06:48:52 porky rc: Starting readahead:  succeeded
Oct  8 06:48:53 porky messagebus: messagebus startup succeeded
Oct  8 06:48:53 porky mdmonitor: mdadm succeeded
Oct  8 06:48:53 porky mdmpd: mdmpd succeeded

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Ingo Molnar]

* K.R. Foley <kr@cybsft.com> wrote:

> First let me say that, in case you haven't been following the other
> thread about this "2.6.9-rc3-mm3 fails to detect aic7xxx", I resolved
> this by backing out the bk-scsi.patch and bk-scsi-target.patch.
> Without those everything works fine.

> >could you send me the following info:
> >
> >  - full log of a failed boot
> 
> I would like to be able to be able to send you this, but it doesn't
> get to the point of logging. [...]

meanwhile i could reproduce an aic79xx detection problem on a
testsystem, so no need to send the log.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Thu, 2004-10-07 at 06:52, Ingo Molnar wrote:
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 

[adding Andrew Morton to the cc: list as these issues are increasingly
relevant to -mm and not VP specific] 

I am seeing the same prune_icache latency that Mark reported.  I have
never seen this one at all before T3.  This one seem very frequent,
enough so to overtake the netif_skb single-packet processing latency
that seems to be our lower bound. 

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 242 us, entries: 178 (178)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: kswapd0/54, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: prune_icache+0x52/0x460
 => ended at:   prune_icache+0x162/0x460
=======>
00000001 0.000ms (+0.001ms): prune_icache (shrink_icache_memory)
00000001 0.001ms (+0.002ms): inode_has_buffers (prune_icache)
00000001 0.004ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.005ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.007ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.008ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.010ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.011ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.012ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.014ms (+0.001ms): inode_has_buffers (prune_icache)
00000001 0.015ms (+0.001ms): inode_has_buffers (prune_icache)

[more of same interrupted by the timer a few times]

Workload is just a kernel compile and an RT task (jackd). 
Interestingly, kswapd seems to have triggered the above, but I should
not be hitting swap!  I have swappiness set to 0, and here is what
vmstat showed:

procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa
 1  0      4  30608  54476 221680    0    0     9    12  310   600 36  8 56  0
 1  0      4  41424  54476 221796    0    0     0     0 1109  2577 88 12  0  0
 1  0      4  41168  54484 221808    0    0    24     0 1005  2158 83 17  0  0
 1  0      4  34704  54496 221808    0    0     0   192 1015  2063 92  8  0  0
 1  0      4  32208  54496 221808    0    0     0     0 1003  2045 96  4  0  0
 1  0      4  30928  54496 221808    0    0     0     0 1004  2090 98  2  0  0

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Thu, 2004-10-07 at 06:52, Ingo Molnar wrote:
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 

Also, I am still seeing some long latencies in the ext3 journaling code:

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 607 us, entries: 1087 (1087)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: kjournald/687, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: journal_commit_transaction+0x75/0x2830
 => ended at:   __journal_clean_checkpoint_list+0xb2/0xf0
=======>
00000001 0.000ms (+0.003ms): journal_commit_transaction (kjournald)

Here is the loop:

00000002 0.003ms (+0.001ms): kfree (journal_commit_transaction)
00000001 0.004ms (+0.001ms): journal_refile_buffer (journal_commit_transaction)
00000003 0.006ms (+0.000ms): __journal_refile_buffer (journal_refile_buffer)
00000003 0.006ms (+0.001ms): __journal_unfile_buffer (journal_refile_buffer)
00000002 0.008ms (+0.000ms): journal_remove_journal_head (journal_refile_buffer)
00000003 0.008ms (+0.000ms): __journal_remove_journal_head (journal_remove_journal_head)
00000003 0.009ms (+0.000ms): __brelse (__journal_remove_journal_head)
00000003 0.010ms (+0.000ms): journal_free_journal_head (journal_remove_journal_head)
00000003 0.010ms (+0.001ms): kmem_cache_free (journal_free_journal_head)
00000001 0.011ms (+0.000ms): __brelse (journal_commit_transaction)

[end loop]

00000002 0.012ms (+0.000ms): kfree (journal_commit_transaction)
00000001 0.013ms (+0.000ms): journal_refile_buffer (journal_commit_transaction)

I think I already reported this one with S7.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Thu, 2004-10-07 at 06:52, Ingo Molnar wrote:
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 

Wow, this is a really bad one - 5576 usecs in shmem_truncate!  I think
this was triggered by Mozilla deleting a large video file from /tmp
which is a tmpfs mount.

(mozilla-bin/16141): new 5576 us maximum-latency critical section.
 => started at: <shmem_truncate+0x67/0x630>
 => ended at:   <shmem_truncate+0x3bc/0x630>
 [<c013d96a>] check_preempt_timing+0x14a/0x1e0
 [<c013d2f5>] __mcount+0x15/0x20
 [<c02dd08a>] preempt_schedule+0xa/0x70
 [<c013dbba>] sub_preempt_count+0x5a/0x90
 [<c016b39c>] shmem_truncate+0x3bc/0x630
 [<c016b39c>] shmem_truncate+0x3bc/0x630
 [<c016b964>] shmem_delete_inode+0x134/0x340
 [<c016b830>] shmem_delete_inode+0x0/0x340
 [<c01991ee>] generic_delete_inode+0xde/0x300
 [<c0189615>] sys_unlink+0xf5/0x150
 [<c0106b47>] syscall_call+0x7/0xb

Full trace:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc3-mm3-VP-T3#/var/www/2.6.9-rc3-mm3-VP-T3/shmem-truncate-latency-trace.txt

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Thu, 2004-10-07 at 06:52, Ingo Molnar wrote:
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 

With VP and PREEMPT in general, does the scheduler always run the
highest priority process, or do we only preempt if a SCHED_FIFO process
is runnable?

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Florian Schmidt]

On Thu, 7 Oct 2004 12:52:30 +0200
Ingo Molnar <mingo@elte.hu> wrote:

> 
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3

Hi,

i just wanted to report that audio usage has been become quite a bit worse
when compared to T1. I get more xruns (40 to 80 per night as opposed to 5 to
10 on T1), RT apps like ardour seem to be much more unstable with T3 than T1
(ardour gets kicked off the jack graph regularly at 64 frames on T3 which
doesn't happen with T1).

This goes together with a general increase of > 200us non preempt. crit.
sect. which were very seldom in T1 (at loeast for the work i do) but appear
rather regularly in T3.


Flo

P.S.: Are there tools available which can check the "correctness" of the
interplay of nptl libc and kernel wrt to threading? Especially when it comes
to wakeup order of blocking threads in different scheduler classes and with
different priorities.

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Thu, 2004-10-07 at 06:52, Ingo Molnar wrote:
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 

Just to recap, these are the three problem areas that still produce
latencies over 500 usec on my machine.

	journal_clean_checkpoint_list
	rt_garbage_collect
	vga console

I have found that the latter does not require switching back and forth
to X; anything that produces a lot of console output can trigger 500
usec latencies.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> Just to recap, these are the three problem areas that still produce
> latencies over 500 usec on my machine.
> 
> 	journal_clean_checkpoint_list

you might want to send this trace to Andrew too - the primary master of
ext3 latency-breaking.

> 	rt_garbage_collect

this one is still nasty and needs revisiting.

> 	vga console
> 
> I have found that the latter does not require switching back and forth
> to X; anything that produces a lot of console output can trigger 500
> usec latencies.

the vga console one we got rid of at a certain stage and it now
resurfaced. The issue was doing VGA-text-RAM copies/memsets under the
vga_lock. Maybe there were changes in vgacon recently that moved some of
those back under the lock?

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Tue, 2004-10-12 at 05:17, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > Just to recap, these are the three problem areas that still produce
> > latencies over 500 usec on my machine.
> > 
> > 	journal_clean_checkpoint_list
> 
> you might want to send this trace to Andrew too - the primary master of
> ext3 latency-breaking.
> 

OK, Andrew, here it is.  This is one of the last 2 or 3 code paths that
can still produce latencies > 200 usecs on a typical machine.

--

Also, I am still seeing some long latencies in the ext3 journaling code:

preemption latency trace v1.0.7 on 2.6.9-rc3-mm3-VP-T3
-------------------------------------------------------
 latency: 607 us, entries: 1087 (1087)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: kjournald/687, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: journal_commit_transaction+0x75/0x2830
 => ended at:   __journal_clean_checkpoint_list+0xb2/0xf0
=======>
00000001 0.000ms (+0.003ms): journal_commit_transaction (kjournald)

Here is the loop:

00000002 0.003ms (+0.001ms): kfree (journal_commit_transaction)
00000001 0.004ms (+0.001ms): journal_refile_buffer (journal_commit_transaction)
00000003 0.006ms (+0.000ms): __journal_refile_buffer (journal_refile_buffer)
00000003 0.006ms (+0.001ms): __journal_unfile_buffer (journal_refile_buffer)
00000002 0.008ms (+0.000ms): journal_remove_journal_head (journal_refile_buffer)
00000003 0.008ms (+0.000ms): __journal_remove_journal_head (journal_remove_journal_head)
00000003 0.009ms (+0.000ms): __brelse (__journal_remove_journal_head)
00000003 0.010ms (+0.000ms): journal_free_journal_head (journal_remove_journal_head)
00000003 0.010ms (+0.001ms): kmem_cache_free (journal_free_journal_head)
00000001 0.011ms (+0.000ms): __brelse (journal_commit_transaction)

[end loop]

00000002 0.012ms (+0.000ms): kfree (journal_commit_transaction)
00000001 0.013ms (+0.000ms): journal_refile_buffer (journal_commit_transaction)

Lee

Re: [patch] voluntary-preempt-2.6.9-rc3-mm3-T3

[Lee Revell]

On Thu, 2004-10-07 at 06:52, Ingo Molnar wrote:
> i've released the -T3 VP patch:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc3-mm3-T3
> 

Ingo, here's the data from an 87 million sample run (about 24 hours) of
my jackd test.  Note the 1292 usec outlier.  This is definitely not
latency trace overhead as it was disabled.  I suspect either the
rt_garbage_collect or journal_clean_checkpoint_list code path is
responsible.

Delay   # samples
-----   ---------
0       86798124
1       122
2       113
3       118
4       109
5       96
6       78
7       66
8       66
9       51
10      52
11      41
12      39
13      43
14      43
15      30
16      17
17      18
18      28
19      17
20      18
21      16
22      19
23      19
24      19
25      15
26      26
27      13
28      13
29      10
30      17
31      19
32      12
33      12
34      17
35      7
36      16
37      13
38      7
39      10
40      9
41      9
42      9
43      8
44      11
45      18
46      12
47      13
48      6
49      12
50      12
51      13
52      8
53      11
54      14
55      5
56      5
57      11
58      8
59      11
60      8
61      5
62      11
63      8
64      9
65      11
66      9
67      8
68      8
69      8
70      8
71      8
72      11
73      10
74      10
75      8
76      2
77      7
78      4
79      9
80      5
81      4
82      2
83      7
84      6
85      1
86      7
87      5
88      10
89      7
90      3
91      7
92      7
93      7
94      1
95      7
96      5
97      7
98      2
99      3
100     3
101     4
102     4
103     4
104     5
105     3
106     5
107     2
108     4
109     1
110     2
111     2
112     3
113     2
115     1
116     3
117     2
118     3
119     3
120     1
121     2
122     2
123     2
124     1
127     1
128     2
129     2
130     2
133     1
135     1
139     1
141     2
145     1
147     1
152     1
156     1
169     1
173     1
177     1
187     1
194     2
233     1
242     1
290     1
352     1
1292    1

Lee