Re: [patch] Real-Time Preemption, -RT-2.6.12-rc6-V0.7.48-00
From: William Weston
Date: Wed Jun 22 2005 - 17:08:58 EST
On Wed, 22 Jun 2005, Ingo Molnar wrote:
>
> the second trace seems to be a cross-CPU wakeup bug. It's not completely
> clear from the trace what happened - but we measured the latency of a
> task (wmcube-3191), where the wakeup happened on CPU#0 and wmcube-3191
> was queued to CPU#1 which was idle at that time. The bug is that it
> wasnt until timestamp 306us that this actually happened - and CPU#1 was
> just idling around in default_idle() for no good reason. CPU#1 should
> have run wmcube-3191 at around timestamp 13us.
>
> I've uploaded the -50-07 kernel which will put some more info into the
> traces - could you try to repeat the measurement and get similar
> latencies? As i guess you already found out that you can always reset
> the measurement to get a new set of traces, via:
>
> echo 0 > /proc/sys/kernel/preempt_max_latency
>
> (it's not a problem if you send me multiple latency traces, i'll figure
> out which is the most useful one.)
>
> Ingo
Hi Ingo,
Latency traces (attached) are looking a little bit better with -50-11.
The CPU consistently seems to idle for ~200us at a time in the traces.
Maximum wakeup latency since boot (over an hour ago) is 310us. With
previous RT kernels, maximums would generally go over 800us.
Should I apply your SMT scheduler latency fix, or is that patch for -mm
only?
--wwpreemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-debug
--------------------------------------------------------------------
latency: 231 us, #88/88, CPU#1 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
-----------------
| task: softirq-timer/1-13 (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 1Dnh3 0us : find_next_bit (__trace_start_sched_wakeup)
<idle>-0 0Dnh1 0us : _raw_spin_unlock (scheduler_tick)
<idle>-0 1Dnh3 0us : <70617773> (<00726570>)
<idle>-0 0Dnh. 0us : rebalance_tick (scheduler_tick)
<idle>-0 1Dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
<idle>-0 1Dnh3 1us : __trace_start_sched_wakeup <<...>-13> (69 1)
<idle>-0 0Dnh. 1us : softlockup_tick (smp_apic_timer_interrupt)
<idle>-0 1Dnh3 1us : _raw_spin_unlock (try_to_wake_up)
<idle>-0 0Dnh. 1us : irq_exit (apic_timer_interrupt)
<idle>-0 1Dnh2 1us : resched_task (try_to_wake_up)
<idle>-0 0Dnh1 1us : do_softirq (irq_exit)
<idle>-0 0Dnh1 2us : __do_softirq (do_softirq)
<idle>-0 1Dnh2 2us : try_to_wake_up <<...>-13> (69 8c)
<idle>-0 0Dnh1 2us : trigger_softirqs (do_softirq)
<idle>-0 1Dnh2 2us : _raw_spin_unlock_irqrestore (try_to_wake_up)
<idle>-0 0Dnh1 2us : wakeup_softirqd (trigger_softirqs)
<idle>-0 1Dnh1 2us : preempt_schedule (try_to_wake_up)
<idle>-0 1Dnh1 3us : wake_up_process (trigger_softirqs)
<idle>-0 0Dnh1 3us : wake_up_process (trigger_softirqs)
<idle>-0 0Dnh1 3us : try_to_wake_up (wake_up_process)
<idle>-0 1Dnh. 3us : preempt_schedule_irq (need_resched)
<idle>-0 0Dnh1 3us : _raw_spin_lock (try_to_wake_up)
<idle>-0 1Dnh. 3us : __schedule (preempt_schedule_irq)
<idle>-0 1Dnh. 4us : profile_hit (__schedule)
<idle>-0 0Dnh2 4us : wake_idle (try_to_wake_up)
<idle>-0 1Dnh1 4us : sched_clock (__schedule)
<idle>-0 0Dnh2 4us : idle_cpu (wake_idle)
<idle>-0 1Dnh1 5us : _raw_spin_lock_irq (__schedule)
<idle>-0 0Dnh2 5us : activate_task (try_to_wake_up)
<idle>-0 1Dnh1 5us : _raw_spin_lock_irqsave (__schedule)
<idle>-0 0Dnh2 5us : sched_clock (activate_task)
<idle>-0 0Dnh2 5us : recalc_task_prio (activate_task)
<idle>-0 1Dnh2 5us : dependent_sleeper (__schedule)
<idle>-0 0Dnh2 6us : effective_prio (recalc_task_prio)
<idle>-0 1Dnh2 6us : _raw_spin_unlock (dependent_sleeper)
<idle>-0 0Dnh2 6us : activate_task <<...>-4> (69 0)
<idle>-0 1Dnh1 6us : preempt_schedule (dependent_sleeper)
<idle>-0 0Dnh2 6us : enqueue_task (activate_task)
<idle>-0 1Dnh1 6us : _raw_spin_lock (dependent_sleeper)
<idle>-0 0Dnh2 7us : __trace_start_sched_wakeup (try_to_wake_up)
<idle>-0 1Dnh1 7us : preempt_schedule (_raw_spin_lock)
<idle>-0 0Dnh2 7us : _raw_spin_lock (__trace_start_sched_wakeup)
<idle>-0 0Dnh3 7us : _raw_spin_unlock (try_to_wake_up)
<idle>-0 0Dnh2 7us : resched_task (try_to_wake_up)
<idle>-0 0Dnh2 8us : try_to_wake_up <<...>-4> (69 8c)
<idle>-0 0Dnh2 8us : _raw_spin_unlock_irqrestore (try_to_wake_up)
<idle>-0 1Dnh2 8us : find_next_bit (dependent_sleeper)
<idle>-0 0Dnh1 8us : preempt_schedule (try_to_wake_up)
<idle>-0 1Dnh2 8us : _raw_spin_lock (dependent_sleeper)
<idle>-0 0Dnh1 8us : wake_up_process (trigger_softirqs)
<idle>-0 1Dnh3 9us : find_next_bit (dependent_sleeper)
<idle>-0 0Dnh. 9us : preempt_schedule_irq (need_resched)
<idle>-0 0Dnh. 9us : __schedule (preempt_schedule_irq)
<idle>-0 1Dnh3 9us : resched_task (dependent_sleeper)
<idle>-0 0Dnh. 10us : profile_hit (__schedule)
<idle>-0 1Dnh3 10us : find_next_bit (dependent_sleeper)
<idle>-0 0Dnh1 10us : sched_clock (__schedule)
<idle>-0 1Dnh3 10us : _raw_spin_unlock (dependent_sleeper)
<idle>-0 0Dnh1 10us : _raw_spin_lock_irq (__schedule)
<idle>-0 1Dnh2 11us : preempt_schedule (dependent_sleeper)
<idle>-0 0Dnh1 11us : _raw_spin_lock_irqsave (__schedule)
<idle>-0 1Dnh2 11us : find_next_bit (dependent_sleeper)
<idle>-0 0Dnh2 11us : dependent_sleeper (__schedule)
<idle>-0 0Dnh2 11us : _raw_spin_unlock (dependent_sleeper)
<idle>-0 1Dnh2 11us : dequeue_task (__schedule)
<idle>-0 0Dnh1 12us : preempt_schedule (dependent_sleeper)
<idle>-0 1Dnh2 12us : recalc_task_prio (__schedule)
<idle>-0 0Dnh1 12us : _raw_spin_lock (dependent_sleeper)
<idle>-0 1Dnh2 12us : effective_prio (recalc_task_prio)
<idle>-0 0Dnh2 12us : find_next_bit (dependent_sleeper)
<idle>-0 1Dnh2 12us : enqueue_task (__schedule)
<idle>-0 0Dnh2 13us : _raw_spin_lock (dependent_sleeper)
<idle>-0 1Dnh2 13us : trace_array (__schedule)
<idle>-0 0Dnh2 13us : preempt_schedule (_raw_spin_lock)
<idle>-0 1Dnh2 14us : trace_array <<...>-13> (69 6e)
<idle>-0 1Dnh2 15us : trace_array (__schedule)
<...>-13 1Dnh2 17us : __switch_to (__schedule)
<...>-13 1Dnh2 17us : __schedule <<idle>-0> (8c 69)
<...>-13 1Dnh2 17us : _raw_spin_unlock (__schedule)
<...>-13 1Dnh1 18us : trace_stop_sched_switched (__schedule)
<idle>-0 0Dnh3 18us!: find_next_bit (dependent_sleeper)
<...>-13 1Dnh1 229us : _raw_spin_lock (trace_stop_sched_switched)
<...>-13 1Dnh2 230us : trace_stop_sched_switched <<...>-13> (69 1)
<idle>-0 0Dnh3 230us : find_next_bit (dependent_sleeper)
<...>-13 1Dnh2 230us : _raw_spin_unlock (trace_stop_sched_switched)
<idle>-0 0Dnh3 231us : _raw_spin_unlock (dependent_sleeper)
<...>-13 1Dnh1 231us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-debug
--------------------------------------------------------------------
latency: 233 us, #121/121, CPU#1 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
-----------------
| task: wmcube-2964 (uid:500 nice:10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
X-2870 0Dnh2 0us : __trace_start_sched_wakeup (try_to_wake_up)
X-2870 0Dnh2 0us : __trace_start_sched_wakeup <<...>-2964> (36 1)
X-2870 0Dnh2 0us : _raw_spin_unlock (try_to_wake_up)
X-2870 0Dnh1 0us : resched_task (try_to_wake_up)
X-2870 0Dnh1 1us : smp_send_reschedule (try_to_wake_up)
X-2870 0Dnh1 1us : send_IPI_mask_bitmask (smp_send_reschedule)
X-2870 0Dnh1 1us : _raw_spin_unlock_irqrestore (try_to_wake_up)
X-2870 0.... 1us : _spin_unlock_irqrestore (sock_def_readable)
softirq--13 1Dnh1 1us : wake_idle (try_to_wake_up)
X-2870 0.... 2us : up_mutex (sock_def_readable)
softirq--13 1Dnh1 2us : idle_cpu (wake_idle)
X-2870 0.... 2us : __up_mutex (up_mutex)
softirq--13 1Dnh1 2us : idle_cpu (wake_idle)
X-2870 0Dnh. 2us : _raw_spin_lock (__up_mutex)
softirq--13 1Dnh1 2us : find_next_bit (wake_idle)
softirq--13 1Dnh1 3us : idle_cpu (wake_idle)
X-2870 0Dnh1 3us : _raw_spin_unlock (__up_mutex)
softirq--13 1Dnh1 3us : find_next_bit (wake_idle)
X-2870 0.... 3us : _read_unlock (unix_stream_sendmsg)
softirq--13 1Dnh1 3us : idle_cpu (wake_idle)
X-2870 0.... 3us : up_read_mutex (unix_stream_sendmsg)
softirq--13 1Dnh1 4us : find_next_bit (wake_idle)
X-2870 0.... 4us : up_write_mutex (unix_stream_sendmsg)
softirq--13 1Dnh1 4us : idle_cpu (wake_idle)
X-2870 0.... 4us : __up_mutex (up_write_mutex)
softirq--13 1Dnh1 4us : find_next_bit (wake_idle)
X-2870 0Dnh. 4us : _raw_spin_lock (__up_mutex)
softirq--13 1Dnh1 5us : activate_task (try_to_wake_up)
X-2870 0Dnh1 5us : _raw_spin_unlock (__up_mutex)
softirq--13 1Dnh1 5us : sched_clock (activate_task)
softirq--13 1Dnh1 5us : recalc_task_prio (activate_task)
X-2870 0.... 6us : dnotify_parent (do_readv_writev)
softirq--13 1Dnh1 6us : effective_prio (recalc_task_prio)
X-2870 0.... 6us : _spin_lock (dnotify_parent)
softirq--13 1Dnh1 6us : activate_task <<...>-2967> (36 2)
X-2870 0.... 6us : __might_sleep (_spin_lock)
softirq--13 1Dnh1 6us : enqueue_task (activate_task)
X-2870 0.... 6us : irqs_disabled (__might_sleep)
X-2870 0.... 7us : _down_mutex (_spin_lock)
softirq--13 1Dnh1 7us : __trace_start_sched_wakeup (try_to_wake_up)
X-2870 0.... 7us : __down_mutex (_spin_lock)
softirq--13 1Dnh1 7us : _raw_spin_lock (__trace_start_sched_wakeup)
X-2870 0Dnh. 7us : _raw_spin_lock (__down_mutex)
softirq--13 1Dnh2 8us : _raw_spin_unlock (try_to_wake_up)
X-2870 0Dnh1 8us : grab_lock (__down_mutex)
softirq--13 1Dnh1 8us : preempt_schedule (try_to_wake_up)
X-2870 0Dnh1 8us : __down_mutex <X-2870> (36 0)
softirq--13 1Dnh1 8us : resched_task (try_to_wake_up)
X-2870 0Dnh1 9us : _raw_spin_unlock (__down_mutex)
softirq--13 1Dnh1 9us : try_to_wake_up <<...>-2967> (36 69)
X-2870 0.... 9us : _spin_unlock (do_readv_writev)
softirq--13 1Dnh1 9us : _raw_spin_unlock_irqrestore (try_to_wake_up)
X-2870 0.... 9us : up_mutex (do_readv_writev)
X-2870 0.... 10us : __up_mutex (up_mutex)
softirq--13 1Dnh. 10us : smp_reschedule_interrupt (c0306aaa 0 0)
X-2870 0Dnh. 10us : _raw_spin_lock (__up_mutex)
softirq--13 1Dnh. 10us : preempt_schedule_irq (need_resched)
X-2870 0Dnh1 10us : _raw_spin_unlock (__up_mutex)
softirq--13 1Dnh. 11us : __schedule (preempt_schedule_irq)
X-2870 0Dnh. 11us < (32)
softirq--13 1Dnh. 11us : profile_hit (__schedule)
softirq--13 1Dnh1 11us : sched_clock (__schedule)
softirq--13 1Dnh1 11us : _raw_spin_lock_irq (__schedule)
softirq--13 1Dnh1 12us : _raw_spin_lock_irqsave (__schedule)
X-2870 0.... 12us > sys_gettimeofday (bf8d4b28 00000000 0000007b)
softirq--13 1Dnh2 12us : pull_rt_tasks (__schedule)
X-2870 0.... 12us : sys_gettimeofday (sysenter_past_esp)
X-2870 0.... 13us : timeofday_API_hacks (sys_gettimeofday)
softirq--13 1Dnh2 13us : find_next_bit (pull_rt_tasks)
X-2870 0.... 13us : do_gettimeofday (sys_gettimeofday)
softirq--13 1Dnh2 13us : find_next_bit (pull_rt_tasks)
X-2870 0.... 13us : get_offset_pmtmr (do_gettimeofday)
softirq--13 1Dnh2 13us : dependent_sleeper (__schedule)
softirq--13 1Dnh2 14us : _raw_spin_unlock (dependent_sleeper)
softirq--13 1Dnh1 14us : preempt_schedule (dependent_sleeper)
softirq--13 1Dnh1 14us : _raw_spin_lock (dependent_sleeper)
softirq--13 1Dnh2 15us : find_next_bit (dependent_sleeper)
softirq--13 1Dnh2 15us : _raw_spin_lock (dependent_sleeper)
softirq--13 1Dnh3 15us : find_next_bit (dependent_sleeper)
softirq--13 1Dnh3 16us : find_next_bit (dependent_sleeper)
softirq--13 1Dnh3 16us : _raw_spin_unlock (dependent_sleeper)
X-2870 0.... 16us : copy_to_user (sys_gettimeofday)
softirq--13 1Dnh2 16us : preempt_schedule (dependent_sleeper)
X-2870 0.... 16us : __might_sleep (copy_to_user)
softirq--13 1Dnh2 16us : find_next_bit (dependent_sleeper)
X-2870 0.... 17us : irqs_disabled (__might_sleep)
X-2870 0.... 17us : __might_sleep (copy_to_user)
softirq--13 1Dnh2 17us : trace_array (__schedule)
X-2870 0.... 17us : irqs_disabled (__might_sleep)
X-2870 0.... 17us : __copy_to_user_ll (copy_to_user)
X-2870 0Dnh. 18us < (0)
softirq--13 1Dnh2 18us : trace_array <<...>-2964> (36 82)
softirq--13 1Dnh2 18us : trace_array <<...>-2967> (36 78)
softirq--13 1Dnh2 19us : trace_array <softirq--13> (69 6e)
softirq--13 1Dnh2 19us!: trace_array (__schedule)
X-2870 0.... 227us > sys_select (00000100 08207260 0000007b)
X-2870 0.... 228us : sys_select (sysenter_past_esp)
X-2870 0.... 228us : select_bits_alloc (sys_select)
X-2870 0.... 228us : __kmalloc (select_bits_alloc)
X-2870 0.... 229us : __might_sleep (__kmalloc)
X-2870 0.... 229us : irqs_disabled (__might_sleep)
X-2870 0.... 229us : __local_save_flags (__kmalloc)
X-2870 0.... 229us : _spin_lock (__kmalloc)
X-2870 0.... 230us : __might_sleep (_spin_lock)
<...>-2964 1Dnh2 230us : __switch_to (__schedule)
X-2870 0.... 230us : irqs_disabled (__might_sleep)
<...>-2964 1Dnh2 230us : __schedule <softirq--13> (69 36)
X-2870 0.... 230us : _down_mutex (_spin_lock)
X-2870 0.... 231us : __down_mutex (_spin_lock)
<...>-2964 1Dnh2 231us : _raw_spin_unlock (__schedule)
X-2870 0Dnh. 231us : _raw_spin_lock (__down_mutex)
<...>-2964 1Dnh1 231us : trace_stop_sched_switched (__schedule)
<...>-2964 1Dnh1 231us : _raw_spin_lock (trace_stop_sched_switched)
X-2870 0Dnh1 231us : grab_lock (__down_mutex)
<...>-2964 1Dnh2 232us : trace_stop_sched_switched <<...>-2964> (36 1)
X-2870 0Dnh1 232us : __down_mutex <X-2870> (36 0)
<...>-2964 1Dnh2 232us : _raw_spin_unlock (trace_stop_sched_switched)
X-2870 0Dnh1 232us : _raw_spin_unlock (__down_mutex)
<...>-2964 1Dnh1 232us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-debug
--------------------------------------------------------------------
latency: 223 us, #76/76, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
-----------------
| task: wmfortune-2967 (uid:500 nice:0 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
<...>-3083 1Dnh1 0us : grab_lock (__down_mutex)
softirq--4 0Dnh. 0us : preempt_schedule (__up_mutex)
softirq--4 0Dnh. 0us : irqs_disabled (preempt_schedule)
<...>-3083 1Dnh1 0us : __down_mutex <<...>-3083> (36 0)
<...>-3083 1Dnh1 0us : _raw_spin_unlock (__down_mutex)
softirq--4 0Dn.. 0us : preempt_schedule (up_mutex)
softirq--4 0Dn.. 0us : irqs_disabled (preempt_schedule)
<...>-3083 1.... 0us : __local_save_flags (_spin_lock_irqsave)
softirq--4 0Dnh. 1us : __schedule (preempt_schedule)
<...>-3083 1.... 1us : _spin_unlock_irqrestore (extract_buf)
softirq--4 0Dnh. 1us : profile_hit (__schedule)
<...>-3083 1.... 1us : up_mutex (extract_buf)
<...>-3083 1.... 1us : __up_mutex (up_mutex)
softirq--4 0Dnh1 1us : sched_clock (__schedule)
softirq--4 0Dnh1 2us!: _raw_spin_lock_irq (__schedule)
<...>-3083 1Dnh. 207us : _raw_spin_lock (__up_mutex)
<...>-3083 1Dnh1 208us : _raw_spin_unlock (__up_mutex)
softirq--4 0Dnh1 208us : _raw_spin_lock_irqsave (__schedule)
<...>-3083 1.... 208us : sha_transform (extract_buf)
softirq--4 0Dnh2 208us : dependent_sleeper (__schedule)
softirq--4 0Dnh2 209us : _raw_spin_unlock (dependent_sleeper)
softirq--4 0Dnh1 209us : preempt_schedule (dependent_sleeper)
<...>-3083 1.... 209us : __add_entropy_words (extract_buf)
softirq--4 0Dnh1 209us : _raw_spin_lock (dependent_sleeper)
<...>-3083 1.... 209us : _spin_lock_irqsave (__add_entropy_words)
softirq--4 0Dnh2 209us : find_next_bit (dependent_sleeper)
<...>-3083 1.... 210us : __might_sleep (_spin_lock_irqsave)
softirq--4 0Dnh2 210us : _raw_spin_lock (dependent_sleeper)
<...>-3083 1.... 210us : irqs_disabled (__might_sleep)
<...>-3083 1.... 210us : _down_mutex (_spin_lock_irqsave)
softirq--4 0Dnh3 210us : find_next_bit (dependent_sleeper)
<...>-3083 1.... 210us : __down_mutex (_spin_lock_irqsave)
<...>-3083 1Dnh. 211us : _raw_spin_lock (__down_mutex)
softirq--4 0Dnh3 211us : find_next_bit (dependent_sleeper)
softirq--4 0Dnh3 211us : _raw_spin_unlock (dependent_sleeper)
<...>-3083 1Dnh1 211us : grab_lock (__down_mutex)
softirq--4 0Dnh2 211us : preempt_schedule (dependent_sleeper)
<...>-3083 1Dnh1 211us : __down_mutex <<...>-3083> (36 0)
softirq--4 0Dnh2 212us : find_next_bit (dependent_sleeper)
<...>-3083 1Dnh1 212us : _raw_spin_unlock (__down_mutex)
<...>-3083 1.... 212us : __local_save_flags (_spin_lock_irqsave)
softirq--4 0Dnh2 212us : trace_array (__schedule)
<...>-3083 1.... 212us : _spin_unlock_irqrestore (extract_buf)
<...>-3083 1.... 213us : up_mutex (extract_buf)
<...>-3083 1.... 213us : __up_mutex (up_mutex)
softirq--4 0Dnh2 213us : trace_array <<...>-2967> (34 78)
<...>-3083 1Dnh. 213us : _raw_spin_lock (__up_mutex)
<...>-3083 1Dnh1 214us : _raw_spin_unlock (__up_mutex)
<...>-3083 1.... 214us : __add_entropy_words (extract_buf)
softirq--4 0Dnh2 214us : trace_array <softirq--4> (69 6e)
<...>-3083 1.... 214us : _spin_lock_irqsave (__add_entropy_words)
<...>-3083 1.... 214us : __might_sleep (_spin_lock_irqsave)
softirq--4 0Dnh2 215us : trace_array (__schedule)
<...>-3083 1.... 215us : irqs_disabled (__might_sleep)
<...>-3083 1.... 215us : _down_mutex (_spin_lock_irqsave)
<...>-3083 1.... 215us : __down_mutex (_spin_lock_irqsave)
<...>-3083 1Dnh. 215us : _raw_spin_lock (__down_mutex)
<...>-3083 1Dnh1 216us : grab_lock (__down_mutex)
<...>-3083 1Dnh1 216us : __down_mutex <<...>-3083> (36 0)
<...>-3083 1Dnh1 216us : _raw_spin_unlock (__down_mutex)
<...>-3083 1.... 216us : __local_save_flags (_spin_lock_irqsave)
<...>-2967 0Dnh2 217us : __switch_to (__schedule)
<...>-3083 1.... 217us : _spin_unlock_irqrestore (extract_buf)
<...>-3083 1.... 217us : up_mutex (extract_buf)
<...>-2967 0Dnh2 217us : __schedule <softirq--4> (69 34)
<...>-3083 1.... 217us : __up_mutex (up_mutex)
<...>-2967 0Dnh2 218us : _raw_spin_unlock (__schedule)
<...>-3083 1Dnh. 218us : _raw_spin_lock (__up_mutex)
<...>-2967 0Dnh1 218us : trace_stop_sched_switched (__schedule)
<...>-3083 1Dnh1 218us : _raw_spin_unlock (__up_mutex)
<...>-2967 0Dnh1 218us : _raw_spin_lock (trace_stop_sched_switched)
<...>-3083 1.... 219us : sha_transform (extract_buf)
<...>-2967 0Dnh2 219us : trace_stop_sched_switched <<...>-2967> (34 0)
<...>-2967 0Dnh2 219us : _raw_spin_unlock (trace_stop_sched_switched)
<...>-2967 0Dnh1 219us : trace_stop_sched_switched (__schedule)
vim:ft=help
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 <softirq--13> (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 <softirq--13> (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
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-debug
--------------------------------------------------------------------
latency: 223 us, #70/70, CPU#1 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
-----------------
| task: X-2870 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
<...>-3083 0Dnh1 0us : _raw_spin_unlock (__up_mutex)
softirq--13 1Dn.. 0us : preempt_schedule (up_mutex)
<...>-3083 0.... 0us : __add_entropy_words (extract_buf)
softirq--13 1Dn.. 0us : irqs_disabled (preempt_schedule)
<...>-3083 0.... 0us : _spin_lock_irqsave (__add_entropy_words)
softirq--13 1Dnh. 0us : __schedule (preempt_schedule)
<...>-3083 0.... 0us : __might_sleep (_spin_lock_irqsave)
<...>-3083 0.... 1us!: irqs_disabled (__might_sleep)
softirq--13 1Dnh. 207us : profile_hit (__schedule)
<...>-3083 0.... 207us : _down_mutex (_spin_lock_irqsave)
<...>-3083 0.... 207us : __down_mutex (_spin_lock_irqsave)
softirq--13 1Dnh1 208us : sched_clock (__schedule)
<...>-3083 0Dnh. 208us : _raw_spin_lock (__down_mutex)
softirq--13 1Dnh1 208us : _raw_spin_lock_irq (__schedule)
softirq--13 1Dnh1 208us : _raw_spin_lock_irqsave (__schedule)
<...>-3083 0Dnh1 208us : grab_lock (__down_mutex)
softirq--13 1Dnh2 209us : dependent_sleeper (__schedule)
<...>-3083 0Dnh1 209us : __down_mutex <<...>-3083> (36 0)
softirq--13 1Dnh2 209us : _raw_spin_unlock (dependent_sleeper)
<...>-3083 0Dnh1 209us : _raw_spin_unlock (__down_mutex)
softirq--13 1Dnh1 209us : preempt_schedule (dependent_sleeper)
<...>-3083 0.... 209us : __local_save_flags (_spin_lock_irqsave)
softirq--13 1Dnh1 210us : _raw_spin_lock (dependent_sleeper)
<...>-3083 0.... 210us : _spin_unlock_irqrestore (extract_buf)
softirq--13 1Dnh2 210us : find_next_bit (dependent_sleeper)
<...>-3083 0.... 210us : up_mutex (extract_buf)
softirq--13 1Dnh2 210us : _raw_spin_lock (dependent_sleeper)
<...>-3083 0.... 210us : __up_mutex (up_mutex)
softirq--13 1Dnh3 211us : find_next_bit (dependent_sleeper)
<...>-3083 0Dnh. 211us : _raw_spin_lock (__up_mutex)
<...>-3083 0Dnh1 211us : _raw_spin_unlock (__up_mutex)
softirq--13 1Dnh3 211us : find_next_bit (dependent_sleeper)
softirq--13 1Dnh3 212us : _raw_spin_unlock (dependent_sleeper)
<...>-3083 0.... 212us : sha_transform (extract_buf)
softirq--13 1Dnh2 212us : preempt_schedule (dependent_sleeper)
softirq--13 1Dnh2 212us : find_next_bit (dependent_sleeper)
softirq--13 1Dnh2 213us : trace_array (__schedule)
<...>-3083 0.... 213us : copy_to_user (extract_entropy_user)
<...>-3083 0.... 213us : __might_sleep (copy_to_user)
<...>-3083 0.... 213us : irqs_disabled (__might_sleep)
softirq--13 1Dnh2 213us : trace_array <<...>-2870> (34 78)
<...>-3083 0.... 214us : __might_sleep (copy_to_user)
<...>-3083 0.... 214us : irqs_disabled (__might_sleep)
<...>-3083 0.... 214us : __copy_to_user_ll (copy_to_user)
softirq--13 1Dnh2 214us : trace_array <softirq--13> (69 6e)
<...>-3083 0.... 215us : extract_buf (extract_entropy_user)
<...>-3083 0.... 215us : sha_init (extract_buf)
softirq--13 1Dnh2 215us : trace_array (__schedule)
<...>-3083 0.... 215us : sha_transform (extract_buf)
<...>-3083 0.... 216us : __add_entropy_words (extract_buf)
<...>-3083 0.... 216us : _spin_lock_irqsave (__add_entropy_words)
<...>-3083 0.... 216us : __might_sleep (_spin_lock_irqsave)
<...>-3083 0.... 217us : irqs_disabled (__might_sleep)
<...>-3083 0.... 217us : _down_mutex (_spin_lock_irqsave)
<...>-2870 1Dnh2 217us : __switch_to (__schedule)
<...>-3083 0.... 217us : __down_mutex (_spin_lock_irqsave)
<...>-3083 0Dnh. 218us : _raw_spin_lock (__down_mutex)
<...>-2870 1Dnh2 218us : __schedule <softirq--13> (69 34)
<...>-2870 1Dnh2 218us : _raw_spin_unlock (__schedule)
<...>-3083 0Dnh1 218us : grab_lock (__down_mutex)
<...>-2870 1Dnh1 218us : trace_stop_sched_switched (__schedule)
<...>-3083 0Dnh1 218us : __down_mutex <<...>-3083> (36 0)
<...>-2870 1Dnh1 219us : _raw_spin_lock (trace_stop_sched_switched)
<...>-3083 0Dnh1 219us : _raw_spin_unlock (__down_mutex)
<...>-2870 1Dnh2 219us : trace_stop_sched_switched <<...>-2870> (34 1)
<...>-3083 0.... 219us : __local_save_flags (_spin_lock_irqsave)
<...>-2870 1Dnh2 219us : _raw_spin_unlock (trace_stop_sched_switched)
<...>-3083 0.... 219us : _spin_unlock_irqrestore (extract_buf)
<...>-2870 1Dnh1 220us : trace_stop_sched_switched (__schedule)
vim:ft=help