Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S261391AbVBWCW1 (ORCPT ); Tue, 22 Feb 2005 21:22:27 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S261393AbVBWCW1 (ORCPT ); Tue, 22 Feb 2005 21:22:27 -0500 Received: from mustang.oldcity.dca.net ([216.158.38.3]:41442 "HELO mustang.oldcity.dca.net") by vger.kernel.org with SMTP id S261391AbVBWCWQ (ORCPT ); Tue, 22 Feb 2005 21:22:16 -0500 Subject: Re: [patch] Real-Time Preemption, -RT-2.6.11-rc3-V0.7.38-01 From: Lee Revell To: Ingo Molnar Cc: linux-kernel@vger.kernel.org, Andrew Morton In-Reply-To: <20050219090312.GA30513@elte.hu> References: <20050204100347.GA13186@elte.hu> <1108789704.8411.9.camel@krustophenia.net> <20050219090036.GA30456@elte.hu> <20050219090312.GA30513@elte.hu> Content-Type: text/plain; charset=ISO-8859-1 Date: Tue, 22 Feb 2005 21:22:13 -0500 Message-Id: <1109125334.5737.2.camel@krustophenia.net> Mime-Version: 1.0 X-Mailer: Evolution 2.0.3 Content-Transfer-Encoding: 8bit Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 11373 Lines: 103 On Sat, 2005-02-19 at 10:03 +0100, Ingo Molnar wrote: > * Ingo Molnar 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 (try_to_wake_up+0x81/0x150 ) (T1/#3) dpkg 4362 0 5 00000004 00000003 [0000380181316766] 0.001ms (+0.001ms): wake_up_state+0x1e/0x30 (signal_wake_up+0x2d/0x30 ) (T1/#4) dpkg 4362 0 5 00000000 00000004 [0000380181317637] 0.003ms (+0.000ms): __wake_up+0xe/0x70 (mousedev_event+0xd8/0x140 ) (T1/#5) dpkg 4362 0 5 00000001 00000005 [0000380181318080] 0.003ms (+0.001ms): __wake_up_common+0xb/0x70 (__wake_up+0x3b/0x70 ) (T1/#6) dpkg 4362 0 5 00000000 00000006 [0000380181318983] 0.005ms (+0.002ms): usb_submit_urb+0xe/0x2c0 (hid_irq_in+0x4e/0xe0 ) (T1/#7) dpkg 4362 0 5 00000000 00000007 [0000380181320688] 0.008ms (+0.001ms): hcd_submit_urb+0xe/0x200 (usb_submit_urb+0x1c6/0x2c0 ) (T1/#8) dpkg 4362 0 5 00000001 00000008 [0000380181321463] 0.009ms (+0.000ms): usb_get_dev+0x9/0x30 (hcd_submit_urb+0x1a9/0x200 ) (T1/#9) dpkg 4362 0 5 00000001 00000009 [0000380181321943] 0.010ms (+0.000ms): get_device+0x8/0x30 (usb_get_dev+0x19/0x30 ) (T1/#10) dpkg 4362 0 5 00000001 0000000a [0000380181322283] 0.010ms (+0.000ms): kobject_get+0x9/0x30 (get_device+0x1a/0x30 ) (T1/#11) dpkg 4362 0 5 00000001 0000000b [0000380181322691] 0.011ms (+0.001ms): kref_get+0x9/0x60 (kobject_get+0x19/0x30 ) (T1/#12) dpkg 4362 0 5 00000000 0000000c [0000380181323295] 0.012ms (+0.000ms): usb_get_urb+0x9/0x20 (hcd_submit_urb+0xc6/0x200 ) (T1/#13) dpkg 4362 0 5 00000000 0000000d [0000380181323566] 0.012ms (+0.001ms): kref_get+0x9/0x60 (usb_get_urb+0x16/0x20 ) (T1/#14) dpkg 4362 0 5 00000000 0000000e [0000380181324216] 0.013ms (+0.000ms): uhci_urb_enqueue+0xe/0x290 (hcd_submit_urb+0x123/0x200 ) (T1/#15) dpkg 4362 0 5 00000001 0000000f [0000380181324743] 0.014ms (+0.000ms): uhci_find_urb_ep+0xe/0xb0 (uhci_urb_enqueue+0x7a/0x290 ) (T1/#16) dpkg 4362 0 5 00000001 00000010 [0000380181325251] 0.015ms (+0.000ms): uhci_alloc_urb_priv+0xb/0x80 (uhci_urb_enqueue+0x87/0x290 ) (T1/#17) dpkg 4362 0 5 00000001 00000011 [0000380181325582] 0.016ms (+0.001ms): kmem_cache_alloc+0xb/0x70 (uhci_alloc_urb_priv+0x1c/0x80 ) (T1/#18) dpkg 4362 0 5 00000001 00000012 [0000380181326332] 0.017ms (+0.000ms): usb_check_bandwidth+0xc/0x140 (uhci_urb_enqueue+0x200/0x290 ) (T1/#19) dpkg 4362 0 5 00000001 00000013 [0000380181326926] 0.018ms (+0.001ms): usb_calc_bus_time+0x9/0x270 (usb_check_bandwidth+0x6b/0x140 ) (T1/#20) dpkg 4362 0 5 00000001 00000014 [0000380181327893] 0.020ms (+0.001ms): uhci_submit_common+0xe/0x380 (uhci_urb_enqueue+0x239/0x290 ) (T1/#21) dpkg 4362 0 5 00000001 00000015 [0000380181328984] 0.021ms (+0.001ms): uhci_alloc_td+0xb/0x80 (uhci_submit_common+0xf0/0x380 ) (T1/#22) dpkg 4362 0 5 00000001 00000016 [0000380181329685] 0.023ms (+0.002ms): dma_pool_alloc+0xe/0x1a0 (uhci_alloc_td+0x20/0x80 ) (T1/#23) dpkg 4362 0 5 00000001 00000017 [0000380181331207] 0.025ms (+0.000ms): usb_get_dev+0x9/0x30 (uhci_alloc_td+0x69/0x80 ) (T1/#24) dpkg 4362 0 5 00000001 00000018 [0000380181331544] 0.026ms (+0.000ms): get_device+0x8/0x30 (usb_get_dev+0x19/0x30 ) (T1/#25) dpkg 4362 0 5 00000001 00000019 [0000380181331882] 0.026ms (+0.000ms): kobject_get+0x9/0x30 (get_device+0x1a/0x30 ) (T1/#26) dpkg 4362 0 5 00000001 0000001a [0000380181332215] 0.027ms (+0.000ms): kref_get+0x9/0x60 (kobject_get+0x19/0x30 ) (T1/#27) dpkg 4362 0 5 00000001 0000001b [0000380181332606] 0.027ms (+0.001ms): uhci_add_td_to_urb+0x9/0x30 (uhci_submit_common+0x10b/0x380 ) (T1/#28) dpkg 4362 0 5 00000001 0000001c [0000380181333448] 0.029ms (+0.000ms): uhci_alloc_qh+0xb/0x70 (uhci_submit_common+0x1d7/0x380 ) (T1/#29) dpkg 4362 0 5 00000001 0000001d [0000380181333880] 0.030ms (+0.001ms): dma_pool_alloc+0xe/0x1a0 (uhci_alloc_qh+0x20/0x70 ) (T1/#30) dpkg 4362 0 5 00000001 0000001e [0000380181334888] 0.031ms (+0.000ms): usb_get_dev+0x9/0x30 (uhci_alloc_qh+0x60/0x70 ) (T1/#31) dpkg 4362 0 5 00000001 0000001f [0000380181335311] 0.032ms (+0.000ms): get_device+0x8/0x30 (usb_get_dev+0x19/0x30 ) (T1/#32) dpkg 4362 0 5 00000001 00000020 [0000380181335644] 0.033ms (+0.000ms): kobject_get+0x9/0x30 (get_device+0x1a/0x30 ) (T1/#33) dpkg 4362 0 5 00000001 00000021 [0000380181335972] 0.033ms (+0.000ms): kref_get+0x9/0x60 (kobject_get+0x19/0x30 ) (T1/#34) dpkg 4362 0 5 00000001 00000022 [0000380181336517] 0.034ms (+0.000ms): uhci_insert_tds_in_qh+0xb/0x60 (uhci_submit_common+0x1f7/0x380 ) (T1/#35) dpkg 4362 0 5 00000001 00000023 [0000380181337025] 0.035ms (+0.001ms): uhci_insert_qh+0xb/0x90 (uhci_submit_common+0x235/0x380 ) (T1/#36) dpkg 4362 0 5 00000001 00000024 [0000380181337741] 0.036ms (+0.001ms): usb_claim_bandwidth+0x8/0x40 (uhci_urb_enqueue+0x178/0x290 ) (T1/#37) dpkg 4362 0 5 00000000 00000025 [0000380181338690] 0.038ms (+0.000ms): usb_free_urb+0x8/0x20 (uhci_finish_urb+0x40/0x60 ) (T1/#38) dpkg 4362 0 5 00000000 00000026 [0000380181339041] 0.038ms (+0.001ms): kref_put+0xa/0xb0 (usb_free_urb+0x1a/0x20 ) (T1/#39) dpkg 4362 0 5 00000000 00000027 [0000380181339653] 0.039ms (+0.000ms): __wake_up+0xe/0x70 (uhci_irq+0x1cd/0x200 ) (T1/#40) dpkg 4362 0 5 00000001 00000028 [0000380181340175] 0.040ms (+0.001ms): __wake_up_common+0xb/0x70 (__wake_up+0x3b/0x70 ) (T1/#41) dpkg 4362 0 5 00000001 00000029 [0000380181341026] 0.042ms (+0.000ms): note_interrupt+0xb/0x90 (__do_IRQ+0x148/0x160 ) (T1/#42) dpkg 4362 0 5 00000001 0000002a [0000380181341399] 0.042ms (+0.000ms): end_8259A_irq+0x8/0x40 (__do_IRQ+0x110/0x160 ) (T1/#43) dpkg 4362 0 5 00000001 0000002b [0000380181341746] 0.043ms (+0.002ms): enable_8259A_irq+0xb/0x80 (__do_IRQ+0x110/0x160 ) (T1/#44) dpkg 4362 0 7 00000002 0000002c [0000380181343089] 0.045ms (+0.001ms): irq_exit+0x8/0x50 (do_IRQ+0x60/0x80 ) (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 (copy_pte_range+0xb7/0x1c0 ) (T1/#47) dpkg 4362 0 2 00000001 0000002f [0000380181504953] 0.315ms (+0.000ms): __cond_resched_raw_spinlock+0x8/0x50 (copy_pte_range+0xa7/0x1c0 ) (T1/#48) dpkg 4362 0 2 00000000 00000030 [0000380181505442] 0.316ms (+0.001ms): __cond_resched+0x9/0x70 (__cond_resched_raw_spinlock+0x3d/0x50 ) (T1/#49) dpkg 4362 0 3 00000000 00000031 [0000380181506068] 0.317ms (+0.000ms): __schedule+0xe/0x630 (__cond_resched+0x45/0x70 ) (T1/#50) dpkg 4362 0 3 00000000 00000032 [0000380181506442] 0.317ms (+0.001ms): profile_hit+0x9/0x50 (__schedule+0x3a/0x630 ) (T1/#51) dpkg 4362 0 3 00000001 00000033 [0000380181507130] 0.318ms (+0.001ms): sched_clock+0xe/0xe0 (__schedule+0x62/0x630 ) (T1/#52) dpkg 4362 0 3 00000002 00000034 [0000380181508079] 0.320ms (+0.000ms): dequeue_task+0xa/0x50 (__schedule+0x1ab/0x630 ) (T1/#53) dpkg 4362 0 3 00000002 00000035 [0000380181508503] 0.321ms (+0.000ms): recalc_task_prio+0xc/0x1a0 (__schedule+0x1c5/0x630 ) (T1/#54) dpkg 4362 0 3 00000002 00000036 [0000380181509011] 0.321ms (+0.000ms): effective_prio+0x8/0x50 (recalc_task_prio+0xa6/0x1a0 ) (T1/#55) dpkg 4362 0 3 00000002 00000037 [0000380181509402] 0.322ms (+0.001ms): enqueue_task+0xa/0x80 (__schedule+0x1cc/0x630 ) (T4/#56) [ => dpkg ] 0.324ms (+0.001ms) (T1/#57) <...> 2593 0 1 00000002 00000039 [0000380181511577] 0.326ms (+0.002ms): __switch_to+0xb/0x1a0 (__schedule+0x2bd/0x630 ) (T3/#58) <...>-2593 0d..2 328?s : __schedule+0x2ea/0x630

(75 73): (T1/#59) <...> 2593 0 1 00000002 0000003b [0000380181513468] 0.329ms (+0.000ms): finish_task_switch+0xc/0x90 (__schedule+0x2f6/0x630 ) (T1/#60) <...> 2593 0 1 00000001 0000003c [0000380181513919] 0.330ms (+0.000ms): trace_stop_sched_switched+0xa/0x150 (finish_task_switch+0x43/0x90 ) (T3/#61) <...>-2593 0d..1 330?s : trace_stop_sched_switched+0x42/0x150 <<...>-2593> (73 0): (T1/#62) <...> 2593 0 1 00000001 0000003e [0000380181515016] 0.331ms (+0.000ms): trace_stop_sched_switched+0xfe/0x150 (finish_task_switch+0x43/0x90 ) vim:ft=help - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/