Re: Latency data - 2.6.14-rc3-rt13
From: Mark Knecht
Date: Tue Oct 11 2005 - 20:09:45 EST
On 10/11/05, Lee Revell <rlrevell@xxxxxxxxxxx> wrote:
> On Tue, 2005-10-11 at 15:45 -0700, Mark Knecht wrote:
> > On 10/11/05, Ingo Molnar <mingo@xxxxxxx> wrote:
> > >
> > > * Mark Knecht <markknecht@xxxxxxxxx> 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
-
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/