Latency tests with 2.6.12-rc1

Latency tests with 2.6.12-rc1

[Lee Revell]

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

Re: Latency tests with 2.6.12-rc1

[Ingo Molnar]

* 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

Re: Latency tests with 2.6.12-rc1

[Lee Revell]

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

Re: Latency tests with 2.6.12-rc1

[Lee Revell]

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

Re: Latency tests with 2.6.12-rc1

[Ingo Molnar]

* 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

Re: Latency tests with 2.6.12-rc1

[Lee Revell]

[-- 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 --]

Re: Latency tests with 2.6.12-rc1

[Lee Revell]

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

Re: Latency tests with 2.6.12-rc1

[Ingo Molnar]

* 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