Nov 21 19:22:42 eran kernel: (multiload-apple/5506/CPU#0): 1694 us wakeup latency violates 1000 us threshold. preemption latency trace v1.0.7 on 2.6.10-rc2-mm2-V0.7.29-5 ------------------------------------------------------- latency: 1694 us, entries: 21 (21) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1] ----------------- | task: multiload-apple/5506, uid:500 nice:0 policy:0 rt_prio:0 ----------------- => started at: try_to_wake_up+0x165/0x1d0 => ended at: finish_task_switch+0x4f/0xc0 =======> 131 88000006 0.000ms (+0.000ms): __trace_start_sched_wakeup (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): (115) ((116)) 131 88000005 0.000ms (+0.000ms): (5506) ((131)) 131 88000005 0.001ms (+0.000ms): try_to_wake_up (wake_up_process) 131 88000005 0.001ms (+0.000ms): (0) ((1)) 131 88000004 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000004 0.001ms (+0.000ms): wake_up_process (__up_mutex) 131 88000003 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 88000002 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 08000001 0.002ms (+0.000ms): preempt_schedule (__schedule) 131 08000001 0.002ms (+0.000ms): sched_clock (__schedule) 131 88000002 0.003ms (+0.000ms): deactivate_task (__schedule) 131 88000002 0.003ms (+1.687ms): dequeue_task (deactivate_task) 5506 80000002 1.691ms (+0.001ms): __switch_to (__schedule) 5506 80000002 1.692ms (+0.000ms): (131) ((5506)) 5506 80000002 1.693ms (+0.000ms): (116) ((115)) 5506 80000002 1.693ms (+0.000ms): finish_task_switch (__schedule) 5506 80000001 1.693ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) 5506 80000001 1.693ms (+0.005ms): (5506) ((115)) 5506 80000001 1.699ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) ================== Nov 21 19:30:58 eran kernel: (firefox-bin/14054/CPU#0): 1991 us wakeup latency violates 1000 us threshold. preemption latency trace v1.0.7 on 2.6.10-rc2-mm2-V0.7.29-5 ------------------------------------------------------- latency: 1991 us, entries: 21 (21) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1] ----------------- | task: firefox-bin/14054, uid:500 nice:0 policy:0 rt_prio:0 ----------------- => started at: try_to_wake_up+0x165/0x1d0 => ended at: finish_task_switch+0x4f/0xc0 =======> 131 88000006 0.000ms (+0.000ms): __trace_start_sched_wakeup (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): (115) ((116)) 131 88000005 0.000ms (+0.000ms): <000036e6> ((131)) 131 88000005 0.000ms (+0.000ms): try_to_wake_up (wake_up_process) 131 88000005 0.001ms (+0.000ms): (0) ((1)) 131 88000004 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000004 0.001ms (+0.000ms): wake_up_process (__up_mutex) 131 88000003 0.001ms (+0.000ms): preempt_schedule (__up_mutex) 131 88000002 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 08000001 0.002ms (+0.000ms): preempt_schedule (__schedule) 131 08000001 0.002ms (+0.000ms): sched_clock (__schedule) 131 88000002 0.003ms (+0.000ms): deactivate_task (__schedule) 131 88000002 0.003ms (+1.986ms): dequeue_task (deactivate_task) 14054 80000002 1.989ms (+0.000ms): __switch_to (__schedule) 14054 80000002 1.989ms (+0.000ms): (131) (<000036e6>) 14054 80000002 1.989ms (+0.000ms): (116) ((115)) 14054 80000002 1.990ms (+0.000ms): finish_task_switch (__schedule) 14054 80000001 1.990ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) 14054 80000001 1.990ms (+0.006ms): <000036e6> ((115)) 14054 80000001 1.996ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) ================== Nov 21 19:31:44 eran kernel: (IRQ 0/2/CPU#0): 1213 us wakeup latency violates 1000 us threshold. preemption latency trace v1.0.7 on 2.6.10-rc2-mm2-V0.7.29-5 ------------------------------------------------------- latency: 1213 us, entries: 23 (23) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1] ----------------- | task: IRQ 0/2, uid:0 nice:0 policy:1 rt_prio:49 ----------------- => started at: try_to_wake_up+0x165/0x1d0 => ended at: finish_task_switch+0x4f/0xc0 =======> 3 88010003 0.000ms (+0.000ms): __trace_start_sched_wakeup (try_to_wake_up) 3 88010002 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up) 3 88010002 0.000ms (+0.000ms): (50) ((105)) 3 88010002 0.000ms (+0.000ms): (2) ((3)) 3 88010002 0.000ms (+0.000ms): try_to_wake_up (wake_up_process) 3 88010002 0.001ms (+0.000ms): (0) ((1)) 3 88010001 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up) 3 88010001 0.001ms (+0.000ms): wake_up_process (redirect_hardirq) 3 88010000 0.001ms (+0.000ms): preempt_schedule (__do_IRQ) 3 88010000 0.002ms (+0.000ms): irq_exit (do_IRQ) 3 88000001 0.002ms (+0.000ms): do_softirq (irq_exit) 3 88000001 0.002ms (+0.000ms): __do_softirq (do_softirq) 3 88000000 0.002ms (+0.000ms): preempt_schedule_irq (need_resched) 3 98000000 0.003ms (+0.000ms): __schedule (preempt_schedule_irq) 3 98000000 0.003ms (+0.000ms): profile_hit (__schedule) 3 98000001 0.003ms (+0.000ms): sched_clock (__schedule) 2 80000002 0.004ms (+1.207ms): __switch_to (__schedule) 2 80000002 1.212ms (+0.000ms): (3) ((2)) 2 80000002 1.212ms (+0.000ms): (105) ((50)) 2 80000002 1.212ms (+0.000ms): finish_task_switch (__schedule) 2 80000001 1.212ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) 2 80000001 1.212ms (+0.006ms): (2) ((50)) 2 80000001 1.219ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) ================== Nov 21 19:36:18 eran kernel: (firefox-bin/14054/CPU#0): 1881 us wakeup latency violates 1000 us threshold. preemption latency trace v1.0.7 on 2.6.10-rc2-mm2-V0.7.29-5 ------------------------------------------------------- latency: 1881 us, entries: 21 (21) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1] ----------------- | task: firefox-bin/14054, uid:500 nice:0 policy:0 rt_prio:0 ----------------- => started at: try_to_wake_up+0x165/0x1d0 => ended at: finish_task_switch+0x4f/0xc0 =======> 131 88000006 0.000ms (+0.000ms): __trace_start_sched_wakeup (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): (115) ((116)) 131 88000005 0.000ms (+0.000ms): <000036e6> ((131)) 131 88000005 0.001ms (+0.000ms): try_to_wake_up (wake_up_process) 131 88000005 0.001ms (+0.000ms): (0) ((1)) 131 88000004 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000004 0.001ms (+0.000ms): wake_up_process (__up_mutex) 131 88000003 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 88000002 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 08000001 0.002ms (+0.000ms): preempt_schedule (__schedule) 131 08000001 0.002ms (+0.000ms): sched_clock (__schedule) 131 88000002 0.003ms (+0.000ms): deactivate_task (__schedule) 131 88000002 0.003ms (+1.875ms): dequeue_task (deactivate_task) 14054 80000002 1.878ms (+0.001ms): __switch_to (__schedule) 14054 80000002 1.880ms (+0.000ms): (131) (<000036e6>) 14054 80000002 1.880ms (+0.000ms): (116) ((115)) 14054 80000002 1.880ms (+0.000ms): finish_task_switch (__schedule) 14054 80000001 1.880ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) 14054 80000001 1.881ms (+0.008ms): <000036e6> ((115)) 14054 80000001 1.890ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) ================== Nov 21 19:37:18 eran kernel: (firefox-bin/14054/CPU#0): 1347 us wakeup latency violates 1000 us threshold. preemption latency trace v1.0.7 on 2.6.10-rc2-mm2-V0.7.29-5 ------------------------------------------------------- latency: 1347 us, entries: 21 (21) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1] ----------------- | task: firefox-bin/14054, uid:500 nice:0 policy:0 rt_prio:0 ----------------- => started at: try_to_wake_up+0x165/0x1d0 => ended at: finish_task_switch+0x4f/0xc0 =======> 131 88000006 0.000ms (+0.000ms): __trace_start_sched_wakeup (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): (115) ((116)) 131 88000005 0.000ms (+0.000ms): <000036e6> ((131)) 131 88000005 0.000ms (+0.000ms): try_to_wake_up (wake_up_process) 131 88000005 0.001ms (+0.000ms): (0) ((1)) 131 88000004 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000004 0.001ms (+0.000ms): wake_up_process (__up_mutex) 131 88000003 0.001ms (+0.000ms): preempt_schedule (__up_mutex) 131 88000002 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 08000001 0.002ms (+0.000ms): preempt_schedule (__schedule) 131 08000001 0.002ms (+0.000ms): sched_clock (__schedule) 131 88000002 0.003ms (+0.000ms): deactivate_task (__schedule) 131 88000002 0.003ms (+0.000ms): dequeue_task (deactivate_task) 14054 80000002 0.003ms (+0.000ms): __switch_to (__schedule) 14054 80000002 0.004ms (+0.000ms): (131) (<000036e6>) 14054 80000002 0.004ms (+0.000ms): (116) ((115)) 14054 80000002 0.004ms (+0.000ms): finish_task_switch (__schedule) 14054 80000001 0.005ms (+1.342ms): trace_stop_sched_switched (finish_task_switch) 14054 80000001 1.347ms (+0.103ms): <000036e6> ((115)) 14054 80000001 1.450ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) ================== Nov 21 19:49:21 eran kernel: (gnome-terminal/5434/CPU#0): 1683 us wakeup latency violates 1000 us threshold. preemption latency trace v1.0.7 on 2.6.10-rc2-mm2-V0.7.29-5 ------------------------------------------------------- latency: 1683 us, entries: 21 (21) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1] ----------------- | task: gnome-terminal/5434, uid:500 nice:0 policy:0 rt_prio:0 ----------------- => started at: try_to_wake_up+0x165/0x1d0 => ended at: finish_task_switch+0x4f/0xc0 =======> 131 88000006 0.000ms (+0.000ms): __trace_start_sched_wakeup (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000005 0.000ms (+0.000ms): (115) ((116)) 131 88000005 0.001ms (+0.000ms): (5434) ((131)) 131 88000005 0.001ms (+0.000ms): try_to_wake_up (wake_up_process) 131 88000005 0.001ms (+0.000ms): (0) ((1)) 131 88000004 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up) 131 88000004 0.001ms (+0.000ms): wake_up_process (__up_mutex) 131 88000003 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 88000002 0.002ms (+0.000ms): preempt_schedule (__up_mutex) 131 08000001 0.002ms (+0.000ms): preempt_schedule (__schedule) 131 08000001 0.002ms (+0.000ms): sched_clock (__schedule) 131 88000002 0.003ms (+0.000ms): deactivate_task (__schedule) 131 88000002 0.003ms (+1.676ms): dequeue_task (deactivate_task) 5434 80000002 1.680ms (+0.001ms): __switch_to (__schedule) 5434 80000002 1.681ms (+0.000ms): (131) ((5434)) 5434 80000002 1.682ms (+0.000ms): (116) ((115)) 5434 80000002 1.682ms (+0.000ms): finish_task_switch (__schedule) 5434 80000001 1.682ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) 5434 80000001 1.682ms (+0.006ms): (5434) ((115)) 5434 80000001 1.689ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) ================== Nov 21 19:52:18 eran kernel: (IRQ 0/2/CPU#0): 2009 us wakeup latency violates 1000 us threshold. preemption latency trace v1.0.7 on 2.6.10-rc2-mm2-V0.7.29-5 ------------------------------------------------------- latency: 2009 us, entries: 37 (37) | [VP:0 KP:1 SP:1 HP:1 #CPUS:1] ----------------- | task: IRQ 0/2, uid:0 nice:0 policy:1 rt_prio:49 ----------------- => started at: try_to_wake_up+0x165/0x1d0 => ended at: finish_task_switch+0x4f/0xc0 =======> 783 88010003 0.000ms (+0.000ms): __trace_start_sched_wakeup (try_to_wake_up) 783 88010002 0.000ms (+0.000ms): preempt_schedule (try_to_wake_up) 783 88010002 0.000ms (+0.000ms): (50) ((54)) 783 88010002 0.000ms (+0.000ms): (2) ((783)) 783 88010002 0.000ms (+0.000ms): try_to_wake_up (wake_up_process) 783 88010002 0.001ms (+0.000ms): (0) ((1)) 783 88010001 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up) 783 88010001 0.001ms (+0.000ms): wake_up_process (redirect_hardirq) 783 88010000 0.001ms (+0.000ms): preempt_schedule (__do_IRQ) 783 88010000 0.002ms (+0.000ms): irq_exit (do_IRQ) 783 88000001 0.002ms (+0.000ms): do_softirq (irq_exit) 783 88000001 0.002ms (+0.000ms): __do_softirq (do_softirq) 783 88000001 0.003ms (+0.000ms): wake_up_process (do_softirq) 783 88000001 0.003ms (+0.000ms): try_to_wake_up (wake_up_process) 783 88000001 0.003ms (+0.000ms): task_rq_lock (try_to_wake_up) 783 88000002 0.003ms (+0.000ms): activate_task (try_to_wake_up) 783 88000002 0.004ms (+0.000ms): sched_clock (activate_task) 783 88000002 0.004ms (+0.000ms): recalc_task_prio (activate_task) 783 88000002 0.004ms (+0.000ms): effective_prio (recalc_task_prio) 783 88000002 0.004ms (+0.000ms): enqueue_task (activate_task) 783 88000002 0.005ms (+0.000ms): (105) ((54)) 783 88000002 0.005ms (+0.000ms): (3) ((783)) 783 88000002 0.005ms (+0.000ms): try_to_wake_up (wake_up_process) 783 88000002 0.006ms (+1.999ms): (0) ((1)) 783 88000001 2.005ms (+0.000ms): preempt_schedule (try_to_wake_up) 783 88000001 2.005ms (+0.000ms): wake_up_process (do_softirq) 783 88000000 2.006ms (+0.000ms): preempt_schedule_irq (need_resched) 783 98000000 2.006ms (+0.000ms): __schedule (preempt_schedule_irq) 783 98000000 2.006ms (+0.000ms): profile_hit (__schedule) 783 98000001 2.007ms (+0.000ms): sched_clock (__schedule) 2 80000002 2.007ms (+0.000ms): __switch_to (__schedule) 2 80000002 2.008ms (+0.000ms): (783) ((2)) 2 80000002 2.008ms (+0.000ms): (54) ((50)) 2 80000002 2.008ms (+0.000ms): finish_task_switch (__schedule) 2 80000001 2.008ms (+0.000ms): trace_stop_sched_switched (finish_task_switch) 2 80000001 2.009ms (+0.006ms): (2) ((50)) 2 80000001 2.015ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)