preemption latency trace v1.0.7 on 2.6.9-rc2-mm1-VP-S1
-------------------------------------------------------
 latency: 376 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.344ms): _spin_lock_irqsave (tulip_mdio_read)
00000001 0.344ms (+0.001ms): _spin_unlock_irqrestore (tulip_mdio_read)
00010001 0.346ms (+0.000ms): do_IRQ (_spin_unlock_irqrestore)
00010001 0.346ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.347ms (+0.000ms): _spin_lock (do_IRQ)
00010002 0.347ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
00010002 0.347ms (+0.003ms): _spin_lock_irqsave (mask_and_ack_8259A)
00010003 0.351ms (+0.000ms): _spin_unlock_irqrestore (do_IRQ)
00010002 0.351ms (+0.000ms): redirect_hardirq (do_IRQ)
00010002 0.352ms (+0.000ms): _spin_unlock (do_IRQ)
00010001 0.352ms (+0.000ms): handle_IRQ_event (do_IRQ)
00010001 0.352ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.353ms (+0.001ms): _spin_lock (timer_interrupt)
00010002 0.354ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010002 0.354ms (+0.000ms): _spin_lock (mark_offset_tsc)
00010003 0.354ms (+0.014ms): _spin_lock (mark_offset_tsc)
00010004 0.369ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010003 0.370ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010002 0.370ms (+0.000ms): do_timer (timer_interrupt)
00010002 0.371ms (+0.000ms): update_wall_time (do_timer)
00010002 0.371ms (+0.001ms): update_wall_time_one_tick (update_wall_time)
00010002 0.372ms (+0.000ms): _spin_unlock (timer_interrupt)
00010001 0.372ms (+0.000ms): _spin_lock (do_IRQ)
00010002 0.373ms (+0.000ms): note_interrupt (do_IRQ)
00010002 0.373ms (+0.000ms): end_8259A_irq (do_IRQ)
00010002 0.373ms (+0.000ms): enable_8259A_irq (do_IRQ)
00010002 0.373ms (+0.001ms): _spin_lock_irqsave (enable_8259A_irq)
00010003 0.375ms (+0.000ms): _spin_unlock_irqrestore (do_IRQ)
00010002 0.375ms (+0.001ms): _spin_unlock (do_IRQ)
00000001 0.376ms (+0.000ms): sub_preempt_count (_spin_unlock_irqrestore)
00000001 0.377ms (+0.000ms): update_max_trace (check_preempt_timing)