preemption latency trace v1.0.7 on 2.6.9-rc2-mm1-VP-S1
-------------------------------------------------------
 latency: 407 us, entries: 31 (31)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: ksoftirqd/0/3, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: _spin_lock_irqsave+0x22/0x80
 => ended at:   _spin_unlock_irqrestore+0x1c/0x40
=======>
00000001 0.000ms (+0.375ms): _spin_lock_irqsave (tulip_mdio_read)
00000001 0.375ms (+0.001ms): _spin_unlock_irqrestore (tulip_mdio_read)
00010001 0.377ms (+0.000ms): do_IRQ (_spin_unlock_irqrestore)
00010001 0.377ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.378ms (+0.000ms): _spin_lock (do_IRQ)
00010002 0.379ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
00010002 0.379ms (+0.004ms): _spin_lock_irqsave (mask_and_ack_8259A)
00010003 0.383ms (+0.000ms): _spin_unlock_irqrestore (do_IRQ)
00010002 0.384ms (+0.000ms): redirect_hardirq (do_IRQ)
00010002 0.384ms (+0.000ms): _spin_unlock (do_IRQ)
00010001 0.384ms (+0.000ms): handle_IRQ_event (do_IRQ)
00010001 0.385ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.385ms (+0.000ms): _spin_lock (timer_interrupt)
00010002 0.385ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010002 0.386ms (+0.000ms): _spin_lock (mark_offset_tsc)
00010003 0.386ms (+0.014ms): _spin_lock (mark_offset_tsc)
00010004 0.401ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010003 0.401ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010002 0.401ms (+0.000ms): do_timer (timer_interrupt)
00010002 0.402ms (+0.000ms): update_wall_time (do_timer)
00010002 0.402ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010002 0.403ms (+0.000ms): _spin_unlock (timer_interrupt)
00010001 0.403ms (+0.000ms): _spin_lock (do_IRQ)
00010002 0.404ms (+0.000ms): note_interrupt (do_IRQ)
00010002 0.404ms (+0.000ms): end_8259A_irq (do_IRQ)
00010002 0.404ms (+0.000ms): enable_8259A_irq (do_IRQ)
00010002 0.404ms (+0.001ms): _spin_lock_irqsave (enable_8259A_irq)
00010003 0.406ms (+0.000ms): _spin_unlock_irqrestore (do_IRQ)
00010002 0.406ms (+0.001ms): _spin_unlock (do_IRQ)
00000001 0.407ms (+0.000ms): sub_preempt_count (_spin_unlock_irqrestore)
00000001 0.408ms (+0.000ms): update_max_trace (check_preempt_timing)