lkml.org 
[lkml]   [2005]   [Oct]   [11]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: Latency data - 2.6.14-rc3-rt13
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>

Call Trace: <IRQ> <ffffffff8014c42c>{check_critical_timing+492}
<ffffffff8014c64b>{sub_preempt_count_ti+75} <ffffffff80110159>{do_IRQ+57}
<ffffffff8010e16c>{ret_from_intr+0} <EOI>
<ffffffff80249a75>{copy_page+5}
<ffffffff801671f1>{do_no_page+737}
<ffffffff801674ee>{__handle_mm_fault+414}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
<ffffffff803eac99>{do_page_fault+1049}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
<ffffffff80168eee>{vma_link+286}
<ffffffff8010e4c1>{error_exit+0} <ffffffff8024a866>{__clear_user+22}
<ffffffff801a46fb>{padzero+27} <ffffffff801a4b42>{load_elf_interp+850}
<ffffffff801a5b1d>{load_elf_binary+3341}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
<ffffffff8014c64b>{sub_preempt_count_ti+75}
<ffffffff801a4e10>{load_elf_binary+0}
<ffffffff80182ee0>{search_binary_handler+272}
<ffffffff801831f5>{do_execve+405}
<ffffffff8010dbc6>{system_call+126} <ffffffff8010c634>{sys_execve+68}
<ffffffff8010dfea>{stub_execve+106}
=> dump-end timestamp 117628777

( nautilus-7955 |#0): new 14 us maximum-latency critical section.
=> started at timestamp 127874927: <do_IRQ+0x29/0x50>
=> ended at timestamp 127874941: <do_IRQ+0x39/0x50>

Call Trace: <IRQ> <ffffffff8014c42c>{check_critical_timing+492}
<ffffffff8014c64b>{sub_preempt_count_ti+75} <ffffffff80110159>{do_IRQ+57}
<ffffffff8010e16c>{ret_from_intr+0} <EOI>
<ffffffff8010dbc6>{system_call+126}

=> dump-end timestamp 127874996

( nautilus-7955 |#0): new 14 us maximum-latency critical section.
=> started at timestamp 128647499: <do_IRQ+0x29/0x50>
=> ended at timestamp 128647514: <do_IRQ+0x39/0x50>

Call Trace: <IRQ> <ffffffff8014c42c>{check_critical_timing+492}
<ffffffff8014c64b>{sub_preempt_count_ti+75} <ffffffff80110159>{do_IRQ+57}
<ffffffff8010e16c>{ret_from_intr+0} <EOI>
=> dump-end timestamp 128647567

lightning ~ #

NOTE: In my first kernel build I turned on latency measurement for
both max preempt and ITQ-off. The kernel segfaulted immediately after
the boot messages reminding me that these were on. I rebuilt the
kernel with only the max preempt and that worked. I suspect some
problem with the IRQ-off section since that's the only change I made
and it did not segfault in -rc3-rt13.

Thanks,
Mark
-
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/

\
 
 \ /
  Last update: 2005-10-12 00:48    [W:0.035 / U:1.880 seconds]
©2003-2018 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site