Re: Latency data - 2.6.14-rc3-rt13

[Mark Knecht <markknecht@gmail.com>]

On 10/11/05, Lee Revell <rlrevell@joe-job.com> wrote:
> On Tue, 2005-10-11 at 15:45 -0700, Mark Knecht wrote:
> > On 10/11/05, Ingo Molnar <mingo@elte.hu> wrote:
> > >
> > > * Mark Knecht <markknecht@gmail.com> wrote:
> > >
> > > > > ( softirq-timer/0-3    |#0): new 3997 us maximum-latency critical section.
> > > >
> > > > So the root cause of this 4mS delay is the 250Hz timer. If I change
> > > > the system to use the 1Khz timer then the time in this section drops,
> > > > as expected, to 1mS.
> > >
> > > this was a bug in the critical-section-latency measurement code of x64.
> > > The timer irq is the one that leaves userspace running for the longest
> > > time, between two kernel calls.
> > >
> > > I have fixed these bugs in -rc4-rt1, could you try it? It should report
> > > much lower latencies, regardless of PM settings.
> > >
> > >         Ingo
> > >
> >
> > Ingo,
> >    This test now reports much more intersting data:
> >
> > (           dmesg-8010 |#0): new 13 us maximum-latency critical section.
> >  => started at timestamp 117628604: <do_IRQ+0x29/0x50>
> >  =>   ended at timestamp 117628618: <do_IRQ+0x39/0x50>
>
> This is the expected, correct behavior - very small maximum latency
> critical sections.  Do you get anything longer (say 300 usecs or more)
> if you leave it running?
>
> So far the latency tracer on my much slower system has only gone up to
> 123 usecs.  So the bug seems to be fixed at least on i386.
>
> Lee
>
>

I've been watching this now for a couple of hours. Still no xruns. Max
latency has only gone up to 19uS, so this is all good. However the
thing I am seeing is that all my free memory has gone away and I've
now swapped out just a little nit. There was really no change in the
state of the machine, other than xscreensaver starting and running for
a while, which is standard for me. None the less here's the sort of
state things are in - 17uS right after booting, and only 19uS now.
That's good. But in the middle look at the change in memory statistics
during a one hour time period.

(               X-7860 |#0): new 16 us maximum-latency critical section.
 => started at timestamp 259455017: <__schedule+0xb8/0x596>
 =>   ended at timestamp 259455034: <thread_return+0xb4/0x10a>

Call Trace:<ffffffff8014c42c>{check_critical_timing+492}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
       <ffffffff803e7d9a>{thread_return+180} <ffffffff803e7ef5>{schedule+261}
       <ffffffff803e89e4>{schedule_timeout+148}
<ffffffff8013a660>{process_timeout+0}
       <ffffffff8018b767>{do_select+967} <ffffffff8018b2b0>{__pollwait+0}
       <ffffffff8018baad>{sys_select+749}
<ffffffff8010d9e9>{sys_rt_sigreturn+553}
       <ffffffff8010dbc6>{system_call+126}
 =>   dump-end timestamp 259455125

(               X-7860 |#0): new 17 us maximum-latency critical section.
 => started at timestamp 375451745: <__schedule+0xb8/0x596>
 =>   ended at timestamp 375451762: <thread_return+0xb4/0x10a>

Call Trace:<ffffffff8014c42c>{check_critical_timing+492}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
       <ffffffff803e7d9a>{thread_return+180} <ffffffff803e7ef5>{schedule+261}
       <ffffffff803e89e4>{schedule_timeout+148}
<ffffffff8013a660>{process_timeout+0}
       <ffffffff8018b767>{do_select+967} <ffffffff8018b2b0>{__pollwait+0}
       <ffffffff8018baad>{sys_select+749}
<ffffffff8010d9e9>{sys_rt_sigreturn+553}
       <ffffffff8010dbc6>{system_call+126}
 =>   dump-end timestamp 375451852

kjournald starting.  Commit interval 5 seconds
EXT3 FS on sdc1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
lightning ~ #



lightning ~ # date && free
Tue Oct 11 16:21:41 PDT 2005
             total       used       free     shared    buffers     cached
Mem:        510460     410816      99644          0      15896     169664
-/+ buffers/cache:     225256     285204
Swap:       996020          0     996020
lightning ~ # date && free
Tue Oct 11 17:39:03 PDT 2005
             total       used       free     shared    buffers     cached
Mem:        510460     504464       5996          0      39828     119012
-/+ buffers/cache:     345624     164836
Swap:       996020        304     995716
lightning ~ #



(       hdspmixer-8071 |#0): new 18 us maximum-latency critical section.
 => started at timestamp 2132546112: <snd_ctl_open+0x71/0x200 [snd]>
 =>   ended at timestamp 2132546131: <snd_ctl_open+0x8a/0x200 [snd]>

Call Trace:<ffffffff8014c42c>{check_critical_timing+492}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
       <ffffffff88006a0a>{:snd:snd_ctl_open+138}
<ffffffff8800414b>{:snd:snd_open+267}
       <ffffffff801806d9>{chrdev_open+441} <ffffffff801766a8>{__dentry_open+280}
       <ffffffff80176877>{filp_open+135}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
       <ffffffff80176a06>{get_unused_fd+230} <ffffffff80176b71>{do_sys_open+81}
       <ffffffff8010dbc6>{system_call+126}
 =>   dump-end timestamp 2132546239

(          IRQ 58-4526 |#0): new 19 us maximum-latency critical section.
 => started at timestamp 8439787551: <__schedule+0xb8/0x596>
 =>   ended at timestamp 8439787571: <thread_return+0xb4/0x10a>

Call Trace:<ffffffff8014c42c>{check_critical_timing+492}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
       <ffffffff803e7d9a>{thread_return+180}
<ffffffff80146550>{keventd_create_kthread+0}
       <ffffffff803e7ef5>{schedule+261} <ffffffff80156062>{do_irqd+514}
       <ffffffff80155e60>{do_irqd+0} <ffffffff8014650d>{kthread+205}
       <ffffffff8010e676>{child_rip+8}
<ffffffff80146550>{keventd_create_kthread+0}
       <ffffffff80354d00>{pci_conf1_read+0} <ffffffff80146440>{kthread+0}
       <ffffffff8010e66e>{child_rip+0}
 =>   dump-end timestamp 8439787658

lightning ~ #


Now, I know these command line methods are probably frowned upon by
folks in the know so I'm happy to do this in a more rigorous way. (Is
it called valgrind?) Should free memory drop like that over time?

The only apps running were Aqualung, hdspmixer and Firefox. Is one of
them leaking, is the kernel leaking, or is this normal?

I will continue to let this run for another 4-6 hours today and hope I
catch another xrun. If not I'll start it up again tomorrow and
certainly will get something.

Thanks much,
Mark