Hi Ingo,
More SMT weirdness. Latency traces aren't looking quite right on -51-17
with my SMT debug config.
Started jackd, immediately after boot (before logging in to X), then:
[root@manzanita ~]# cat /proc/latency_trace
cat/2149[CPU#1]: BUG in update_out_trace at kernel/latency.c:698
[<c01041a3>] dump_stack+0x23/0x30 (20)
[<c012317b>] __WARN_ON+0x6b/0x90 (52)
[<c0142237>] update_out_trace+0x467/0x4e0 (100)
[<c0142590>] l_start+0x2e0/0x310 (72)
[<c019415b>] seq_read+0x7b/0x2d0 (60)
[<c0170f74>] vfs_read+0xd4/0x140 (36)
[<c0171250>] sys_read+0x50/0x80 (44)
[<c01031b0>] sysenter_past_esp+0x61/0x89 (-8116)
---------------------------
| preempt count: 00000002 ]
| 2-level deep critical section nesting:
----------------------------------------
.. [<c01434dc>] .... add_preempt_count+0x1c/0x20
.....[<c0123137>] .. ( <= __WARN_ON+0x27/0x90)
.. [<c01434dc>] .... add_preempt_count+0x1c/0x20
.....[<c014454d>] .. ( <= print_traces+0x1d/0x60)
------------------------------
| showing all locks held by: | (cat/2149 [dda0e030, 39]):
------------------------------
#001: [db76afa4] {(struct semaphore *)(&p->sem)}
... acquired at: seq_read+0x2b/0x2d0
#002: [c05fe424] {out_mutex.lock}
... acquired at: l_start+0x1b/0x310
#003: [c06d4404] {max_mutex.lock}
... acquired at: l_start+0x2db/0x310
CPU0: 0000003e0d590d0c (0000003e0d593ba8) ... #50 (0000003e0d610158) 0000003e0d611a78
CPU1: 0000003e0d6122c8 (0000003e0d6125b0) ... #4 (0000003e0d612dac) 0000003e0d6136bc
CPU0 entries: 50
first stamp: 0000003e0d6122c8
last stamp: 0000003e0d6122c8
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.51-17-debug
--------------------------------------------------------------------
latency: 159 us, #54/54, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
-----------------
| task: softirq-timer/0-4 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
vim:ft=help
After logging into X:
<15:26:38 root@manzanita ~># cat /proc/latency_trace
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.51-17-debug
--------------------------------------------------------------------
latency: 202 us, #102/102, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
-----------------
| task: jackd-1929 (uid:500 nice:0 policy:1 rt_prio:60)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
<...>-1817 1.... 0us : set_palette (redraw_screen)
IRQ 5-724 0Dnh2 0us : find_next_bit (pull_rt_tasks)
<...>-1817 1.... 0us : is_console_locked (set_palette)
IRQ 5-724 0Dnh2 0us : dependent_sleeper (__schedule)
<...>-1817 1.... 0us : vgacon_set_palette (set_palette)
IRQ 5-724 0Dnh2 1us : _raw_spin_unlock (dependent_sleeper)
<...>-1817 1.... 1us : vga_set_palette (vgacon_set_palette)
IRQ 5-724 0Dnh1 1us : preempt_schedule (dependent_sleeper)
IRQ 5-724 0Dnh1 1us : _raw_spin_lock (dependent_sleeper)
IRQ 5-724 0Dnh2 2us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh2 2us : _raw_spin_lock (dependent_sleeper)
IRQ 5-724 0Dnh3 2us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh3 3us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh3 3us : _raw_spin_unlock (dependent_sleeper)
IRQ 5-724 0Dnh2 3us : preempt_schedule (dependent_sleeper)
IRQ 5-724 0Dnh2 3us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh2 4us : trace_array (__schedule)
IRQ 5-724 0Dnh2 4us : trace_array <<...>-1929> (27 27)
IRQ 5-724 0Dnh2 5us : trace_array <IRQ 5-724> (31 31)
IRQ 5-724 0Dnh2 6us : trace_array (__schedule)
<...>-1929 0Dnh2 8us+: __switch_to (__schedule)
<...>-1929 0Dnh2 11us : __schedule <IRQ 5-724> (31 27)
<...>-1929 0Dnh2 11us : finish_task_switch (__schedule)
<...>-1929 0Dnh2 13us : smp_send_reschedule_allbutself (finish_task_switch)
<...>-1929 0Dnh2 13us : __bitmap_weight (smp_send_reschedule_allbutself)
<...>-1929 0Dnh2 13us : __send_IPI_shortcut (smp_send_reschedule_allbutself)
<...>-1929 0Dnh2 13us : _raw_spin_unlock (finish_task_switch)
<...>-1929 0Dnh1 15us : trace_stop_sched_switched (finish_task_switch)
<...>-1929 0Dnh1 15us : _raw_spin_lock (trace_stop_sched_switched)
<...>-1929 0Dnh2 15us : trace_stop_sched_switched <<...>-1929> (27 0)
<...>-1817 1Dnh. 15us : smp_reschedule_interrupt (c026c17a 0 0)
<...>-1929 0Dnh3 16us : _raw_spin_unlock (trace_stop_sched_switched)
<...>-1817 1Dnh. 16us : preempt_schedule_irq (need_resched)
<...>-1929 0Dnh2 16us!: trace_stop_sched_switched (finish_task_switch)
IRQ 5-724 0Dnh2 0us : find_next_bit (pull_rt_tasks)
IRQ 5-724 0Dnh2 0us : dependent_sleeper (__schedule)
IRQ 5-724 0Dnh2 1us : _raw_spin_unlock (dependent_sleeper)
IRQ 5-724 0Dnh1 1us : preempt_schedule (dependent_sleeper)
IRQ 5-724 0Dnh1 1us : _raw_spin_lock (dependent_sleeper)
IRQ 5-724 0Dnh2 2us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh2 2us : _raw_spin_lock (dependent_sleeper)
IRQ 5-724 0Dnh3 2us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh3 3us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh3 3us : _raw_spin_unlock (dependent_sleeper)
IRQ 5-724 0Dnh2 3us : preempt_schedule (dependent_sleeper)
IRQ 5-724 0Dnh2 3us : find_next_bit (dependent_sleeper)
IRQ 5-724 0Dnh2 4us : trace_array (__schedule)
IRQ 5-724 0Dnh2 4us : trace_array <<...>-1929> (27 27)
IRQ 5-724 0Dnh2 5us : trace_array <IRQ 5-724> (31 31)
IRQ 5-724 0Dnh2 6us : trace_array (__schedule)
<...>-1929 0Dnh2 8us+: __switch_to (__schedule)
<...>-1929 0Dnh2 11us : __schedule <IRQ 5-724> (31 27)
<...>-1929 0Dnh2 11us : finish_task_switch (__schedule)
<...>-1929 0Dnh2 13us : smp_send_reschedule_allbutself (finish_task_switch)
<...>-1929 0Dnh2 13us : __bitmap_weight (smp_send_reschedule_allbutself)
<...>-1929 0Dnh2 13us : __send_IPI_shortcut (smp_send_reschedule_allbutself)
<...>-1929 0Dnh2 13us : _raw_spin_unlock (finish_task_switch)
<...>-1929 0Dnh1 15us : trace_stop_sched_switched (finish_task_switch)
<...>-1929 0Dnh1 15us : _raw_spin_lock (trace_stop_sched_switched)
<...>-1929 0Dnh2 15us : trace_stop_sched_switched <<...>-1929> (27 0)
<...>-1929 0Dnh3 16us : _raw_spin_unlock (trace_stop_sched_switched)
<...>-1929 0Dnh2 16us!: trace_stop_sched_switched (finish_task_switch)
vim:ft=help
--ww
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[Index of Archives]
[Kernel Newbies]
[Netfilter]
[Bugtraq]
[Photo]
[Gimp]
[Yosemite News]
[MIPS Linux]
[ARM Linux]
[Linux Security]
[Linux RAID]
[Video 4 Linux]
[Linux for the blind]
| |
 |