Re: [patch 7/9] LTTng instrumentation - kernel

[Frederic Weisbecker <fweisbec@gmail.com>]

On Tue, Mar 24, 2009 at 07:33:13PM +0100, Ingo Molnar wrote:
> 
> (Rusty Cc:-ed - for the module.c tracepoints below)
> 
> * Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca> wrote:
> 
> > Instrument the core kernel : module load/free and printk events. It helps the
> > tracer to keep track of module related events and to export valuable printk
> > information into the traces.
> > 
> > Those tracepoints are used by LTTng.
> > 
> > About the performance impact of tracepoints (which is comparable to markers),
> > even without immediate values optimizations, tests done by Hideo Aoki on ia64
> > show no regression. His test case was using hackbench on a kernel where
> > scheduler instrumentation (about 5 events in code scheduler code) was added.
> > See the "Tracepoints" patch header for performance result detail.
> > 
> > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
> > CC: 'Ingo Molnar' <mingo@elte.hu>
> > CC: Frederic Weisbecker <fweisbec@gmail.com>
> > CC: Andrew Morton <akpm@linux-foundation.org>
> > CC: Masami Hiramatsu <mhiramat@redhat.com>
> > CC: 'Peter Zijlstra' <peterz@infradead.org>
> > CC: "Frank Ch. Eigler" <fche@redhat.com>
> > CC: 'Hideo AOKI' <haoki@redhat.com>
> > CC: Takashi Nishiie <t-nishiie@np.css.fujitsu.com>
> > CC: 'Steven Rostedt' <rostedt@goodmis.org>
> > CC: Eduard - Gabriel Munteanu <eduard.munteanu@linux360.ro>
> > ---
> >  include/trace/kernel.h |   19 +++++++++++++++++++
> >  kernel/module.c        |    8 ++++++++
> >  kernel/printk.c        |    7 +++++++
> >  3 files changed, 34 insertions(+)
> > 
> > Index: linux-2.6-lttng/kernel/printk.c
> > ===================================================================
> > --- linux-2.6-lttng.orig/kernel/printk.c	2009-03-24 09:09:52.000000000 -0400
> > +++ linux-2.6-lttng/kernel/printk.c	2009-03-24 09:31:53.000000000 -0400
> > @@ -32,6 +32,7 @@
> >  #include <linux/security.h>
> >  #include <linux/bootmem.h>
> >  #include <linux/syscalls.h>
> > +#include <trace/kernel.h>
> >  
> >  #include <asm/uaccess.h>
> >  
> > @@ -59,6 +60,7 @@ int console_printk[4] = {
> >  	MINIMUM_CONSOLE_LOGLEVEL,	/* minimum_console_loglevel */
> >  	DEFAULT_CONSOLE_LOGLEVEL,	/* default_console_loglevel */
> >  };
> > +EXPORT_SYMBOL_GPL(console_printk);
> >  
> >  /*
> >   * Low level drivers may need that to know if they can schedule in
> > @@ -128,6 +130,9 @@ EXPORT_SYMBOL(console_set_on_cmdline);
> >  /* Flag: console code may call schedule() */
> >  static int console_may_schedule;
> >  
> > +DEFINE_TRACE(kernel_printk);
> > +DEFINE_TRACE(kernel_vprintk);
> > +
> >  #ifdef CONFIG_PRINTK
> >  
> >  static char __log_buf[__LOG_BUF_LEN];
> > @@ -560,6 +565,7 @@ asmlinkage int printk(const char *fmt, .
> >  	int r;
> >  
> >  	va_start(args, fmt);
> > +	trace_kernel_printk(_RET_IP_);
> >  	r = vprintk(fmt, args);
> >  	va_end(args);
> >
> > @@ -667,6 +673,7 @@ asmlinkage int vprintk(const char *fmt, 
> >  	printed_len += vscnprintf(printk_buf + printed_len,
> >  				  sizeof(printk_buf) - printed_len, fmt, args);
> >  
> > +	trace_kernel_vprintk(_RET_IP_, printk_buf, printed_len);
> 
> So here we pass in the formatted output. What sense does it make to 
> have the above printk tracepoint? Little i think.
> 
> Also, i'm not entirely convinced about the wiseness of instrumenting 
> an essential debug facility like printk(). Lets keep this one at the 
> tail portion of the patch-queue, ok?


Especially the trace_kernel_printk hook which only probes the printk callers.
I don't think a performance measurement of a printk call in that relevant.

Concerning trace_kernel_vprintk(), if the goal is to capture the printk messages,
I would rather see it through the dynamic printk facility or setting a console which
route printk output to trace_printk(). If that is useful for someone.

Thanks,
Frederic.

 
> > Index: linux-2.6-lttng/kernel/module.c
> > ===================================================================
> > --- linux-2.6-lttng.orig/kernel/module.c	2009-03-24 09:09:59.000000000 -0400
> > +++ linux-2.6-lttng/kernel/module.c	2009-03-24 09:31:53.000000000 -0400
> > @@ -51,6 +51,7 @@
> >  #include <linux/tracepoint.h>
> >  #include <linux/ftrace.h>
> >  #include <linux/async.h>
> > +#include <trace/kernel.h>
> >  
> >  #if 0
> >  #define DEBUGP printk
> > @@ -78,6 +79,9 @@ static BLOCKING_NOTIFIER_HEAD(module_not
> >  /* Bounds of module allocation, for speeding __module_text_address */
> >  static unsigned long module_addr_min = -1UL, module_addr_max = 0;
> >  
> > +DEFINE_TRACE(kernel_module_load);
> > +DEFINE_TRACE(kernel_module_free);
> 
> I believe that to have a complete picture of module usage, module 
> refcount get/put events should be included as well, beyond the basic 
> load/free events.
> 
> These both have performance impact (a module get/put in a fastpath 
> hurts scalability), and are informative in terms of establishing the 
> module dependency graph.
> 
> Another thing that is iteresting and which is not covered here are 
> module request events and usermode helper callouts. These too have 
> instrumentation and performance analysis uses.
> 
> Plus, here too it would be desired to put in default probes as well, 
> via TRACE_EVENT().
> 
> Thanks,
> 
> 	Ingo