* Latency tests with 2.6.12-rc1 @ 2005-03-19 4:03 Lee Revell 2005-03-19 7:08 ` Ingo Molnar 0 siblings, 1 reply; 8+ messages in thread From: Lee Revell @ 2005-03-19 4:03 UTC (permalink / raw) To: linux-kernel; +Cc: Andrew Morton, Ingo Molnar, Jack O'Quin I did the same quick latency tests with 2.6.12-rc1 that I posted about for 2.6.11 a few weeks ago. 2.6.12-rc1 is significantly better than 2.6.11. Running JACK at 64 frames (1.3 ms) works very well. I was not able to produce xruns even with "dbench 64", which slows the system to a crawl. With 2.6.11, I could easily produce xruns with much lighter loads. It would appear that the latency issues related to the 4 level page tables merge have been resolved. Lee ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: Latency tests with 2.6.12-rc1 2005-03-19 4:03 Latency tests with 2.6.12-rc1 Lee Revell @ 2005-03-19 7:08 ` Ingo Molnar 2005-03-19 7:51 ` Lee Revell 0 siblings, 1 reply; 8+ messages in thread From: Ingo Molnar @ 2005-03-19 7:08 UTC (permalink / raw) To: Lee Revell; +Cc: linux-kernel, Andrew Morton, Jack O'Quin * Lee Revell <rlrevell@joe-job.com> wrote: > I did the same quick latency tests with 2.6.12-rc1 that I posted about > for 2.6.11 a few weeks ago. > > 2.6.12-rc1 is significantly better than 2.6.11. Running JACK at 64 > frames (1.3 ms) works very well. I was not able to produce xruns even > with "dbench 64", which slows the system to a crawl. With 2.6.11, I > could easily produce xruns with much lighter loads. > > It would appear that the latency issues related to the 4 level page > tables merge have been resolved. great! The change in question is most likely the copy_page_range() fix that Hugh resurrected: ChangeSet 1.2037, 2005/03/08 09:26:46-08:00, hugh@veritas.com [PATCH] copy_pte_range latency fix Ingo's patch to reduce scheduling latencies, by checking for lockbreak in copy_page_range, was in the -VP and -mm patchsets some months ago; but got preempted by the 4level rework, and not reinstated since. Restore it now in copy_pte_range - which mercifully makes it easier. are the ext3 related latencies are gone as well - or are you working it around by not using data=ordered? Ingo ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: Latency tests with 2.6.12-rc1 2005-03-19 7:08 ` Ingo Molnar @ 2005-03-19 7:51 ` Lee Revell 2005-03-19 21:56 ` Lee Revell 0 siblings, 1 reply; 8+ messages in thread From: Lee Revell @ 2005-03-19 7:51 UTC (permalink / raw) To: Ingo Molnar; +Cc: linux-kernel, Andrew Morton, Jack O'Quin On Sat, 2005-03-19 at 08:08 +0100, Ingo Molnar wrote: > great! The change in question is most likely the copy_page_range() fix > that Hugh resurrected: > > ChangeSet 1.2037, 2005/03/08 09:26:46-08:00, hugh@veritas.com > > [PATCH] copy_pte_range latency fix > > Ingo's patch to reduce scheduling latencies, by checking for lockbreak in > copy_page_range, was in the -VP and -mm patchsets some months ago; but got > preempted by the 4level rework, and not reinstated since. Restore it now > in copy_pte_range - which mercifully makes it easier. > > are the ext3 related latencies are gone as well - or are you working it > around by not using data=ordered? As a matter of fact the ext3 latencies do not appear to be causing problems, at least not at those settings, even with data=ordered. It's impossible to tell much more because the mainline kernel lacks the instrumentation that the realtime patchset provides. Lee ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: Latency tests with 2.6.12-rc1 2005-03-19 7:51 ` Lee Revell @ 2005-03-19 21:56 ` Lee Revell 2005-03-22 8:22 ` Ingo Molnar 2005-03-31 8:02 ` Ingo Molnar 0 siblings, 2 replies; 8+ messages in thread From: Lee Revell @ 2005-03-19 21:56 UTC (permalink / raw) To: Ingo Molnar; +Cc: linux-kernel, Andrew Morton, Jack O'Quin On Sat, 2005-03-19 at 02:51 -0500, Lee Revell wrote: > On Sat, 2005-03-19 at 08:08 +0100, Ingo Molnar wrote: > > great! The change in question is most likely the copy_page_range() fix > > that Hugh resurrected: > > > > ChangeSet 1.2037, 2005/03/08 09:26:46-08:00, hugh@veritas.com > > > > [PATCH] copy_pte_range latency fix > > > > Ingo's patch to reduce scheduling latencies, by checking for lockbreak in > > copy_page_range, was in the -VP and -mm patchsets some months ago; but got > > preempted by the 4level rework, and not reinstated since. Restore it now > > in copy_pte_range - which mercifully makes it easier. > > > > are the ext3 related latencies are gone as well - or are you working it > > around by not using data=ordered? > > As a matter of fact the ext3 latencies do not appear to be causing > problems, at least not at those settings, even with data=ordered. > > It's impossible to tell much more because the mainline kernel lacks the > instrumentation that the realtime patchset provides. Ingo, I think I have nailed this down to a bug in the latency tracer. I ran 2.6.12-rc1 all night with JACK at 64 frames. Anything longer than 1.3 ms will cause xruns at this setting. I did not get a single xrun all night, despite running "dbench 64". (The workload for all of the following tests was "dbench 16") Then I tried 2.6.12-rc1-RT-V0.7.41-00 with PREEMPT_DESKTOP which should be similar to mainline, with the addition of IRQ threading and the latency instrumentation. As soon as I ran "updatedb", the latency tracer reported 3 and 4ms bumps in that same ext3 code path. But, JACK was not running at the time. Next I tried the same test but with JACK running. The longest latency reported was only 200 usecs, and I did not get xruns. Then, right after I stopped JACK, the latency tracer shot up to 1645 usecs. So there seems to be a bug in the latency tracer where the timer is not being reset on reschedule. If an RT task like JACK is running, the task does wakeup properly and the counter is reset. But if JACK is not running then long latencies will be reported. Lee preemption latency trace v1.1.4 on 2.6.12-rc1-RT-V0.7.41-00 -------------------------------------------------------------------- latency: 3402 �s, #4095/20285, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1 #P:1) ----------------- | task: ksoftirqd/0-2 (uid:0 nice:-10 policy:0 rt_prio:0) ----------------- _------=> CPU# / _-----=> irqs-off | / _----=> need-resched || / _---=> hardirq/softirq ||| / _--=> preempt-depth |||| / ||||| delay cmd pid ||||| time | caller \ / ||||| \ | / (T1/#0) <...> 2576 0 3 00000004 00000000 [0002512920677720] 0.000ms (+3971052.610ms): <756f6a6b> (<6c616e72>) (T1/#2) <...> 2576 0 3 00000004 00000002 [0002512920677953] 0.000ms (+0.000ms): __trace_start_sched_wakeup+0x9a/0xd0 <c013150a> (try_to_wake_up+0x94/0x140 <c0110474>) (T1/#3) <...> 2576 0 3 00000003 00000003 [0002512920678126] 0.000ms (+0.000ms): preempt_schedule+0x11/0x80 <c02b57c1> (try_to_wake_up+0x94/0x140 <c0110474>) (T3/#4) <...>-2576 0dn.3 0�s : try_to_wake_up+0x11e/0x140 <c01104fe> <<...>-2> (69 73): (T1/#5) <...> 2576 0 3 00000002 00000005 [0002512920678609] 0.000ms (+0.000ms): preempt_schedule+0x11/0x80 <c02b57c1> (try_to_wake_up+0xf8/0x140 <c01104d8>) (T1/#6) <...> 2576 0 3 00000002 00000006 [0002512920678807] 0.000ms (+0.000ms): wake_up_process+0x35/0x40 <c0110555> (do_softirq+0x3f/0x50 <c011b05f>) (T6/#7) <...>-2576 0dn.1 1�s < (1) (T1/#8) <...> 2576 0 2 00000001 00000008 [0002512920679575] 0.001ms (+0.000ms): __journal_unfile_buffer+0xe/0x1c0 <c01a9d2e> (journal_commit_transaction+0xda2/0x1170 <c01aba72>) (T1/#9) <...> 2576 0 2 00000001 00000009 [0002512920680035] 0.001ms (+0.000ms): journal_remove_journal_head+0xc/0x60 <c01b074c> (journal_commit_transaction+0xdb7/0x1170 <c01aba87>) (T1/#10) <...> 2576 0 2 00000001 0000000a [0002512920680231] 0.001ms (+0.000ms): __journal_remove_journal_head+0x11/0x180 <c01b05d1> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#11) <...> 2576 0 2 00000001 0000000b [0002512920680454] 0.002ms (+0.000ms): __brelse+0xb/0x70 <c015c10b> (__journal_remove_journal_head+0xb5/0x180 <c01b0675>) (T1/#12) <...> 2576 0 2 00000001 0000000c [0002512920680599] 0.002ms (+0.000ms): journal_free_journal_head+0xb/0x30 <c01b040b> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#13) <...> 2576 0 2 00000001 0000000d [0002512920680736] 0.002ms (+0.000ms): kmem_cache_free+0x14/0x60 <c01432c4> (journal_free_journal_head+0x1f/0x30 <c01b041f>) (T1/#14) <...> 2576 0 2 00000001 0000000e [0002512920681179] 0.002ms (+0.000ms): inverted_lock+0xb/0x50 <c01aab4b> (journal_commit_transaction+0x333/0x1170 <c01ab003>) (T1/#15) <...> 2576 0 2 00000001 0000000f [0002512920681438] 0.002ms (+0.000ms): __journal_unfile_buffer+0xe/0x1c0 <c01a9d2e> (journal_commit_transaction+0xda2/0x1170 <c01aba72>) (T1/#16) <...> 2576 0 2 00000001 00000010 [0002512920681752] 0.003ms (+0.000ms): journal_remove_journal_head+0xc/0x60 <c01b074c> (journal_commit_transaction+0xdb7/0x1170 <c01aba87>) (T1/#17) <...> 2576 0 2 00000001 00000011 [0002512920681919] 0.003ms (+0.000ms): __journal_remove_journal_head+0x11/0x180 <c01b05d1> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#18) <...> 2576 0 2 00000001 00000012 [0002512920682099] 0.003ms (+0.000ms): __brelse+0xb/0x70 <c015c10b> (__journal_remove_journal_head+0xb5/0x180 <c01b0675>) (T1/#19) <...> 2576 0 2 00000001 00000013 [0002512920682214] 0.003ms (+0.000ms): journal_free_journal_head+0xb/0x30 <c01b040b> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#20) <...> 2576 0 2 00000001 00000014 [0002512920682324] 0.003ms (+0.000ms): kmem_cache_free+0x14/0x60 <c01432c4> (journal_free_journal_head+0x1f/0x30 <c01b041f>) (T1/#21) <...> 2576 0 2 00000001 00000015 [0002512920682960] 0.003ms (+0.000ms): inverted_lock+0xb/0x50 <c01aab4b> (journal_commit_transaction+0x333/0x1170 <c01ab003>) (T1/#22) <...> 2576 0 2 00000001 00000016 [0002512920683128] 0.004ms (+0.000ms): __journal_unfile_buffer+0xe/0x1c0 <c01a9d2e> (journal_commit_transaction+0xda2/0x1170 <c01aba72>) (T1/#23) <...> 2576 0 2 00000001 00000017 [0002512920683821] 0.004ms (+0.000ms): journal_remove_journal_head+0xc/0x60 <c01b074c> (journal_commit_transaction+0xdb7/0x1170 <c01aba87>) (T1/#24) <...> 2576 0 2 00000001 00000018 [0002512920683933] 0.004ms (+0.000ms): __journal_remove_journal_head+0x11/0x180 <c01b05d1> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#25) <...> 2576 0 2 00000001 00000019 [0002512920684068] 0.004ms (+0.000ms): __brelse+0xb/0x70 <c015c10b> (__journal_remove_journal_head+0xb5/0x180 <c01b0675>) (T1/#26) <...> 2576 0 2 00000001 0000001a [0002512920684192] 0.004ms (+0.000ms): journal_free_journal_head+0xb/0x30 <c01b040b> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#27) <...> 2576 0 2 00000001 0000001b [0002512920684330] 0.004ms (+0.000ms): kmem_cache_free+0x14/0x60 <c01432c4> (journal_free_journal_head+0x1f/0x30 <c01b041f>) (T1/#28) <...> 2576 0 2 00000001 0000001c [0002512920685322] 0.005ms (+0.000ms): inverted_lock+0xb/0x50 <c01aab4b> (journal_commit_transaction+0x333/0x1170 <c01ab003>) (T1/#29) <...> 2576 0 2 00000001 0000001d [0002512920685528] 0.005ms (+0.000ms): __journal_unfile_buffer+0xe/0x1c0 <c01a9d2e> (journal_commit_transaction+0xda2/0x1170 <c01aba72>) (T1/#30) <...> 2576 0 2 00000001 0000001e [0002512920686007] 0.006ms (+0.000ms): journal_remove_journal_head+0xc/0x60 <c01b074c> (journal_commit_transaction+0xdb7/0x1170 <c01aba87>) (T1/#31) <...> 2576 0 2 00000001 0000001f [0002512920686121] 0.006ms (+0.000ms): __journal_remove_journal_head+0x11/0x180 <c01b05d1> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#32) <...> 2576 0 2 00000001 00000020 [0002512920686252] 0.006ms (+0.000ms): __brelse+0xb/0x70 <c015c10b> (__journal_remove_journal_head+0xb5/0x180 <c01b0675>) (T1/#33) <...> 2576 0 2 00000001 00000021 [0002512920686386] 0.006ms (+0.000ms): journal_free_journal_head+0xb/0x30 <c01b040b> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#34) <...> 2576 0 2 00000001 00000022 [0002512920686520] 0.006ms (+0.000ms): kmem_cache_free+0x14/0x60 <c01432c4> (journal_free_journal_head+0x1f/0x30 <c01b041f>) (T1/#35) <...> 2576 0 2 00000001 00000023 [0002512920687308] 0.007ms (+0.000ms): inverted_lock+0xb/0x50 <c01aab4b> (journal_commit_transaction+0x333/0x1170 <c01ab003>) (T1/#36) <...> 2576 0 2 00000001 00000024 [0002512920687446] 0.007ms (+0.000ms): __journal_unfile_buffer+0xe/0x1c0 <c01a9d2e> (journal_commit_transaction+0xda2/0x1170 <c01aba72>) (T1/#37) <...> 2576 0 2 00000001 00000025 [0002512920687924] 0.007ms (+0.000ms): journal_remove_journal_head+0xc/0x60 <c01b074c> (journal_commit_transaction+0xdb7/0x1170 <c01aba87>) (T1/#38) <...> 2576 0 2 00000001 00000026 [0002512920688036] 0.007ms (+0.000ms): __journal_remove_journal_head+0x11/0x180 <c01b05d1> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#39) <...> 2576 0 2 00000001 00000027 [0002512920688427] 0.008ms (+0.000ms): __brelse+0xb/0x70 <c015c10b> (__journal_remove_journal_head+0xb5/0x180 <c01b0675>) (T1/#40) <...> 2576 0 2 00000001 00000028 [0002512920688542] 0.008ms (+0.000ms): journal_free_journal_head+0xb/0x30 <c01b040b> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#41) <...> 2576 0 2 00000001 00000029 [0002512920688680] 0.008ms (+0.000ms): kmem_cache_free+0x14/0x60 <c01432c4> (journal_free_journal_head+0x1f/0x30 <c01b041f>) (T1/#42) <...> 2576 0 3 00000001 0000002a [0002512920688960] 0.008ms (+0.000ms): cache_flusharray+0xe/0x100 <c014301e> (kmem_cache_free+0x4f/0x60 <c01432ff>) (T1/#43) <...> 2576 0 3 00000002 0000002b [0002512920689162] 0.008ms (+0.001ms): free_block+0xe/0xe0 <c0142f3e> (cache_flusharray+0x54/0x100 <c0143064>) (T1/#44) <...> 2576 0 3 00000001 0000002c [0002512920690764] 0.009ms (+0.000ms): preempt_schedule+0x11/0x80 <c02b57c1> (cache_flusharray+0x9e/0x100 <c01430ae>) (T1/#45) <...> 2576 0 3 00000001 0000002d [0002512920690907] 0.009ms (+0.000ms): memmove+0x14/0x60 <c01e2b14> (cache_flusharray+0x91/0x100 <c01430a1>) (T1/#46) <...> 2576 0 3 00000001 0000002e [0002512920691038] 0.009ms (+0.000ms): memcpy+0x11/0x60 <c01e2a91> (memmove+0x50/0x60 <c01e2b50>) (T1/#47) <...> 2576 0 2 00000001 0000002f [0002512920692070] 0.010ms (+0.000ms): inverted_lock+0xb/0x50 <c01aab4b> (journal_commit_transaction+0x333/0x1170 <c01ab003>) (T1/#48) <...> 2576 0 2 00000001 00000030 [0002512920692254] 0.010ms (+0.000ms): __journal_unfile_buffer+0xe/0x1c0 <c01a9d2e> (journal_commit_transaction+0xda2/0x1170 <c01aba72>) (T1/#49) <...> 2576 0 2 00000001 00000031 [0002512920692401] 0.010ms (+0.000ms): journal_remove_journal_head+0xc/0x60 <c01b074c> (journal_commit_transaction+0xdb7/0x1170 <c01aba87>) (T1/#50) <...> 2576 0 2 00000001 00000032 [0002512920692513] 0.011ms (+0.000ms): __journal_remove_journal_head+0x11/0x180 <c01b05d1> (journal_remove_journal_head+0x3c/0x60 <c01b077c>) (T1/#51) <...> 2576 0 2 00000001 00000033 [0002512920692919] 0.011ms (+0.000ms): __brelse+0xb/0x70 <c015c10b> (__journal_remove_journal_head+0xb5/0x180 <c01b0675>) etc ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: Latency tests with 2.6.12-rc1 2005-03-19 21:56 ` Lee Revell @ 2005-03-22 8:22 ` Ingo Molnar 2005-03-23 22:12 ` Lee Revell 2005-03-31 8:02 ` Ingo Molnar 1 sibling, 1 reply; 8+ messages in thread From: Ingo Molnar @ 2005-03-22 8:22 UTC (permalink / raw) To: Lee Revell; +Cc: linux-kernel, Andrew Morton, Jack O'Quin * Lee Revell <rlrevell@joe-job.com> wrote: > [...] Next I tried the same test but with JACK running. The longest > latency reported was only 200 usecs, and I did not get xruns. > > Then, right after I stopped JACK, the latency tracer shot up to 1645 > usecs. > > So there seems to be a bug in the latency tracer where the timer is > not being reset on reschedule. If an RT task like JACK is running, > the task does wakeup properly and the counter is reset. But if JACK > is not running then long latencies will be reported. hm, weird, and i have no solution for this yet. But i just found a related bug in the -RT patch in that it reverted a latency breaker in the ext3 path that your trace shows - affecting PREEMPT_DESKTOP. Could you try the 40-03 patch i just uploaded (assuming it's stable for you otherwise ...) and see whether you can still reproduce these latencies? (if yes then please also send me a full trace via private mail, or bzip -9 it in your public mail.) Ingo ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: Latency tests with 2.6.12-rc1 2005-03-22 8:22 ` Ingo Molnar @ 2005-03-23 22:12 ` Lee Revell 2005-03-24 17:13 ` Lee Revell 0 siblings, 1 reply; 8+ messages in thread From: Lee Revell @ 2005-03-23 22:12 UTC (permalink / raw) To: Ingo Molnar; +Cc: linux-kernel, Andrew Morton, Jack O'Quin [-- Attachment #1: Type: text/plain, Size: 814 bytes --] On Tue, 2005-03-22 at 09:22 +0100, Ingo Molnar wrote: > hm, weird, and i have no solution for this yet. But i just found a > related bug in the -RT patch in that it reverted a latency breaker in > the ext3 path that your trace shows - affecting PREEMPT_DESKTOP. Could > you try the 40-03 patch i just uploaded (assuming it's stable for you > otherwise ...) and see whether you can still reproduce these latencies? > (if yes then please also send me a full trace via private mail, or bzip > -9 it in your public mail.) Ingo, The problem is fixed. Now the longest latency I see with "dbench 16" and PREEMPT_DESKTOP is 591us in the ext3 reservation code. Trace is attached (compressed) in case anyone is interested. But I do not consider anything under a millisecond to be a problem with PREEMPT_DESKTOP. Lee [-- Attachment #2: latency_trace.bz2 --] [-- Type: application/x-bzip, Size: 7667 bytes --] ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: Latency tests with 2.6.12-rc1 2005-03-23 22:12 ` Lee Revell @ 2005-03-24 17:13 ` Lee Revell 0 siblings, 0 replies; 8+ messages in thread From: Lee Revell @ 2005-03-24 17:13 UTC (permalink / raw) To: Ingo Molnar; +Cc: linux-kernel, Andrew Morton, Jack O'Quin On Wed, 2005-03-23 at 17:12 -0500, Lee Revell wrote: > Now the longest latency I see with "dbench 16" > and PREEMPT_DESKTOP is 591us in the ext3 reservation code. Trace is > attached (compressed) in case anyone is interested. But I do not > consider anything under a millisecond to be a problem with > PREEMPT_DESKTOP. I set the swappiness to 100 just to see what would happen (I usually use 0) and ran overnight, and got these swap-related latencies up to ~1.8 ms. If I read the trace correctly the latency is in get_swap_page. Also interesting, it's clear from this trace that call sequence the timer ISR changed quite a bit from 2.6.11 to 2.6.12. I am really impressed the kernel works so well given the current rate of change. preemption latency trace v1.1.4 on 2.6.12-rc1-RT-V0.7.41-08 -------------------------------------------------------------------- latency: 1820 us, #46/46, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1 #P:1) ----------------- | task: ksoftirqd/0-2 (uid:0 nice:-10 policy:0 rt_prio:0) ----------------- _------=> CPU# / _-----=> irqs-off | / _----=> need-resched || / _---=> hardirq/softirq ||| / _--=> preempt-depth |||| / ||||| delay cmd pid ||||| time | caller \ / ||||| \ | / (T1/#0) kswapd0 66 0 9 00000002 00000000 [0038065890208203] 0.000ms (+903083.399ms): <6177736b> (<00306470>) (T1/#2) kswapd0 66 0 9 00000002 00000002 [0038065890208522] 0.000ms (+0.000ms): __trace_start_sched_wakeup+0x96/0xc0 <c012f806> (try_to_wake_up+0x84/0x140 <c010f9e4>) (T1/#3) kswapd0 66 0 9 00000000 00000003 [0038065890209061] 0.001ms (+0.000ms): wake_up_process+0x1c/0x30 <c010fabc> (do_softirq+0x4b/0x60 <c01047bb>) (T6/#4) kswapd0-66 0dn.2 2us!< (1) (T2/#5) kswapd0-66 0dnh2 978us : do_IRQ+0x2d/0x80 <c010467d> (c014e3d0 0 0) (T1/#6) kswapd0 66 0 5 00000001 00000006 [0038065890797005] 0.979ms (+0.002ms): mask_and_ack_8259A+0xb/0x110 <c010818b> (__do_IRQ+0x8b/0x160 <c01364ab>) (T1/#7) kswapd0 66 0 5 00000001 00000007 [0038065890798780] 0.982ms (+0.000ms): redirect_hardirq+0x8/0x90 <c0136288> (__do_IRQ+0xbc/0x160 <c01364dc>) (T1/#8) kswapd0 66 0 5 00000000 00000008 [0038065890799219] 0.983ms (+0.000ms): handle_IRQ_event+0xe/0xf0 <c013631e> (__do_IRQ+0xea/0x160 <c013650a>) (T1/#9) kswapd0 66 0 5 00000000 00000009 [0038065890799507] 0.983ms (+0.000ms): timer_interrupt+0xb/0x100 <c0106fcb> (handle_IRQ_event+0x61/0xf0 <c0136371>) (T1/#10) kswapd0 66 0 5 00000001 0000000a [0038065890799947] 0.984ms (+0.004ms): mark_offset_tsc+0xe/0x370 <c010c81e> (timer_interrupt+0x24/0x100 <c0106fe4>) (T1/#11) kswapd0 66 0 5 00000001 0000000b [0038065890802748] 0.989ms (+0.000ms): do_timer+0x8/0x20 <c011e718> (timer_interrupt+0x2a/0x100 <c0106fea>) (T1/#12) kswapd0 66 0 5 00000001 0000000c [0038065890803125] 0.989ms (+0.000ms): update_process_times+0xa/0x100 <c011e17a> (timer_interrupt+0x44/0x100 <c0107004>) (T1/#13) kswapd0 66 0 5 00000001 0000000d [0038065890803494] 0.990ms (+0.000ms): account_system_time+0xa/0xb0 <c011013a> (update_process_times+0xed/0x100 <c011e25d>) (T1/#14) kswapd0 66 0 5 00000001 0000000e [0038065890803863] 0.991ms (+0.000ms): acct_update_integrals+0xa/0x60 <c013609a> (account_system_time+0x40/0xb0 <c0110170>) (T1/#15) kswapd0 66 0 5 00000001 0000000f [0038065890804182] 0.991ms (+0.000ms): update_mem_hiwater+0x8/0x50 <c0147b68> (update_process_times+0xed/0x100 <c011e25d>) (T1/#16) kswapd0 66 0 5 00000001 00000010 [0038065890804497] 0.992ms (+0.000ms): run_local_timers+0x8/0x20 <c011e298> (update_process_times+0x2d/0x100 <c011e19d>) (T1/#17) kswapd0 66 0 5 00000001 00000011 [0038065890804910] 0.992ms (+0.000ms): raise_softirq+0xa/0x70 <c011a21a> (update_process_times+0x2d/0x100 <c011e19d>) (T1/#18) kswapd0 66 0 5 00000001 00000012 [0038065890805402] 0.993ms (+0.000ms): rcu_check_callbacks+0x8/0xc0 <c0126e18> (update_process_times+0x68/0x100 <c011e1d8>) (T1/#19) kswapd0 66 0 5 00000001 00000013 [0038065890805759] 0.994ms (+0.000ms): idle_cpu+0x8/0x20 <c0110c28> (rcu_check_callbacks+0x66/0xc0 <c0126e76>) (T1/#20) kswapd0 66 0 5 00000001 00000014 [0038065890806218] 0.995ms (+0.000ms): scheduler_tick+0xc/0x3e0 <c011024c> (update_process_times+0x6f/0x100 <c011e1df>) (T1/#21) kswapd0 66 0 5 00000001 00000015 [0038065890806546] 0.995ms (+0.001ms): sched_clock+0xe/0xe0 <c010c57e> (scheduler_tick+0x1d/0x3e0 <c011025d>) (T1/#22) kswapd0 66 0 5 00000001 00000016 [0038065890807424] 0.997ms (+0.000ms): run_posix_cpu_timers+0xe/0x1b0 <c012d04e> (timer_interrupt+0x44/0x100 <c0107004>) (T1/#23) kswapd0 66 0 5 00000001 00000017 [0038065890807932] 0.997ms (+0.001ms): profile_hit+0x9/0x50 <c0115a79> (timer_interrupt+0x4e/0x100 <c010700e>) (T1/#24) kswapd0 66 0 5 00000001 00000018 [0038065890808639] 0.999ms (+0.000ms): note_interrupt+0xb/0x90 <c0136e0b> (__do_IRQ+0x148/0x160 <c0136568>) (T1/#25) kswapd0 66 0 5 00000001 00000019 [0038065890809012] 0.999ms (+0.000ms): end_8259A_irq+0x8/0x40 <c0107f58> (__do_IRQ+0x110/0x160 <c0136530>) (T1/#26) kswapd0 66 0 5 00000001 0000001a [0038065890809359] 1.000ms (+0.002ms): enable_8259A_irq+0xb/0x80 <c010803b> (__do_IRQ+0x110/0x160 <c0136530>) (T1/#27) kswapd0 66 0 7 00000002 0000001b [0038065890810630] 1.002ms (+0.000ms): irq_exit+0x8/0x50 <c011a1c8> (do_IRQ+0x60/0x80 <c01046b0>) (T1/#28) kswapd0 66 0 3 00000003 0000001c [0038065890811106] 1.003ms (+0.000ms): do_softirq+0xb/0x60 <c010477b> (irq_exit+0x45/0x50 <c011a205>) (T1/#29) kswapd0 66 0 9 00000000 0000001d [0038065890811604] 1.003ms (+0.001ms): __do_softirq+0xa/0x90 <c011a05a> (do_softirq+0x4b/0x60 <c01047bb>) (T6/#30) kswapd0-66 0dn.2 1005us!< (1) (T1/#31) kswapd0 66 0 2 00000001 0000001f [0038065891293001] 1.804ms (+0.001ms): preempt_schedule+0xa/0x70 <c02a837a> (get_swap_page+0x208/0x290 <c014e488>) (T1/#32) kswapd0 66 0 2 00000000 00000020 [0038065891293653] 1.806ms (+0.000ms): preempt_schedule+0xa/0x70 <c02a837a> (get_swap_page+0xc4/0x290 <c014e344>) (T1/#33) kswapd0 66 0 3 00000000 00000021 [0038065891294198] 1.806ms (+0.000ms): __schedule+0xe/0x710 <c02a7b5e> (preempt_schedule+0x4f/0x70 <c02a83bf>) (T1/#34) kswapd0 66 0 3 00000000 00000022 [0038065891294675] 1.807ms (+0.000ms): profile_hit+0x9/0x50 <c0115a79> (__schedule+0x3a/0x710 <c02a7b8a>) (T1/#35) kswapd0 66 0 3 00000001 00000023 [0038065891295125] 1.808ms (+0.001ms): sched_clock+0xe/0xe0 <c010c57e> (__schedule+0x68/0x710 <c02a7bb8>) (T1/#36) kswapd0 66 0 3 00000002 00000024 [0038065891296151] 1.810ms (+0.000ms): dequeue_task+0xa/0x50 <c010f5ba> (__schedule+0x1ca/0x710 <c02a7d1a>) (T1/#37) kswapd0 66 0 3 00000002 00000025 [0038065891296676] 1.811ms (+0.000ms): recalc_task_prio+0xc/0x1a0 <c010f71c> (__schedule+0x1e4/0x710 <c02a7d34>) (T1/#38) kswapd0 66 0 3 00000002 00000026 [0038065891297091] 1.811ms (+0.000ms): effective_prio+0x8/0x50 <c010f6c8> (recalc_task_prio+0xa6/0x1a0 <c010f7b6>) (T1/#39) kswapd0 66 0 3 00000002 00000027 [0038065891297465] 1.812ms (+0.001ms): enqueue_task+0xa/0x80 <c010f60a> (__schedule+0x1eb/0x710 <c02a7d3b>) (T4/#40) [ => kswapd0 ] 1.813ms (+0.001ms) (T1/#41) <...> 2 0 1 00000002 00000029 [0038065891299097] 1.815ms (+0.001ms): __switch_to+0xb/0x1a0 <c01013bb> (__schedule+0x329/0x710 <c02a7e79>) (T3/#42) <...>-2 0d..2 1816us : __schedule+0x356/0x710 <c02a7ea6> <kswapd0-66> (73 69): (T1/#43) <...> 2 0 1 00000001 0000002b [0038065891300595] 1.817ms (+0.000ms): trace_stop_sched_switched+0xa/0x150 <c012f83a> (__schedule+0x38d/0x710 <c02a7edd>) (T3/#44) <...>-2 0d..1 1818us : trace_stop_sched_switched+0x42/0x150 <c012f872> <<...>-2> (69 0): (T1/#45) <...> 2 0 1 00000001 0000002d [0038065891301715] 1.819ms (+0.000ms): trace_stop_sched_switched+0xfe/0x150 <c012f92e> (__schedule+0x38d/0x710 <c02a7edd>) vim:ft=help Lee ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: Latency tests with 2.6.12-rc1 2005-03-19 21:56 ` Lee Revell 2005-03-22 8:22 ` Ingo Molnar @ 2005-03-31 8:02 ` Ingo Molnar 1 sibling, 0 replies; 8+ messages in thread From: Ingo Molnar @ 2005-03-31 8:02 UTC (permalink / raw) To: Lee Revell; +Cc: linux-kernel, Andrew Morton, Jack O'Quin * Lee Revell <rlrevell@joe-job.com> wrote: > So there seems to be a bug in the latency tracer where the timer is > not being reset on reschedule. [...] update: i found a bug in the latency tracer that could explain some of the artifacts you noticed, IRQs would reset the tracing timer under certain circumstances. So sometimes traces would show up, sometimes they wouldnt - and even if traces were generated, they often were truncated. The bug is fixed in the -41-24 patch. If you were hit by this bug then you'll likely see new and larger latencies reported. Ingo ^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2005-03-31 8:03 UTC | newest] Thread overview: 8+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2005-03-19 4:03 Latency tests with 2.6.12-rc1 Lee Revell 2005-03-19 7:08 ` Ingo Molnar 2005-03-19 7:51 ` Lee Revell 2005-03-19 21:56 ` Lee Revell 2005-03-22 8:22 ` Ingo Molnar 2005-03-23 22:12 ` Lee Revell 2005-03-24 17:13 ` Lee Revell 2005-03-31 8:02 ` Ingo Molnar
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox