preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-debug -------------------------------------------------------------------- latency: 237 us, #120/120, CPU#1 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2) ----------------- | task: wmWeather-2968 (uid:500 nice:10 policy:0 rt_prio:0) ----------------- _------=> CPU# / _-----=> irqs-off | / _----=> need-resched || / _---=> hardirq/softirq ||| / _--=> preempt-depth |||| / ||||| delay cmd pid ||||| time | caller \ / ||||| \ | / softirq--13 1Dnh2 0us : find_next_bit (__trace_start_sched_wakeup) <...>-3083 0.... 0us : __down_mutex (_spin_lock_irqsave) <...>-3083 0Dnh. 0us : _raw_spin_lock (__down_mutex) softirq--13 1Dnh2 0us : <74666f73> (<2d717269>) softirq--13 1Dnh2 0us : __trace_start_sched_wakeup (try_to_wake_up) <...>-3083 0Dnh1 0us : grab_lock (__down_mutex) softirq--13 1Dnh2 1us : __trace_start_sched_wakeup <<...>-2968> (34 1) <...>-3083 0Dnh1 1us : __down_mutex <<...>-3083> (36 0) softirq--13 1Dnh2 1us : _raw_spin_unlock (try_to_wake_up) <...>-3083 0Dnh1 1us : _raw_spin_unlock (__down_mutex) softirq--13 1Dnh1 1us : resched_task (try_to_wake_up) <...>-3083 0.... 1us!: __local_save_flags (_spin_lock_irqsave) softirq--13 1Dnh1 213us : try_to_wake_up <<...>-2968> (34 69) softirq--13 1Dnh1 213us : _raw_spin_unlock_irqrestore (try_to_wake_up) softirq--13 1Dnh. 214us : irqs_disabled (smp_processor_id) softirq--13 1Dnh. 214us : smp_apic_timer_interrupt (c0306aaa 0 0) softirq--13 1Dnh. 215us : update_process_times (smp_apic_timer_interrupt) softirq--13 1Dnh. 215us : account_system_time (update_process_times) softirq--13 1Dnh. 216us : acct_update_integrals (account_system_time) softirq--13 1Dnh. 216us : update_mem_hiwater (update_process_times) softirq--13 1Dnh. 216us : run_local_timers (update_process_times) softirq--13 1Dnh. 216us : raise_softirq (update_process_times) <...>-3083 0.... 216us : _spin_unlock_irqrestore (extract_buf) <...>-3083 0.... 217us : up_mutex (extract_buf) softirq--13 1Dnh. 217us : scheduler_tick (update_process_times) <...>-3083 0.... 217us : __up_mutex (up_mutex) softirq--13 1Dnh. 217us : sched_clock (scheduler_tick) <...>-3083 0Dnh. 217us : _raw_spin_lock (__up_mutex) softirq--13 1Dnh. 218us : _raw_spin_lock (scheduler_tick) <...>-3083 0Dnh1 218us : _raw_spin_unlock (__up_mutex) softirq--13 1Dnh1 218us : __bitmap_weight (scheduler_tick) <...>-3083 0.... 218us : sha_transform (extract_buf) softirq--13 1Dnh1 219us : _raw_spin_unlock (scheduler_tick) softirq--13 1Dnh. 219us : preempt_schedule (scheduler_tick) softirq--13 1Dnh. 219us : rebalance_tick (scheduler_tick) <...>-3083 0.... 220us : __add_entropy_words (extract_buf) softirq--13 1Dnh. 220us : softlockup_tick (smp_apic_timer_interrupt) <...>-3083 0.... 220us : _spin_lock_irqsave (__add_entropy_words) softirq--13 1Dnh. 220us : irq_exit (apic_timer_interrupt) <...>-3083 0.... 220us : __might_sleep (_spin_lock_irqsave) <...>-3083 0.... 220us : irqs_disabled (__might_sleep) softirq--13 1Dnh1 221us : do_softirq (irq_exit) <...>-3083 0.... 221us : _down_mutex (_spin_lock_irqsave) softirq--13 1Dnh1 221us : __do_softirq (do_softirq) <...>-3083 0.... 221us : __down_mutex (_spin_lock_irqsave) softirq--13 1Dnh1 221us : trigger_softirqs (do_softirq) <...>-3083 0Dnh. 221us : _raw_spin_lock (__down_mutex) softirq--13 1Dnh1 222us : wakeup_softirqd (trigger_softirqs) <...>-3083 0Dnh1 222us : grab_lock (__down_mutex) softirq--13 1Dnh. 222us : preempt_schedule_irq (need_resched) <...>-3083 0Dnh1 222us : __down_mutex <<...>-3083> (36 0) softirq--13 1Dnh. 222us : __schedule (preempt_schedule_irq) <...>-3083 0Dnh1 223us : _raw_spin_unlock (__down_mutex) softirq--13 1Dnh. 223us : profile_hit (__schedule) softirq--13 1Dnh1 223us : sched_clock (__schedule) <...>-3083 0.... 223us : __local_save_flags (_spin_lock_irqsave) softirq--13 1Dnh1 223us : _raw_spin_lock_irq (__schedule) <...>-3083 0.... 224us : _spin_unlock_irqrestore (extract_buf) <...>-3083 0.... 224us : up_mutex (extract_buf) softirq--13 1Dnh1 224us : _raw_spin_lock_irqsave (__schedule) <...>-3083 0.... 224us : __up_mutex (up_mutex) softirq--13 1Dnh2 224us : dependent_sleeper (__schedule) <...>-3083 0Dnh. 224us : _raw_spin_lock (__up_mutex) softirq--13 1Dnh2 225us : _raw_spin_unlock (dependent_sleeper) <...>-3083 0Dnh1 225us : _raw_spin_unlock (__up_mutex) softirq--13 1Dnh1 225us : preempt_schedule (dependent_sleeper) <...>-3083 0.... 225us : __add_entropy_words (extract_buf) softirq--13 1Dnh1 225us : _raw_spin_lock (dependent_sleeper) <...>-3083 0.... 225us : _spin_lock_irqsave (__add_entropy_words) softirq--13 1Dnh2 226us : find_next_bit (dependent_sleeper) <...>-3083 0.... 226us : __might_sleep (_spin_lock_irqsave) softirq--13 1Dnh2 226us : _raw_spin_lock (dependent_sleeper) <...>-3083 0.... 226us : irqs_disabled (__might_sleep) softirq--13 1Dnh3 226us : find_next_bit (dependent_sleeper) <...>-3083 0.... 226us : _down_mutex (_spin_lock_irqsave) <...>-3083 0.... 227us : __down_mutex (_spin_lock_irqsave) <...>-3083 0Dnh. 227us : _raw_spin_lock (__down_mutex) softirq--13 1Dnh3 227us : find_next_bit (dependent_sleeper) <...>-3083 0Dnh1 227us : grab_lock (__down_mutex) softirq--13 1Dnh3 227us : _raw_spin_unlock (dependent_sleeper) <...>-3083 0Dnh1 228us : __down_mutex <<...>-3083> (36 0) softirq--13 1Dnh2 228us : preempt_schedule (dependent_sleeper) <...>-3083 0Dnh1 228us : _raw_spin_unlock (__down_mutex) softirq--13 1Dnh2 228us : find_next_bit (dependent_sleeper) <...>-3083 0.... 228us : __local_save_flags (_spin_lock_irqsave) softirq--13 1Dnh2 229us : trace_array (__schedule) <...>-3083 0.... 229us : _spin_unlock_irqrestore (extract_buf) <...>-3083 0.... 229us : up_mutex (extract_buf) <...>-3083 0.... 229us : __up_mutex (up_mutex) softirq--13 1Dnh2 229us : trace_array <<...>-2968> (34 82) <...>-3083 0Dnh. 229us : _raw_spin_lock (__up_mutex) <...>-3083 0Dnh1 230us : _raw_spin_unlock (__up_mutex) <...>-3083 0.... 230us : sha_transform (extract_buf) softirq--13 1Dnh2 230us : trace_array (69 6e) softirq--13 1Dnh2 231us : trace_array (__schedule) <...>-3083 0.... 231us : copy_to_user (extract_entropy_user) <...>-3083 0.... 232us : __might_sleep (copy_to_user) <...>-3083 0.... 232us : irqs_disabled (__might_sleep) <...>-3083 0.... 232us : __might_sleep (copy_to_user) <...>-3083 0.... 232us : irqs_disabled (__might_sleep) <...>-3083 0.... 232us : __copy_to_user_ll (copy_to_user) <...>-3083 0.... 233us : extract_buf (extract_entropy_user) <...>-3083 0.... 233us : sha_init (extract_buf) <...>-3083 0.... 234us : sha_transform (extract_buf) <...>-2968 1Dnh2 234us : __switch_to (__schedule) <...>-2968 1Dnh2 235us : __schedule (69 34) <...>-3083 0.... 235us : __add_entropy_words (extract_buf) <...>-2968 1Dnh2 235us : _raw_spin_unlock (__schedule) <...>-3083 0.... 235us : _spin_lock_irqsave (__add_entropy_words) <...>-2968 1Dnh1 235us : trace_stop_sched_switched (__schedule) <...>-3083 0.... 236us : __might_sleep (_spin_lock_irqsave) <...>-2968 1Dnh1 236us : _raw_spin_lock (trace_stop_sched_switched) <...>-3083 0.... 236us : irqs_disabled (__might_sleep) <...>-2968 1Dnh2 236us : trace_stop_sched_switched <<...>-2968> (34 1) <...>-3083 0.... 236us : _down_mutex (_spin_lock_irqsave) <...>-2968 1Dnh2 236us : _raw_spin_unlock (trace_stop_sched_switched) <...>-3083 0.... 237us : __down_mutex (_spin_lock_irqsave) <...>-3083 0Dnh. 237us : _raw_spin_lock (__down_mutex) <...>-2968 1Dnh1 237us : trace_stop_sched_switched (__schedule) vim:ft=help