preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-VP-U0 ------------------------------------------------------- latency: 146 us, entries: 90 (90) | [VP:1 KP:1 SP:1 HP:1 #CPUS:2] ----------------- | task: holey/18647, uid:0 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 (file_read_actor) 00000001 0.000ms (+0.000ms): page_address (file_read_actor) 00000001 0.000ms (+0.016ms): __copy_to_user_ll (file_read_actor) 00010001 0.016ms (+0.000ms): do_IRQ (__copy_to_user_ll) 00010001 0.016ms (+0.000ms): do_IRQ (<00000000>) 00010001 0.017ms (+0.000ms): _spin_lock (__do_IRQ) 00010002 0.017ms (+0.000ms): mask_and_ack_8259A (__do_IRQ) 00010002 0.017ms (+0.034ms): _spin_lock_irqsave (mask_and_ack_8259A) 00010003 0.051ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ) 00010002 0.052ms (+0.000ms): redirect_hardirq (__do_IRQ) 00010002 0.052ms (+0.000ms): _spin_unlock (__do_IRQ) 00010001 0.052ms (+0.000ms): handle_IRQ_event (__do_IRQ) 00010001 0.052ms (+0.000ms): timer_interrupt (handle_IRQ_event) 00010001 0.053ms (+0.000ms): _spin_lock (timer_interrupt) 00010002 0.053ms (+0.000ms): mark_offset_tsc (timer_interrupt) 00010002 0.053ms (+0.000ms): _spin_lock (mark_offset_tsc) 00010003 0.054ms (+0.012ms): _spin_lock (mark_offset_tsc) 00010004 0.066ms (+0.001ms): _spin_unlock (mark_offset_tsc) 00010003 0.067ms (+0.000ms): _spin_unlock (mark_offset_tsc) 00010002 0.068ms (+0.001ms): do_timer (timer_interrupt) 00010002 0.069ms (+0.000ms): update_wall_time (do_timer) 00010002 0.069ms (+0.001ms): update_wall_time_one_tick (update_wall_time) 00010002 0.071ms (+0.000ms): _spin_unlock (timer_interrupt) 00010001 0.071ms (+0.000ms): _spin_lock (__do_IRQ) 00010002 0.071ms (+0.000ms): note_interrupt (__do_IRQ) 00010002 0.072ms (+0.000ms): end_8259A_irq (__do_IRQ) 00010002 0.072ms (+0.000ms): enable_8259A_irq (__do_IRQ) 00010002 0.072ms (+0.001ms): _spin_lock_irqsave (enable_8259A_irq) 00010003 0.074ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ) 00010002 0.074ms (+0.000ms): _spin_unlock (__do_IRQ) 00010001 0.074ms (+0.002ms): irq_exit (do_IRQ) 00000001 0.076ms (+0.000ms): smp_apic_timer_interrupt (__copy_to_user_ll) 00010001 0.077ms (+0.000ms): profile_tick (smp_apic_timer_interrupt) 00010001 0.077ms (+0.000ms): profile_hook (profile_tick) 00010001 0.078ms (+0.001ms): _read_lock (profile_hook) 00010002 0.079ms (+0.000ms): notifier_call_chain (profile_hook) 00010002 0.079ms (+0.000ms): _read_unlock (profile_tick) 00010001 0.080ms (+0.000ms): profile_hit (smp_apic_timer_interrupt) 00010001 0.081ms (+0.000ms): update_process_times (smp_apic_timer_interrupt) 00010001 0.081ms (+0.000ms): update_one_process (update_process_times) 00010001 0.082ms (+0.000ms): run_local_timers (update_process_times) 00010001 0.082ms (+0.000ms): raise_softirq (update_process_times) 00010001 0.083ms (+0.000ms): scheduler_tick (update_process_times) 00010001 0.083ms (+0.001ms): sched_clock (scheduler_tick) 00010001 0.085ms (+0.000ms): _spin_lock (scheduler_tick) 00010002 0.085ms (+0.000ms): _spin_unlock (scheduler_tick) 00010001 0.085ms (+0.000ms): rebalance_tick (scheduler_tick) 00010001 0.086ms (+0.000ms): irq_exit (smp_apic_timer_interrupt) 00000002 0.087ms (+0.000ms): do_softirq (irq_exit) 00000002 0.087ms (+0.000ms): __do_softirq (do_softirq) 00000002 0.088ms (+0.000ms): wake_up_process (do_softirq) 00000002 0.088ms (+0.000ms): try_to_wake_up (wake_up_process) 00000002 0.088ms (+0.000ms): task_rq_lock (try_to_wake_up) 00000002 0.088ms (+0.000ms): _spin_lock (task_rq_lock) 00000003 0.089ms (+0.000ms): activate_task (try_to_wake_up) 00000003 0.089ms (+0.000ms): sched_clock (activate_task) 00000003 0.089ms (+0.000ms): recalc_task_prio (activate_task) 00000003 0.089ms (+0.000ms): effective_prio (recalc_task_prio) 00000003 0.090ms (+0.000ms): enqueue_task (activate_task) 00000003 0.090ms (+0.000ms): resched_task (try_to_wake_up) 00000003 0.091ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up) 00000002 0.091ms (+0.001ms): preempt_schedule (try_to_wake_up) 00010001 0.093ms (+0.000ms): do_IRQ (__copy_to_user_ll) 00010001 0.093ms (+0.000ms): do_IRQ (<00000008>) 00010001 0.093ms (+0.000ms): _spin_lock (__do_IRQ) 00010002 0.093ms (+0.000ms): mask_and_ack_8259A (__do_IRQ) 00010002 0.093ms (+0.034ms): _spin_lock_irqsave (mask_and_ack_8259A) 00010003 0.128ms (+0.000ms): _spin_unlock_irqrestore (__do_IRQ) 00010002 0.128ms (+0.000ms): preempt_schedule (__do_IRQ) 00010002 0.129ms (+0.000ms): redirect_hardirq (__do_IRQ) 00010002 0.129ms (+0.000ms): wake_up_process (redirect_hardirq) 00010002 0.129ms (+0.000ms): try_to_wake_up (wake_up_process) 00010002 0.129ms (+0.000ms): task_rq_lock (try_to_wake_up) 00010002 0.130ms (+0.000ms): _spin_lock (task_rq_lock) 00010003 0.130ms (+0.000ms): activate_task (try_to_wake_up) 00010003 0.130ms (+0.000ms): sched_clock (activate_task) 00010003 0.130ms (+0.000ms): recalc_task_prio (activate_task) 00010003 0.131ms (+0.000ms): effective_prio (recalc_task_prio) 00010003 0.131ms (+0.000ms): enqueue_task (activate_task) 00010003 0.131ms (+0.000ms): resched_task (try_to_wake_up) 00010003 0.131ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up) 00010002 0.132ms (+0.000ms): preempt_schedule (try_to_wake_up) 00010002 0.132ms (+0.000ms): _spin_unlock (__do_IRQ) 00010001 0.132ms (+0.000ms): preempt_schedule (__do_IRQ) 00010001 0.132ms (+0.000ms): irq_exit (do_IRQ) 00000002 0.132ms (+0.000ms): do_softirq (irq_exit) 00000002 0.133ms (+0.012ms): __do_softirq (do_softirq) 00000001 0.146ms (+0.000ms): kunmap_atomic (file_read_actor) 00000001 0.147ms (+0.000ms): sub_preempt_count (kunmap_atomic) 00000001 0.147ms (+0.000ms): update_max_trace (check_preempt_timing)