preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.51-02
--------------------------------------------------------------------
 latency: 2692 us, #78/78, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
    -----------------
    | task: softirq-timer/0-3 (uid:0 nice:-10 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> need-resched    
               || / _---=> hardirq/softirq 
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
  <idle>-0     0dnh3    0us!: <70617773> (<00726570>)
  <idle>-0     0dnh3    0us : __trace_start_sched_wakeup (try_to_wake_up)
  <idle>-0     0dnh3    0us : __trace_start_sched_wakeup <softirq--3> (69 0)
  <idle>-0     0dnh2    1us : try_to_wake_up <softirq--3> (69 8c)
  <idle>-0     0dnh1    1us : preempt_schedule (try_to_wake_up)
  <idle>-0     0dnh1    1us : wake_up_process (trigger_softirqs)
  <idle>-0     0dnh1    2us : local_irq_restore (do_softirq)
  <idle>-0     0dnh.    2us < (608)
  <idle>-0     0dn..    3us : acpi_hw_low_level_read (acpi_hw_register_read)
  <idle>-0     0dn..    4us : acpi_hw_register_write (acpi_set_register)
  <idle>-0     0dn..    4us : acpi_hw_low_level_write (acpi_hw_register_write)
  <idle>-0     0dn..    4us+: acpi_os_write_port (acpi_hw_low_level_write)
  <idle>-0     0dn..    7us!: acpi_hw_low_level_write (acpi_hw_register_write)
  <idle>-0     0dnh. 2645us : smp_apic_timer_interrupt (c0252485 0 0)
  <idle>-0     0dnh. 2646us : irq_exit (apic_timer_interrupt)
  <idle>-0     0dnh1 2646us : do_softirq (irq_exit)
  <idle>-0     0dnh1 2647us : __local_irq_save (do_softirq)
  <idle>-0     0dnh1 2647us : __do_softirq (do_softirq)
  <idle>-0     0dnh1 2647us : trigger_softirqs (do_softirq)
  <idle>-0     0dnh1 2648us : wakeup_softirqd (trigger_softirqs)
  <idle>-0     0dnh1 2648us : local_irq_restore (do_softirq)
  <idle>-0     0dnh. 2648us+< (608)
  <idle>-0     0dnh. 2652us : do_IRQ (c0252485 0 0)
  <idle>-0     0dnh. 2652us : __local_irq_save (__do_IRQ)
  <idle>-0     0dnh1 2653us+: mask_and_ack_8259A (__do_IRQ)
  <idle>-0     0dnh1 2659us : preempt_schedule (__do_IRQ)
  <idle>-0     0dnh1 2660us : redirect_hardirq (__do_IRQ)
  <idle>-0     0dnh. 2660us : preempt_schedule (__do_IRQ)
  <idle>-0     0dnh. 2661us : handle_IRQ_event (__do_IRQ)
  <idle>-0     0dnh. 2661us : timer_interrupt (handle_IRQ_event)
  <idle>-0     0dnh1 2661us : mark_offset_tsc (timer_interrupt)
  <idle>-0     0dnh1 2662us : preempt_schedule (mark_offset_tsc)
  <idle>-0     0dnh1 2662us : preempt_schedule (mark_offset_tsc)
  <idle>-0     0dnh1 2663us : do_timer (timer_interrupt)
  <idle>-0     0dnh1 2663us : update_process_times (timer_interrupt)
  <idle>-0     0dnh1 2663us : account_system_time (update_process_times)
  <idle>-0     0dnh1 2664us : update_mem_hiwater (update_process_times)
  <idle>-0     0dnh1 2664us : run_local_timers (update_process_times)
  <idle>-0     0dnh1 2664us : raise_softirq (update_process_times)
  <idle>-0     0dnh1 2665us : scheduler_tick (update_process_times)
  <idle>-0     0dnh1 2665us : sched_clock (scheduler_tick)
  <idle>-0     0dnh1 2666us : softlockup_tick (timer_interrupt)
  <idle>-0     0dnh. 2666us : preempt_schedule (timer_interrupt)
  <idle>-0     0dnh1 2666us : note_interrupt (__do_IRQ)
  <idle>-0     0dnh1 2667us : end_8259A_irq (__do_IRQ)
  <idle>-0     0dnh1 2667us+: enable_8259A_irq (__do_IRQ)
  <idle>-0     0dnh1 2670us : preempt_schedule (__do_IRQ)
  <idle>-0     0dnh. 2670us : preempt_schedule (__do_IRQ)
  <idle>-0     0dnh. 2671us : local_irq_restore (__do_IRQ)
  <idle>-0     0dnh. 2671us : irq_exit (do_IRQ)
  <idle>-0     0dnh1 2671us : do_softirq (irq_exit)
  <idle>-0     0dnh1 2672us : __local_irq_save (do_softirq)
  <idle>-0     0dnh1 2672us : __do_softirq (do_softirq)
  <idle>-0     0dnh1 2672us : trigger_softirqs (do_softirq)
  <idle>-0     0dnh1 2673us : wakeup_softirqd (trigger_softirqs)
  <idle>-0     0dnh1 2673us : local_irq_restore (do_softirq)
  <idle>-0     0dnh. 2673us+< (608)
  <idle>-0     0dn.. 2678us : local_irq_enable (acpi_processor_idle)
  <idle>-0     0Dn.. 2679us : preempt_schedule (acpi_processor_idle)
  <idle>-0     0Dn.. 2679us : irqs_disabled (preempt_schedule)
  <idle>-0     0Dnh. 2679us : __schedule (preempt_schedule)
  <idle>-0     0Dnh. 2680us : profile_hit (__schedule)
  <idle>-0     0Dnh1 2680us : sched_clock (__schedule)
  <idle>-0     0Dnh2 2681us : dequeue_task (__schedule)
  <idle>-0     0Dnh2 2681us : recalc_task_prio (__schedule)
  <idle>-0     0Dnh2 2681us : effective_prio (recalc_task_prio)
  <idle>-0     0Dnh2 2682us : enqueue_task (__schedule)
  <idle>-0     0Dnh2 2682us+: trace_array (__schedule)
  <idle>-0     0Dnh2 2684us : trace_array <softirq--3> (69 6e)
  <idle>-0     0Dnh2 2685us+: trace_array (__schedule)
softirq--3     0Dnh2 2689us : __switch_to (__schedule)
softirq--3     0Dnh2 2689us : __schedule <<idle>-0> (8c 69)
softirq--3     0Dnh2 2690us : finish_task_switch (__schedule)
softirq--3     0Dnh1 2690us : trace_stop_sched_switched (finish_task_switch)
softirq--3     0Dnh2 2691us : trace_stop_sched_switched <softirq--3> (69 0)
softirq--3     0Dnh2 2691us : trace_stop_sched_switched (finish_task_switch)


vim:ft=help