From mboxrd@z Thu Jan  1 00:00:00 1970
From: mingo@elte.hu (Ingo Molnar)
Date: Tue, 24 Mar 2009 19:33:13 +0100
Subject: [ltt-dev] [patch 7/9] LTTng instrumentation - kernel
In-Reply-To: <20090324160148.872305963@polymtl.ca>
References: <20090324155625.420966314@polymtl.ca>
	<20090324160148.872305963@polymtl.ca>
Message-ID: <20090324183313.GH31117@elte.hu>


(Rusty Cc:-ed - for the module.c tracepoints below)

* Mathieu Desnoyers <mathieu.desnoyers at 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 at polymtl.ca>
> CC: 'Ingo Molnar' <mingo at elte.hu>
> CC: Frederic Weisbecker <fweisbec at gmail.com>
> CC: Andrew Morton <akpm at linux-foundation.org>
> CC: Masami Hiramatsu <mhiramat at redhat.com>
> CC: 'Peter Zijlstra' <peterz at infradead.org>
> CC: "Frank Ch. Eigler" <fche at redhat.com>
> CC: 'Hideo AOKI' <haoki at redhat.com>
> CC: Takashi Nishiie <t-nishiie at np.css.fujitsu.com>
> CC: 'Steven Rostedt' <rostedt at goodmis.org>
> CC: Eduard - Gabriel Munteanu <eduard.munteanu at 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?

> 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