Re: [patch] Real-Time Preemption, -RT-2.6.11-rc3-V0.7.38-01
From: Lee Revell
Date: Tue Feb 22 2005 - 21:24:03 EST
On Sat, 2005-02-19 at 10:03 +0100, Ingo Molnar wrote:
> * Ingo Molnar <mingo@xxxxxxx> wrote:
>
> > > Testing on an all SCSI 1.3Ghz Athlon XP system, I am seeing very long
> > > latencies in the journalling code with 2.6.11-rc4-RT-V0.7.39-02.
> >
> > could you send me the full trace?
>
On my other machine this 333us trace is the longest latency reported in
the first few minutes with PREEMPT_DESKTOP. It seems to be a regression
from earlier versions. If I read the trace right copy_pte_range is the
problem.
Lee
preemption latency trace v1.1.4 on 2.6.11-rc4-RT-V0.7.39-02
--------------------------------------------------------------------
latency: 333 µs, #63/63, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: XFree86-2593 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
(T1/#0) dpkg 4362 0 5 00000006 00000000 [0000380181315825] 0.000ms (+3550398.796ms): <676b7064> (<00746500>)
(T1/#2) dpkg 4362 0 5 00000006 00000002 [0000380181316227] 0.000ms (+0.000ms): __trace_start_sched_wakeup+0x96/0xc0 <c012cbe6> (try_to_wake_up+0x81/0x150 <c010f911>)
(T1/#3) dpkg 4362 0 5 00000004 00000003 [0000380181316766] 0.001ms (+0.001ms): wake_up_state+0x1e/0x30 <c010fa5e> (signal_wake_up+0x2d/0x30 <c011f7bd>)
(T1/#4) dpkg 4362 0 5 00000000 00000004 [0000380181317637] 0.003ms (+0.000ms): __wake_up+0xe/0x70 <c011059e> (mousedev_event+0xd8/0x140 <c0223ac8>)
(T1/#5) dpkg 4362 0 5 00000001 00000005 [0000380181318080] 0.003ms (+0.001ms): __wake_up_common+0xb/0x70 <c011052b> (__wake_up+0x3b/0x70 <c01105cb>)
(T1/#6) dpkg 4362 0 5 00000000 00000006 [0000380181318983] 0.005ms (+0.002ms): usb_submit_urb+0xe/0x2c0 <dcabaefe> (hid_irq_in+0x4e/0xe0 <dca7335e>)
(T1/#7) dpkg 4362 0 5 00000000 00000007 [0000380181320688] 0.008ms (+0.001ms): hcd_submit_urb+0xe/0x200 <dcaba57e> (usb_submit_urb+0x1c6/0x2c0 <dcabb0b6>)
(T1/#8) dpkg 4362 0 5 00000001 00000008 [0000380181321463] 0.009ms (+0.000ms): usb_get_dev+0x9/0x30 <dcab5939> (hcd_submit_urb+0x1a9/0x200 <dcaba719>)
(T1/#9) dpkg 4362 0 5 00000001 00000009 [0000380181321943] 0.010ms (+0.000ms): get_device+0x8/0x30 <c02012d8> (usb_get_dev+0x19/0x30 <dcab5949>)
(T1/#10) dpkg 4362 0 5 00000001 0000000a [0000380181322283] 0.010ms (+0.000ms): kobject_get+0x9/0x30 <c01d7869> (get_device+0x1a/0x30 <c02012ea>)
(T1/#11) dpkg 4362 0 5 00000001 0000000b [0000380181322691] 0.011ms (+0.001ms): kref_get+0x9/0x60 <c01d8339> (kobject_get+0x19/0x30 <c01d7879>)
(T1/#12) dpkg 4362 0 5 00000000 0000000c [0000380181323295] 0.012ms (+0.000ms): usb_get_urb+0x9/0x20 <dcabaed9> (hcd_submit_urb+0xc6/0x200 <dcaba636>)
(T1/#13) dpkg 4362 0 5 00000000 0000000d [0000380181323566] 0.012ms (+0.001ms): kref_get+0x9/0x60 <c01d8339> (usb_get_urb+0x16/0x20 <dcabaee6>)
(T1/#14) dpkg 4362 0 5 00000000 0000000e [0000380181324216] 0.013ms (+0.000ms): uhci_urb_enqueue+0xe/0x290 <dca6bf4e> (hcd_submit_urb+0x123/0x200 <dcaba693>)
(T1/#15) dpkg 4362 0 5 00000001 0000000f [0000380181324743] 0.014ms (+0.000ms): uhci_find_urb_ep+0xe/0xb0 <dca6be9e> (uhci_urb_enqueue+0x7a/0x290 <dca6bfba>)
(T1/#16) dpkg 4362 0 5 00000001 00000010 [0000380181325251] 0.015ms (+0.000ms): uhci_alloc_urb_priv+0xb/0x80 <dca6aebb> (uhci_urb_enqueue+0x87/0x290 <dca6bfc7>)
(T1/#17) dpkg 4362 0 5 00000001 00000011 [0000380181325582] 0.016ms (+0.001ms): kmem_cache_alloc+0xb/0x70 <c013dc6b> (uhci_alloc_urb_priv+0x1c/0x80 <dca6aecc>)
(T1/#18) dpkg 4362 0 5 00000001 00000012 [0000380181326332] 0.017ms (+0.000ms): usb_check_bandwidth+0xc/0x140 <dcaba2fc> (uhci_urb_enqueue+0x200/0x290 <dca6c140>)
(T1/#19) dpkg 4362 0 5 00000001 00000013 [0000380181326926] 0.018ms (+0.001ms): usb_calc_bus_time+0x9/0x270 <dcaba089> (usb_check_bandwidth+0x6b/0x140 <dcaba35b>)
(T1/#20) dpkg 4362 0 5 00000001 00000014 [0000380181327893] 0.020ms (+0.001ms): uhci_submit_common+0xe/0x380 <dca6b77e> (uhci_urb_enqueue+0x239/0x290 <dca6c179>)
(T1/#21) dpkg 4362 0 5 00000001 00000015 [0000380181328984] 0.021ms (+0.001ms): uhci_alloc_td+0xb/0x80 <dca6a5bb> (uhci_submit_common+0xf0/0x380 <dca6b860>)
(T1/#22) dpkg 4362 0 5 00000001 00000016 [0000380181329685] 0.023ms (+0.002ms): dma_pool_alloc+0xe/0x1a0 <c02051fe> (uhci_alloc_td+0x20/0x80 <dca6a5d0>)
(T1/#23) dpkg 4362 0 5 00000001 00000017 [0000380181331207] 0.025ms (+0.000ms): usb_get_dev+0x9/0x30 <dcab5939> (uhci_alloc_td+0x69/0x80 <dca6a619>)
(T1/#24) dpkg 4362 0 5 00000001 00000018 [0000380181331544] 0.026ms (+0.000ms): get_device+0x8/0x30 <c02012d8> (usb_get_dev+0x19/0x30 <dcab5949>)
(T1/#25) dpkg 4362 0 5 00000001 00000019 [0000380181331882] 0.026ms (+0.000ms): kobject_get+0x9/0x30 <c01d7869> (get_device+0x1a/0x30 <c02012ea>)
(T1/#26) dpkg 4362 0 5 00000001 0000001a [0000380181332215] 0.027ms (+0.000ms): kref_get+0x9/0x60 <c01d8339> (kobject_get+0x19/0x30 <c01d7879>)
(T1/#27) dpkg 4362 0 5 00000001 0000001b [0000380181332606] 0.027ms (+0.001ms): uhci_add_td_to_urb+0x9/0x30 <dca6af39> (uhci_submit_common+0x10b/0x380 <dca6b87b>)
(T1/#28) dpkg 4362 0 5 00000001 0000001c [0000380181333448] 0.029ms (+0.000ms): uhci_alloc_qh+0xb/0x70 <dca6a89b> (uhci_submit_common+0x1d7/0x380 <dca6b947>)
(T1/#29) dpkg 4362 0 5 00000001 0000001d [0000380181333880] 0.030ms (+0.001ms): dma_pool_alloc+0xe/0x1a0 <c02051fe> (uhci_alloc_qh+0x20/0x70 <dca6a8b0>)
(T1/#30) dpkg 4362 0 5 00000001 0000001e [0000380181334888] 0.031ms (+0.000ms): usb_get_dev+0x9/0x30 <dcab5939> (uhci_alloc_qh+0x60/0x70 <dca6a8f0>)
(T1/#31) dpkg 4362 0 5 00000001 0000001f [0000380181335311] 0.032ms (+0.000ms): get_device+0x8/0x30 <c02012d8> (usb_get_dev+0x19/0x30 <dcab5949>)
(T1/#32) dpkg 4362 0 5 00000001 00000020 [0000380181335644] 0.033ms (+0.000ms): kobject_get+0x9/0x30 <c01d7869> (get_device+0x1a/0x30 <c02012ea>)
(T1/#33) dpkg 4362 0 5 00000001 00000021 [0000380181335972] 0.033ms (+0.000ms): kref_get+0x9/0x60 <c01d8339> (kobject_get+0x19/0x30 <c01d7879>)
(T1/#34) dpkg 4362 0 5 00000001 00000022 [0000380181336517] 0.034ms (+0.000ms): uhci_insert_tds_in_qh+0xb/0x60 <dca6a76b> (uhci_submit_common+0x1f7/0x380 <dca6b967>)
(T1/#35) dpkg 4362 0 5 00000001 00000023 [0000380181337025] 0.035ms (+0.001ms): uhci_insert_qh+0xb/0x90 <dca6a9ab> (uhci_submit_common+0x235/0x380 <dca6b9a5>)
(T1/#36) dpkg 4362 0 5 00000001 00000024 [0000380181337741] 0.036ms (+0.001ms): usb_claim_bandwidth+0x8/0x40 <dcaba438> (uhci_urb_enqueue+0x178/0x290 <dca6c0b8>)
(T1/#37) dpkg 4362 0 5 00000000 00000025 [0000380181338690] 0.038ms (+0.000ms): usb_free_urb+0x8/0x20 <dcabaeb8> (uhci_finish_urb+0x40/0x60 <dca6c9b0>)
(T1/#38) dpkg 4362 0 5 00000000 00000026 [0000380181339041] 0.038ms (+0.001ms): kref_put+0xa/0xb0 <c01d839a> (usb_free_urb+0x1a/0x20 <dcabaeca>)
(T1/#39) dpkg 4362 0 5 00000000 00000027 [0000380181339653] 0.039ms (+0.000ms): __wake_up+0xe/0x70 <c011059e> (uhci_irq+0x1cd/0x200 <dca6cc5d>)
(T1/#40) dpkg 4362 0 5 00000001 00000028 [0000380181340175] 0.040ms (+0.001ms): __wake_up_common+0xb/0x70 <c011052b> (__wake_up+0x3b/0x70 <c01105cb>)
(T1/#41) dpkg 4362 0 5 00000001 00000029 [0000380181341026] 0.042ms (+0.000ms): note_interrupt+0xb/0x90 <c01341db> (__do_IRQ+0x148/0x160 <c0133938>)
(T1/#42) dpkg 4362 0 5 00000001 0000002a [0000380181341399] 0.042ms (+0.000ms): end_8259A_irq+0x8/0x40 <c0107c38> (__do_IRQ+0x110/0x160 <c0133900>)
(T1/#43) dpkg 4362 0 5 00000001 0000002b [0000380181341746] 0.043ms (+0.002ms): enable_8259A_irq+0xb/0x80 <c0107d1b> (__do_IRQ+0x110/0x160 <c0133900>)
(T1/#44) dpkg 4362 0 7 00000002 0000002c [0000380181343089] 0.045ms (+0.001ms): irq_exit+0x8/0x50 <c0119fb8> (do_IRQ+0x60/0x80 <c01041f0>)
(T6/#45) dpkg-4362 0dn.2 46µs!< (1)
(T1/#46) dpkg 4362 0 2 00000001 0000002e [0000380181504494] 0.314ms (+0.000ms): preempt_schedule+0xa/0x70 <c027d0ca> (copy_pte_range+0xb7/0x1c0 <c0142ad7>)
(T1/#47) dpkg 4362 0 2 00000001 0000002f [0000380181504953] 0.315ms (+0.000ms): __cond_resched_raw_spinlock+0x8/0x50 <c0111398> (copy_pte_range+0xa7/0x1c0 <c0142ac7>)
(T1/#48) dpkg 4362 0 2 00000000 00000030 [0000380181505442] 0.316ms (+0.001ms): __cond_resched+0x9/0x70 <c0111329> (__cond_resched_raw_spinlock+0x3d/0x50 <c01113cd>)
(T1/#49) dpkg 4362 0 3 00000000 00000031 [0000380181506068] 0.317ms (+0.000ms): __schedule+0xe/0x630 <c027c98e> (__cond_resched+0x45/0x70 <c0111365>)
(T1/#50) dpkg 4362 0 3 00000000 00000032 [0000380181506442] 0.317ms (+0.001ms): profile_hit+0x9/0x50 <c0115749> (__schedule+0x3a/0x630 <c027c9ba>)
(T1/#51) dpkg 4362 0 3 00000001 00000033 [0000380181507130] 0.318ms (+0.001ms): sched_clock+0xe/0xe0 <c010c3ae> (__schedule+0x62/0x630 <c027c9e2>)
(T1/#52) dpkg 4362 0 3 00000002 00000034 [0000380181508079] 0.320ms (+0.000ms): dequeue_task+0xa/0x50 <c010f4ea> (__schedule+0x1ab/0x630 <c027cb2b>)
(T1/#53) dpkg 4362 0 3 00000002 00000035 [0000380181508503] 0.321ms (+0.000ms): recalc_task_prio+0xc/0x1a0 <c010f64c> (__schedule+0x1c5/0x630 <c027cb45>)
(T1/#54) dpkg 4362 0 3 00000002 00000036 [0000380181509011] 0.321ms (+0.000ms): effective_prio+0x8/0x50 <c010f5f8> (recalc_task_prio+0xa6/0x1a0 <c010f6e6>)
(T1/#55) dpkg 4362 0 3 00000002 00000037 [0000380181509402] 0.322ms (+0.001ms): enqueue_task+0xa/0x80 <c010f53a> (__schedule+0x1cc/0x630 <c027cb4c>)
(T4/#56) [ => dpkg ] 0.324ms (+0.001ms)
(T1/#57) <...> 2593 0 1 00000002 00000039 [0000380181511577] 0.326ms (+0.002ms): __switch_to+0xb/0x1a0 <c0100f5b> (__schedule+0x2bd/0x630 <c027cc3d>)
(T3/#58) <...>-2593 0d..2 328µs : __schedule+0x2ea/0x630 <c027cc6a> <dpkg-4362> (75 73):
(T1/#59) <...> 2593 0 1 00000002 0000003b [0000380181513468] 0.329ms (+0.000ms): finish_task_switch+0xc/0x90 <c010fdec> (__schedule+0x2f6/0x630 <c027cc76>)
(T1/#60) <...> 2593 0 1 00000001 0000003c [0000380181513919] 0.330ms (+0.000ms): trace_stop_sched_switched+0xa/0x150 <c012cc1a> (finish_task_switch+0x43/0x90 <c010fe23>)
(T3/#61) <...>-2593 0d..1 330µs : trace_stop_sched_switched+0x42/0x150 <c012cc52> <<...>-2593> (73 0):
(T1/#62) <...> 2593 0 1 00000001 0000003e [0000380181515016] 0.331ms (+0.000ms): trace_stop_sched_switched+0xfe/0x150 <c012cd0e> (finish_task_switch+0x43/0x90 <c010fe23>)
vim:ft=help
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/