[patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

i've uploaded the latest version of the voluntary-preempt patch:
     
  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6

during the past couple of weeks there has been a steady trend towards
rarer and harder to analyze latencies.

The preempt-timing patch was a nice starting point but it only prints
limited info about the beginning and the end of a critical section -
often leaving us in the dark about what happened within the critical
section. Often the trace only contains generic entry/exit points like
e.g. do_poll() which are not very helpful in determining the precise
reason for the latency.

so in -O6 i've implemented a 'latency tracer', which automatically
records all kernel functions called during a maximum-latency incident.
This typically means thousands of functions per critical section. I've
combined this tracer with the preempt-timing approach to produce a
pretty powerful tool to find & squash latencies.

there's a new /proc/latency_trace file that holds the current latency
trace (belonging to the previous high-latency event). It has a format
that is intended to make it as easy as possible for kernel developers to
fix any particular latency source. Audio developers and users can
generate such traces and send them along to kernel developers as text
files.

Sample use of the latency tracer:

E.g. the following incident:

 (default.hotplug/1470): 121 us critical section violates 100 us threshold.
  => started at: <kmap_high+0x2b/0x2d0>
  => ended at:   <kmap_high+0x1a9/0x2d0>
  [<c0105a23>] dump_stack+0x23/0x30
  [<c0140d14>] check_preempt_timing+0x184/0x1e0
  [<c0140e84>] sub_preempt_count+0x54/0x5d
  [<c0152959>] kmap_high+0x1a9/0x2d0
  [<c017655a>] copy_strings+0xea/0x230
  [<c01766db>] copy_strings_kernel+0x3b/0x50
  [<c017840d>] do_execve+0x12d/0x1f0
  [<c0103284>] sys_execve+0x44/0x80
  [<c0104b95>] sysenter_past_esp+0x52/0x71

this doesnt tell us too much about why it took 121 usecs to get from one
end of kmap_high() to the other end of kmap_high(). Looking at
/proc/latency_trace tells us the full story:

  preemption latency trace v1.0
  -----------------------------
   latency: 121 us, entries: 1032 (1032)
   process: default.hotplug/1470, uid: 0
   nice: -10, policy: 0, rt_priority: 0
  =======>
   0.000ms (+0.000ms): page_address (kmap_high)
   0.000ms (+0.000ms): page_slot (page_address)
   0.000ms (+0.000ms): flush_all_zero_pkmaps (kmap_high)
   0.000ms (+0.000ms): set_page_address (flush_all_zero_pkmaps)
  [...]
   0.118ms (+0.000ms): page_slot (set_page_address)
   0.118ms (+0.000ms): check_preempt_timing (sub_preempt_count)

it's the rare but possible call to flush_all_zero_pkmaps() that
generates this particular latency.

as can be seen in the above the example, the trace contains a header
portion and a trace line for every kernel function called. Only function
entries are recorded (not function returns) so i've added the parent
function to the trace too, for easier identification of the call
sequence.

there's a MAX_TRACE define in kernel/latency.c - set to 4000 currently -
this is the maximum number of function calls traced per critical
section. Feel free to increase/decrease this. The header portion shows
the true number of functions called in a critical section, e.g.:

   latency: 1531 us, entries: 4000 (16098)

tells us that there were 16098 trace entries but only the first 4000
were recorded.

-O6 also adds another timing option besides preempt_thresh: if
preempt_thresh is set to 0 then the tracer will automatically track the
largest-previous latency. (i.e. the system does a search for the
absolute maximum latency.) The /proc/sys/kernel/preempt_max_latency 
control can be used to reset this value to conduct a new search for a 
new workload, without having to reboot the system.

-O6 also does some SMP improvements: the IRQ threads now listen to the
/proc/irq/*/smp_affinity mask and bind themselves to the configured CPU. 
This means that e.g. the irqbalance daemon will work as expected.

-O6 also fixes and cleans up a number of other aspects of the
preempt-timing mechanism.

the latency tracer can be turned on/off via CONFIG_LATENCY_TRACE at
compile time. An active tracer means considerable runtime overhead. 
Especially code that does alot of small function calls will see a
performance hit. I'm seeing a ~10% overhead on a 2GHz system, but YMMV. 

reports, suggestions welcome,

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 19:51, Ingo Molnar wrote:
> i've uploaded the latest version of the voluntary-preempt patch:
>      
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> 

Does not compile.  For each module I get:

WARNING: /lib/modules/2.6.8-rc4-O6/kernel/drivers/ieee1394/ohci1394.ko
needs unknown symbol mcount

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 21:25, Lee Revell wrote:
> Does not compile.  For each module I get:
> 

Never mind, stupid mistake on my part.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 21:31, Lee Revell wrote:
> On Thu, 2004-08-12 at 21:25, Lee Revell wrote:
> > Does not compile.  For each module I get:
> > 
> 
> Never mind, stupid mistake on my part.
> 

Argh, this is actually a fatal bug, and not a mistake on my part. 
mcount is an unknown symbol, and make modules_install does not like
that.

I checked Module.symvers and it is not in there, but this seems to be a
generated file, and I have no idea why mcount does not appear.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 22:39, Lee Revell wrote:
> On Thu, 2004-08-12 at 21:31, Lee Revell wrote:
> > On Thu, 2004-08-12 at 21:25, Lee Revell wrote:
> > > Does not compile.  For each module I get:
> > > 
> > 
> > Never mind, stupid mistake on my part.
> > 
> 
> Argh, this is actually a fatal bug, and not a mistake on my part. 
> mcount is an unknown symbol, and make modules_install does not like
> that.
> 
> I checked Module.symvers and it is not in there, but this seems to be a
> generated file, and I have no idea why mcount does not appear.
> 

I think appending this to i386_ksyms.c fixes the problem:

#ifdef CONFIG_PREEMPT_TIMING
EXPORT_SYMBOL(mcount);
#endif

Possibly that should be CONFIG_LATENCY_TRACE.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 23:54, Lee Revell wrote:
> On Thu, 2004-08-12 at 22:39, Lee Revell wrote:
> > On Thu, 2004-08-12 at 21:31, Lee Revell wrote:
> > > On Thu, 2004-08-12 at 21:25, Lee Revell wrote:
> > > > Does not compile.  For each module I get:
> > > > 
> > > 
> > > Never mind, stupid mistake on my part.
> > > 
> > 
> > Argh, this is actually a fatal bug, and not a mistake on my part. 
> > mcount is an unknown symbol, and make modules_install does not like
> > that.
> > 
> > I checked Module.symvers and it is not in there, but this seems to be a
> > generated file, and I have no idea why mcount does not appear.
> > 
> 
> I think appending this to i386_ksyms.c fixes the problem:
> 
> #ifdef CONFIG_PREEMPT_TIMING
> EXPORT_SYMBOL(mcount);
> #endif
> 
> Possibly that should be CONFIG_LATENCY_TRACE.

I believe this is the correct patch, based on
arch/sparc64/kernel/sparc64_ksyms.c.  Ingo, are you using a sparc64 for
your testing?

--- arch/i386/kernel/i386_ksyms.c.orig	2004-08-13 00:18:51.000000000 -0400
+++ arch/i386/kernel/i386_ksyms.c	2004-08-13 00:19:46.000000000 -0400
@@ -59,6 +59,11 @@
 extern unsigned long cpu_khz;
 extern unsigned long get_cmos_time(void);
 
+#if defined(CONFIG_MCOUNT)
+extern void mcount(void);
+EXPORT_SYMBOL_NOVERS(mcount);
+#endif
+
 /* platform dependent support */
 EXPORT_SYMBOL(boot_cpu_data);
 EXPORT_SYMBOL(MCA_bus);

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Roland Dreier]

    Lee> I believe this is the correct patch, based on
    Lee> arch/sparc64/kernel/sparc64_ksyms.c.  Ingo, are you using a
    Lee> sparc64 for your testing?

He's probably just not using modules.  There's no way LATENCY_TRACE
can work on anything except i386, since that's the only definition of
mcount that's provided (and if one were being anal, it would probably
make more sense to add the config stuff to arch/i386/Kconfig rather
than init/Kconfig).

 - R.

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Fri, 2004-08-13 at 00:35, Roland Dreier wrote:
>     Lee> I believe this is the correct patch, based on
>     Lee> arch/sparc64/kernel/sparc64_ksyms.c.  Ingo, are you using a
>     Lee> sparc64 for your testing?
> 
> He's probably just not using modules.  There's no way LATENCY_TRACE
> can work on anything except i386, since that's the only definition of
> mcount that's provided (and if one were being anal, it would probably
> make more sense to add the config stuff to arch/i386/Kconfig rather
> than init/Kconfig).
> 

It also exists on sparc64, it's just called _mcount.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Roland Dreier]

    Lee> It also exists on sparc64, it's just called _mcount.

That's something completely different (used for stack overflow
debugging, I think).  (and ".globl mcount, _mcount" means it's also
called mcount)

Look at Ingo's patch; it only adds mcount() to arch/i386 (although
__mcount is defined in kernel/latency.c, there's no way for any other
arch to call it).

 - Roland

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Matt Heler]

Ingo,

I get the following error when I have CONFIG_PREEMPT_TIMING=n

  AS      arch/i386/kernel/entry.o
  CC      arch/i386/kernel/traps.o
arch/i386/kernel/traps.c: In function `do_nmi':
arch/i386/kernel/traps.c:539: error: syntax error before "do"
arch/i386/kernel/traps.c:539: error: syntax error before ')' token
arch/i386/kernel/traps.c:537: warning: unused variable `cpu'
arch/i386/kernel/traps.c: At top level:
arch/i386/kernel/traps.c:541: warning: type defaults to `int' in declaration 
of `cpu'
arch/i386/kernel/traps.c:541: warning: data definition has no type or storage 
class
arch/i386/kernel/traps.c:542: error: syntax error before '++' token
arch/i386/kernel/traps.c:500: warning: `default_do_nmi' defined but not used
make[1]: *** [arch/i386/kernel/traps.o] Error 1
make: *** [arch/i386/kernel] Error 2


Matt 

On Thursday 12 August 2004 4:51 pm, Ingo Molnar wrote:
> i've uploaded the latest version of the voluntary-preempt patch:
>
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
>
> during the past couple of weeks there has been a steady trend towards
> rarer and harder to analyze latencies.
>
> The preempt-timing patch was a nice starting point but it only prints
> limited info about the beginning and the end of a critical section -
> often leaving us in the dark about what happened within the critical
> section. Often the trace only contains generic entry/exit points like
> e.g. do_poll() which are not very helpful in determining the precise
> reason for the latency.
>
> so in -O6 i've implemented a 'latency tracer', which automatically
> records all kernel functions called during a maximum-latency incident.
> This typically means thousands of functions per critical section. I've
> combined this tracer with the preempt-timing approach to produce a
> pretty powerful tool to find & squash latencies.
>
> there's a new /proc/latency_trace file that holds the current latency
> trace (belonging to the previous high-latency event). It has a format
> that is intended to make it as easy as possible for kernel developers to
> fix any particular latency source. Audio developers and users can
> generate such traces and send them along to kernel developers as text
> files.
>
> Sample use of the latency tracer:
>
> E.g. the following incident:
>
>  (default.hotplug/1470): 121 us critical section violates 100 us threshold.
>   => started at: <kmap_high+0x2b/0x2d0>
>   => ended at:   <kmap_high+0x1a9/0x2d0>
>   [<c0105a23>] dump_stack+0x23/0x30
>   [<c0140d14>] check_preempt_timing+0x184/0x1e0
>   [<c0140e84>] sub_preempt_count+0x54/0x5d
>   [<c0152959>] kmap_high+0x1a9/0x2d0
>   [<c017655a>] copy_strings+0xea/0x230
>   [<c01766db>] copy_strings_kernel+0x3b/0x50
>   [<c017840d>] do_execve+0x12d/0x1f0
>   [<c0103284>] sys_execve+0x44/0x80
>   [<c0104b95>] sysenter_past_esp+0x52/0x71
>
> this doesnt tell us too much about why it took 121 usecs to get from one
> end of kmap_high() to the other end of kmap_high(). Looking at
> /proc/latency_trace tells us the full story:
>
>   preemption latency trace v1.0
>   -----------------------------
>    latency: 121 us, entries: 1032 (1032)
>    process: default.hotplug/1470, uid: 0
>    nice: -10, policy: 0, rt_priority: 0
>   =======>
>    0.000ms (+0.000ms): page_address (kmap_high)
>    0.000ms (+0.000ms): page_slot (page_address)
>    0.000ms (+0.000ms): flush_all_zero_pkmaps (kmap_high)
>    0.000ms (+0.000ms): set_page_address (flush_all_zero_pkmaps)
>   [...]
>    0.118ms (+0.000ms): page_slot (set_page_address)
>    0.118ms (+0.000ms): check_preempt_timing (sub_preempt_count)
>
> it's the rare but possible call to flush_all_zero_pkmaps() that
> generates this particular latency.
>
> as can be seen in the above the example, the trace contains a header
> portion and a trace line for every kernel function called. Only function
> entries are recorded (not function returns) so i've added the parent
> function to the trace too, for easier identification of the call
> sequence.
>
> there's a MAX_TRACE define in kernel/latency.c - set to 4000 currently -
> this is the maximum number of function calls traced per critical
> section. Feel free to increase/decrease this. The header portion shows
> the true number of functions called in a critical section, e.g.:
>
>    latency: 1531 us, entries: 4000 (16098)
>
> tells us that there were 16098 trace entries but only the first 4000
> were recorded.
>
> -O6 also adds another timing option besides preempt_thresh: if
> preempt_thresh is set to 0 then the tracer will automatically track the
> largest-previous latency. (i.e. the system does a search for the
> absolute maximum latency.) The /proc/sys/kernel/preempt_max_latency
> control can be used to reset this value to conduct a new search for a
> new workload, without having to reboot the system.
>
> -O6 also does some SMP improvements: the IRQ threads now listen to the
> /proc/irq/*/smp_affinity mask and bind themselves to the configured CPU.
> This means that e.g. the irqbalance daemon will work as expected.
>
> -O6 also fixes and cleans up a number of other aspects of the
> preempt-timing mechanism.
>
> the latency tracer can be turned on/off via CONFIG_LATENCY_TRACE at
> compile time. An active tracer means considerable runtime overhead.
> Especially code that does alot of small function calls will see a
> performance hit. I'm seeing a ~10% overhead on a 2GHz system, but YMMV.
>
> reports, suggestions welcome,
>
> 	Ingo
> -
> 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/

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 19:51, Ingo Molnar wrote:
> i've uploaded the latest version of the voluntary-preempt patch:
>      
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> 

Interesting results.  One of the problems is kallsyms_lookup, triggered
by the printks:

 0.100ms (+0.000ms): emit_log_char (printk)
 0.100ms (+0.000ms): emit_log_char (printk)
 0.101ms (+0.000ms): emit_log_char (printk)
 0.101ms (+0.000ms): preempt_schedule (printk)
 0.101ms (+0.000ms): release_console_sem (printk)
 0.102ms (+0.000ms): preempt_schedule (release_console_sem)
 0.102ms (+0.000ms): call_console_drivers (release_console_sem)
 0.103ms (+0.000ms): _call_console_drivers (call_console_drivers)
 0.103ms (+0.000ms): __call_console_drivers (call_console_drivers)
 0.105ms (+0.001ms): vt_console_print (__call_console_drivers)
 0.106ms (+0.001ms): vc_cons_allocated (vt_console_print)
 0.108ms (+0.001ms): preempt_schedule (release_console_sem)
 0.108ms (+0.000ms): __print_symbol (print_context_stack)
 0.109ms (+0.001ms): kallsyms_lookup (__print_symbol)
 0.491ms (+0.381ms): sprintf (__print_symbol)
 0.492ms (+0.000ms): vsprintf (sprintf)
 0.492ms (+0.000ms): vsnprintf (vsprintf)
 0.494ms (+0.001ms): number (vsnprintf)
 0.496ms (+0.001ms): number (vsnprintf)
 0.497ms (+0.001ms): printk (__print_symbol)
 0.497ms (+0.000ms): vscnprintf (printk)
 0.497ms (+0.000ms): vsnprintf (vscnprintf)
 0.499ms (+0.001ms): emit_log_char (printk)
 0.499ms (+0.000ms): emit_log_char (printk)

 0.778ms (+0.000ms): emit_log_char (printk)
 0.779ms (+0.000ms): emit_log_char (printk)
 0.779ms (+0.000ms): preempt_schedule (printk)
 0.779ms (+0.000ms): release_console_sem (printk)
 0.780ms (+0.000ms): preempt_schedule (release_console_sem)
 0.780ms (+0.000ms): call_console_drivers (release_console_sem)
 0.781ms (+0.000ms): _call_console_drivers (call_console_drivers)
 0.781ms (+0.000ms): __call_console_drivers (call_console_drivers)
 0.781ms (+0.000ms): vt_console_print (__call_console_drivers)
 0.782ms (+0.000ms): vc_cons_allocated (vt_console_print)
 0.782ms (+0.000ms): preempt_schedule (release_console_sem)
 0.782ms (+0.000ms): __print_symbol (print_context_stack)
 0.783ms (+0.000ms): kallsyms_lookup (__print_symbol)
 1.448ms (+0.665ms): sprintf (__print_symbol)
 1.448ms (+0.000ms): vsprintf (sprintf)
 1.448ms (+0.000ms): vsnprintf (vsprintf)
 1.450ms (+0.001ms): number (vsnprintf)
 1.452ms (+0.001ms): number (vsnprintf)
 1.453ms (+0.000ms): printk (__print_symbol)
 1.453ms (+0.000ms): vscnprintf (printk)
 1.453ms (+0.000ms): vsnprintf (vscnprintf)
 1.455ms (+0.001ms): emit_log_char (printk)
 1.456ms (+0.000ms): emit_log_char (printk)

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 19:51, Ingo Molnar wrote:
> i've uploaded the latest version of the voluntary-preempt patch:
>      
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6

My results with -O6 confirm Florian's results that when xrun_debug is
off, mlockall() does not produce a long non-preemptible section at all,
but does cause xruns in jackd.  I have no idea how this is possible.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Fri, 2004-08-13 at 01:27, Lee Revell wrote:
> On Thu, 2004-08-12 at 19:51, Ingo Molnar wrote:
> > i've uploaded the latest version of the voluntary-preempt patch:
> >      
> >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> 

Ugh, this is a bad one:

preemption latency trace v1.0
-----------------------------
 latency: 506 us, entries: 157 (157)
 process: evolution/3461, uid: 1000
 nice: 0, policy: 0, rt_priority: 0
=======>
 0.000ms (+0.000ms): get_random_bytes (__check_and_rekey)
 0.000ms (+0.000ms): extract_entropy (get_random_bytes)
 0.002ms (+0.001ms): extract_entropy (extract_entropy)
 0.003ms (+0.001ms): SHATransform (extract_entropy)
 0.004ms (+0.000ms): memcpy (SHATransform)
 0.014ms (+0.010ms): add_entropy_words (extract_entropy)
 0.016ms (+0.002ms): SHATransform (extract_entropy)
 0.016ms (+0.000ms): memcpy (SHATransform)
 0.025ms (+0.008ms): add_entropy_words (extract_entropy)
 0.026ms (+0.000ms): SHATransform (extract_entropy)
 0.026ms (+0.000ms): memcpy (SHATransform)
 0.035ms (+0.008ms): add_entropy_words (extract_entropy)
 0.035ms (+0.000ms): SHATransform (extract_entropy)
 0.036ms (+0.000ms): memcpy (SHATransform)
 0.044ms (+0.008ms): add_entropy_words (extract_entropy)
 0.045ms (+0.000ms): SHATransform (extract_entropy)
 0.045ms (+0.000ms): memcpy (SHATransform)
 0.053ms (+0.008ms): add_entropy_words (extract_entropy)
 0.054ms (+0.000ms): SHATransform (extract_entropy)
 0.055ms (+0.000ms): memcpy (SHATransform)
 0.063ms (+0.008ms): add_entropy_words (extract_entropy)
 0.064ms (+0.000ms): SHATransform (extract_entropy)
 0.064ms (+0.000ms): memcpy (SHATransform)
 0.072ms (+0.008ms): add_entropy_words (extract_entropy)
 0.073ms (+0.000ms): SHATransform (extract_entropy)
 0.073ms (+0.000ms): memcpy (SHATransform)
 0.082ms (+0.008ms): add_entropy_words (extract_entropy)
 0.083ms (+0.001ms): SHATransform (extract_entropy)
 0.083ms (+0.000ms): memcpy (SHATransform)
 0.091ms (+0.008ms): add_entropy_words (extract_entropy)
 0.092ms (+0.000ms): SHATransform (extract_entropy)
 0.092ms (+0.000ms): memcpy (SHATransform)
 0.101ms (+0.008ms): add_entropy_words (extract_entropy)
 0.101ms (+0.000ms): SHATransform (extract_entropy)
 0.102ms (+0.000ms): memcpy (SHATransform)
 0.110ms (+0.008ms): add_entropy_words (extract_entropy)
 0.111ms (+0.000ms): SHATransform (extract_entropy)
 0.111ms (+0.000ms): memcpy (SHATransform)
 0.119ms (+0.008ms): add_entropy_words (extract_entropy)
 0.120ms (+0.000ms): SHATransform (extract_entropy)
 0.120ms (+0.000ms): memcpy (SHATransform)
 0.129ms (+0.008ms): add_entropy_words (extract_entropy)
 0.129ms (+0.000ms): SHATransform (extract_entropy)
 0.129ms (+0.000ms): memcpy (SHATransform)
 0.138ms (+0.008ms): add_entropy_words (extract_entropy)
 0.139ms (+0.000ms): SHATransform (extract_entropy)
 0.139ms (+0.000ms): memcpy (SHATransform)
 0.147ms (+0.008ms): add_entropy_words (extract_entropy)
 0.148ms (+0.000ms): SHATransform (extract_entropy)
 0.148ms (+0.000ms): memcpy (SHATransform)
 0.157ms (+0.008ms): add_entropy_words (extract_entropy)
 0.158ms (+0.000ms): SHATransform (extract_entropy)
 0.158ms (+0.000ms): memcpy (SHATransform)
 0.166ms (+0.008ms): add_entropy_words (extract_entropy)
 0.167ms (+0.000ms): SHATransform (extract_entropy)
 0.167ms (+0.000ms): memcpy (SHATransform)
 0.176ms (+0.008ms): add_entropy_words (extract_entropy)
 0.177ms (+0.000ms): SHATransform (extract_entropy)
 0.177ms (+0.000ms): memcpy (SHATransform)
 0.185ms (+0.008ms): add_entropy_words (extract_entropy)
 0.186ms (+0.000ms): SHATransform (extract_entropy)
 0.186ms (+0.000ms): memcpy (SHATransform)
 0.195ms (+0.008ms): add_entropy_words (extract_entropy)
 0.196ms (+0.000ms): SHATransform (extract_entropy)
 0.196ms (+0.000ms): memcpy (SHATransform)
 0.204ms (+0.008ms): add_entropy_words (extract_entropy)
 0.205ms (+0.000ms): SHATransform (extract_entropy)
 0.205ms (+0.000ms): memcpy (SHATransform)
 0.214ms (+0.008ms): add_entropy_words (extract_entropy)
 0.214ms (+0.000ms): SHATransform (extract_entropy)
 0.215ms (+0.000ms): memcpy (SHATransform)
 0.223ms (+0.008ms): add_entropy_words (extract_entropy)
 0.224ms (+0.000ms): SHATransform (extract_entropy)
 0.224ms (+0.000ms): memcpy (SHATransform)
 0.233ms (+0.008ms): add_entropy_words (extract_entropy)
 0.234ms (+0.001ms): SHATransform (extract_entropy)
 0.234ms (+0.000ms): memcpy (SHATransform)
 0.242ms (+0.008ms): add_entropy_words (extract_entropy)
 0.243ms (+0.000ms): SHATransform (extract_entropy)
 0.243ms (+0.000ms): memcpy (SHATransform)
 0.252ms (+0.008ms): add_entropy_words (extract_entropy)
 0.252ms (+0.000ms): SHATransform (extract_entropy)
 0.253ms (+0.000ms): memcpy (SHATransform)
 0.261ms (+0.008ms): add_entropy_words (extract_entropy)
 0.262ms (+0.000ms): SHATransform (extract_entropy)
 0.262ms (+0.000ms): memcpy (SHATransform)
 0.271ms (+0.008ms): add_entropy_words (extract_entropy)
 0.271ms (+0.000ms): SHATransform (extract_entropy)
 0.272ms (+0.000ms): memcpy (SHATransform)
 0.280ms (+0.008ms): add_entropy_words (extract_entropy)
 0.281ms (+0.000ms): SHATransform (extract_entropy)
 0.281ms (+0.000ms): memcpy (SHATransform)
 0.289ms (+0.008ms): add_entropy_words (extract_entropy)
 0.290ms (+0.000ms): SHATransform (extract_entropy)
 0.290ms (+0.000ms): memcpy (SHATransform)
 0.299ms (+0.008ms): add_entropy_words (extract_entropy)
 0.300ms (+0.000ms): SHATransform (extract_entropy)
 0.300ms (+0.000ms): memcpy (SHATransform)
 0.308ms (+0.008ms): add_entropy_words (extract_entropy)
 0.309ms (+0.000ms): SHATransform (extract_entropy)
 0.309ms (+0.000ms): memcpy (SHATransform)
 0.318ms (+0.008ms): add_entropy_words (extract_entropy)
 0.319ms (+0.000ms): SHATransform (extract_entropy)
 0.319ms (+0.000ms): memcpy (SHATransform)
 0.327ms (+0.008ms): add_entropy_words (extract_entropy)
 0.328ms (+0.000ms): SHATransform (extract_entropy)
 0.328ms (+0.000ms): memcpy (SHATransform)
 0.337ms (+0.008ms): add_entropy_words (extract_entropy)
 0.338ms (+0.000ms): SHATransform (extract_entropy)
 0.338ms (+0.000ms): memcpy (SHATransform)
 0.346ms (+0.008ms): add_entropy_words (extract_entropy)
 0.347ms (+0.000ms): SHATransform (extract_entropy)
 0.347ms (+0.000ms): memcpy (SHATransform)
 0.356ms (+0.008ms): add_entropy_words (extract_entropy)
 0.356ms (+0.000ms): SHATransform (extract_entropy)
 0.357ms (+0.000ms): memcpy (SHATransform)
 0.365ms (+0.008ms): add_entropy_words (extract_entropy)
 0.366ms (+0.000ms): SHATransform (extract_entropy)
 0.366ms (+0.000ms): memcpy (SHATransform)
 0.375ms (+0.008ms): add_entropy_words (extract_entropy)
 0.375ms (+0.000ms): SHATransform (extract_entropy)
 0.376ms (+0.000ms): memcpy (SHATransform)
 0.384ms (+0.008ms): add_entropy_words (extract_entropy)
 0.385ms (+0.001ms): add_entropy_words (extract_entropy)
 0.396ms (+0.010ms): credit_entropy_store (extract_entropy)
 0.397ms (+0.001ms): SHATransform (extract_entropy)
 0.397ms (+0.000ms): memcpy (SHATransform)
 0.405ms (+0.008ms): add_entropy_words (extract_entropy)
 0.406ms (+0.000ms): SHATransform (extract_entropy)
 0.407ms (+0.000ms): memcpy (SHATransform)
 0.415ms (+0.008ms): add_entropy_words (extract_entropy)
 0.416ms (+0.001ms): SHATransform (extract_entropy)
 0.416ms (+0.000ms): memcpy (SHATransform)
 0.425ms (+0.008ms): add_entropy_words (extract_entropy)
 0.425ms (+0.000ms): SHATransform (extract_entropy)
 0.426ms (+0.000ms): memcpy (SHATransform)
 0.434ms (+0.008ms): add_entropy_words (extract_entropy)
 0.435ms (+0.001ms): SHATransform (extract_entropy)
 0.436ms (+0.000ms): memcpy (SHATransform)
 0.444ms (+0.008ms): add_entropy_words (extract_entropy)
 0.445ms (+0.000ms): SHATransform (extract_entropy)
 0.445ms (+0.000ms): memcpy (SHATransform)
 0.453ms (+0.008ms): add_entropy_words (extract_entropy)
 0.455ms (+0.001ms): SHATransform (extract_entropy)
 0.455ms (+0.000ms): memcpy (SHATransform)
 0.463ms (+0.008ms): add_entropy_words (extract_entropy)
 0.464ms (+0.000ms): SHATransform (extract_entropy)
 0.464ms (+0.000ms): memcpy (SHATransform)
 0.473ms (+0.008ms): add_entropy_words (extract_entropy)
 0.474ms (+0.001ms): SHATransform (extract_entropy)
 0.474ms (+0.000ms): memcpy (SHATransform)
 0.482ms (+0.008ms): add_entropy_words (extract_entropy)
 0.483ms (+0.000ms): SHATransform (extract_entropy)
 0.483ms (+0.000ms): memcpy (SHATransform)
 0.492ms (+0.008ms): add_entropy_words (extract_entropy)
 0.493ms (+0.001ms): local_bh_enable (__check_and_rekey)
 0.494ms (+0.000ms): check_preempt_timing (sub_preempt_count)

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-12 at 19:51, Ingo Molnar wrote:
> i've uploaded the latest version of the voluntary-preempt patch:
>      
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6

Here's another weird one.  This happens when you create a new tab in
gnome-terminal, which causes a fork().

preemption latency trace v1.0
-----------------------------
 latency: 613 us, entries: 697 (697)
 process: gnome-terminal/3467, uid: 1000
 nice: 0, policy: 0, rt_priority: 0
=======>
 0.000ms (+0.000ms): do_IRQ (common_interrupt)
 0.000ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
 0.003ms (+0.003ms): generic_redirect_hardirq (do_IRQ)
 0.004ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
 0.004ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
 0.005ms (+0.000ms): mark_offset_tsc (timer_interrupt)
 0.011ms (+0.006ms): do_timer (timer_interrupt)
 0.011ms (+0.000ms): update_process_times (do_timer)
 0.012ms (+0.000ms): update_one_process (update_process_times)
 0.012ms (+0.000ms): run_local_timers (update_process_times)
 0.012ms (+0.000ms): raise_softirq (update_process_times)
 0.013ms (+0.000ms): scheduler_tick (update_process_times)
 0.013ms (+0.000ms): sched_clock (scheduler_tick)
 0.014ms (+0.001ms): task_timeslice (scheduler_tick)
 0.015ms (+0.000ms): update_wall_time (do_timer)
 0.015ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
 0.017ms (+0.001ms): generic_note_interrupt (do_IRQ)
 0.017ms (+0.000ms): end_8259A_irq (do_IRQ)
 0.017ms (+0.000ms): enable_8259A_irq (do_IRQ)
 0.019ms (+0.001ms): do_softirq (do_IRQ)
 0.019ms (+0.000ms): __do_softirq (do_softirq)
 0.019ms (+0.000ms): wake_up_process (do_softirq)
 0.020ms (+0.000ms): try_to_wake_up (wake_up_process)
 0.020ms (+0.000ms): task_rq_lock (try_to_wake_up)
 0.020ms (+0.000ms): activate_task (try_to_wake_up)
 0.021ms (+0.000ms): sched_clock (activate_task)
 0.021ms (+0.000ms): recalc_task_prio (activate_task)
 0.022ms (+0.000ms): effective_prio (recalc_task_prio)
 0.022ms (+0.000ms): enqueue_task (activate_task)
 0.023ms (+0.000ms): preempt_schedule (try_to_wake_up)
 0.024ms (+0.000ms): preempt_schedule (copy_page_range)
 0.024ms (+0.000ms): preempt_schedule (copy_page_range)
 0.025ms (+0.000ms): preempt_schedule (copy_page_range)
 0.026ms (+0.000ms): preempt_schedule (copy_page_range)

...about 400+ of the same deleted...

 0.459ms (+0.000ms): preempt_schedule (copy_page_range)
 0.459ms (+0.000ms): preempt_schedule (copy_page_range)
 0.460ms (+0.000ms): preempt_schedule (copy_page_range)
 0.461ms (+0.000ms): preempt_schedule (copy_page_range)
 0.461ms (+0.000ms): preempt_schedule (copy_page_range)
 0.461ms (+0.000ms): check_preempt_timing (touch_preempt_timing)

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Peter Zijlstra]

On Thu, 2004-08-12 at 21:49 -0700, Matt Heler wrote:
> Ingo,
> 
> I get the following error when I have CONFIG_PREEMPT_TIMING=n
> 
>   AS      arch/i386/kernel/entry.o
>   CC      arch/i386/kernel/traps.o
> arch/i386/kernel/traps.c: In function `do_nmi':
> arch/i386/kernel/traps.c:539: error: syntax error before "do"
> arch/i386/kernel/traps.c:539: error: syntax error before ')' token
> arch/i386/kernel/traps.c:537: warning: unused variable `cpu'
> arch/i386/kernel/traps.c: At top level:
> arch/i386/kernel/traps.c:541: warning: type defaults to `int' in declaration 
> of `cpu'
> arch/i386/kernel/traps.c:541: warning: data definition has no type or storage 
> class
> arch/i386/kernel/traps.c:542: error: syntax error before '++' token
> arch/i386/kernel/traps.c:500: warning: `default_do_nmi' defined but not used
> make[1]: *** [arch/i386/kernel/traps.o] Error 1
> make: *** [arch/i386/kernel] Error 2
> 
> 
> Matt 
> 

This fixes it.

--- ./include/asm-i386/hardirq.h~       2004-08-13 11:17:38.668333125 +0200
+++ ./include/asm-i386/hardirq.h        2004-08-13 11:51:40.835968747 +0200
@@ -73,7 +73,7 @@
 #define hardirq_endlock()      do { } while (0)
 
 #define irq_enter()            add_preempt_count(HARDIRQ_OFFSET)
-#define nmi_enter()            (irq_enter())
+#define nmi_enter()            irq_enter()
 #define nmi_exit()             sub_preempt_count(HARDIRQ_OFFSET)
 
 #ifdef CONFIG_PREEMPT



-- 
Peter Zijlstra <a.p.zijlstra@chello.nl>

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> +#if defined(CONFIG_MCOUNT)
> +extern void mcount(void);
> +EXPORT_SYMBOL_NOVERS(mcount);
> +#endif

yeah, we need this export. (i've put it into kernel/latency.c and it's
fine to do it as an EXPORT_SYMBOL()). Will show up in -O7.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> > arch/i386/kernel/traps.c: In function `do_nmi':
> > arch/i386/kernel/traps.c:539: error: syntax error before "do"

> This fixes it.
> 
> --- ./include/asm-i386/hardirq.h~       2004-08-13 11:17:38.668333125 +0200
> +++ ./include/asm-i386/hardirq.h        2004-08-13 11:51:40.835968747 +0200
> @@ -73,7 +73,7 @@
>  #define hardirq_endlock()      do { } while (0)
>  
>  #define irq_enter()            add_preempt_count(HARDIRQ_OFFSET)
> -#define nmi_enter()            (irq_enter())
> +#define nmi_enter()            irq_enter()

yep - thx, this fix too will be in -O7. It seems this compilation error
only happens with older gcc and i'm using 3.3.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Roland Dreier <roland@topspin.com> wrote:

> Look at Ingo's patch; it only adds mcount() to arch/i386 (although
> __mcount is defined in kernel/latency.c, there's no way for any other
> arch to call it).

should be trivial to add it to other arches. But the patch indeed is
x86-only for the time being - 100% of the testers so far were x86 users
so i dont see any point in bloating the patch with untested arch
changes. Tested contributions are welcome of course!

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> Interesting results.  One of the problems is kallsyms_lookup,
> triggered by the printks:

yeah - kallsyms_lookup does a linear search over thousands of symbols. 
Especially since /proc/latency_trace uses it too it would be worthwile
to implement some sort of binary searching.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Peter Zijlstra]

On Fri, 2004-08-13 at 12:19 +0200, Ingo Molnar wrote:
> * Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> 
> > > arch/i386/kernel/traps.c: In function `do_nmi':
> > > arch/i386/kernel/traps.c:539: error: syntax error before "do"
> 
> > This fixes it.
> > 
> > --- ./include/asm-i386/hardirq.h~       2004-08-13 11:17:38.668333125 +0200
> > +++ ./include/asm-i386/hardirq.h        2004-08-13 11:51:40.835968747 +0200
> > @@ -73,7 +73,7 @@
> >  #define hardirq_endlock()      do { } while (0)
> >  
> >  #define irq_enter()            add_preempt_count(HARDIRQ_OFFSET)
> > -#define nmi_enter()            (irq_enter())
> > +#define nmi_enter()            irq_enter()
> 
> yep - thx, this fix too will be in -O7. It seems this compilation error
> only happens with older gcc and i'm using 3.3.
> 
> 	Ingo
FYI,

peter@twins ~ $ gcc --version
gcc (GCC) 3.3.4 20040623 (Gentoo Linux 3.3.4-r1, ssp-3.3.2-2, pie-8.7.6)
Copyright (C) 2003 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

and it hits here too.

-- 
Peter Zijlstra <a.p.zijlstra@chello.nl>

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> > >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> 
> Ugh, this is a bad one:
> 
> preemption latency trace v1.0
> -----------------------------
>  latency: 506 us, entries: 157 (157)
>  process: evolution/3461, uid: 1000
>  nice: 0, policy: 0, rt_priority: 0
> =======>
>  0.000ms (+0.000ms): get_random_bytes (__check_and_rekey)
[...]
>  0.493ms (+0.001ms): local_bh_enable (__check_and_rekey)

indeed this is a new one. Entropy rekeying every 300 seconds. Most of
the overhead comes from the memcpy's - 10 usecs a pop!

this could possibly explain some earlier reports of RTC problems every
couple of minutes - on slower boxes it could easily be more than the 0.5
msec you got. (and with a 8192 Hz RTC the interrupt period is 122
usecs.)

such bhs-off spinlocked sections exclude all softirq traffic - and in
the redirected hardirqs case the hardirqs are excluded too.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Florian Schmidt]

On Fri, 13 Aug 2004 01:51:16 +0200
Ingo Molnar <mingo@elte.hu> wrote:

> -O6 also adds another timing option besides preempt_thresh: if
> preempt_thresh is set to 0 then the tracer will automatically track
> the largest-previous latency. (i.e. the system does a search for the
> absolute maximum latency.) The /proc/sys/kernel/preempt_max_latency 
> control can be used to reset this value to conduct a new search for a 
> new workload, without having to reboot the system.

Hmm, should a new report only be generated when the newly measured
latency is really > than all other ones? I get the feeling that >= seems
to be enough. Here a dmesg extract:

(swapper/1): new 6 us maximum-latency critical section.
 => started at: <schedule+0x5c/0x5b0>
 => ended at:   <finish_task_switch+0x32/0x90>
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0130c64>] check_preempt_timing+0x184/0x1e0
 [<c0130db4>] sub_preempt_count+0x44/0x50
 [<c0112c22>] finish_task_switch+0x32/0x90
 [<c0112c9e>] schedule_tail+0x1e/0x60
 [<c0105df6>] ret_from_fork+0x6/0x14
(swapper/1): new 8 us maximum-latency critical section.
 => started at: <voluntary_resched+0x1e/0x50>
 => ended at:   <voluntary_resched+0x1e/0x50>
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0130c64>] check_preempt_timing+0x184/0x1e0
 [<c0130cf8>] touch_preempt_timing+0x38/0x60
 [<c0292a9e>] voluntary_resched+0x1e/0x50
 [<c013a1b6>] kmem_cache_alloc+0x56/0x60
 [<c01160c0>] copy_process+0x9e0/0xbd0
 [<c0116302>] do_fork+0x52/0x1b3
 [<c0104135>] kernel_thread+0x85/0x90
 [<c012a907>] keventd_create_kthread+0x27/0x50
 [<c012a9a7>] kthread_create+0x77/0xd0
 [<c031dc9b>] cpu_callback+0x5b/0xc0
 [<c031dd22>] spawn_ksoftirqd+0x22/0x50
 [<c0100334>] init+0x34/0x170
 [<c01040a5>] kernel_thread_helper+0x5/0x10
(swapper/1): new 9 us maximum-latency critical section.
 => started at: <voluntary_resched+0x1e/0x50>
 => ended at:   <voluntary_resched+0x1e/0x50>
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0130c64>] check_preempt_timing+0x184/0x1e0
 [<c0130cf8>] touch_preempt_timing+0x38/0x60
 [<c0292a9e>] voluntary_resched+0x1e/0x50
 [<c013a1b6>] kmem_cache_alloc+0x56/0x60
 [<c0116009>] copy_process+0x929/0xbd0
 [<c0116302>] do_fork+0x52/0x1b3
 [<c0104135>] kernel_thread+0x85/0x90
 [<c012a907>] keventd_create_kthread+0x27/0x50
 [<c012a9a7>] kthread_create+0x77/0xd0
 [<c031dc9b>] cpu_callback+0x5b/0xc0
 [<c031dd22>] spawn_ksoftirqd+0x22/0x50
 [<c0100334>] init+0x34/0x170
 [<c01040a5>] kernel_thread_helper+0x5/0x10


Here are two reports with the same maximum-latency (31 us):

(swapper/1): new 31 us maximum-latency critical section.
 => started at: <voluntary_resched+0x1e/0x50>
 => ended at:   <voluntary_resched+0x1e/0x50>
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0130c64>] check_preempt_timing+0x184/0x1e0
 [<c0130cf8>] touch_preempt_timing+0x38/0x60
 [<c0292a9e>] voluntary_resched+0x1e/0x50
 [<c013a3f0>] __kmalloc+0x80/0x90
 [<c0316279>] malloc+0x19/0x20
 [<c01024d4>] huft_build+0x2d4/0x590
 [<c0102ea1>] inflate_fixed+0xc1/0x1a0
 [<c010379a>] inflate+0x4a/0xb0
 [<c0103b89>] gunzip+0x2f9/0x530
 [<c0316e41>] unpack_to_rootfs+0x191/0x220
 [<c0316efb>] populate_rootfs+0x2b/0x130
 [<c010033e>] init+0x3e/0x170
 [<c01040a5>] kernel_thread_helper+0x5/0x10
(swapper/1): new 31 us maximum-latency critical section.
 => started at: <voluntary_resched+0x1e/0x50>
 => ended at:   <voluntary_resched+0x1e/0x50>
 [<c01064ae>] dump_stack+0x1e/0x20
 [<c0130c64>] check_preempt_timing+0x184/0x1e0
 [<c0130cf8>] touch_preempt_timing+0x38/0x60
 [<c0292a9e>] voluntary_resched+0x1e/0x50
 [<c013a1b6>] kmem_cache_alloc+0x56/0x60
 [<c015c8e9>] getname+0x29/0xc0
 [<c015f3fd>] sys_mkdir+0x1d/0xf0
 [<c03169af>] do_name+0x10f/0x1b0
 [<c0316bb1>] write_buffer+0x21/0x30
 [<c0316be4>] flush_buffer+0x24/0x60
 [<c0316c64>] flush_window+0x24/0x70
 [<c01037db>] inflate+0x8b/0xb0
 [<c0103b89>] gunzip+0x2f9/0x530
 [<c0316e41>] unpack_to_rootfs+0x191/0x220
 [<c0316efb>] populate_rootfs+0x2b/0x130
 [<c010033e>] init+0x3e/0x170
 [<c01040a5>] kernel_thread_helper+0x5/0x10
NET: Registered protocol family 16

Btw: i do have some regular ca. 300 us latencies.. Here are some traces
(these happen with an average frequency of ca. 0.3hz):


Aug 13 12:40:49 mango kernel: (ksoftirqd/0/2): 307 us critical section
violates 250 us threshold.
Aug 13 12:40:49 mango kernel:  => started at: <___do_softirq+0x20/0x90>
Aug 13 12:40:49 mango kernel:  => ended at:  
<cond_resched_softirq+0x59/0x70>
Aug 13 12:40:49 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 13 12:40:49 mango kernel:  [<c0130c64>]
check_preempt_timing+0x184/0x1e0
Aug 13 12:40:49 mango kernel:  [<c0130cf8>]
touch_preempt_timing+0x38/0x60
Aug 13 12:40:49 mango kernel:  [<c0113df9>]
cond_resched_softirq+0x59/0x70
Aug 13 12:40:49 mango kernel:  [<c011faef>] run_timer_softirq+0xdf/0x1d0
Aug 13 12:40:49 mango kernel:  [<c011adbc>] ___do_softirq+0x7c/0x90
Aug 13 12:40:49 mango kernel:  [<c011ae19>] _do_softirq+0x9/0x10
Aug 13 12:40:49 mango kernel:  [<c011b1d4>] ksoftirqd+0x84/0xd0
Aug 13 12:40:49 mango kernel:  [<c012a8da>] kthread+0xaa/0xb0
Aug 13 12:40:49 mango kernel:  [<c01040a5>]
kernel_thread_helper+0x5/0x10
Aug 13 12:40:54 mango kernel: (ksoftirqd/0/2): 307 us critical section
violates 250 us threshold.
Aug 13 12:40:54 mango kernel:  => started at: <___do_softirq+0x20/0x90>
Aug 13 12:40:54 mango kernel:  => ended at:  
<cond_resched_softirq+0x59/0x70>
Aug 13 12:40:54 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 13 12:40:54 mango kernel:  [<c0130c64>]
check_preempt_timing+0x184/0x1e0
Aug 13 12:40:54 mango kernel:  [<c0130cf8>]
touch_preempt_timing+0x38/0x60
Aug 13 12:40:54 mango kernel:  [<c0113df9>]
cond_resched_softirq+0x59/0x70
Aug 13 12:40:54 mango kernel:  [<c011faef>] run_timer_softirq+0xdf/0x1d0
Aug 13 12:40:54 mango kernel:  [<c011adbc>] ___do_softirq+0x7c/0x90
Aug 13 12:40:54 mango kernel:  [<c011ae19>] _do_softirq+0x9/0x10
Aug 13 12:40:54 mango kernel:  [<c011b1d4>] ksoftirqd+0x84/0xd0
Aug 13 12:40:54 mango kernel:  [<c012a8da>] kthread+0xaa/0xb0
Aug 13 12:40:54 mango kernel:  [<c01040a5>]
kernel_thread_helper+0x5/0x10
Aug 13 12:40:59 mango kernel: (ksoftirqd/0/2): 308 us critical section
violates 250 us threshold.
Aug 13 12:40:59 mango kernel:  => started at: <___do_softirq+0x20/0x90>
Aug 13 12:40:59 mango kernel:  => ended at:  
<cond_resched_softirq+0x59/0x70>
Aug 13 12:40:59 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 13 12:40:59 mango kernel:  [<c0130c64>]
check_preempt_timing+0x184/0x1e0
Aug 13 12:40:59 mango kernel:  [<c0130cf8>]
touch_preempt_timing+0x38/0x60
Aug 13 12:40:59 mango kernel:  [<c0113df9>]
cond_resched_softirq+0x59/0x70
Aug 13 12:40:59 mango kernel:  [<c011faef>] run_timer_softirq+0xdf/0x1d0
Aug 13 12:40:59 mango kernel:  [<c011adbc>] ___do_softirq+0x7c/0x90
Aug 13 12:40:59 mango kernel:  [<c011ae19>] _do_softirq+0x9/0x10
Aug 13 12:40:59 mango kernel:  [<c011b1d4>] ksoftirqd+0x84/0xd0
Aug 13 12:40:59 mango kernel:  [<c012a8da>] kthread+0xaa/0xb0
Aug 13 12:40:59 mango kernel:  [<c01040a5>]
kernel_thread_helper+0x5/0x10
Aug 13 12:41:04 mango kernel: (ksoftirqd/0/2): 307 us critical section
violates 250 us threshold.
Aug 13 12:41:04 mango kernel:  => started at: <___do_softirq+0x20/0x90>
Aug 13 12:41:04 mango kernel:  => ended at:  
<cond_resched_softirq+0x59/0x70>
Aug 13 12:41:04 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 13 12:41:04 mango kernel:  [<c0130c64>]
check_preempt_timing+0x184/0x1e0
Aug 13 12:41:04 mango kernel:  [<c0130cf8>]
touch_preempt_timing+0x38/0x60
Aug 13 12:41:04 mango kernel:  [<c0113df9>]
cond_resched_softirq+0x59/0x70
Aug 13 12:41:04 mango kernel:  [<c011faef>] run_timer_softirq+0xdf/0x1d0
Aug 13 12:41:04 mango kernel:  [<c011adbc>] ___do_softirq+0x7c/0x90
Aug 13 12:41:04 mango kernel:  [<c011ae19>] _do_softirq+0x9/0x10
Aug 13 12:41:04 mango kernel:  [<c011b1d4>] ksoftirqd+0x84/0xd0
Aug 13 12:41:04 mango kernel:  [<c012a8da>] kthread+0xaa/0xb0
Aug 13 12:41:04 mango kernel:  [<c01040a5>]
kernel_thread_helper+0x5/0x10
Aug 13 12:41:09 mango kernel: (ksoftirqd/0/2): 307 us critical section
violates 250 us threshold.
Aug 13 12:41:09 mango kernel:  => started at: <___do_softirq+0x20/0x90>
Aug 13 12:41:09 mango kernel:  => ended at:  
<cond_resched_softirq+0x59/0x70>
Aug 13 12:41:09 mango kernel:  [<c01064ae>] dump_stack+0x1e/0x20
Aug 13 12:41:09 mango kernel:  [<c0130c64>]
check_preempt_timing+0x184/0x1e0
Aug 13 12:41:09 mango kernel:  [<c0130cf8>]
touch_preempt_timing+0x38/0x60
Aug 13 12:41:09 mango kernel:  [<c0113df9>]
cond_resched_softirq+0x59/0x70
Aug 13 12:41:09 mango kernel:  [<c011faef>] run_timer_softirq+0xdf/0x1d0
Aug 13 12:41:09 mango kernel:  [<c011adbc>] ___do_softirq+0x7c/0x90
Aug 13 12:41:09 mango kernel:  [<c011ae19>] _do_softirq+0x9/0x10
Aug 13 12:41:09 mango kernel:  [<c011b1d4>] ksoftirqd+0x84/0xd0
Aug 13 12:41:09 mango kernel:  [<c012a8da>] kthread+0xaa/0xb0
Aug 13 12:41:09 mango kernel:  [<c01040a5>]
kernel_thread_helper+0x5/0x10

Some system info:

I do not habe preempt-tracing enabled, only voluntary preempt and
preempt timing..

Linux mango.fruits.de 2.6.8-rc4 #1 Fri Aug 13 03:05:04 CEST 2004 i686
GNU/Linux
-----------
processor       : 0
vendor_id       : AuthenticAMD
cpu family      : 6
model           : 7
model name      : AMD Duron(tm) Processor
stepping        : 1
cpu MHz         : 1195.497
cache size      : 64 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 1
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 sep mtrr pge mca
cmov pat pse36 mmx fxsr sse syscall mp mmxext 3dnowext 3dnow
bogomips        : 2359.29

-----------
/proc/interrupts:
           CPU0       
  0:    1832325          XT-PIC  timer
  1:       8892          XT-PIC  i8042
  2:          0          XT-PIC  cascade
  5:          0          XT-PIC  CS46XX
  8:          4          XT-PIC  rtc
 10:       2066          XT-PIC  eth0
 12:      39786          XT-PIC  i8042
 14:        900          XT-PIC  ide0
 15:      12719          XT-PIC  ide1
NMI:          0 
ERR:          0
-----------
/proc/irq/10/eth0/threaded:1
/proc/irq/12/i8042/threaded:1
/proc/irq/14/ide0/threaded:1
/proc/irq/15/ide1/threaded:1
/proc/irq/1/i8042/threaded:1
/proc/irq/5/CS46XX/threaded:0
/proc/irq/8/rtc/threaded:0
-----------
/sys/block/hda/queue/max_sectors_kb:16
/sys/block/hdd/queue/max_sectors_kb:16
-----------
voluntary_preemption
3
kernel_preemption
1
-----------
preempt_thresh
250


-- 
Palimm Palimm!
http://affenbande.org/~tapas/

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Florian Schmidt <mista.tapas@gmx.net> wrote:

> Hmm, should a new report only be generated when the newly measured
> latency is really > than all other ones? I get the feeling that >=
> seems to be enough. Here a dmesg extract:
> 
> (swapper/1): new 6 us maximum-latency critical section.
> (swapper/1): new 8 us maximum-latency critical section.
> (swapper/1): new 9 us maximum-latency critical section.

> Here are two reports with the same maximum-latency (31 us):
> 
> (swapper/1): new 31 us maximum-latency critical section.
> (swapper/1): new 31 us maximum-latency critical section.

the latency tracer tracks latencies in cycle units - but they are
displayed at microsecond accuracy - hence these 'equal' latencies.

to jump-start all those smaller latencies you can do this:

	echo 100 > /proc/sys/kernel/preempt_max_latency
	echo 0 > /proc/sys/kernel/preempt_thresh

this way the maximum-searching only starts at 100 usecs.

> Btw: i do have some regular ca. 300 us latencies.. Here are some traces
> (these happen with an average frequency of ca. 0.3hz):

> (ksoftirqd/0/2): 307 us critical section violates 250 us threshold.
>  => started at: <___do_softirq+0x20/0x90>
>  => ended at: <cond_resched_softirq+0x59/0x70>

this is too opaque - could you try -O7, enable tracing and save a
/proc/latency_trace instance of such a latency? It looks like some sort
of softirq latency - perhaps one particular driver's timer fn causes it
- we'll be able to tell more from the trace.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Florian Schmidt <mista.tapas@gmx.net> wrote:

> On Fri, 13 Aug 2004 12:54:06 +0200
> Ingo Molnar <mingo@elte.hu> wrote:
> 
> > > (ksoftirqd/0/2): 307 us critical section violates 250 us threshold.
> > >  => started at: <___do_softirq+0x20/0x90>
> > >  => ended at: <cond_resched_softirq+0x59/0x70>
> > 
> > this is too opaque - could you try -O7, enable tracing and save a
> > /proc/latency_trace instance of such a latency? It looks like some
> > sort of softirq latency - perhaps one particular driver's timer fn
> > causes it- we'll be able to tell more from the trace.
> 
> Hi, this looks like one of them:
> 
> mango:~# cat /proc/latency_trace 
> preemption latency trace v1.0
> -----------------------------
>  latency: 308 us, entries: 12 (12)
>  process: ksoftirqd/0/2, uid: 0
>  nice: -10, policy: 0, rt_priority: 0
> =======>
>  0.000ms (+0.000ms): run_timer_softirq (___do_softirq)
>  0.000ms (+0.000ms): sis900_timer (run_timer_softirq)
>  0.001ms (+0.000ms): mdio_read (sis900_timer)
>  0.002ms (+0.000ms): mdio_reset (mdio_read)
>  0.071ms (+0.069ms): mdio_idle (mdio_read)
>  0.151ms (+0.079ms): mdio_read (sis900_timer)
>  0.151ms (+0.000ms): mdio_reset (mdio_read)
>  0.220ms (+0.069ms): mdio_idle (mdio_read)
>  0.300ms (+0.079ms): __mod_timer (sis900_timer)
>  0.300ms (+0.000ms): internal_add_timer (__mod_timer)
>  0.300ms (+0.000ms): cond_resched_softirq (run_timer_softirq)
>  0.301ms (+0.000ms): check_preempt_timing (touch_preempt_timing)

indeed this seems to be a driver related timer: driver/net/sis900.c's
sis900_timer() function. This timer polls your network card for link
status once every second. The mdio_read() function does alot of in/out
instructions which are quite slow.

could you try the following and disable mdio_delay():

	#define mdio_delay() do { } while (0)

normally it should work just fine. Worst-case you'd get a non-working
network driver. Does this change reduce the latency?

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Florian Schmidt]

On Fri, 13 Aug 2004 12:54:06 +0200
Ingo Molnar <mingo@elte.hu> wrote:

> > (ksoftirqd/0/2): 307 us critical section violates 250 us threshold.
> >  => started at: <___do_softirq+0x20/0x90>
> >  => ended at: <cond_resched_softirq+0x59/0x70>
> 
> this is too opaque - could you try -O7, enable tracing and save a
> /proc/latency_trace instance of such a latency? It looks like some
> sort of softirq latency - perhaps one particular driver's timer fn
> causes it- we'll be able to tell more from the trace.

Hi, this looks like one of them:

mango:~# cat /proc/latency_trace 
preemption latency trace v1.0
-----------------------------
 latency: 308 us, entries: 12 (12)
 process: ksoftirqd/0/2, uid: 0
 nice: -10, policy: 0, rt_priority: 0
=======>
 0.000ms (+0.000ms): run_timer_softirq (___do_softirq)
 0.000ms (+0.000ms): sis900_timer (run_timer_softirq)
 0.001ms (+0.000ms): mdio_read (sis900_timer)
 0.002ms (+0.000ms): mdio_reset (mdio_read)
 0.071ms (+0.069ms): mdio_idle (mdio_read)
 0.151ms (+0.079ms): mdio_read (sis900_timer)
 0.151ms (+0.000ms): mdio_reset (mdio_read)
 0.220ms (+0.069ms): mdio_idle (mdio_read)
 0.300ms (+0.079ms): __mod_timer (sis900_timer)
 0.300ms (+0.000ms): internal_add_timer (__mod_timer)
 0.300ms (+0.000ms): cond_resched_softirq (run_timer_softirq)
 0.301ms (+0.000ms): check_preempt_timing (touch_preempt_timing)

Flo

-- 
Palimm Palimm!
http://affenbande.org/~tapas/

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Andi Kleen]

Ingo Molnar <mingo@elte.hu> writes:

> * Lee Revell <rlrevell@joe-job.com> wrote:
>
>> Interesting results.  One of the problems is kallsyms_lookup,
>> triggered by the printks:
>
> yeah - kallsyms_lookup does a linear search over thousands of symbols. 
> Especially since /proc/latency_trace uses it too it would be worthwile
> to implement some sort of binary searching.

Or just stick some cond_sched()s in there. It was designed to be slow,
but there are no locking issues.

-Andi

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Andi Kleen <ak@muc.de> wrote:

> >> Interesting results.  One of the problems is kallsyms_lookup,
> >> triggered by the printks:
> >
> > yeah - kallsyms_lookup does a linear search over thousands of symbols. 
> > Especially since /proc/latency_trace uses it too it would be worthwile
> > to implement some sort of binary searching.
> 
> Or just stick some cond_sched()s in there. It was designed to be slow,
> but there are no locking issues.

the speedup would be important: even on a 2GHz box reading 10,000 trace
entries takes a couple of seconds.

[ the /proc/latency_trace read()ing itself is fully preemptible, i'd be
  ashamed if it werent ;) ]

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> > Or just stick some cond_sched()s in there. It was designed to be slow,
> > but there are no locking issues.
> 
> the speedup would be important: even on a 2GHz box reading 10,000
> trace entries takes a couple of seconds.

binary searching should be doable without much extra code, the kallsym
entries are already sorted.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Andi Kleen]

On Fri, Aug 13, 2004 at 02:15:02PM +0200, Ingo Molnar wrote:
> 
> * Andi Kleen <ak@muc.de> wrote:
> 
> > >> Interesting results.  One of the problems is kallsyms_lookup,
> > >> triggered by the printks:
> > >
> > > yeah - kallsyms_lookup does a linear search over thousands of symbols. 
> > > Especially since /proc/latency_trace uses it too it would be worthwile
> > > to implement some sort of binary searching.
> > 
> > Or just stick some cond_sched()s in there. It was designed to be slow,
> > but there are no locking issues.
> 
> the speedup would be important: even on a 2GHz box reading 10,000 trace
> entries takes a couple of seconds.

That's because you're abusing it - it was never designed to process
that much data.

With binary search you would need to backward search to find the stem for the 
stem compression. It's probably doable, but would be a bit ugly I guess.

-Andi

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Andi Kleen <ak@muc.de> wrote:

> > > > yeah - kallsyms_lookup does a linear search over thousands of symbols. 
> > > > Especially since /proc/latency_trace uses it too it would be worthwile
> > > > to implement some sort of binary searching.
> > > 
> > > Or just stick some cond_sched()s in there. It was designed to be slow,
> > > but there are no locking issues.
> > 
> > the speedup would be important: even on a 2GHz box reading 10,000 trace
> > entries takes a couple of seconds.
> 
> That's because you're abusing it - it was never designed to process
> that much data.

i'm not abusing it. Linear searching of 20 thousand symbols is a gross
first-approximation algorithm no matter what. Yes, most users of the
symbols dont care about performance. And i'm not complaining at all, i'm
just pointing out the reason why e.g. printing a simple stack backtrace
can take milliseconds.

> With binary search you would need to backward search to find the stem
> for the stem compression. It's probably doable, but would be a bit
> ugly I guess.

yeah. Maybe someone will find the time to improve the algorithm. But
it's not a highprio thing.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Fri, 2004-08-13 at 06:22, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > Interesting results.  One of the problems is kallsyms_lookup,
> > triggered by the printks:
> 
> yeah - kallsyms_lookup does a linear search over thousands of symbols. 
> Especially since /proc/latency_trace uses it too it would be worthwile
> to implement some sort of binary searching.
> 

Would it be easier to have a mode where the symbols are not resolved,
and would just require the traces to be postprocessed? 

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Fri, 2004-08-13 at 06:31, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > > >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> > 
> > Ugh, this is a bad one:
> > 
> > preemption latency trace v1.0
> > -----------------------------
> >  latency: 506 us, entries: 157 (157)
> >  process: evolution/3461, uid: 1000
> >  nice: 0, policy: 0, rt_priority: 0
> > =======>
> >  0.000ms (+0.000ms): get_random_bytes (__check_and_rekey)
> [...]
> >  0.493ms (+0.001ms): local_bh_enable (__check_and_rekey)
> 
> indeed this is a new one. Entropy rekeying every 300 seconds. Most of
> the overhead comes from the memcpy's - 10 usecs a pop!

Here's another case where those memcpy's hurt.  This was the biggest
latency reported last night:

preemption latency trace v1.0
-----------------------------
 latency: 683 us, entries: 329 (329)
 process: ksoftirqd/0/2, uid: 0
 nice: -10, policy: 0, rt_priority: 0
=======>
 0.000ms (+0.000ms): process_backlog (net_rx_action)
 0.000ms (+0.000ms): netif_receive_skb (process_backlog)
 0.002ms (+0.002ms): packet_rcv_spkt (netif_receive_skb)
 0.003ms (+0.000ms): skb_clone (packet_rcv_spkt)
 0.003ms (+0.000ms): kmem_cache_alloc (skb_clone)
 0.004ms (+0.000ms): memcpy (skb_clone)
 0.006ms (+0.001ms): strlcpy (packet_rcv_spkt)
 0.007ms (+0.001ms): sk_run_filter (packet_rcv_spkt)
 0.010ms (+0.002ms): __kfree_skb (packet_rcv_spkt)
 0.010ms (+0.000ms): kfree_skbmem (__kfree_skb)
 0.010ms (+0.000ms): skb_release_data (kfree_skbmem)
 0.011ms (+0.000ms): kmem_cache_free (kfree_skbmem)
 0.011ms (+0.000ms): ip_rcv (netif_receive_skb)
 0.013ms (+0.001ms): ip_route_input (ip_rcv)
 0.014ms (+0.000ms): rt_hash_code (ip_route_input)
 0.015ms (+0.001ms): ip_route_input_slow (ip_rcv)
 0.017ms (+0.001ms): rt_hash_code (ip_route_input_slow)
 0.018ms (+0.001ms): fn_hash_lookup (ip_route_input_slow)
 0.020ms (+0.001ms): fib_semantic_match (fn_hash_lookup)
 0.022ms (+0.002ms): fib_validate_source (ip_route_input_slow)
 0.023ms (+0.001ms): fn_hash_lookup (fib_validate_source)
 0.024ms (+0.001ms): fn_hash_lookup (fib_validate_source)
 0.026ms (+0.001ms): fib_semantic_match (fn_hash_lookup)
 0.027ms (+0.000ms): __fib_res_prefsrc (fib_validate_source)
 0.027ms (+0.000ms): inet_select_addr (__fib_res_prefsrc)
 0.030ms (+0.002ms): do_IRQ (common_interrupt)
 0.030ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
 0.034ms (+0.003ms): generic_redirect_hardirq (do_IRQ)
 0.034ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
 0.034ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
 0.035ms (+0.000ms): mark_offset_tsc (timer_interrupt)
 0.041ms (+0.005ms): do_timer (timer_interrupt)
 0.041ms (+0.000ms): update_process_times (do_timer)
 0.041ms (+0.000ms): update_one_process (update_process_times)
 0.042ms (+0.000ms): run_local_timers (update_process_times)
 0.042ms (+0.000ms): raise_softirq (update_process_times)
 0.043ms (+0.000ms): scheduler_tick (update_process_times)
 0.043ms (+0.000ms): sched_clock (scheduler_tick)
 0.044ms (+0.001ms): task_timeslice (scheduler_tick)
 0.045ms (+0.000ms): update_wall_time (do_timer)
 0.045ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
 0.046ms (+0.000ms): generic_note_interrupt (do_IRQ)
 0.046ms (+0.000ms): end_8259A_irq (do_IRQ)
 0.046ms (+0.000ms): enable_8259A_irq (do_IRQ)
 0.048ms (+0.001ms): dst_alloc (ip_route_input_slow)
 0.049ms (+0.000ms): kmem_cache_alloc (dst_alloc)
 0.050ms (+0.000ms): cache_alloc_refill (kmem_cache_alloc)
 0.055ms (+0.005ms): rt_intern_hash (ip_route_input_slow)
 0.056ms (+0.001ms): local_bh_enable (rt_intern_hash)
 0.058ms (+0.001ms): ip_local_deliver (ip_rcv)
 0.059ms (+0.001ms): tcp_v4_rcv (ip_local_deliver)
 0.060ms (+0.000ms): tcp_v4_checksum_init (tcp_v4_rcv)
 0.060ms (+0.000ms): skb_checksum (tcp_v4_checksum_init)
 0.065ms (+0.004ms): tcp_v4_do_rcv (tcp_v4_rcv)
 0.066ms (+0.000ms): tcp_v4_hnd_req (tcp_v4_do_rcv)
 0.066ms (+0.000ms): tcp_v4_search_req (tcp_v4_hnd_req)
 0.068ms (+0.002ms): tcp_rcv_state_process (tcp_v4_do_rcv)
 0.069ms (+0.001ms): tcp_v4_conn_request (tcp_rcv_state_process)
 0.070ms (+0.000ms): kmem_cache_alloc (tcp_v4_conn_request)
 0.071ms (+0.000ms): cache_alloc_refill (kmem_cache_alloc)
 0.072ms (+0.001ms): cache_grow (cache_alloc_refill)
 0.073ms (+0.000ms): kmem_flagcheck (cache_grow)
 0.073ms (+0.000ms): kmem_getpages (cache_grow)
 0.073ms (+0.000ms): __get_free_pages (kmem_getpages)
 0.074ms (+0.000ms): __alloc_pages (__get_free_pages)
 0.074ms (+0.000ms): buffered_rmqueue (__alloc_pages)
 0.075ms (+0.000ms): bad_range (buffered_rmqueue)
 0.076ms (+0.000ms): prep_new_page (buffered_rmqueue)
 0.076ms (+0.000ms): zone_statistics (__alloc_pages)
 0.077ms (+0.000ms): alloc_slabmgmt (cache_grow)
 0.077ms (+0.000ms): set_slab_attr (cache_grow)
 0.078ms (+0.000ms): cache_init_objs (cache_grow)
 0.084ms (+0.005ms): tcp_parse_options (tcp_v4_conn_request)
 0.087ms (+0.003ms): secure_tcp_sequence_number (tcp_v4_conn_request)
 0.087ms (+0.000ms): do_gettimeofday (secure_tcp_sequence_number)
 0.088ms (+0.000ms): get_offset_tsc (do_gettimeofday)
 0.089ms (+0.000ms): __check_and_rekey (secure_tcp_sequence_number)
 0.089ms (+0.000ms): get_random_bytes (__check_and_rekey)
 0.090ms (+0.000ms): extract_entropy (get_random_bytes)
 0.091ms (+0.001ms): extract_entropy (extract_entropy)
 0.093ms (+0.001ms): SHATransform (extract_entropy)
 0.093ms (+0.000ms): memcpy (SHATransform)
 0.103ms (+0.009ms): add_entropy_words (extract_entropy)

[...]

 0.572ms (+0.000ms): SHATransform (extract_entropy)
 0.572ms (+0.000ms): memcpy (SHATransform)
 0.581ms (+0.008ms): add_entropy_words (extract_entropy)
 0.582ms (+0.001ms): local_bh_enable (__check_and_rekey)
 0.583ms (+0.000ms): halfMD4Transform (secure_tcp_sequence_number)
 0.584ms (+0.001ms): tcp_v4_send_synack (tcp_v4_conn_request)
 0.585ms (+0.000ms): tcp_v4_route_req (tcp_v4_send_synack)
 0.586ms (+0.001ms): do_IRQ (common_interrupt)
 0.587ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
 0.591ms (+0.004ms): generic_redirect_hardirq (do_IRQ)
 0.592ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
 0.592ms (+0.000ms): rtc_interrupt (generic_handle_IRQ_event)
 0.592ms (+0.000ms): is_hpet_enabled (rtc_interrupt)
 0.596ms (+0.004ms): mod_timer (rtc_interrupt)
 0.597ms (+0.000ms): __mod_timer (rtc_interrupt)
 0.597ms (+0.000ms): internal_add_timer (__mod_timer)
 0.598ms (+0.000ms): __wake_up (rtc_interrupt)
 0.598ms (+0.000ms): __wake_up_common (__wake_up)
 0.599ms (+0.000ms): kill_fasync (rtc_interrupt)
 0.599ms (+0.000ms): generic_note_interrupt (do_IRQ)
 0.599ms (+0.000ms): end_8259A_irq (do_IRQ)
 0.600ms (+0.000ms): enable_8259A_irq (do_IRQ)
 0.601ms (+0.001ms): ip_route_output_flow (tcp_v4_route_req)
 0.602ms (+0.000ms): __ip_route_output_key (ip_route_output_flow)
 0.602ms (+0.000ms): rt_hash_code (__ip_route_output_key)
 0.603ms (+0.000ms): ip_route_output_slow (ip_route_output_flow)
 0.604ms (+0.001ms): ip_dev_find (ip_route_output_slow)
 0.604ms (+0.000ms): fn_hash_lookup (ip_dev_find)
 0.605ms (+0.000ms): fib_semantic_match (fn_hash_lookup)
 0.606ms (+0.000ms): fn_hash_lookup (ip_route_output_slow)
 0.607ms (+0.000ms): fn_hash_lookup (ip_route_output_slow)
 0.607ms (+0.000ms): fib_semantic_match (fn_hash_lookup)
 0.608ms (+0.000ms): fn_hash_select_default (ip_route_output_slow)
 0.610ms (+0.001ms): dst_alloc (ip_route_output_slow)
 0.610ms (+0.000ms): kmem_cache_alloc (dst_alloc)
 0.613ms (+0.002ms): rt_set_nexthop (ip_route_output_slow)
 0.613ms (+0.000ms): memcpy (rt_set_nexthop)
 0.614ms (+0.000ms): rt_hash_code (ip_route_output_slow)
 0.614ms (+0.000ms): rt_intern_hash (ip_route_output_slow)
 0.615ms (+0.000ms): arp_bind_neighbour (rt_intern_hash)
 0.615ms (+0.000ms): neigh_lookup (arp_bind_neighbour)
 0.616ms (+0.000ms): arp_hash (neigh_lookup)
 0.618ms (+0.001ms): local_bh_enable (neigh_lookup)
 0.618ms (+0.000ms): local_bh_enable (rt_intern_hash)
 0.619ms (+0.001ms): tcp_make_synack (tcp_v4_send_synack)
 0.619ms (+0.000ms): sock_wmalloc (tcp_make_synack)
 0.620ms (+0.000ms): alloc_skb (sock_wmalloc)
 0.620ms (+0.000ms): kmem_cache_alloc (alloc_skb)
 0.621ms (+0.000ms): __kmalloc (alloc_skb)
 0.626ms (+0.005ms): ip_build_and_send_pkt (tcp_v4_send_synack)
 0.628ms (+0.001ms): ip_output (ip_build_and_send_pkt)
 0.628ms (+0.000ms): ip_finish_output (ip_build_and_send_pkt)
 0.629ms (+0.000ms): neigh_resolve_output (ip_finish_output)
 0.630ms (+0.000ms): neigh_hh_init (neigh_resolve_output)
 0.631ms (+0.001ms): eth_header (neigh_resolve_output)
 0.632ms (+0.001ms): local_bh_enable (neigh_resolve_output)
 0.633ms (+0.000ms): dev_queue_xmit (neigh_resolve_output)
 0.634ms (+0.001ms): pfifo_fast_enqueue (dev_queue_xmit)
 0.635ms (+0.000ms): qdisc_restart (dev_queue_xmit)
 0.635ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart)
 0.636ms (+0.000ms): dev_queue_xmit_nit (qdisc_restart)
 0.637ms (+0.000ms): skb_clone (dev_queue_xmit_nit)
 0.637ms (+0.000ms): kmem_cache_alloc (skb_clone)
 0.638ms (+0.000ms): memcpy (skb_clone)
 0.639ms (+0.001ms): packet_rcv_spkt (dev_queue_xmit_nit)
 0.639ms (+0.000ms): strlcpy (packet_rcv_spkt)
 0.640ms (+0.000ms): sk_run_filter (packet_rcv_spkt)
 0.641ms (+0.001ms): __kfree_skb (packet_rcv_spkt)
 0.642ms (+0.000ms): kfree_skbmem (__kfree_skb)
 0.642ms (+0.000ms): skb_release_data (kfree_skbmem)
 0.642ms (+0.000ms): kmem_cache_free (kfree_skbmem)
 0.643ms (+0.000ms): rhine_start_tx (qdisc_restart)
 0.646ms (+0.003ms): qdisc_restart (dev_queue_xmit)
 0.646ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart)
 0.647ms (+0.000ms): local_bh_enable (dev_queue_xmit)
 0.648ms (+0.001ms): tcp_v4_synq_add (tcp_v4_conn_request)
 0.649ms (+0.000ms): tcp_reset_keepalive_timer (tcp_v4_synq_add)
 0.649ms (+0.000ms): sk_reset_timer (tcp_reset_keepalive_timer)
 0.650ms (+0.000ms): mod_timer (sk_reset_timer)
 0.650ms (+0.000ms): __mod_timer (sk_reset_timer)
 0.651ms (+0.000ms): internal_add_timer (__mod_timer)
 0.652ms (+0.001ms): init_westwood (tcp_rcv_state_process)
 0.652ms (+0.000ms): init_bictcp (tcp_rcv_state_process)
 0.653ms (+0.000ms): __kfree_skb (tcp_rcv_state_process)
 0.654ms (+0.000ms): kfree_skbmem (__kfree_skb)
 0.654ms (+0.000ms): skb_release_data (kfree_skbmem)
 0.654ms (+0.000ms): kfree (kfree_skbmem)
 0.656ms (+0.001ms): do_IRQ (common_interrupt)
 0.656ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
 0.660ms (+0.004ms): generic_redirect_hardirq (do_IRQ)
 0.661ms (+0.000ms): wake_up_process (generic_redirect_hardirq)
 0.661ms (+0.000ms): try_to_wake_up (wake_up_process)
 0.661ms (+0.000ms): task_rq_lock (try_to_wake_up)
 0.662ms (+0.000ms): activate_task (try_to_wake_up)
 0.662ms (+0.000ms): sched_clock (activate_task)
 0.662ms (+0.000ms): recalc_task_prio (activate_task)
 0.663ms (+0.000ms): effective_prio (recalc_task_prio)
 0.663ms (+0.000ms): enqueue_task (activate_task)
 0.664ms (+0.001ms): kmem_cache_free (kfree_skbmem)
 0.666ms (+0.001ms): check_preempt_timing (touch_preempt_timing)

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

[-- Attachment #1: Type: text/plain, Size: 2156 bytes --]

Ingo Molnar wrote:
>...
> 
>>With binary search you would need to backward search to find the stem
>>for the stem compression. It's probably doable, but would be a bit
>>ugly I guess.
> 
> 
> yeah. Maybe someone will find the time to improve the algorithm. But
> it's not a highprio thing.

Well, I found some time and decided to give it a go :)

I first built a small test program that could provide the same symbol 
data to the lookup function, so that I could test using a user space app.

This way I could benchmark both the original algorithm and any 
improvement I could make, and do it confortably from user space.

The original algorithm took, on average, 1340us per lookup on my P4 
2.8GHz. The compile settings for the test are not the same on the 
kernel, so this can be only compared against other results from the same 
setup.

With the attached patch it takes 14us per lookup. This is almost a 100x 
improvement.

The largest portion of the time it took to do a lookup, was the 
decompression of the symbol names. It seemed a waste of time to keep 
strcpy'ing over the result lots of names that would probably not 
contribute to the final name.

With the strcpy's out, the speed-up was around 5x, but even then, 
looking sequentially for the symbol name was still slow.

The final algorithm pre-calculates markers on the compressed symbols so 
that the search time is almost divided by the number of markers.

There are still a few issues with this approach. The biggest issue is 
that this is clearly a speed/space trade-off, and maybe we don't want to 
waste the space on a code path that is not supposed to be "hot". If this 
is the case, I can make a smaller patch, that fixes just the name 
"decompression" strcpy's.

As always, any comments will be greatly appreciated.


Just one side note: gcc gives a warning about 2 variables that might be 
used before initialization. I know they are not, and it didn't seem a 
good idea to put extra code just to shut up gcc. What is the standard 
way to convince gcc that those vars are ok?

-- 
Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

[-- Attachment #2: patch --]
[-- Type: text/plain, Size: 4396 bytes --]

--- kernel/kallsyms.c.old	2004-08-14 00:28:58.000000000 +0100
+++ kernel/kallsyms.c	2004-08-14 05:10:09.873194752 +0100
@@ -22,6 +22,13 @@ extern char kallsyms_names[] __attribute
 /* Defined by the linker script. */
 extern char _stext[], _etext[], _sinittext[], _einittext[];
 
+/* auxiliary markers to speed up symbol lookup */
+#define KALLSYMS_STEM_MARKS	8
+
+static int kallsyms_stem_mark_idx[KALLSYMS_STEM_MARKS];
+static char *kallsyms_stem_mark[KALLSYMS_STEM_MARKS];
+
+
 static inline int is_kernel_inittext(unsigned long addr)
 {
 	if (addr >= (unsigned long)_sinittext
@@ -56,13 +63,42 @@ unsigned long kallsyms_lookup_name(const
 	return module_kallsyms_lookup_name(name);
 }
 
+/* build markers into the compressed symbol table, so that lookups can be faster */
+static void build_stem_marks(void)
+{
+	char *name = kallsyms_names;
+	int i, mark_cnt;
+
+	unsigned prefix;
+
+	mark_cnt = 0;
+	for (i = 0 ; i < kallsyms_num_syms; i++) { 
+		prefix=*name;
+		if (prefix == 0) {
+			/* if this is the first 0-prefix stem in the desired interval */
+			if(i > (mark_cnt + 1) * (kallsyms_num_syms / (KALLSYMS_STEM_MARKS + 1)) && 
+			   kallsyms_stem_mark_idx[mark_cnt]==0) {
+				kallsyms_stem_mark[mark_cnt] = name;
+				kallsyms_stem_mark_idx[mark_cnt] = i;
+				mark_cnt++;
+				if(mark_cnt >= KALLSYMS_STEM_MARKS) break;
+			}
+		}
+		do {
+			name++;
+		} while(*name);
+		name ++;
+	}
+}
 /* Lookup an address.  modname is set to NULL if it's in the kernel. */
 const char *kallsyms_lookup(unsigned long addr,
 			    unsigned long *symbolsize,
 			    unsigned long *offset,
 			    char **modname, char *namebuf)
 {
-	unsigned long i, best = 0;
+	unsigned long i, last_0idx;
+	unsigned long mark, low, high, mid;
+	char *last_0prefix;
 
 	/* This kernel should never had been booted. */
 	BUG_ON(!kallsyms_addresses);
@@ -72,39 +108,67 @@ const char *kallsyms_lookup(unsigned lon
 
 	if (is_kernel_text(addr) || is_kernel_inittext(addr)) {
 		unsigned long symbol_end;
-		char *name = kallsyms_names;
+		char *name;
 
-		/* They're sorted, we could be clever here, but who cares? */
-		for (i = 0; i < kallsyms_num_syms; i++) {
-			if (kallsyms_addresses[i] > kallsyms_addresses[best] &&
-			    kallsyms_addresses[i] <= addr)
-				best = i;
+		/* do a binary search on the sorted kallsyms_addresses array */
+		low = 0;
+		high = kallsyms_num_syms;
+		while( high-low > 1 ) { 
+			mid = (low + high) / 2;
+			if( kallsyms_addresses[mid] <= addr ) low = mid;
+			else high = mid;
 		}
 
 		/* Grab name */
-		for (i = 0; i <= best; i++) { 
-			unsigned prefix = *name++;
-			strncpy(namebuf + prefix, name, KSYM_NAME_LEN - prefix);
-			name += strlen(name) + 1;
-		}
+		i = 0;
+		name = kallsyms_names;
 
-		/* At worst, symbol ends at end of section. */
-		if (is_kernel_inittext(addr))
-			symbol_end = (unsigned long)_einittext;
-		else
-			symbol_end = (unsigned long)_etext;
+		if(kallsyms_stem_mark_idx[0]==0)
+			build_stem_marks();
+
+		for(mark = 0; mark < KALLSYMS_STEM_MARKS; mark++) {
+			if( low >= kallsyms_stem_mark_idx[mark] ) {
+				i = kallsyms_stem_mark_idx[mark];
+				name = kallsyms_stem_mark[mark];
+			}
+			else break;
+		}
 
-		/* Search for next non-aliased symbol */
-		for (i = best+1; i < kallsyms_num_syms; i++) {
-			if (kallsyms_addresses[i] > kallsyms_addresses[best]) {
-				symbol_end = kallsyms_addresses[i];
-				break;
+		/* find the last stem before the actual symbol that as 0 prefix */
+		unsigned prefix;
+		for (; i <= low; i++) { 
+			prefix=*name;
+			if (prefix == 0) {
+				last_0prefix = name;
+				last_0idx = i;
 			}
+			do {
+				name++;
+			} while(*name);
+			name ++;
 		}
 
-		*symbolsize = symbol_end - kallsyms_addresses[best];
+		/* build the name from there */
+		name = last_0prefix;
+		for (i = last_0idx; i <= low; i++) { 
+			prefix = *name++;
+			strncpy(namebuf + prefix, name, KSYM_NAME_LEN - prefix);
+			name += strlen(name) + 1;
+		}
+
+		if(low == kallsyms_num_syms - 1) {
+			/* At worst, symbol ends at end of section. */
+			if (is_kernel_inittext(addr))
+				symbol_end = (unsigned long)_einittext;
+			else
+				symbol_end = (unsigned long)_etext;
+		}
+		else
+			symbol_end = kallsyms_addresses[low + 1];
+		
+		*symbolsize = symbol_end - kallsyms_addresses[low];
 		*modname = NULL;
-		*offset = addr - kallsyms_addresses[best];
+		*offset = addr - kallsyms_addresses[low];
 		return namebuf;
 	}
 

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Sat, 2004-08-14 at 00:50, Paulo Marques wrote:
> Ingo Molnar wrote:
> >...
> > 
> >>With binary search you would need to backward search to find the stem
> >>for the stem compression. It's probably doable, but would be a bit
> >>ugly I guess.
> > 
> > 
> > yeah. Maybe someone will find the time to improve the algorithm. But
> > it's not a highprio thing.
> 
> Well, I found some time and decided to give it a go :)
> 

I get a few warnings:

  CC      kernel/kallsyms.o
kernel/kallsyms.c: In function `kallsyms_lookup':
kernel/kallsyms.c:99: warning: `last_0idx' might be used uninitialized in this function
kernel/kallsyms.c:101: warning: `last_0prefix' might be used uninitialized in this function

rlrevell@mindpipe:~/cvs/alsa/alsa-driver$ gcc --version
gcc (GCC) 3.3.4 (Debian 1:3.3.4-7)
Copyright (C) 2003 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Paulo Marques <pmarques@grupopie.com> wrote:

> >yeah. Maybe someone will find the time to improve the algorithm. But
> >it's not a highprio thing.
> 
> Well, I found some time and decided to give it a go :)

great, your patch is looking really good!

> The original algorithm took, on average, 1340us per lookup on my P4
> 2.8GHz. The compile settings for the test are not the same on the
> kernel, so this can be only compared against other results from the
> same setup.

ouch. I consider fixing this a quality of implementation issue.

> With the attached patch it takes 14us per lookup. This is almost a
> 100x improvement.

wow! I have tried your patch and /proc/latency_trace now produces
instantaneous output.

> There are still a few issues with this approach. The biggest issue is
> that this is clearly a speed/space trade-off, and maybe we don't want
> to waste the space on a code path that is not supposed to be "hot". If
> this is the case, I can make a smaller patch, that fixes just the name
> "decompression" strcpy's.

your patch doesnt add all that much of code. It adds 288 bytes to .text
and 64 bytes to .data. A typical .config generates 180K of compressed
kallsyms data (with !KALLSYMS_ALL), so your patch increases the kallsyms
overhead by a mere 0.2%. So it's really not an issue - especially since
kallsyms can be disabled in .config. 

i've put your patch into the -O8 patch:

 http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O8

i'd strongly recommend merging this patch upstream as well.

> Just one side note: gcc gives a warning about 2 variables that might
> be used before initialization. I know they are not, and it didn't seem
> a good idea to put extra code just to shut up gcc. What is the
> standard way to convince gcc that those vars are ok?

the standard way is to add the extra initializers. The gcc folks feel
that those rare cases where gcc gets it wrong justify the benefit of
catching lots of real bugs. I've added the extra initialization to -O8.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Florian Schmidt <mista.tapas@gmx.net> wrote:

> This is something i wanted to ask anyways: In one of your first VP
> announcements you mentioned you wanted to eliminate all latencies > 1
> ms. To me it seems, that that goal is pretty much reached [at least i
> don't see any longer ones except for at boot and shutdown]. So the
> question is: What is the lower limit for laterncies that you want to
> hear reports about?

well ... i'm interested in all latencies that are well above the typical
average latencies in the system. E.g. when the average is around 20-30
usecs then reports of 200-300 usecs would be interesting.

there's no hard limit, really. Also, sometimes latencies that are 0.3
msec in the report could be 3 msec if triggered properly. So a seemingly
lower than 1 msec latency can very well pinpoint a problem area.

> WRT mlockall: i tried mlockall'ing 500 megs. This produced a new max
> latency of 299 us. the trace is rather long. This one is with jackd
> running and the one below this is w/o jackd running:

>  0.010ms (+0.000ms): free_page_and_swap_cache (clear_page_tables)
>  0.010ms (+0.000ms): __page_cache_release (clear_page_tables)
>  0.010ms (+0.000ms): free_hot_page (clear_page_tables)

hm, the reason for this one is that clear_page_tables() does all the
freeing in a single uninterrupted critical section covered by
mm->page_table_lock.

This function needs a lock-break i believe. Especially in the
process-exit case (exit_mmap()) the lock seems unjustified - the current
task is the sole owner of a never-to-be-used-again collection of
pagetables.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[James Courtier-Dutton]

Ingo Molnar wrote:
> i've uploaded the latest version of the voluntary-preempt patch:
>      
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> 
<snip>
> reports, suggestions welcome,
> 
> 	Ingo

I used O7.

I have tested this for a day now, and I have noticed problems:
1)
kernel syslog gets a record like this:
 >  (default.hotplug/1470): 121 us critical section violates 100 us 
threshold.
 >   => started at: <kmap_high+0x2b/0x2d0>
 >   => ended at:   <kmap_high+0x1a9/0x2d0>
 >   [<c0105a23>] dump_stack+0x23/0x30
 >   [<c0140d14>] check_preempt_timing+0x184/0x1e0
 >   [<c0140e84>] sub_preempt_count+0x54/0x5d
 >   [<c0152959>] kmap_high+0x1a9/0x2d0
 >   [<c017655a>] copy_strings+0xea/0x230
 >   [<c01766db>] copy_strings_kernel+0x3b/0x50
 >   [<c017840d>] do_execve+0x12d/0x1f0
 >   [<c0103284>] sys_execve+0x44/0x80
 >   [<c0104b95>] sysenter_past_esp+0x52/0x71
and the /proc/latency_trace gets:
 >   preemption latency trace v1.0
 >   -----------------------------
 >    latency: 121 us, entries: 1032 (1032)
 >    process: default.hotplug/1470, uid: 0
 >    nice: -10, policy: 0, rt_priority: 0
 >   =======>
 >    0.000ms (+0.000ms): page_address (kmap_high)
 >    0.000ms (+0.000ms): page_slot (page_address)
 >    0.000ms (+0.000ms): flush_all_zero_pkmaps (kmap_high)
 >    0.000ms (+0.000ms): set_page_address (flush_all_zero_pkmaps)
 >   [...]
 >    0.118ms (+0.000ms): page_slot (set_page_address)
 >    0.118ms (+0.000ms): check_preempt_timing (sub_preempt_count)

Could the patch be adjusted to make the syslog and the 
/proc/latency_trace produce the same output?

2)
I suspect that there is a problem with reiserfs, but when I detect a 
momentary hang in the system(mouse stops moving), no latency_trace appears.

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* James Courtier-Dutton <James@superbug.demon.co.uk> wrote:

> I have tested this for a day now, and I have noticed problems:
> 1)
> kernel syslog gets a record like this:
> >  (default.hotplug/1470): 121 us critical section violates 100 us 
> threshold.

> and the /proc/latency_trace gets:
> >   preemption latency trace v1.0
> >   -----------------------------
> >    latency: 121 us, entries: 1032 (1032)
> >    process: default.hotplug/1470, uid: 0
> >    nice: -10, policy: 0, rt_priority: 0
> >   =======>
> >    0.000ms (+0.000ms): page_address (kmap_high)
> >    0.000ms (+0.000ms): page_slot (page_address)
> >    0.000ms (+0.000ms): flush_all_zero_pkmaps (kmap_high)
> >    0.000ms (+0.000ms): set_page_address (flush_all_zero_pkmaps)

> Could the patch be adjusted to make the syslog and the
> /proc/latency_trace produce the same output?

We cannot include the full trace in the syslog - it's possibly thousands
of lines long.

> 2)
> I suspect that there is a problem with reiserfs, but when I detect a 
> momentary hang in the system(mouse stops moving), no latency_trace appears.

well, the mouse could stop moving for a number of reasons. It's handled
via the X server and if the X server is preempted (for whatever reason)
then the mouse pointer isnt updated.

you could try to change the mouse IRQ to be non-threaded. Also, do you
have kernel_preemption set to 1? It defaults to 0.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Keith Owens]

On Sat, 14 Aug 2004 05:50:50 +0100, 
Paulo Marques <pmarques@grupopie.com> wrote:
>Well, I found some time and decided to give it a go :)

This patch regresses some recent changes to kallsyms which handle
aliased symbols, IOW symbols with the same address.  The speed up is
very good, but it has two problems with repeated addresses.

The binary chop will give different results on different configs.
Depending on the chop, it will pick any one of the aliased symbols, the
previous kallsyms would always pick the first name.  For consistent bug
reports, always report the first symbol from an aliased set.

When calculating the size of a symbol, you must skip the aliased
entries.

Patch over kallsyms-speedup, to handle aliased symbols again.  Also
removes a warning about mixing code and declarations.

Index: linux/kernel/kallsyms.c
===================================================================
--- linux.orig/kernel/kallsyms.c	Sat Aug 14 22:16:06 2004
+++ linux/kernel/kallsyms.c	Sat Aug 14 22:16:04 2004
@@ -107,7 +107,8 @@ const char *kallsyms_lookup(unsigned lon
 	namebuf[0] = 0;
 
 	if (is_kernel_text(addr) || is_kernel_inittext(addr)) {
-		unsigned long symbol_end;
+		unsigned long symbol_end = 0;
+		unsigned prefix;
 		char *name;
 
 		/* do a binary search on the sorted kallsyms_addresses array */
@@ -118,6 +119,7 @@ const char *kallsyms_lookup(unsigned lon
 			if( kallsyms_addresses[mid] <= addr ) low = mid;
 			else high = mid;
 		}
+		while (low && kallsyms_addresses[low-1] == kallsyms_addresses[low]) --low;
 
 		/* Grab name */
 		i = 0;
@@ -135,7 +137,6 @@ const char *kallsyms_lookup(unsigned lon
 		}
 
 		/* find the last stem before the actual symbol that as 0 prefix */
-		unsigned prefix;
 		for (; i <= low; i++) { 
 			prefix=*name;
 			if (prefix == 0) {
@@ -156,15 +157,20 @@ const char *kallsyms_lookup(unsigned lon
 			name += strlen(name) + 1;
 		}
 
-		if(low == kallsyms_num_syms - 1) {
+		/* Search for next non-aliased symbol */
+		for (i = low + 1; i < kallsyms_num_syms; i++) {
+			if (kallsyms_addresses[i] > kallsyms_addresses[low]) {
+				symbol_end = kallsyms_addresses[i];
+				break;
+			}
+		}
+		if (!symbol_end) {
 			/* At worst, symbol ends at end of section. */
 			if (is_kernel_inittext(addr))
 				symbol_end = (unsigned long)_einittext;
 			else
 				symbol_end = (unsigned long)_etext;
 		}
-		else
-			symbol_end = kallsyms_addresses[low + 1];
 		
 		*symbolsize = symbol_end - kallsyms_addresses[low];
 		*modname = NULL;

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[James Courtier-Dutton]

This is just for info, now that we have a nice latency testing tool, we 
might as well collect some useful traces that we can later work on.

Here is a trace showing a latency of 39034us. 
http://www.superbug.demon.co.uk/kernel/

The interesting parts of it are:
0.002ms (+0.000ms): __preempt_spin_lock (schedule)
0.523ms (+0.520ms): do_IRQ (common_interrupt)
...
0.532ms (+0.000ms): end_edge_ioapic_irq (do_IRQ)
0.763ms (+0.230ms): smp_apic_timer_interrupt (apic_timer_interrupt)
...
0.768ms (+0.000ms): preempt_schedule (try_to_wake_up)
1.523ms (+0.754ms): do_IRQ (common_interrupt)
...
1.533ms (+0.000ms): __do_softirq (do_softirq)
1.763ms (+0.229ms): smp_apic_timer_interrupt (apic_timer_interrupt)
...
1.765ms (+0.000ms): __do_softirq (do_softirq)
2.523ms (+0.757ms): do_IRQ (common_interrupt)
...
2.533ms (+0.000ms): do_softirq (do_IRQ)
2.533ms (+0.000ms): __do_softirq (do_softirq)
2.763ms (+0.230ms): smp_apic_timer_interrupt (apic_timer_interrupt)
...

This looks to me to be a bug somewhere. Either in the O7 patch, or in 
the kernel. Surely, do_IRQ should happen quickly, and not take 39ms.

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* James Courtier-Dutton <James@superbug.demon.co.uk> wrote:

> This is just for info, now that we have a nice latency testing tool,
> we might as well collect some useful traces that we can later work on.
> 
> Here is a trace showing a latency of 39034us. 
> http://www.superbug.demon.co.uk/kernel/

> This looks to me to be a bug somewhere. Either in the O7 patch, or in
> the kernel. Surely, do_IRQ should happen quickly, and not take 39ms.

something's wrong indeed. Is this an x86 SMP system? If it's SMP then
please apply the patch below (ontop of -O7), it fixes an SMP false
positive bug in the latency timing code.

the process is looping somewhere. Here are the non-IRQ trace entries:

 0.001ms (+0.000ms): __switch_to (schedule)
 0.002ms (+0.000ms): finish_task_switch (schedule)
 0.002ms (+0.000ms): __preempt_spin_lock (schedule)
... [lots of IRQs] ...
 38.126ms (+0.362ms): preempt_schedule (schedule)
 38.126ms (+0.000ms): sched_clock (schedule)
 38.127ms (+0.000ms): find_next_bit (schedule)
 38.127ms (+0.000ms): task_timeslice (schedule)

this shows that we are looping in __preempt_spin_lock() - most likely
via schedule()'s reqacquire_kernel_lock() code.

i.e. another CPU is holding the big kernel lock and this CPU is looping. 
_but_ this CPU is fully preemptible so the trace produces this false
positive.

	Ingo

--- linux/kernel/sched.c.orig2	
+++ linux/kernel/sched.c	
@@ -4210,7 +4210,9 @@ void __sched __preempt_spin_lock(spinloc
 	do {
 		preempt_enable();
 		while (spin_is_locked(lock)) {
+			preempt_disable();
 			touch_preempt_timing();
+			preempt_enable();
 			cpu_relax();
 		}
 		preempt_disable();
@@ -4229,7 +4231,9 @@ void __sched __preempt_write_lock(rwlock
 	do {
 		preempt_enable();
 		while (rwlock_is_locked(lock)) {
+			preempt_disable();
 			touch_preempt_timing();
+			preempt_enable();
 			cpu_relax();
 		}
 		preempt_disable();

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Andi Kleen]

> The final algorithm pre-calculates markers on the compressed symbols so 
> that the search time is almost divided by the number of markers.

You could do that at compile time (in scripts/kallsyms.c) 

> 
> There are still a few issues with this approach. The biggest issue is 
> that this is clearly a speed/space trade-off, and maybe we don't want to 
> waste the space on a code path that is not supposed to be "hot". If this 
> is the case, I can make a smaller patch, that fixes just the name 
> "decompression" strcpy's.

I'm surprised that using 8 markers helps anything. There should 
be many many more 0 stems than that in a not so big kernel.
Did you actually measure the hit rate of the cache? I bet it is pretty low.

-Andi

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

Ingo Molnar wrote:
> * Paulo Marques <pmarques@grupopie.com> wrote:
> 
> 
>>>yeah. Maybe someone will find the time to improve the algorithm. But
>>>it's not a highprio thing.
>>
>>Well, I found some time and decided to give it a go :)
> 
> 
> great, your patch is looking really good!

Thanks :)

> 
>>The original algorithm took, on average, 1340us per lookup on my P4
>>2.8GHz. The compile settings for the test are not the same on the
>>kernel, so this can be only compared against other results from the
>>same setup.
> 
> 
> ouch. I consider fixing this a quality of implementation issue.
> 
> 
>>With the attached patch it takes 14us per lookup. This is almost a
>>100x improvement.
> 
> 
> wow! I have tried your patch and /proc/latency_trace now produces
> instantaneous output.

Good to ear

>...
> 
> your patch doesnt add all that much of code. It adds 288 bytes to .text
> and 64 bytes to .data. A typical .config generates 180K of compressed
> kallsyms data (with !KALLSYMS_ALL), so your patch increases the kallsyms
> overhead by a mere 0.2%. So it's really not an issue - especially since
> kallsyms can be disabled in .config. 

The 64 bytes of data can be further tuned using the KALLSYMS_STEM_MARKS 
define.

Setting it to 16 instead of 8 will speed up the algorithm by _almost_ 
twice the speed. As the number grows higher, the speed up is less 
noticeable.

>...
> 
> the standard way is to add the extra initializers. The gcc folks feel
> that those rare cases where gcc gets it wrong justify the benefit of
> catching lots of real bugs. I've added the extra initialization to -O8.

Ok, now that I know how it should be done, next time I'll add them myself :)

-- 
Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

Lee Revell wrote:
> On Sat, 2004-08-14 at 00:50, Paulo Marques wrote:
> 
>>Ingo Molnar wrote:
>>
>>>...
>>>
>>>
>>>>With binary search you would need to backward search to find the stem
>>>>for the stem compression. It's probably doable, but would be a bit
>>>>ugly I guess.
>>>
>>>
>>>yeah. Maybe someone will find the time to improve the algorithm. But
>>>it's not a highprio thing.
>>
>>Well, I found some time and decided to give it a go :)
>>
> 
> 
> I get a few warnings:
> 
>   CC      kernel/kallsyms.o
> kernel/kallsyms.c: In function `kallsyms_lookup':
> kernel/kallsyms.c:99: warning: `last_0idx' might be used uninitialized in this function
> kernel/kallsyms.c:101: warning: `last_0prefix' might be used uninitialized in this function
> 
> rlrevell@mindpipe:~/cvs/alsa/alsa-driver$ gcc --version
> gcc (GCC) 3.3.4 (Debian 1:3.3.4-7)
> Copyright (C) 2003 Free Software Foundation, Inc.
> This is free software; see the source for copying conditions.  There is NO
> warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

My original email explained this problem. These warning are harmless 
(although not pretty, for sure), and Ingo corrected them for the O8 
patch (this was only 2 hours after your email :)

-- 
Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

Andi Kleen wrote:
>>The final algorithm pre-calculates markers on the compressed symbols so 
>>that the search time is almost divided by the number of markers.
> 
> 
> You could do that at compile time (in scripts/kallsyms.c) 

You're right! I'll see if I can come up with a patch.

If this is done in scripts/kallsyms.c, there is less code needed in the 
actual kernel, and there is no time penalty on the first lookup. This is 
a true win-win scenario :)

Thanks a lot for your suggestion.

>>There are still a few issues with this approach. The biggest issue is 
>>that this is clearly a speed/space trade-off, and maybe we don't want to 
>>waste the space on a code path that is not supposed to be "hot". If this 
>>is the case, I can make a smaller patch, that fixes just the name 
>>"decompression" strcpy's.
> 
> 
> I'm surprised that using 8 markers helps anything. There should 
> be many many more 0 stems than that in a not so big kernel.
> Did you actually measure the hit rate of the cache? I bet it is pretty low.

Well, I only left in the resulting source code the pieces that I 
actually measured to be a significant improvment.

The thing is, this is not exactly a cache.

The problem that the markers address is that the decompression must be 
done sequentially.

If I have 20000 symbols and already figured out from the binary search 
that I need symbol 11201 (for instance), I would have to go through 
11201 symbols to get to the symbol I need.

The algorithm I wrote keeps markers in the middle of the stream, so that 
when I try to fetch symbol 11201, I already know where symbol 10000 is 
because of the marker and only have to go through 1201 symbols.

With N markers you get N times the speed on the name search. (actually 
this is not exactly right for high values of N, because you can only use 
a marker that is a 0 stem, but for N<~32 this is a good approximation)

-- 
Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Sat, 2004-08-14 at 09:35, Paulo Marques wrote:

> My original email explained this problem. These warning are harmless 
> (although not pretty, for sure), and Ingo corrected them for the O8 
> patch (this was only 2 hours after your email :)

Oops, should have read the whole thing...

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[James Courtier-Dutton]

Ingo Molnar wrote:
> * James Courtier-Dutton <James@superbug.demon.co.uk> wrote:
> 
> 
>>This is just for info, now that we have a nice latency testing tool,
>>we might as well collect some useful traces that we can later work on.
>>
>>Here is a trace showing a latency of 39034us. 
>>http://www.superbug.demon.co.uk/kernel/
> 
> 
>>This looks to me to be a bug somewhere. Either in the O7 patch, or in
>>the kernel. Surely, do_IRQ should happen quickly, and not take 39ms.
> 
> 
> something's wrong indeed. Is this an x86 SMP system? If it's SMP then
> please apply the patch below (ontop of -O7), it fixes an SMP false
> positive bug in the latency timing code.
> 
> the process is looping somewhere. Here are the non-IRQ trace entries:
> 
>  0.001ms (+0.000ms): __switch_to (schedule)
>  0.002ms (+0.000ms): finish_task_switch (schedule)
>  0.002ms (+0.000ms): __preempt_spin_lock (schedule)
> ... [lots of IRQs] ...
>  38.126ms (+0.362ms): preempt_schedule (schedule)
>  38.126ms (+0.000ms): sched_clock (schedule)
>  38.127ms (+0.000ms): find_next_bit (schedule)
>  38.127ms (+0.000ms): task_timeslice (schedule)
> 
> this shows that we are looping in __preempt_spin_lock() - most likely
> via schedule()'s reqacquire_kernel_lock() code.
> 
> i.e. another CPU is holding the big kernel lock and this CPU is looping. 
> _but_ this CPU is fully preemptible so the trace produces this false
> positive.
> 
> 	Ingo
> 

I have not seen that particular problem any more, so I think the patch 
helped.

I have found a new problem though:

# cat latency_trace
preemption latency trace v1.0
-----------------------------
  latency: 1883455195 us, entries: 1 (1)
  process: ksoftirqd/1/5, uid: 0
  nice: -10, policy: 0, rt_priority: 0
=======>
  0.000ms (+0.000ms): cond_resched_softirq (___do_softirq)


That looks bad to me. The user did not notice any latency, but 1883 
seconds seems like a high latency to me!

James

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

Keith Owens wrote:
> On Sat, 14 Aug 2004 05:50:50 +0100, 
> Paulo Marques <pmarques@grupopie.com> wrote:
> 
>>Well, I found some time and decided to give it a go :)
> 
> 
> This patch regresses some recent changes to kallsyms which handle
> aliased symbols, IOW symbols with the same address.  The speed up is
> very good, but it has two problems with repeated addresses.

Oops, I didn't realize that there could be repeated addresses :(

I did a test running 500000 lookups with the original function and my 
own and compared the results from both functions looking for any 
differences. The test program was fed from /proc/kallsyms from my 
machine. Because there were no aliases there, the result was ok and I 
felt confident about the algorithm.

Anyway, at first glance your patch looks right, and I don't think there 
will be any performance implications from it, unless there can be 
thousands of aliases for the same address :)

-- 
Paulo Marques - www.grupopie.com

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Fri, 2004-08-13 at 06:31, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > > >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.8-rc4-O6
> > 
> > Ugh, this is a bad one:
> > 
> > preemption latency trace v1.0
> > -----------------------------
> >  latency: 506 us, entries: 157 (157)
> >  process: evolution/3461, uid: 1000
> >  nice: 0, policy: 0, rt_priority: 0
> > =======>
> >  0.000ms (+0.000ms): get_random_bytes (__check_and_rekey)
> [...]
> >  0.493ms (+0.001ms): local_bh_enable (__check_and_rekey)
> 
> indeed this is a new one. Entropy rekeying every 300 seconds. Most of
> the overhead comes from the memcpy's - 10 usecs a pop!
> 

I have attached a patch that effectively disables extract_entropy.  I am
adding Theodore T'so to the cc: list as he is the author of the code in
question.

For the time being this hack is required to avoid ~0.5 ms
non-preemptible sections caused by the excessive memcpy's in
extract_entropy.

I am not a crypto expert, but it seems like there would be a zero-copy
solution.  Alternatively, a way to tell the system that we just don't
need THAT much entropy would be acceptable.  I would gladly trade
predictable TCP sequence numbers for the ability to do low latency
audio.

Ingo, can you add this to -P3, unless someone proposes a better way?

Lee

--- linux-2.6.8.1/drivers/char/random.c	2004-08-14 06:54:48.000000000 -0400
+++ linux-2.6.8.1-P2/drivers/char/random.c	2004-08-16 19:26:29.000000000 -0400
@@ -1354,6 +1354,8 @@
 static ssize_t extract_entropy(struct entropy_store *r, void * buf,
 			       size_t nbytes, int flags)
 {
+	return nbytes;
+    
 	ssize_t ret, i;
 	__u32 tmp[TMP_BUF_SIZE];
 	__u32 x;

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> I have attached a patch that effectively disables extract_entropy.  I
> am adding Theodore T'so to the cc: list as he is the author of the
> code in question.
> 
> For the time being this hack is required to avoid ~0.5 ms
> non-preemptible sections caused by the excessive memcpy's in
> extract_entropy.

i'm not 100% sure it's the memcpy's - but it's extract_entropy()
overhead. Might be the algorithmic slowness of SHATransform().

> +	return nbytes;
> +    

since this effectively disables the random driver i cannot add it to the
patch.

there's another thing you could try: various SHA_CODE_SIZE values in
drivers/char/random.c. Could you try 1, 2 and 3, does it change the
overhead as seen in the trace?

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Tue, 2004-08-17 at 03:48, Ingo Molnar wrote:
> > +	return nbytes;
> > +    
> 
> since this effectively disables the random driver i cannot add it to the
> patch.
> 

Yes, I figured as much, this is more of a temporary workaround, so we
can continue to identify other issues - otherwise this one shows up
constantly in latency_trace.

> there's another thing you could try: various SHA_CODE_SIZE values in
> drivers/char/random.c. Could you try 1, 2 and 3, does it change the
> overhead as seen in the trace?
> 

Sure, I will test this.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

Keith Owens wrote:
> On Sat, 14 Aug 2004 05:50:50 +0100, 
> Paulo Marques <pmarques@grupopie.com> wrote:
> 
>>Well, I found some time and decided to give it a go :)
> 
> 
> This patch regresses some recent changes to kallsyms which handle
> aliased symbols, IOW symbols with the same address.  The speed up is
> very good, but it has two problems with repeated addresses.

Hi,

I've been messing with scripts/kallsyms.c to try to follow Andi Kleen's 
suggestion of calculating the markers at compile time. This would make 
the code in kernel/kallsyms.c much simpler.

In the process I could get rid of the aliased symbols at compile time 
also. There are only 2 places where they might matter:

  - the kallsyms_lookup_name function. GREP'ing through the code shows 
that this function is only used in arch/ppc64/xmon/xmon.c. Does xmon 
need to know about aliased symbols?

  - /proc/kallsyms. Of course this is a problem, because since this is 
available in user space we can break applications that rely on having 
aliased symbols there. Are there any?

I have no problem in keeping the aliased symbols as the code to handle 
them is not that big anyway. Is just that it hurts my programmer 
instincts to leave completely useless code hanging around. If it is not 
completely useless, then it's another story :)

Any comments will be greatly appreciated,

-- 
Paulo Marques - www.grupopie.com

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Keith Owens]

On Tue, 17 Aug 2004 13:14:32 +0100, 
Paulo Marques <pmarques@grupopie.com> wrote:
>Keith Owens wrote:
>> On Sat, 14 Aug 2004 05:50:50 +0100, 
>> Paulo Marques <pmarques@grupopie.com> wrote:
>> 
>>>Well, I found some time and decided to give it a go :)
>> 
>> 
>> This patch regresses some recent changes to kallsyms which handle
>> aliased symbols, IOW symbols with the same address.  The speed up is
>> very good, but it has two problems with repeated addresses.
>
>Hi,
>
>I've been messing with scripts/kallsyms.c to try to follow Andi Kleen's 
>suggestion of calculating the markers at compile time. This would make 
>the code in kernel/kallsyms.c much simpler.
>
>In the process I could get rid of the aliased symbols at compile time 
>also. There are only 2 places where they might matter:
>
>  - the kallsyms_lookup_name function. GREP'ing through the code shows 
>that this function is only used in arch/ppc64/xmon/xmon.c. Does xmon 
>need to know about aliased symbols?

kdb uses aliased symbols as well.  The user can enter any kernel symbol
name and have it converted to an address.

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

Keith Owens wrote:
> On Tue, 17 Aug 2004 13:14:32 +0100, 
> Paulo Marques <pmarques@grupopie.com> wrote:
> 
>>Keith Owens wrote:
>>
>>>On Sat, 14 Aug 2004 05:50:50 +0100, 
>>>Paulo Marques <pmarques@grupopie.com> wrote:
>>>
>>>
>>>>Well, I found some time and decided to give it a go :)
>>>
>>>
>>>This patch regresses some recent changes to kallsyms which handle
>>>aliased symbols, IOW symbols with the same address.  The speed up is
>>>very good, but it has two problems with repeated addresses.
>>
>>Hi,
>>
>>I've been messing with scripts/kallsyms.c to try to follow Andi Kleen's 
>>suggestion of calculating the markers at compile time. This would make 
>>the code in kernel/kallsyms.c much simpler.
>>
>>In the process I could get rid of the aliased symbols at compile time 
>>also. There are only 2 places where they might matter:
>>
>> - the kallsyms_lookup_name function. GREP'ing through the code shows 
>>that this function is only used in arch/ppc64/xmon/xmon.c. Does xmon 
>>need to know about aliased symbols?
> 
> 
> kdb uses aliased symbols as well.  The user can enter any kernel symbol
> name and have it converted to an address.

Ok, I'll leave them alone, then.

Just another quick question: is kallsyms_names only used by the 
functions in kallsyms.c and everyone else simply uses those functions, 
or are there direct users of kallsyms_names?

This is because another thing I was pondering was to change the stem 
compression scheme into a different one, changing all the stuff in 
kallsyms.c accordingly. If there are direct users of kallsyms_names, 
this would break them. There are none in the vanilla kernel as far as I 
can grep, but there might be outside (like in kdb).

I've done some tests with a different scheme and my uncompressed 170kb 
symbol table goes to about 134kb with stem compression and to about 90kb 
with the new scheme. This is not usable right now because compression 
still takes a long time (although the decompression inside 
kernel/kallsyms.c is even simpler than it is now). I'm now trying to 
speed up compression.

As always, comments will be greatly appreciated :)

-- 
Paulo Marques - www.grupopie.com

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Sam Ravnborg]

On Tue, Aug 17, 2004 at 03:02:18PM +0100, Paulo Marques wrote:
> >
> >kdb uses aliased symbols as well.  The user can enter any kernel symbol
> >name and have it converted to an address.
> 
> Ok, I'll leave them alone, then.
> 
> Just another quick question: is kallsyms_names only used by the 
> functions in kallsyms.c and everyone else simply uses those functions, 
> or are there direct users of kallsyms_names?
> 
> This is because another thing I was pondering was to change the stem 
> compression scheme into a different one, changing all the stuff in 
> kallsyms.c accordingly. If there are direct users of kallsyms_names, 
> this would break them. There are none in the vanilla kernel as far as I 
> can grep, but there might be outside (like in kdb).
> 
> I've done some tests with a different scheme and my uncompressed 170kb 
> symbol table goes to about 134kb with stem compression and to about 90kb 
> with the new scheme. This is not usable right now because compression 
> still takes a long time (although the decompression inside 
> kernel/kallsyms.c is even simpler than it is now). I'm now trying to 
> speed up compression.
> 
> As always, comments will be greatly appreciated :)

Hi Paulo.

kallsyms_names should only be used by kallsyms, so there
are no issue changing this interface.
That said do not put too much effort moving kode from the kernel to
kallsyms.c. kallsyms support can be deselected, and users will not
care about the little extra overhead (down in noise compared
with the symbols).
Keeping the data passed in from the build tools as simple as possible
is the better goal here. Then the kernel can implement the extra
code to optimize speed.



kallsyms parses the output of objdump as does other tools in the kernel.
Would you be willing to look into an elf-tool for the kernel?

A consistent output from an Elf-tool is preferred as replacement
for the hacking needed to use output from objdump and nm.
See arch/sparc/boot/btfixup as a horrid example.

objdump and nm has been optimised for human readable output,
and is not easy to parse up for various tricky usage.

Rusty Russell's module-init-tools has some good starting stuff.

PS. Please cc: me on future patches in this area - thanks.

	Sam

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* Sam Ravnborg <sam@ravnborg.org> wrote:

> That said do not put too much effort moving kode from the kernel to
> kallsyms.c. kallsyms support can be deselected, and users will not
> care about the little extra overhead (down in noise compared with the
> symbols).

distributions tend to enable it though, so saving 64K of kernel RAM is 
good indeed. Good compression of the symbols increases the applicability 
of kallsyms.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Paulo Marques]

Ingo Molnar wrote:
> * Sam Ravnborg <sam@ravnborg.org> wrote:
> 
> 
>>That said do not put too much effort moving kode from the kernel to
>>kallsyms.c. kallsyms support can be deselected, and users will not
>>care about the little extra overhead (down in noise compared with the
>>symbols).

I know I'm probably putting to much effort on a low priority task 
(understatement of the year), but I was having fun doing it, so I saw no 
reason to stop :)

The new algorithm that I was thinking about is quite simple from the 
kernel point of view. It takes advantage of the fact that not all 
characters are allowed on symbols.

It uses these extra chars to feed a table that maps "special unused 
char"->"small string". For instance, it can say char \x85 is in fact 
"write_". Interesting enough the best string on my test data is "acpi_", 
and saves about 3kb of data to map it to just one char :)

So the work in the kernel is quite easy, and I believe it will in fact 
be faster than now, using less code.

The real problem is that the algorithm has to give the best strings to 
use in the table fast enough as to not be noticed in the total kernel 
compile time. Selecting the best strings is a really interesting problem 
from a mathematical point of view, and I was trying to solve it just for 
the fun of doing it :)

> distributions tend to enable it though, so saving 64K of kernel RAM is 
> good indeed. Good compression of the symbols increases the applicability 
> of kallsyms.

I'm glad you also found this scheme to be useful.

The code might be useful on other situations where we need to compress 
english text (or something like that) in a way that uncompressing a 
small string is quite fast. (I remember a thread a long time ago about 
compressing all the printk texts in the kernel, so maybe this could be 
useful there too)

-- 
Paulo Marques - www.grupopie.com

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Theodore Ts'o]

On Tue, Aug 17, 2004 at 09:48:26AM +0200, Ingo Molnar wrote:
> > +	return nbytes;
> > +    
> 
> since this effectively disables the random driver i cannot add it to the
> patch.

The problem isn't extract_entropy(), as much as the fact that we're
calling it from check_and_rekey(), which in turn is being called by
the secure TCP sequence number generation code.  If you are looking
for a more localized way of getting rid of the probably while
minimizing the amount of code that's being disabled, you can simply do
this instead:

--- random.c	2004-08-09 02:26:29 -0400
+++ random.c.new	2004-08-17 14:04:56 -0400
@@ -2207,7 +2207,8 @@
 #undef K3
 
 /* This should not be decreased so low that ISNs wrap too fast. */
-#define REKEY_INTERVAL	300
+#define REKEY_INTERVAL	((time_t) -1)
+
 /*
  * Bit layout of the tcp sequence numbers (before adding current time):
  * bit 24-31: increased after every key exchange

WARNING: this will effectively disable the secure TCP sequence
generation, thus making your system more vulnerable to TCP hijacking
attacks --- but if you cared about such attacks, you'd be using Real
Crypto in your application progams anyway...

> there's another thing you could try: various SHA_CODE_SIZE values in
> drivers/char/random.c. Could you try 1, 2 and 3, does it change the
> overhead as seen in the trace?

I doubt SHA_CODE_SIZE will make a sufficient difference to avoid the
latency problems.  What we would need to do is to change the code so
that the rekey operation in __check_and_rekey takes place in a
workqueue.  Say, something like this (warning, I haven't tested this
patch; if it breaks, you get to keep both pieces):

===== drivers/char/random.c 1.45 vs edited =====
--- 1.45/drivers/char/random.c	2004-08-08 02:43:40 -04:00
+++ edited/drivers/char/random.c	2004-08-17 15:15:57 -04:00
@@ -2241,30 +2241,35 @@
 static spinlock_t ip_lock = SPIN_LOCK_UNLOCKED;
 static unsigned int ip_cnt;
 
-static struct keydata *__check_and_rekey(time_t time)
+static void rekey_seq_generator(void *private_)
 {
 	struct keydata *keyptr;
+	struct timeval 	tv;
+
+	do_gettimeofday(&tv);
+
 	spin_lock_bh(&ip_lock);
 	keyptr = &ip_keydata[ip_cnt&1];
-	if (!keyptr->rekey_time || (time - keyptr->rekey_time) > REKEY_INTERVAL) {
-		keyptr = &ip_keydata[1^(ip_cnt&1)];
-		keyptr->rekey_time = time;
-		get_random_bytes(keyptr->secret, sizeof(keyptr->secret));
-		keyptr->count = (ip_cnt&COUNT_MASK)<<HASH_BITS;
-		mb();
-		ip_cnt++;
-	}
+
+	keyptr = &ip_keydata[1^(ip_cnt&1)];
+	keyptr->rekey_time = tv.tv_sec;
+	get_random_bytes(keyptr->secret, sizeof(keyptr->secret));
+	keyptr->count = (ip_cnt&COUNT_MASK)<<HASH_BITS;
+	mb();
+	ip_cnt++;
+
 	spin_unlock_bh(&ip_lock);
-	return keyptr;
 }
 
+static DECLARE_WORK(rekey_work, rekey_seq_generator, NULL);
+
 static inline struct keydata *check_and_rekey(time_t time)
 {
 	struct keydata *keyptr = &ip_keydata[ip_cnt&1];
 
 	rmb();
 	if (!keyptr->rekey_time || (time - keyptr->rekey_time) > REKEY_INTERVAL) {
-		keyptr = __check_and_rekey(time);
+		schedule_work(&rekey_work);
 	}
 
 	return keyptr;

						- Ted

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* James Courtier-Dutton <James@superbug.demon.co.uk> wrote:

> Could the patch be adjusted to make the syslog and the
> /proc/latency_trace produce the same output?

to further unify the formats i've added the start/end entries to
latency_trace in -P4. Saving the stacktrace would be too much trouble
though.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Ingo Molnar]

* James Courtier-Dutton <James@superbug.demon.co.uk> wrote:

> I have found a new problem though:
> 
> # cat latency_trace
> preemption latency trace v1.0
> -----------------------------
>  latency: 1883455195 us, entries: 1 (1)
>  process: ksoftirqd/1/5, uid: 0
>  nice: -10, policy: 0, rt_priority: 0
> =======>
>  0.000ms (+0.000ms): cond_resched_softirq (___do_softirq)
> 
> That looks bad to me. The user did not notice any latency, but 1883
> seconds seems like a high latency to me!

yeah, it doesnt look healthy. This could be some sort of tracing
underflow - what is the 'grep MHz /proc/cpuinfo' value of your box?

Also, could you try the -P4 patch, it has a more robust timestamping
mechanism.

	Ingo

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Tue, 2004-08-17 at 15:18, Theodore Ts'o wrote:
> On Tue, Aug 17, 2004 at 09:48:26AM +0200, Ingo Molnar wrote:
> > there's another thing you could try: various SHA_CODE_SIZE values in
> > drivers/char/random.c. Could you try 1, 2 and 3, does it change the
> > overhead as seen in the trace?
> 
> I doubt SHA_CODE_SIZE will make a sufficient difference to avoid the
> latency problems.

Correct, the difference is less than 50%.  I will try the patch.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Tue, 2004-08-17 at 15:18, Theodore Ts'o wrote:
> On Tue, Aug 17, 2004 at 09:48:26AM +0200, Ingo Molnar wrote:
> > > +	return nbytes;
> > > +    
> > 
> > since this effectively disables the random driver i cannot add it to the
> > patch.
> 
> I doubt SHA_CODE_SIZE will make a sufficient difference to avoid the
> latency problems.  What we would need to do is to change the code so
> that the rekey operation in __check_and_rekey takes place in a
> workqueue.  Say, something like this (warning, I haven't tested this
> patch; if it breaks, you get to keep both pieces):
> 

Tested, works for me.  This should probably be pushed upstream, as well
as added to -P5, correct?  Is there any disadvantage to doing it this
way?

Lee  

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Theodore Ts'o]

On Thu, Aug 19, 2004 at 07:19:58AM -0400, Lee Revell wrote:
> > I doubt SHA_CODE_SIZE will make a sufficient difference to avoid the
> > latency problems.  What we would need to do is to change the code so
> > that the rekey operation in __check_and_rekey takes place in a
> > workqueue.  Say, something like this (warning, I haven't tested this
> > patch; if it breaks, you get to keep both pieces):
> > 
> 
> Tested, works for me.  This should probably be pushed upstream, as well
> as added to -P5, correct?  Is there any disadvantage to doing it this
> way?

Great, I will be pushing this upstream very shortly.

						- Ted

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-19 at 15:30, Theodore Ts'o wrote:
> On Thu, Aug 19, 2004 at 07:19:58AM -0400, Lee Revell wrote:
> > > I doubt SHA_CODE_SIZE will make a sufficient difference to avoid the
> > > latency problems.  What we would need to do is to change the code so
> > > that the rekey operation in __check_and_rekey takes place in a
> > > workqueue.  Say, something like this (warning, I haven't tested this
> > > patch; if it breaks, you get to keep both pieces):
> > > 
> > 
> > Tested, works for me.  This should probably be pushed upstream, as well
> > as added to -P5, correct?  Is there any disadvantage to doing it this
> > way?
> 
> Great, I will be pushing this upstream very shortly.
> 

Hmm, turns out that this does not fix the problem:

http://krustophenia.net/testresults.php?dataset=2.6.8.1-P4#/var/www/2.6.8.1-P4/extract_entropy_latency_trace.txt

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-19 at 18:32, Lee Revell wrote:
> On Thu, 2004-08-19 at 15:30, Theodore Ts'o wrote:
> > On Thu, Aug 19, 2004 at 07:19:58AM -0400, Lee Revell wrote:
> > > > I doubt SHA_CODE_SIZE will make a sufficient difference to avoid the
> > > > latency problems.  What we would need to do is to change the code so
> > > > that the rekey operation in __check_and_rekey takes place in a
> > > > workqueue.  Say, something like this (warning, I haven't tested this
> > > > patch; if it breaks, you get to keep both pieces):
> > > > 
> > > 
> > > Tested, works for me.  This should probably be pushed upstream, as well
> > > as added to -P5, correct?  Is there any disadvantage to doing it this
> > > way?
> > 
> > Great, I will be pushing this upstream very shortly.
> > 
> 
> Hmm, turns out that this does not fix the problem:
> 
> http://krustophenia.net/testresults.php?dataset=2.6.8.1-P4#/var/www/2.6.8.1-P4/extract_entropy_latency_trace.txt
> 

Looking at the code, it's obvious why this doesn't fix the problem - you
are still doing 380 usecs (with SHA_CODE_SIZE 3) to 780 usecs (with
SHA_CODE_SIZE 0) worth of work inside the spinlock, it is just being
deferred via a workqueue, rather than executing right away.  So this
improves the average case, but does not help the worst case scenario at
all.  380 usecs is too long to hold a spinlock.

Lee

Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

[Lee Revell]

On Thu, 2004-08-19 at 18:32, Lee Revell wrote:
> On Thu, 2004-08-19 at 15:30, Theodore Ts'o wrote:
> > On Thu, Aug 19, 2004 at 07:19:58AM -0400, Lee Revell wrote:
> > > > I doubt SHA_CODE_SIZE will make a sufficient difference to avoid the
> > > > latency problems.  What we would need to do is to change the code so
> > > > that the rekey operation in __check_and_rekey takes place in a
> > > > workqueue.  Say, something like this (warning, I haven't tested this
> > > > patch; if it breaks, you get to keep both pieces):
> > > > 
> > > 
> > > Tested, works for me.  This should probably be pushed upstream, as well
> > > as added to -P5, correct?  Is there any disadvantage to doing it this
> > > way?
> > 
> > Great, I will be pushing this upstream very shortly.
> > 
> 
> Hmm, turns out that this does not fix the problem:
> 

Here is another new one:

http://krustophenia.net/testresults.php?dataset=2.6.8.1-P4#/var/www/2.6.8.1-P4/kswapd_refill_inactive_zone_latency_trace.txt

Lee