preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-VP-U0
-------------------------------------------------------
 latency: 51 us, entries: 55 (55)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: bash/26309, uid:40000 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: kmap_atomic+0x23/0x90
 => ended at:   kunmap_atomic+0x17/0x40
=======>
00000001 0.000ms (+0.000ms): kmap_atomic (do_anonymous_page)
00000001 0.000ms (+0.007ms): page_address (do_anonymous_page)
00010001 0.007ms (+0.000ms): do_IRQ (do_anonymous_page)
00010001 0.007ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.008ms (+0.000ms): _spin_lock (__do_IRQ)
00010002 0.008ms (+0.000ms): mask_and_ack_8259A (__do_IRQ)
00010002 0.008ms (+0.004ms): _spin_lock_irqsave (mask_and_ack_8259A)
00010003 0.012ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ)
00010002 0.013ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010002 0.013ms (+0.000ms): _spin_unlock (__do_IRQ)
00010001 0.013ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010001 0.014ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.014ms (+0.000ms): _spin_lock (timer_interrupt)
00010002 0.015ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010002 0.015ms (+0.000ms): _spin_lock (mark_offset_tsc)
00010003 0.015ms (+0.014ms): _spin_lock (mark_offset_tsc)
00010004 0.030ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010003 0.031ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010002 0.031ms (+0.000ms): do_timer (timer_interrupt)
00010002 0.032ms (+0.000ms): update_wall_time (do_timer)
00010002 0.032ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010002 0.033ms (+0.000ms): _spin_unlock (timer_interrupt)
00010001 0.033ms (+0.000ms): _spin_lock (__do_IRQ)
00010002 0.033ms (+0.000ms): note_interrupt (__do_IRQ)
00010002 0.034ms (+0.000ms): end_8259A_irq (__do_IRQ)
00010002 0.034ms (+0.000ms): enable_8259A_irq (__do_IRQ)
00010002 0.034ms (+0.001ms): _spin_lock_irqsave (enable_8259A_irq)
00010003 0.035ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ)
00010002 0.036ms (+0.000ms): _spin_unlock (__do_IRQ)
00010001 0.036ms (+0.002ms): irq_exit (do_IRQ)
00010001 0.038ms (+0.000ms): do_IRQ (do_anonymous_page)
00010001 0.038ms (+0.000ms): do_IRQ (<00000008>)
00010001 0.039ms (+0.000ms): _spin_lock (__do_IRQ)
00010002 0.039ms (+0.000ms): mask_and_ack_8259A (__do_IRQ)
00010002 0.039ms (+0.005ms): _spin_lock_irqsave (mask_and_ack_8259A)
00010003 0.044ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ)
00010002 0.045ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010002 0.045ms (+0.000ms): wake_up_process (redirect_hardirq)
00010002 0.045ms (+0.000ms): try_to_wake_up (wake_up_process)
00010002 0.045ms (+0.000ms): task_rq_lock (try_to_wake_up)
00010002 0.045ms (+0.000ms): _spin_lock (task_rq_lock)
00010003 0.046ms (+0.000ms): activate_task (try_to_wake_up)
00010003 0.046ms (+0.000ms): sched_clock (activate_task)
00010003 0.047ms (+0.000ms): recalc_task_prio (activate_task)
00010003 0.047ms (+0.000ms): effective_prio (recalc_task_prio)
00010003 0.047ms (+0.000ms): enqueue_task (activate_task)
00010003 0.048ms (+0.000ms): resched_task (try_to_wake_up)
00010003 0.048ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up)
00010002 0.048ms (+0.000ms): preempt_schedule (try_to_wake_up)
00010002 0.049ms (+0.000ms): _spin_unlock (__do_IRQ)
00010001 0.049ms (+0.000ms): preempt_schedule (__do_IRQ)
00010001 0.049ms (+0.001ms): irq_exit (do_IRQ)
00000001 0.050ms (+0.000ms): kunmap_atomic (do_anonymous_page)
00000001 0.051ms (+0.000ms): sub_preempt_count (kunmap_atomic)
00000001 0.051ms (+0.000ms): update_max_trace (check_preempt_timing)