All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH] tracing: add trace console
@ 2011-11-16 10:18 Johannes Berg
  2011-11-16 14:15 ` Steven Rostedt
  2011-11-16 15:10 ` [PATCH] " Christoph Hellwig
  0 siblings, 2 replies; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 10:18 UTC (permalink / raw)
  To: LKML; +Cc: Steven Rostedt, Frederic Weisbecker, Ingo Molnar

From: Johannes Berg <johannes.berg@intel.com>

As described in the Kconfig entry, logging printk
output is useful to correlate (existing) printk
debugging with (existing) tracing. The easiest way
to achieve this is to register a console that just
calls trace_printk(), which this module does.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
 kernel/trace/Kconfig         |   13 ++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 70 insertions(+)

--- a/kernel/trace/Kconfig	2011-11-16 11:11:27.000000000 +0100
+++ b/kernel/trace/Kconfig	2011-11-16 11:11:35.000000000 +0100
@@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
 
 	  If unsure, say N.
 
+config TRACE_CONSOLE
+	tristate "Support for a tracing console"
+	help
+	  Say M (or Y if you must, but this is not recommended) to be able
+	  to get a tracing console that puts every kernel message into the
+	  tracing infrastructure using trace_printk(). This is useful to
+	  correlate (existing) printk debugging with tracing. When using it
+	  remember to set the console level, e.g. with "dmesg -n8".
+
+	  The module is called trace-console.
+
+	  Say N if unsure.
+
 config KPROBE_EVENT
 	depends on KPROBES
 	depends on HAVE_REGS_AND_STACK_ACCESS_API
--- a/kernel/trace/Makefile	2011-11-16 11:11:27.000000000 +0100
+++ b/kernel/trace/Makefile	2011-11-16 11:11:35.000000000 +0100
@@ -62,4 +62,6 @@ ifeq ($(CONFIG_TRACING),y)
 obj-$(CONFIG_KGDB_KDB) += trace_kdb.o
 endif
 
+obj-$(CONFIG_TRACE_CONSOLE) += trace-console.o
+
 libftrace-y := ftrace.o
--- /dev/null	1970-01-01 00:00:00.000000000 +0000
+++ b/kernel/trace/trace-console.c	2011-11-16 11:11:35.000000000 +0100
@@ -0,0 +1,55 @@
+/*
+ * Copyright (c) 2011 Intel Corporation. All rights reserved.
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ *
+ * The full GNU General Public License is included in this distribution in
+ * the file called COPYING.
+ *
+ * Author: Johannes Berg <johannes.berg@intel.com>
+ */
+#include <linux/init.h>
+#include <linux/module.h>
+#include <linux/console.h>
+
+MODULE_AUTHOR("Johannes Berg <johannes.berg@intel.com>");
+MODULE_DESCRIPTION("Console driver for tracing");
+MODULE_LICENSE("GPL");
+
+
+static void trace_msg(struct console *con, const char *msg, unsigned int len)
+{
+	trace_printk("%*s", len, msg);
+}
+
+static struct console traceconsole = {
+	.name	= "tracecon",
+	.flags	= CON_ENABLED,
+	.write	= trace_msg,
+};
+
+static int __init init_traceconsole(void)
+{
+	register_console(&traceconsole);
+	return 0;
+}
+
+static void __exit exit_traceconsole(void)
+{
+	unregister_console(&traceconsole);
+}
+
+module_init(init_traceconsole);
+module_exit(exit_traceconsole);



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 10:18 [PATCH] tracing: add trace console Johannes Berg
@ 2011-11-16 14:15 ` Steven Rostedt
  2011-11-16 14:25   ` Peter Zijlstra
                     ` (3 more replies)
  2011-11-16 15:10 ` [PATCH] " Christoph Hellwig
  1 sibling, 4 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 14:15 UTC (permalink / raw)
  To: Johannes Berg
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Thomas Gleixner, Andrew Morton

[ Added Peter, Thomas and Andrew ]

On Wed, 2011-11-16 at 11:18 +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> As described in the Kconfig entry, logging printk
> output is useful to correlate (existing) printk
> debugging with (existing) tracing. The easiest way
> to achieve this is to register a console that just
> calls trace_printk(), which this module does.

I'm good with this. Anyone have any issues with it?

-- Steve

> 
> Signed-off-by: Johannes Berg <johannes.berg@intel.com>
> ---
>  kernel/trace/Kconfig         |   13 ++++++++++
>  kernel/trace/Makefile        |    2 +
>  kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
>  3 files changed, 70 insertions(+)
> 
> --- a/kernel/trace/Kconfig	2011-11-16 11:11:27.000000000 +0100
> +++ b/kernel/trace/Kconfig	2011-11-16 11:11:35.000000000 +0100
> @@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
>  
>  	  If unsure, say N.
>  
> +config TRACE_CONSOLE
> +	tristate "Support for a tracing console"
> +	help
> +	  Say M (or Y if you must, but this is not recommended) to be able
> +	  to get a tracing console that puts every kernel message into the
> +	  tracing infrastructure using trace_printk(). This is useful to
> +	  correlate (existing) printk debugging with tracing. When using it
> +	  remember to set the console level, e.g. with "dmesg -n8".
> +
> +	  The module is called trace-console.
> +
> +	  Say N if unsure.
> +
>  config KPROBE_EVENT
>  	depends on KPROBES
>  	depends on HAVE_REGS_AND_STACK_ACCESS_API
> --- a/kernel/trace/Makefile	2011-11-16 11:11:27.000000000 +0100
> +++ b/kernel/trace/Makefile	2011-11-16 11:11:35.000000000 +0100
> @@ -62,4 +62,6 @@ ifeq ($(CONFIG_TRACING),y)
>  obj-$(CONFIG_KGDB_KDB) += trace_kdb.o
>  endif
>  
> +obj-$(CONFIG_TRACE_CONSOLE) += trace-console.o
> +
>  libftrace-y := ftrace.o
> --- /dev/null	1970-01-01 00:00:00.000000000 +0000
> +++ b/kernel/trace/trace-console.c	2011-11-16 11:11:35.000000000 +0100
> @@ -0,0 +1,55 @@
> +/*
> + * Copyright (c) 2011 Intel Corporation. All rights reserved.
> + *
> + * This program is free software; you can redistribute it and/or modify
> + * it under the terms of the GNU General Public License as published by
> + * the Free Software Foundation; either version 2 of the License, or
> + * (at your option) any later version.
> + *
> + * This program is distributed in the hope that it will be useful,
> + * but WITHOUT ANY WARRANTY; without even the implied warranty of
> + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
> + * GNU General Public License for more details.
> + *
> + * You should have received a copy of the GNU General Public License
> + * along with this program; if not, write to the Free Software
> + * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
> + *
> + * The full GNU General Public License is included in this distribution in
> + * the file called COPYING.
> + *
> + * Author: Johannes Berg <johannes.berg@intel.com>
> + */
> +#include <linux/init.h>
> +#include <linux/module.h>
> +#include <linux/console.h>
> +
> +MODULE_AUTHOR("Johannes Berg <johannes.berg@intel.com>");
> +MODULE_DESCRIPTION("Console driver for tracing");
> +MODULE_LICENSE("GPL");
> +
> +
> +static void trace_msg(struct console *con, const char *msg, unsigned int len)
> +{
> +	trace_printk("%*s", len, msg);
> +}
> +
> +static struct console traceconsole = {
> +	.name	= "tracecon",
> +	.flags	= CON_ENABLED,
> +	.write	= trace_msg,
> +};
> +
> +static int __init init_traceconsole(void)
> +{
> +	register_console(&traceconsole);
> +	return 0;
> +}
> +
> +static void __exit exit_traceconsole(void)
> +{
> +	unregister_console(&traceconsole);
> +}
> +
> +module_init(init_traceconsole);
> +module_exit(exit_traceconsole);
> 



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:15 ` Steven Rostedt
@ 2011-11-16 14:25   ` Peter Zijlstra
  2011-11-16 14:30     ` Johannes Berg
  2011-11-16 14:32   ` Thomas Gleixner
                     ` (2 subsequent siblings)
  3 siblings, 1 reply; 47+ messages in thread
From: Peter Zijlstra @ 2011-11-16 14:25 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Johannes Berg, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 09:15 -0500, Steven Rostedt wrote:
> I'm good with this. Anyone have any issues with it?
> 
> -- Steve
> 
> > 
> > Signed-off-by: Johannes Berg <johannes.berg@intel.com>
> > ---
> >  kernel/trace/Kconfig         |   13 ++++++++++
> >  kernel/trace/Makefile        |    2 +
> >  kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
> >  3 files changed, 70 insertions(+)
> > 
> > --- a/kernel/trace/Kconfig    2011-11-16 11:11:27.000000000 +0100
> > +++ b/kernel/trace/Kconfig    2011-11-16 11:11:35.000000000 +0100
> > @@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
> >  
> >         If unsure, say N.
> >  
> > +config TRACE_CONSOLE
> > +     tristate "Support for a tracing console"
> > +     help
> > +       Say M (or Y if you must, but this is not recommended) 

Why not?

> to be able
> > +       to get a tracing console that puts every kernel message into the
> > +       tracing infrastructure using trace_printk(). This is useful to
> > +       correlate (existing) printk debugging with tracing. When using it
> > +       remember to set the console level, e.g. with "dmesg -n8". 

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:25   ` Peter Zijlstra
@ 2011-11-16 14:30     ` Johannes Berg
  2011-11-16 14:41       ` Peter Zijlstra
  2011-11-16 14:48       ` Steven Rostedt
  0 siblings, 2 replies; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 14:30 UTC (permalink / raw)
  To: Peter Zijlstra
  Cc: Steven Rostedt, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 15:25 +0100, Peter Zijlstra wrote:

> > >  kernel/trace/Kconfig         |   13 ++++++++++
> > >  kernel/trace/Makefile        |    2 +
> > >  kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
> > >  3 files changed, 70 insertions(+)
> > > 
> > > --- a/kernel/trace/Kconfig    2011-11-16 11:11:27.000000000 +0100
> > > +++ b/kernel/trace/Kconfig    2011-11-16 11:11:35.000000000 +0100
> > > @@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
> > >  
> > >         If unsure, say N.
> > >  
> > > +config TRACE_CONSOLE
> > > +     tristate "Support for a tracing console"
> > > +     help
> > > +       Say M (or Y if you must, but this is not recommended) 
> 
> Why not?

It'll always be registered and you have no way to turn it off then, so
you can't trace without getting every printk. I didn't want to add extra
API to toggle it, but building it in might be a bit odd that way.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:15 ` Steven Rostedt
  2011-11-16 14:25   ` Peter Zijlstra
@ 2011-11-16 14:32   ` Thomas Gleixner
  2011-11-16 14:35   ` Frederic Weisbecker
  2011-11-16 15:09   ` [PATCH v2] " Johannes Berg
  3 siblings, 0 replies; 47+ messages in thread
From: Thomas Gleixner @ 2011-11-16 14:32 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Johannes Berg, LKML, Frederic Weisbecker, Ingo Molnar,
	Peter Zijlstra, Andrew Morton

On Wed, 16 Nov 2011, Steven Rostedt wrote:

> [ Added Peter, Thomas and Andrew ]
> 
> On Wed, 2011-11-16 at 11:18 +0100, Johannes Berg wrote:
> > From: Johannes Berg <johannes.berg@intel.com>
> > 
> > As described in the Kconfig entry, logging printk
> > output is useful to correlate (existing) printk
> > debugging with (existing) tracing. The easiest way
> > to achieve this is to register a console that just
> > calls trace_printk(), which this module does.
> 
> I'm good with this. Anyone have any issues with it?

Acked-by-me

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:15 ` Steven Rostedt
  2011-11-16 14:25   ` Peter Zijlstra
  2011-11-16 14:32   ` Thomas Gleixner
@ 2011-11-16 14:35   ` Frederic Weisbecker
  2011-11-16 15:09   ` [PATCH v2] " Johannes Berg
  3 siblings, 0 replies; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-16 14:35 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Johannes Berg, LKML, Ingo Molnar, Peter Zijlstra,
	Thomas Gleixner, Andrew Morton

On Wed, Nov 16, 2011 at 09:15:54AM -0500, Steven Rostedt wrote:
> [ Added Peter, Thomas and Andrew ]
> 
> On Wed, 2011-11-16 at 11:18 +0100, Johannes Berg wrote:
> > From: Johannes Berg <johannes.berg@intel.com>
> > 
> > As described in the Kconfig entry, logging printk
> > output is useful to correlate (existing) printk
> > debugging with (existing) tracing. The easiest way
> > to achieve this is to register a console that just
> > calls trace_printk(), which this module does.
> 
> I'm good with this. Anyone have any issues with it?

Correlating trace_printk with printk is a feature I've
often missed.

Acked-by: Frederic Weisbecker <fweisbec@gmail.com>

Thanks.

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:30     ` Johannes Berg
@ 2011-11-16 14:41       ` Peter Zijlstra
  2011-11-16 14:48       ` Steven Rostedt
  1 sibling, 0 replies; 47+ messages in thread
From: Peter Zijlstra @ 2011-11-16 14:41 UTC (permalink / raw)
  To: Johannes Berg
  Cc: Steven Rostedt, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 15:30 +0100, Johannes Berg wrote:
> > > > +config TRACE_CONSOLE
> > > > +     tristate "Support for a tracing console"
> > > > +     help
> > > > +       Say M (or Y if you must, but this is not recommended) 
> > 
> > Why not?
> 
> It'll always be registered and you have no way to turn it off then, so
> you can't trace without getting every printk. I didn't want to add extra
> API to toggle it, but building it in might be a bit odd that way. 

OK, so maybe expand that help text a little to avoid the obvious
question ;-)

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:30     ` Johannes Berg
  2011-11-16 14:41       ` Peter Zijlstra
@ 2011-11-16 14:48       ` Steven Rostedt
  2011-11-16 14:50         ` Peter Zijlstra
  2011-11-16 14:51         ` Johannes Berg
  1 sibling, 2 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 14:48 UTC (permalink / raw)
  To: Johannes Berg
  Cc: Peter Zijlstra, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 15:30 +0100, Johannes Berg wrote:
> On Wed, 2011-11-16 at 15:25 +0100, Peter Zijlstra wrote:
> 
> > > >  kernel/trace/Kconfig         |   13 ++++++++++
> > > >  kernel/trace/Makefile        |    2 +
> > > >  kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
> > > >  3 files changed, 70 insertions(+)
> > > > 
> > > > --- a/kernel/trace/Kconfig    2011-11-16 11:11:27.000000000 +0100
> > > > +++ b/kernel/trace/Kconfig    2011-11-16 11:11:35.000000000 +0100
> > > > @@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
> > > >  
> > > >         If unsure, say N.
> > > >  
> > > > +config TRACE_CONSOLE
> > > > +     tristate "Support for a tracing console"
> > > > +     help
> > > > +       Say M (or Y if you must, but this is not recommended) 
> > 
> > Why not?
> 
> It'll always be registered and you have no way to turn it off then, so
> you can't trace without getting every printk. I didn't want to add extra
> API to toggle it, but building it in might be a bit odd that way.

Actually, that's not quite true. You could just do:

echo 0 > /debug/tracing/options/trace_printk

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:48       ` Steven Rostedt
@ 2011-11-16 14:50         ` Peter Zijlstra
  2011-11-16 14:51         ` Johannes Berg
  1 sibling, 0 replies; 47+ messages in thread
From: Peter Zijlstra @ 2011-11-16 14:50 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Johannes Berg, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 09:48 -0500, Steven Rostedt wrote:

> > It'll always be registered and you have no way to turn it off then, so
> > you can't trace without getting every printk. I didn't want to add extra
> > API to toggle it, but building it in might be a bit odd that way.
> 
> Actually, that's not quite true. You could just do:
> 
> echo 0 > /debug/tracing/options/trace_printk

well, that'll kill all trace_printk()s, which isn't what johill meant.


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:48       ` Steven Rostedt
  2011-11-16 14:50         ` Peter Zijlstra
@ 2011-11-16 14:51         ` Johannes Berg
  2011-11-16 15:17           ` Steven Rostedt
  1 sibling, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 14:51 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Peter Zijlstra, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 09:48 -0500, Steven Rostedt wrote:
> On Wed, 2011-11-16 at 15:30 +0100, Johannes Berg wrote:
> > On Wed, 2011-11-16 at 15:25 +0100, Peter Zijlstra wrote:
> > 
> > > > >  kernel/trace/Kconfig         |   13 ++++++++++
> > > > >  kernel/trace/Makefile        |    2 +
> > > > >  kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
> > > > >  3 files changed, 70 insertions(+)
> > > > > 
> > > > > --- a/kernel/trace/Kconfig    2011-11-16 11:11:27.000000000 +0100
> > > > > +++ b/kernel/trace/Kconfig    2011-11-16 11:11:35.000000000 +0100
> > > > > @@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
> > > > >  
> > > > >         If unsure, say N.
> > > > >  
> > > > > +config TRACE_CONSOLE
> > > > > +     tristate "Support for a tracing console"
> > > > > +     help
> > > > > +       Say M (or Y if you must, but this is not recommended) 
> > > 
> > > Why not?
> > 
> > It'll always be registered and you have no way to turn it off then, so
> > you can't trace without getting every printk. I didn't want to add extra
> > API to toggle it, but building it in might be a bit odd that way.
> 
> Actually, that's not quite true. You could just do:
> 
> echo 0 > /debug/tracing/options/trace_printk

Oh. Maybe I'll just remove it this then. I guess you kinda have to know
(or be told) you want this anyway.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* [PATCH v2] tracing: add trace console
  2011-11-16 14:15 ` Steven Rostedt
                     ` (2 preceding siblings ...)
  2011-11-16 14:35   ` Frederic Weisbecker
@ 2011-11-16 15:09   ` Johannes Berg
  2011-11-16 15:17     ` Peter Zijlstra
  2011-11-16 15:19     ` Steven Rostedt
  3 siblings, 2 replies; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 15:09 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Thomas Gleixner, Andrew Morton

From: Johannes Berg <johannes.berg@intel.com>

As described in the Kconfig entry, logging printk
output is useful to correlate (existing) printk
debugging with (existing) tracing. The easiest way
to achieve this is to register a console that just
calls trace_printk(), which this module does.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
v2: change Kconfig wording

 kernel/trace/Kconfig         |   15 +++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 72 insertions(+)

--- a/kernel/trace/Kconfig	2011-11-16 15:33:29.000000000 +0100
+++ b/kernel/trace/Kconfig	2011-11-16 16:08:27.000000000 +0100
@@ -368,6 +368,21 @@ config BLK_DEV_IO_TRACE
 
 	  If unsure, say N.
 
+config TRACE_CONSOLE
+	tristate "Support for a tracing console"
+	help
+	  Enable this to get a tracing console that puts every kernel message
+	  into the tracing infrastructure using trace_printk(). This is useful
+	  to correlate (existing) printk debugging with tracing. When using it
+	  remember to set the console level, e.g. with "dmesg -n8".
+
+	  Note that if you say Y here you will get every message into tracing
+	  and will not be able to turn it off.
+
+	  The module is called trace-console.
+
+	  Say N if unsure.
+
 config KPROBE_EVENT
 	depends on KPROBES
 	depends on HAVE_REGS_AND_STACK_ACCESS_API
--- a/kernel/trace/Makefile	2011-11-16 15:33:29.000000000 +0100
+++ b/kernel/trace/Makefile	2011-11-16 16:07:14.000000000 +0100
@@ -62,4 +62,6 @@ ifeq ($(CONFIG_TRACING),y)
 obj-$(CONFIG_KGDB_KDB) += trace_kdb.o
 endif
 
+obj-$(CONFIG_TRACE_CONSOLE) += trace-console.o
+
 libftrace-y := ftrace.o
--- /dev/null	1970-01-01 00:00:00.000000000 +0000
+++ b/kernel/trace/trace-console.c	2011-11-16 16:07:14.000000000 +0100
@@ -0,0 +1,55 @@
+/*
+ * Copyright (c) 2011 Intel Corporation. All rights reserved.
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ *
+ * The full GNU General Public License is included in this distribution in
+ * the file called COPYING.
+ *
+ * Author: Johannes Berg <johannes.berg@intel.com>
+ */
+#include <linux/init.h>
+#include <linux/module.h>
+#include <linux/console.h>
+
+MODULE_AUTHOR("Johannes Berg <johannes.berg@intel.com>");
+MODULE_DESCRIPTION("Console driver for tracing");
+MODULE_LICENSE("GPL");
+
+
+static void trace_msg(struct console *con, const char *msg, unsigned int len)
+{
+	trace_printk("%*s", len, msg);
+}
+
+static struct console traceconsole = {
+	.name	= "tracecon",
+	.flags	= CON_ENABLED,
+	.write	= trace_msg,
+};
+
+static int __init init_traceconsole(void)
+{
+	register_console(&traceconsole);
+	return 0;
+}
+
+static void __exit exit_traceconsole(void)
+{
+	unregister_console(&traceconsole);
+}
+
+module_init(init_traceconsole);
+module_exit(exit_traceconsole);



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 10:18 [PATCH] tracing: add trace console Johannes Berg
  2011-11-16 14:15 ` Steven Rostedt
@ 2011-11-16 15:10 ` Christoph Hellwig
  2011-11-16 15:17   ` Johannes Berg
  1 sibling, 1 reply; 47+ messages in thread
From: Christoph Hellwig @ 2011-11-16 15:10 UTC (permalink / raw)
  To: Johannes Berg; +Cc: LKML, Steven Rostedt, Frederic Weisbecker, Ingo Molnar

On Wed, Nov 16, 2011 at 11:18:48AM +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> As described in the Kconfig entry, logging printk
> output is useful to correlate (existing) printk
> debugging with (existing) tracing. The easiest way
> to achieve this is to register a console that just
> calls trace_printk(), which this module does.

I'd much prefer if we could have it built in all the time, but had a
way to enable it at runtime, just like all the "real" tracepoints.


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] tracing: add trace console
  2011-11-16 15:09   ` [PATCH v2] " Johannes Berg
@ 2011-11-16 15:17     ` Peter Zijlstra
  2011-11-16 15:19     ` Steven Rostedt
  1 sibling, 0 replies; 47+ messages in thread
From: Peter Zijlstra @ 2011-11-16 15:17 UTC (permalink / raw)
  To: Johannes Berg
  Cc: Steven Rostedt, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 16:09 +0100, Johannes Berg wrote:
> v2: change Kconfig wording

fair enough,

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

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 15:10 ` [PATCH] " Christoph Hellwig
@ 2011-11-16 15:17   ` Johannes Berg
  2011-11-16 16:41     ` Steven Rostedt
  0 siblings, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 15:17 UTC (permalink / raw)
  To: Christoph Hellwig; +Cc: LKML, Steven Rostedt, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 10:10 -0500, Christoph Hellwig wrote:
> On Wed, Nov 16, 2011 at 11:18:48AM +0100, Johannes Berg wrote:
> > From: Johannes Berg <johannes.berg@intel.com>
> > 
> > As described in the Kconfig entry, logging printk
> > output is useful to correlate (existing) printk
> > debugging with (existing) tracing. The easiest way
> > to achieve this is to register a console that just
> > calls trace_printk(), which this module does.
> 
> I'd much prefer if we could have it built in all the time, but had a
> way to enable it at runtime, just like all the "real" tracepoints.

That's possible, basically adding a tracepoints to printk -- that would
even catch everything and not require setting the console level (which
has its advantages too since other consoles might be slow).

It's a completely different thing though. I did it this way because it
was trivial to do out of tree for a quick test I was doing yesterday.
Doing it the other way is obviously more intrusive in core code.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 14:51         ` Johannes Berg
@ 2011-11-16 15:17           ` Steven Rostedt
  0 siblings, 0 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 15:17 UTC (permalink / raw)
  To: Johannes Berg
  Cc: Peter Zijlstra, LKML, Frederic Weisbecker, Ingo Molnar,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 15:51 +0100, Johannes Berg wrote:
> cho 0 > /debug/tracing/options/trace_printk
> 
> Oh. Maybe I'll just remove it this then. I guess you kinda have to know
> (or be told) you want this anyway.

I would reword it to something that explains this, but don't say
anything about recommending it or not. Just say that when this is
enabled, all printks will go into the trace buffer. If you need to
disable it, you must set it as a module that can be unloaded.

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] tracing: add trace console
  2011-11-16 15:09   ` [PATCH v2] " Johannes Berg
  2011-11-16 15:17     ` Peter Zijlstra
@ 2011-11-16 15:19     ` Steven Rostedt
  1 sibling, 0 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 15:19 UTC (permalink / raw)
  To: Johannes Berg
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Thomas Gleixner, Andrew Morton

On Wed, 2011-11-16 at 16:09 +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>

> +config TRACE_CONSOLE
> +	tristate "Support for a tracing console"
> +	help
> +	  Enable this to get a tracing console that puts every kernel message
> +	  into the tracing infrastructure using trace_printk(). This is useful
> +	  to correlate (existing) printk debugging with tracing. When using it
> +	  remember to set the console level, e.g. with "dmesg -n8".
> +
> +	  Note that if you say Y here you will get every message into tracing
> +	  and will not be able to turn it off.
> +
> +	  The module is called trace-console.

OK, this is much better. I'll apply it for my 3.3 queue.

Peter, can I get your Acked-by?

Thanks!

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 15:17   ` Johannes Berg
@ 2011-11-16 16:41     ` Steven Rostedt
  2011-11-16 16:45       ` Johannes Berg
  0 siblings, 1 reply; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 16:41 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 16:17 +0100, Johannes Berg wrote:
> On Wed, 2011-11-16 at 10:10 -0500, Christoph Hellwig wrote:
> > On Wed, Nov 16, 2011 at 11:18:48AM +0100, Johannes Berg wrote:
> > > From: Johannes Berg <johannes.berg@intel.com>
> > > 
> > > As described in the Kconfig entry, logging printk
> > > output is useful to correlate (existing) printk
> > > debugging with (existing) tracing. The easiest way
> > > to achieve this is to register a console that just
> > > calls trace_printk(), which this module does.
> > 
> > I'd much prefer if we could have it built in all the time, but had a
> > way to enable it at runtime, just like all the "real" tracepoints.
> 
> That's possible, basically adding a tracepoints to printk -- that would
> even catch everything and not require setting the console level (which
> has its advantages too since other consoles might be slow).
> 
> It's a completely different thing though. I did it this way because it
> was trivial to do out of tree for a quick test I was doing yesterday.
> Doing it the other way is obviously more intrusive in core code.

I'm not sure it would be too invasive. Think you could get something
working?

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 16:41     ` Steven Rostedt
@ 2011-11-16 16:45       ` Johannes Berg
  2011-11-16 17:00         ` Steven Rostedt
  0 siblings, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 16:45 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 11:41 -0500, Steven Rostedt wrote:

> > That's possible, basically adding a tracepoints to printk -- that would
> > even catch everything and not require setting the console level (which
> > has its advantages too since other consoles might be slow).
> > 
> > It's a completely different thing though. I did it this way because it
> > was trivial to do out of tree for a quick test I was doing yesterday.
> > Doing it the other way is obviously more intrusive in core code.
> 
> I'm not sure it would be too invasive. Think you could get something
> working?

I briefly looked at it just after writing the email, but quickly got
lost in printk.c because of the multi-line handling it has. We could
instead trace each call to printk(), so the multi-line stuff would end
up in multiple events, but all of that code is too much vodoo for me :)

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 16:45       ` Johannes Berg
@ 2011-11-16 17:00         ` Steven Rostedt
  2011-11-16 17:05           ` Steven Rostedt
  2011-11-16 18:33           ` Johannes Berg
  0 siblings, 2 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 17:00 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 17:45 +0100, Johannes Berg wrote:

> I briefly looked at it just after writing the email, but quickly got
> lost in printk.c because of the multi-line handling it has. We could
> instead trace each call to printk(), so the multi-line stuff would end
> up in multiple events, but all of that code is too much vodoo for me :)

Here's what can go into printk.c:

diff --git a/kernel/printk.c b/kernel/printk.c
index 1455a0d..4b8445a 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -542,6 +542,7 @@ MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to"
 static void _call_console_drivers(unsigned start,
 				unsigned end, int msg_log_level)
 {
+	trace_console(&LOG_BUF(start), end - start);
 	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
 			console_drivers && start != end) {
 		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {


And then you can make a TRACE_EVENT(console) that takes a buffer and a
len, and write that to the ring buffer.

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 17:00         ` Steven Rostedt
@ 2011-11-16 17:05           ` Steven Rostedt
  2011-11-16 18:33           ` Johannes Berg
  1 sibling, 0 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 17:05 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 12:00 -0500, Steven Rostedt wrote:

> diff --git a/kernel/printk.c b/kernel/printk.c
> index 1455a0d..4b8445a 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -542,6 +542,7 @@ MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to"
>  static void _call_console_drivers(unsigned start,
>  				unsigned end, int msg_log_level)
>  {
> +	trace_console(&LOG_BUF(start), end - start);

And since we don't want to trace when end == start, we can use
TRACE_EVENT_CONDITION() and have cond be: len > 0. (where len is the
parameter that takes the end - start.)

This will keep the branch to test len > 0 inside the tracepoint, and it
wont affect the logic when tracing is disabled.

-- Steve


>  	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
>  			console_drivers && start != end) {
>  		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
> 




^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 17:00         ` Steven Rostedt
  2011-11-16 17:05           ` Steven Rostedt
@ 2011-11-16 18:33           ` Johannes Berg
  2011-11-16 19:57             ` Steven Rostedt
  1 sibling, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 18:33 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 12:00 -0500, Steven Rostedt wrote:
> On Wed, 2011-11-16 at 17:45 +0100, Johannes Berg wrote:
> 
> > I briefly looked at it just after writing the email, but quickly got
> > lost in printk.c because of the multi-line handling it has. We could
> > instead trace each call to printk(), so the multi-line stuff would end
> > up in multiple events, but all of that code is too much vodoo for me :)
> 
> Here's what can go into printk.c:
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index 1455a0d..4b8445a 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -542,6 +542,7 @@ MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to"
>  static void _call_console_drivers(unsigned start,
>  				unsigned end, int msg_log_level)
>  {
> +	trace_console(&LOG_BUF(start), end - start);
>  	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
>  			console_drivers && start != end) {
>  		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
> 
> 
> And then you can make a TRACE_EVENT(console) that takes a buffer and a
> len, and write that to the ring buffer.

Yes, of course, but if we're going to modify the code then I thought we
should probably trace everything independent of the console printk
level.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 18:33           ` Johannes Berg
@ 2011-11-16 19:57             ` Steven Rostedt
  2011-11-16 20:12               ` Johannes Berg
  2011-11-16 21:25               ` [PATCH] printk: add console output tracing Johannes Berg
  0 siblings, 2 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-16 19:57 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 19:33 +0100, Johannes Berg wrote:
> On Wed, 2011-11-16 at 12:00 -0500, Steven Rostedt wrote:
> > On Wed, 2011-11-16 at 17:45 +0100, Johannes Berg wrote:
> > 
> > > I briefly looked at it just after writing the email, but quickly got
> > > lost in printk.c because of the multi-line handling it has. We could
> > > instead trace each call to printk(), so the multi-line stuff would end
> > > up in multiple events, but all of that code is too much vodoo for me :)
> > 
> > Here's what can go into printk.c:
> > 
> > diff --git a/kernel/printk.c b/kernel/printk.c
> > index 1455a0d..4b8445a 100644
> > --- a/kernel/printk.c
> > +++ b/kernel/printk.c
> > @@ -542,6 +542,7 @@ MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to"
> >  static void _call_console_drivers(unsigned start,
> >  				unsigned end, int msg_log_level)
> >  {
> > +	trace_console(&LOG_BUF(start), end - start);
> >  	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
> >  			console_drivers && start != end) {
> >  		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
> > 
> > 
> > And then you can make a TRACE_EVENT(console) that takes a buffer and a
> > len, and write that to the ring buffer.
> 
> Yes, of course, but if we're going to modify the code then I thought we
> should probably trace everything independent of the console printk
> level.
> 

This will trace everything independent from the console level. Noticed
that I put the tracepoint before the msg_log_level is checked.

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] tracing: add trace console
  2011-11-16 19:57             ` Steven Rostedt
@ 2011-11-16 20:12               ` Johannes Berg
  2011-11-16 21:25               ` [PATCH] printk: add console output tracing Johannes Berg
  1 sibling, 0 replies; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 20:12 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

On Wed, 2011-11-16 at 14:57 -0500, Steven Rostedt wrote:
> On Wed, 2011-11-16 at 19:33 +0100, Johannes Berg wrote:
> > On Wed, 2011-11-16 at 12:00 -0500, Steven Rostedt wrote:
> > > On Wed, 2011-11-16 at 17:45 +0100, Johannes Berg wrote:
> > > 
> > > > I briefly looked at it just after writing the email, but quickly got
> > > > lost in printk.c because of the multi-line handling it has. We could
> > > > instead trace each call to printk(), so the multi-line stuff would end
> > > > up in multiple events, but all of that code is too much vodoo for me :)
> > > 
> > > Here's what can go into printk.c:
> > > 
> > > diff --git a/kernel/printk.c b/kernel/printk.c
> > > index 1455a0d..4b8445a 100644
> > > --- a/kernel/printk.c
> > > +++ b/kernel/printk.c
> > > @@ -542,6 +542,7 @@ MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to"
> > >  static void _call_console_drivers(unsigned start,
> > >  				unsigned end, int msg_log_level)
> > >  {
> > > +	trace_console(&LOG_BUF(start), end - start);
> > >  	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
> > >  			console_drivers && start != end) {
> > >  		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
> > > 
> > > 
> > > And then you can make a TRACE_EVENT(console) that takes a buffer and a
> > > len, and write that to the ring buffer.
> > 
> > Yes, of course, but if we're going to modify the code then I thought we
> > should probably trace everything independent of the console printk
> > level.
> > 
> 
> This will trace everything independent from the console level. Noticed
> that I put the tracepoint before the msg_log_level is checked.

D'oh, right. Yeah that seems good. Too bad I discarded my previous
attempt already :)

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* [PATCH] printk: add console output tracing
  2011-11-16 19:57             ` Steven Rostedt
  2011-11-16 20:12               ` Johannes Berg
@ 2011-11-16 21:25               ` Johannes Berg
  2011-11-17  1:01                 ` Steven Rostedt
  2011-11-17 14:55                 ` Frederic Weisbecker
  1 sibling, 2 replies; 47+ messages in thread
From: Johannes Berg @ 2011-11-16 21:25 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

From: Johannes Berg <johannes.berg@intel.com>

Add a printk.console trace point to record any printk
messages into the trace, regardless of the current
console loglevel. This can help correlate (existing)
printk debugging with other tracing.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
 include/trace/events/printk.h |   44 ++++++++++++++++++++++++++++++++++++++++++
 kernel/printk.c               |    3 ++
 kernel/trace/Makefile         |    1 
 kernel/trace/printk-trace.c   |   14 +++++++++++++
 4 files changed, 62 insertions(+)

--- /dev/null	1970-01-01 00:00:00.000000000 +0000
+++ b/include/trace/events/printk.h	2011-11-16 22:06:43.000000000 +0100
@@ -0,0 +1,44 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM printk
+
+#if !defined(_TRACE_PRINTK_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PRINTK_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT_CONDITION(console,
+	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
+		 unsigned log_buf_len),
+
+	TP_ARGS(log_buf, start, end, log_buf_len),
+
+	TP_CONDITION(start != end),
+
+	TP_STRUCT__entry(
+		__dynamic_array(char, msg,
+				((end - start + log_buf_len) &
+				 (log_buf_len - 1)) + 1)
+	),
+
+	TP_fast_assign(
+		if ((start & (log_buf_len - 1)) > (end & (log_buf_len - 1))) {
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       log_buf_len - (start & (log_buf_len - 1)));
+			memcpy((char *)__get_dynamic_array(msg) +
+			       log_buf_len - (start & (log_buf_len - 1)),
+			       log_buf, end & (log_buf_len - 1));
+		} else
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       (end - start + log_buf_len) & (log_buf_len - 1));
+		((char *)__get_dynamic_array(msg))[(end - start + log_buf_len) &
+						   (log_buf_len - 1)] = 0;
+	),
+
+	TP_printk("%s", __get_str(msg))
+);
+#endif /* _TRACE_PRINTK_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
--- a/kernel/printk.c	2011-11-16 16:37:20.000000000 +0100
+++ b/kernel/printk.c	2011-11-16 21:47:20.000000000 +0100
@@ -41,6 +41,7 @@
 #include <linux/cpu.h>
 #include <linux/notifier.h>
 #include <linux/rculist.h>
+#include <trace/events/printk.h>
 
 #include <asm/uaccess.h>
 
@@ -542,6 +543,8 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
 static void _call_console_drivers(unsigned start,
 				unsigned end, int msg_log_level)
 {
+	trace_console(&LOG_BUF(0), start, end, log_buf_len);
+
 	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
 			console_drivers && start != end) {
 		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
--- /dev/null	1970-01-01 00:00:00.000000000 +0000
+++ b/kernel/trace/printk-trace.c	2011-11-16 21:22:20.000000000 +0100
@@ -0,0 +1,14 @@
+/*
+ * printk trace points
+ *
+ * Copyright (C) 2011 Johannes Berg <johannes.berg@intel.com>
+ */
+
+#include <linux/string.h>
+#include <linux/types.h>
+#include <linux/workqueue.h>
+#include <linux/sched.h>
+#include <linux/module.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/printk.h>
--- a/kernel/trace/Makefile	2011-11-16 16:37:20.000000000 +0100
+++ b/kernel/trace/Makefile	2011-11-16 21:38:49.000000000 +0100
@@ -55,6 +55,7 @@ endif
 obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
 obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o
 obj-$(CONFIG_TRACEPOINTS) += power-traces.o
+obj-$(CONFIG_TRACEPOINTS) += printk-trace.o
 ifeq ($(CONFIG_PM_RUNTIME),y)
 obj-$(CONFIG_TRACEPOINTS) += rpm-traces.o
 endif



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] printk: add console output tracing
  2011-11-16 21:25               ` [PATCH] printk: add console output tracing Johannes Berg
@ 2011-11-17  1:01                 ` Steven Rostedt
  2011-11-17 14:55                 ` Frederic Weisbecker
  1 sibling, 0 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-17  1:01 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Christoph Hellwig, LKML, Frederic Weisbecker, Ingo Molnar

Thomas, Peter, Frederic, Christoph,

Would you ack this patch please.

Thanks,

-- Steve


On Wed, 2011-11-16 at 22:25 +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> Add a printk.console trace point to record any printk
> messages into the trace, regardless of the current
> console loglevel. This can help correlate (existing)
> printk debugging with other tracing.
> 
> Signed-off-by: Johannes Berg <johannes.berg@intel.com>
> ---
>  include/trace/events/printk.h |   44 ++++++++++++++++++++++++++++++++++++++++++
>  kernel/printk.c               |    3 ++
>  kernel/trace/Makefile         |    1 
>  kernel/trace/printk-trace.c   |   14 +++++++++++++
>  4 files changed, 62 insertions(+)
> 
> --- /dev/null	1970-01-01 00:00:00.000000000 +0000
> +++ b/include/trace/events/printk.h	2011-11-16 22:06:43.000000000 +0100
> @@ -0,0 +1,44 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM printk
> +
> +#if !defined(_TRACE_PRINTK_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_PRINTK_H
> +
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT_CONDITION(console,
> +	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
> +		 unsigned log_buf_len),
> +
> +	TP_ARGS(log_buf, start, end, log_buf_len),
> +
> +	TP_CONDITION(start != end),
> +
> +	TP_STRUCT__entry(
> +		__dynamic_array(char, msg,
> +				((end - start + log_buf_len) &
> +				 (log_buf_len - 1)) + 1)
> +	),
> +
> +	TP_fast_assign(
> +		if ((start & (log_buf_len - 1)) > (end & (log_buf_len - 1))) {
> +			memcpy(__get_dynamic_array(msg),
> +			       log_buf + (start & (log_buf_len - 1)),
> +			       log_buf_len - (start & (log_buf_len - 1)));
> +			memcpy((char *)__get_dynamic_array(msg) +
> +			       log_buf_len - (start & (log_buf_len - 1)),
> +			       log_buf, end & (log_buf_len - 1));
> +		} else
> +			memcpy(__get_dynamic_array(msg),
> +			       log_buf + (start & (log_buf_len - 1)),
> +			       (end - start + log_buf_len) & (log_buf_len - 1));
> +		((char *)__get_dynamic_array(msg))[(end - start + log_buf_len) &
> +						   (log_buf_len - 1)] = 0;
> +	),
> +
> +	TP_printk("%s", __get_str(msg))
> +);
> +#endif /* _TRACE_PRINTK_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> --- a/kernel/printk.c	2011-11-16 16:37:20.000000000 +0100
> +++ b/kernel/printk.c	2011-11-16 21:47:20.000000000 +0100
> @@ -41,6 +41,7 @@
>  #include <linux/cpu.h>
>  #include <linux/notifier.h>
>  #include <linux/rculist.h>
> +#include <trace/events/printk.h>
>  
>  #include <asm/uaccess.h>
>  
> @@ -542,6 +543,8 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
>  static void _call_console_drivers(unsigned start,
>  				unsigned end, int msg_log_level)
>  {
> +	trace_console(&LOG_BUF(0), start, end, log_buf_len);
> +
>  	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
>  			console_drivers && start != end) {
>  		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
> --- /dev/null	1970-01-01 00:00:00.000000000 +0000
> +++ b/kernel/trace/printk-trace.c	2011-11-16 21:22:20.000000000 +0100
> @@ -0,0 +1,14 @@
> +/*
> + * printk trace points
> + *
> + * Copyright (C) 2011 Johannes Berg <johannes.berg@intel.com>
> + */
> +
> +#include <linux/string.h>
> +#include <linux/types.h>
> +#include <linux/workqueue.h>
> +#include <linux/sched.h>
> +#include <linux/module.h>
> +
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/printk.h>
> --- a/kernel/trace/Makefile	2011-11-16 16:37:20.000000000 +0100
> +++ b/kernel/trace/Makefile	2011-11-16 21:38:49.000000000 +0100
> @@ -55,6 +55,7 @@ endif
>  obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
>  obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o
>  obj-$(CONFIG_TRACEPOINTS) += power-traces.o
> +obj-$(CONFIG_TRACEPOINTS) += printk-trace.o
>  ifeq ($(CONFIG_PM_RUNTIME),y)
>  obj-$(CONFIG_TRACEPOINTS) += rpm-traces.o
>  endif
> 



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] printk: add console output tracing
  2011-11-16 21:25               ` [PATCH] printk: add console output tracing Johannes Berg
  2011-11-17  1:01                 ` Steven Rostedt
@ 2011-11-17 14:55                 ` Frederic Weisbecker
  2011-11-17 14:57                   ` Johannes Berg
  1 sibling, 1 reply; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-17 14:55 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Wed, Nov 16, 2011 at 10:25:19PM +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> Add a printk.console trace point to record any printk
> messages into the trace, regardless of the current
> console loglevel. This can help correlate (existing)
> printk debugging with other tracing.
> 
> Signed-off-by: Johannes Berg <johannes.berg@intel.com>
> ---
>  include/trace/events/printk.h |   44 ++++++++++++++++++++++++++++++++++++++++++
>  kernel/printk.c               |    3 ++
>  kernel/trace/Makefile         |    1 
>  kernel/trace/printk-trace.c   |   14 +++++++++++++
>  4 files changed, 62 insertions(+)
<snip> 
> --- /dev/null	1970-01-01 00:00:00.000000000 +0000
> +++ b/kernel/trace/printk-trace.c	2011-11-16 21:22:20.000000000 +0100
> @@ -0,0 +1,14 @@
> +/*
> + * printk trace points
> + *
> + * Copyright (C) 2011 Johannes Berg <johannes.berg@intel.com>
> + */
> +
> +#include <linux/string.h>
> +#include <linux/types.h>
> +#include <linux/workqueue.h>
> +#include <linux/sched.h>
> +#include <linux/module.h>
> +
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/printk.h>

Why not defining the tracepoint in kernel/printk.c ?

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] printk: add console output tracing
  2011-11-17 14:55                 ` Frederic Weisbecker
@ 2011-11-17 14:57                   ` Johannes Berg
  2011-11-17 15:00                     ` Frederic Weisbecker
  0 siblings, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-17 14:57 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Thu, 2011-11-17 at 15:55 +0100, Frederic Weisbecker wrote:

> > +++ b/kernel/trace/printk-trace.c	2011-11-16 21:22:20.000000000 +0100
> > @@ -0,0 +1,14 @@
> > +/*
> > + * printk trace points
> > + *
> > + * Copyright (C) 2011 Johannes Berg <johannes.berg@intel.com>
> > + */
> > +
> > +#include <linux/string.h>
> > +#include <linux/types.h>
> > +#include <linux/workqueue.h>
> > +#include <linux/sched.h>
> > +#include <linux/module.h>
> > +
> > +#define CREATE_TRACE_POINTS
> > +#include <trace/events/printk.h>
> 
> Why not defining the tracepoint in kernel/printk.c ?

Is that even possible? Do you then have to do something like

#include <.../printk.h>
#define CREATE_TRACE_POINTS
#include <.../printk.h>

or how else? In any case it seemed more common to not do that.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] printk: add console output tracing
  2011-11-17 14:57                   ` Johannes Berg
@ 2011-11-17 15:00                     ` Frederic Weisbecker
  2011-11-17 15:17                       ` Steven Rostedt
  2011-11-17 15:21                       ` [PATCH v2] " Johannes Berg
  0 siblings, 2 replies; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-17 15:00 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Thu, Nov 17, 2011 at 03:57:57PM +0100, Johannes Berg wrote:
> On Thu, 2011-11-17 at 15:55 +0100, Frederic Weisbecker wrote:
> 
> > > +++ b/kernel/trace/printk-trace.c	2011-11-16 21:22:20.000000000 +0100
> > > @@ -0,0 +1,14 @@
> > > +/*
> > > + * printk trace points
> > > + *
> > > + * Copyright (C) 2011 Johannes Berg <johannes.berg@intel.com>
> > > + */
> > > +
> > > +#include <linux/string.h>
> > > +#include <linux/types.h>
> > > +#include <linux/workqueue.h>
> > > +#include <linux/sched.h>
> > > +#include <linux/module.h>
> > > +
> > > +#define CREATE_TRACE_POINTS
> > > +#include <trace/events/printk.h>
> > 
> > Why not defining the tracepoint in kernel/printk.c ?
> 
> Is that even possible? Do you then have to do something like
> 
> #include <.../printk.h>
> #define CREATE_TRACE_POINTS
> #include <.../printk.h>
> 
> or how else? In any case it seemed more common to not do that.

You can just do what you did:

#define CREATE_TRACE_POINTS
#include <trace/events/printk.h>

but in kernel/printk.c

We typically define the tracepoint from the file where an unconditional user
resides.

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH] printk: add console output tracing
  2011-11-17 15:00                     ` Frederic Weisbecker
@ 2011-11-17 15:17                       ` Steven Rostedt
  2011-11-17 15:21                       ` [PATCH v2] " Johannes Berg
  1 sibling, 0 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-11-17 15:17 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Johannes Berg, Christoph Hellwig, LKML, Ingo Molnar

On Thu, 2011-11-17 at 16:00 +0100, Frederic Weisbecker wrote:
> On Thu, Nov 17, 2011 at 03:57:57PM +0100, Johannes Berg wrote:
> > On Thu, 2011-11-17 at 15:55 +0100, Frederic Weisbecker wrote:
> > 
> > > > +++ b/kernel/trace/printk-trace.c	2011-11-16 21:22:20.000000000 +0100
> > > > @@ -0,0 +1,14 @@
> > > > +/*
> > > > + * printk trace points
> > > > + *
> > > > + * Copyright (C) 2011 Johannes Berg <johannes.berg@intel.com>
> > > > + */
> > > > +
> > > > +#include <linux/string.h>
> > > > +#include <linux/types.h>
> > > > +#include <linux/workqueue.h>
> > > > +#include <linux/sched.h>
> > > > +#include <linux/module.h>
> > > > +
> > > > +#define CREATE_TRACE_POINTS
> > > > +#include <trace/events/printk.h>
> > > 
> > > Why not defining the tracepoint in kernel/printk.c ?

Right, there's no reason to add another file, except to get Johannes's
copyright in the kernel ;-)

> > 
> > Is that even possible? Do you then have to do something like
> > 
> > #include <.../printk.h>
> > #define CREATE_TRACE_POINTS
> > #include <.../printk.h>
> > 
> > or how else? In any case it seemed more common to not do that.
> 
> You can just do what you did:
> 
> #define CREATE_TRACE_POINTS
> #include <trace/events/printk.h>
> 
> but in kernel/printk.c
> 
> We typically define the tracepoint from the file where an unconditional user
> resides.

The above *is* the correct way to do this.

Thanks Frederic for pointing that out. I should have spotted it, but I
blame my meds ;)

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* [PATCH v2] printk: add console output tracing
  2011-11-17 15:00                     ` Frederic Weisbecker
  2011-11-17 15:17                       ` Steven Rostedt
@ 2011-11-17 15:21                       ` Johannes Berg
  2011-11-18 18:44                         ` Frederic Weisbecker
  1 sibling, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-17 15:21 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

From: Johannes Berg <johannes.berg@intel.com>

Add a printk.console trace point to record any printk
messages into the trace, regardless of the current
console loglevel. This can help correlate (existing)
printk debugging with other tracing.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
v2: remove extra file

 include/trace/events/printk.h |   44 ++++++++++++++++++++++++++++++++++++++++++
 kernel/printk.c               |    5 ++++
 2 files changed, 49 insertions(+)

--- /dev/null	1970-01-01 00:00:00.000000000 +0000
+++ b/include/trace/events/printk.h	2011-11-16 23:18:35.000000000 +0100
@@ -0,0 +1,44 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM printk
+
+#if !defined(_TRACE_PRINTK_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PRINTK_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT_CONDITION(console,
+	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
+		 unsigned log_buf_len),
+
+	TP_ARGS(log_buf, start, end, log_buf_len),
+
+	TP_CONDITION(start != end),
+
+	TP_STRUCT__entry(
+		__dynamic_array(char, msg,
+				((end - start + log_buf_len) &
+				 (log_buf_len - 1)) + 1)
+	),
+
+	TP_fast_assign(
+		if ((start & (log_buf_len - 1)) > (end & (log_buf_len - 1))) {
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       log_buf_len - (start & (log_buf_len - 1)));
+			memcpy((char *)__get_dynamic_array(msg) +
+			       log_buf_len - (start & (log_buf_len - 1)),
+			       log_buf, end & (log_buf_len - 1));
+		} else
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       (end - start + log_buf_len) & (log_buf_len - 1));
+		((char *)__get_dynamic_array(msg))[(end - start + log_buf_len) &
+						   (log_buf_len - 1)] = 0;
+	),
+
+	TP_printk("%s", __get_str(msg))
+);
+#endif /* _TRACE_PRINTK_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
--- a/kernel/printk.c	2011-11-16 22:25:43.000000000 +0100
+++ b/kernel/printk.c	2011-11-17 16:19:19.000000000 +0100
@@ -44,6 +44,9 @@
 
 #include <asm/uaccess.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/printk.h>
+
 /*
  * Architectures can override it:
  */
@@ -542,6 +545,8 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
 static void _call_console_drivers(unsigned start,
 				unsigned end, int msg_log_level)
 {
+	trace_console(&LOG_BUF(0), start, end, log_buf_len);
+
 	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
 			console_drivers && start != end) {
 		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-17 15:21                       ` [PATCH v2] " Johannes Berg
@ 2011-11-18 18:44                         ` Frederic Weisbecker
  2011-11-18 18:46                           ` Johannes Berg
  0 siblings, 1 reply; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-18 18:44 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Thu, Nov 17, 2011 at 04:21:08PM +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> Add a printk.console trace point to record any printk
> messages into the trace, regardless of the current
> console loglevel. This can help correlate (existing)
> printk debugging with other tracing.
> 
> Signed-off-by: Johannes Berg <johannes.berg@intel.com>
> ---
> v2: remove extra file
> 
>  include/trace/events/printk.h |   44 ++++++++++++++++++++++++++++++++++++++++++
>  kernel/printk.c               |    5 ++++
>  2 files changed, 49 insertions(+)
> 
> --- /dev/null	1970-01-01 00:00:00.000000000 +0000
> +++ b/include/trace/events/printk.h	2011-11-16 23:18:35.000000000 +0100
> @@ -0,0 +1,44 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM printk
> +
> +#if !defined(_TRACE_PRINTK_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_PRINTK_H
> +
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT_CONDITION(console,
> +	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
> +		 unsigned log_buf_len),
> +
> +	TP_ARGS(log_buf, start, end, log_buf_len),
> +
> +	TP_CONDITION(start != end),
> +
> +	TP_STRUCT__entry(
> +		__dynamic_array(char, msg,
> +				((end - start + log_buf_len) &
> +				 (log_buf_len - 1)) + 1)

Is all that care about log_buf_len necessary? It seems that
printk ensures that log_end - con_start never exceeds log_buf_len,
looking at emit_log_char()

Thanks.

> +	),
> +
> +	TP_fast_assign(
> +		if ((start & (log_buf_len - 1)) > (end & (log_buf_len - 1))) {
> +			memcpy(__get_dynamic_array(msg),
> +			       log_buf + (start & (log_buf_len - 1)),
> +			       log_buf_len - (start & (log_buf_len - 1)));
> +			memcpy((char *)__get_dynamic_array(msg) +
> +			       log_buf_len - (start & (log_buf_len - 1)),
> +			       log_buf, end & (log_buf_len - 1));
> +		} else
> +			memcpy(__get_dynamic_array(msg),
> +			       log_buf + (start & (log_buf_len - 1)),
> +			       (end - start + log_buf_len) & (log_buf_len - 1));
> +		((char *)__get_dynamic_array(msg))[(end - start + log_buf_len) &
> +						   (log_buf_len - 1)] = 0;
> +	),
> +
> +	TP_printk("%s", __get_str(msg))
> +);
> +#endif /* _TRACE_PRINTK_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> --- a/kernel/printk.c	2011-11-16 22:25:43.000000000 +0100
> +++ b/kernel/printk.c	2011-11-17 16:19:19.000000000 +0100
> @@ -44,6 +44,9 @@
>  
>  #include <asm/uaccess.h>
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/printk.h>
> +
>  /*
>   * Architectures can override it:
>   */
> @@ -542,6 +545,8 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
>  static void _call_console_drivers(unsigned start,
>  				unsigned end, int msg_log_level)
>  {
> +	trace_console(&LOG_BUF(0), start, end, log_buf_len);
> +
>  	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
>  			console_drivers && start != end) {
>  		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
> 
> 

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-18 18:44                         ` Frederic Weisbecker
@ 2011-11-18 18:46                           ` Johannes Berg
  2011-11-18 18:54                             ` Frederic Weisbecker
  0 siblings, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-18 18:46 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Fri, 2011-11-18 at 19:44 +0100, Frederic Weisbecker wrote:

> > +TRACE_EVENT_CONDITION(console,
> > +	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
> > +		 unsigned log_buf_len),
> > +
> > +	TP_ARGS(log_buf, start, end, log_buf_len),
> > +
> > +	TP_CONDITION(start != end),
> > +
> > +	TP_STRUCT__entry(
> > +		__dynamic_array(char, msg,
> > +				((end - start + log_buf_len) &
> > +				 (log_buf_len - 1)) + 1)
> 
> Is all that care about log_buf_len necessary? It seems that
> printk ensures that log_end - con_start never exceeds log_buf_len,
> looking at emit_log_char()

I think it is. The buffer can wrap around so in that case end < start,
which just end-start won't handle here.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-18 18:46                           ` Johannes Berg
@ 2011-11-18 18:54                             ` Frederic Weisbecker
  2011-11-18 18:59                               ` Johannes Berg
  0 siblings, 1 reply; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-18 18:54 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Fri, Nov 18, 2011 at 07:46:15PM +0100, Johannes Berg wrote:
> On Fri, 2011-11-18 at 19:44 +0100, Frederic Weisbecker wrote:
> 
> > > +TRACE_EVENT_CONDITION(console,
> > > +	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
> > > +		 unsigned log_buf_len),
> > > +
> > > +	TP_ARGS(log_buf, start, end, log_buf_len),
> > > +
> > > +	TP_CONDITION(start != end),
> > > +
> > > +	TP_STRUCT__entry(
> > > +		__dynamic_array(char, msg,
> > > +				((end - start + log_buf_len) &
> > > +				 (log_buf_len - 1)) + 1)
> > 
> > Is all that care about log_buf_len necessary? It seems that
> > printk ensures that log_end - con_start never exceeds log_buf_len,
> > looking at emit_log_char()
> 
> I think it is. The buffer can wrap around so in that case end < start,
> which just end-start won't handle here.

Even if it wraps, end - start should always give a positive result.

We have that check in call_console_drivers():

	BUG_ON(((int)(start - end)) > 0)

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-18 18:54                             ` Frederic Weisbecker
@ 2011-11-18 18:59                               ` Johannes Berg
  2011-11-23 13:16                                 ` Frederic Weisbecker
  0 siblings, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-18 18:59 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Fri, 2011-11-18 at 19:54 +0100, Frederic Weisbecker wrote:
> On Fri, Nov 18, 2011 at 07:46:15PM +0100, Johannes Berg wrote:
> > On Fri, 2011-11-18 at 19:44 +0100, Frederic Weisbecker wrote:
> > 
> > > > +TRACE_EVENT_CONDITION(console,
> > > > +	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
> > > > +		 unsigned log_buf_len),
> > > > +
> > > > +	TP_ARGS(log_buf, start, end, log_buf_len),
> > > > +
> > > > +	TP_CONDITION(start != end),
> > > > +
> > > > +	TP_STRUCT__entry(
> > > > +		__dynamic_array(char, msg,
> > > > +				((end - start + log_buf_len) &
> > > > +				 (log_buf_len - 1)) + 1)
> > > 
> > > Is all that care about log_buf_len necessary? It seems that
> > > printk ensures that log_end - con_start never exceeds log_buf_len,
> > > looking at emit_log_char()
> > 
> > I think it is. The buffer can wrap around so in that case end < start,
> > which just end-start won't handle here.
> 
> Even if it wraps, end - start should always give a positive result.
> 
> We have that check in call_console_drivers():
> 
> 	BUG_ON(((int)(start - end)) > 0)

That's .. confusing, start - end > 0 <=> start > end ??

Also, call_console_drivers() doesn't pass this start/end through to
_call_console_drivers(), it has loops and stuff there...

In any case -- feel free to clean it all up, I basically copied the
logic from _call_console_drivers assuming it was needed. I don't really
want to know about the printk details :-)

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-18 18:59                               ` Johannes Berg
@ 2011-11-23 13:16                                 ` Frederic Weisbecker
  2011-11-24 13:21                                   ` Johannes Berg
  0 siblings, 1 reply; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-23 13:16 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Fri, Nov 18, 2011 at 07:59:12PM +0100, Johannes Berg wrote:
> On Fri, 2011-11-18 at 19:54 +0100, Frederic Weisbecker wrote:
> > On Fri, Nov 18, 2011 at 07:46:15PM +0100, Johannes Berg wrote:
> > > On Fri, 2011-11-18 at 19:44 +0100, Frederic Weisbecker wrote:
> > > 
> > > > > +TRACE_EVENT_CONDITION(console,
> > > > > +	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
> > > > > +		 unsigned log_buf_len),
> > > > > +
> > > > > +	TP_ARGS(log_buf, start, end, log_buf_len),
> > > > > +
> > > > > +	TP_CONDITION(start != end),
> > > > > +
> > > > > +	TP_STRUCT__entry(
> > > > > +		__dynamic_array(char, msg,
> > > > > +				((end - start + log_buf_len) &
> > > > > +				 (log_buf_len - 1)) + 1)
> > > > 
> > > > Is all that care about log_buf_len necessary? It seems that
> > > > printk ensures that log_end - con_start never exceeds log_buf_len,
> > > > looking at emit_log_char()
> > > 
> > > I think it is. The buffer can wrap around so in that case end < start,
> > > which just end-start won't handle here.
> > 
> > Even if it wraps, end - start should always give a positive result.
> > 
> > We have that check in call_console_drivers():
> > 
> > 	BUG_ON(((int)(start - end)) > 0)
> 
> That's .. confusing, start - end > 0 <=> start > end ??

Yeah. Both are unsigned, so converting the result into an int
and getting a positive value means we have wrapped INT_MAX.

> 
> Also, call_console_drivers() doesn't pass this start/end through to
> _call_console_drivers(), it has loops and stuff there...

Yeah but looking at the loop there, start and end passed to
__call_console_drivers() are bounded between start and end passed to
call_console_drivers().

> 
> In any case -- feel free to clean it all up, I basically copied the
> logic from _call_console_drivers assuming it was needed.

I'm just reviewing and suggesting a way to keep the patch more simple.
Outside that, I don't really need that patch myself ;)

> I don't really want to know about the printk details :-)

Well, it's like working out outside in winter. It may not sound
very entertaining in the beginning but then it quickly becomes
invigorating, toning and good for the mood...I think...

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-23 13:16                                 ` Frederic Weisbecker
@ 2011-11-24 13:21                                   ` Johannes Berg
  2011-11-24 15:45                                     ` Frederic Weisbecker
  0 siblings, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-24 13:21 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Wed, 2011-11-23 at 14:16 +0100, Frederic Weisbecker wrote:

> > Also, call_console_drivers() doesn't pass this start/end through to
> > _call_console_drivers(), it has loops and stuff there...
> 
> Yeah but looking at the loop there, start and end passed to
> __call_console_drivers() are bounded between start and end passed to
> call_console_drivers().

Looks like. Not that I have any idea why other code handles the wrap
then?

> > In any case -- feel free to clean it all up, I basically copied the
> > logic from _call_console_drivers assuming it was needed.
> 
> I'm just reviewing and suggesting a way to keep the patch more simple.
> Outside that, I don't really need that patch myself ;)

:-)

> > I don't really want to know about the printk details :-)
> 
> Well, it's like working out outside in winter. It may not sound
> very entertaining in the beginning but then it quickly becomes
> invigorating, toning and good for the mood...I think...

Heh....

I don't really feel comfortable modifying the _call_console_drivers()
function to not handle start > end (modulo log buf size of course), but
at the same time I don't feel comfortable putting code into it that
doesn't handle it.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-24 13:21                                   ` Johannes Berg
@ 2011-11-24 15:45                                     ` Frederic Weisbecker
  2011-11-24 19:00                                       ` Johannes Berg
  2011-11-24 19:03                                       ` [PATCH v3] " Johannes Berg
  0 siblings, 2 replies; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-24 15:45 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Thu, Nov 24, 2011 at 02:21:59PM +0100, Johannes Berg wrote:
> On Wed, 2011-11-23 at 14:16 +0100, Frederic Weisbecker wrote:
> 
> > > Also, call_console_drivers() doesn't pass this start/end through to
> > > _call_console_drivers(), it has loops and stuff there...
> > 
> > Yeah but looking at the loop there, start and end passed to
> > __call_console_drivers() are bounded between start and end passed to
> > call_console_drivers().
> 
> Looks like. Not that I have any idea why other code handles the wrap
> then?

It's not the same wrap.
More on that below.

> 
> > > In any case -- feel free to clean it all up, I basically copied the
> > > logic from _call_console_drivers assuming it was needed.
> > 
> > I'm just reviewing and suggesting a way to keep the patch more simple.
> > Outside that, I don't really need that patch myself ;)
> 
> :-)
> 
> > > I don't really want to know about the printk details :-)
> > 
> > Well, it's like working out outside in winter. It may not sound
> > very entertaining in the beginning but then it quickly becomes
> > invigorating, toning and good for the mood...I think...
> 
> Heh....
> 
> I don't really feel comfortable modifying the _call_console_drivers()
> function to not handle start > end (modulo log buf size of course), but
> at the same time I don't feel comfortable putting code into it that
> doesn't handle it.

So, the:

	BUG_ON(((int)(start - end)) > 0);

check is there to ensure we haven't wrapped INT_MAX. If we have reached
that point it definetly means we have a bug because log_buf_len is itself
an int and we shouldn't overlap INT_MAX.

The care on the wrapping that is done in _call_console_drivers() is
different and concerns log_buf_len itself. If log_buf_len = 8, start = 7
and end = 9, then you will enter the "((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK))"
condition that handle the wrap on LOG_BUF_MASK to print the two chars.
But this is totally different from "start > end" which would mean we have
a bug.

So, in your tracepoint you can safely use "end - start" as a length for your
dynamic array. But the rest of your tracepoint (all the fast assign part)
still needs the masks as you did.

But well, I'm being anal about two lines in TP_struct__entry(), that's really
not important...

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-24 15:45                                     ` Frederic Weisbecker
@ 2011-11-24 19:00                                       ` Johannes Berg
  2011-11-25 17:43                                         ` Frederic Weisbecker
  2011-11-24 19:03                                       ` [PATCH v3] " Johannes Berg
  1 sibling, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2011-11-24 19:00 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Thu, 2011-11-24 at 16:45 +0100, Frederic Weisbecker wrote:

> > I don't really feel comfortable modifying the _call_console_drivers()
> > function to not handle start > end (modulo log buf size of course), but
> > at the same time I don't feel comfortable putting code into it that
> > doesn't handle it.
> 
> So, the:
> 
> 	BUG_ON(((int)(start - end)) > 0);
> 
> check is there to ensure we haven't wrapped INT_MAX. If we have reached
> that point it definetly means we have a bug because log_buf_len is itself
> an int and we shouldn't overlap INT_MAX.

Ok that makes sense.

> The care on the wrapping that is done in _call_console_drivers() is
> different and concerns log_buf_len itself. If log_buf_len = 8, start = 7
> and end = 9, then you will enter the "((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK))"
> condition that handle the wrap on LOG_BUF_MASK to print the two chars.
> But this is totally different from "start > end" which would mean we have
> a bug.

Oh. So we get end = 9 in that case? That seems confusing ... I would
have expected end = 1 then! Which is the whole reason I got confused I
guess.

> So, in your tracepoint you can safely use "end - start" as a length for your
> dynamic array. But the rest of your tracepoint (all the fast assign part)
> still needs the masks as you did.

Oh, that's all you were trying to say? I can see that, ok. I just didn't
see that end would be 9 instead of 1 and tried to handle that. The
_call_console_drivers() code is a bit different I guess.

I'll send a new version.

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* [PATCH v3] printk: add console output tracing
  2011-11-24 15:45                                     ` Frederic Weisbecker
  2011-11-24 19:00                                       ` Johannes Berg
@ 2011-11-24 19:03                                       ` Johannes Berg
  2011-11-25 17:41                                         ` Frederic Weisbecker
                                                           ` (2 more replies)
  1 sibling, 3 replies; 47+ messages in thread
From: Johannes Berg @ 2011-11-24 19:03 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

From: Johannes Berg <johannes.berg@intel.com>

Add a printk.console trace point to record any printk
messages into the trace, regardless of the current
console loglevel. This can help correlate (existing)
printk debugging with other tracing.

Signed-off-by: Johannes Berg <johannes.berg@intel.com>
---
v2: remove extra file
v3: simplify length of __dynamic_array, thanks Frederic

 include/trace/events/printk.h |   41 +++++++++++++++++++++++++++++++++++++++++
 kernel/printk.c               |    5 +++++
 2 files changed, 46 insertions(+)

--- /dev/null	1970-01-01 00:00:00.000000000 +0000
+++ b/include/trace/events/printk.h	2011-11-24 20:02:21.000000000 +0100
@@ -0,0 +1,41 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM printk
+
+#if !defined(_TRACE_PRINTK_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PRINTK_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT_CONDITION(console,
+	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
+		 unsigned log_buf_len),
+
+	TP_ARGS(log_buf, start, end, log_buf_len),
+
+	TP_CONDITION(start != end),
+
+	TP_STRUCT__entry(
+		__dynamic_array(char, msg, end - start + 1)
+	),
+
+	TP_fast_assign(
+		if ((start & (log_buf_len - 1)) > (end & (log_buf_len - 1))) {
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       log_buf_len - (start & (log_buf_len - 1)));
+			memcpy((char *)__get_dynamic_array(msg) +
+			       log_buf_len - (start & (log_buf_len - 1)),
+			       log_buf, end & (log_buf_len - 1));
+		} else
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       end - start);
+		((char *)__get_dynamic_array(msg))[end - start] = 0;
+	),
+
+	TP_printk("%s", __get_str(msg))
+);
+#endif /* _TRACE_PRINTK_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
--- a/kernel/printk.c	2011-11-24 09:38:53.000000000 +0100
+++ b/kernel/printk.c	2011-11-24 09:42:37.000000000 +0100
@@ -44,6 +44,9 @@
 
 #include <asm/uaccess.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/printk.h>
+
 /*
  * Architectures can override it:
  */
@@ -542,6 +545,8 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
 static void _call_console_drivers(unsigned start,
 				unsigned end, int msg_log_level)
 {
+	trace_console(&LOG_BUF(0), start, end, log_buf_len);
+
 	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
 			console_drivers && start != end) {
 		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v3] printk: add console output tracing
  2011-11-24 19:03                                       ` [PATCH v3] " Johannes Berg
@ 2011-11-25 17:41                                         ` Frederic Weisbecker
  2011-12-02 18:05                                           ` Steven Rostedt
  2012-02-13 17:30                                         ` Steven Rostedt
  2012-02-17 13:52                                         ` [tip:perf/core] printk/tracing: Add " tip-bot for Johannes Berg
  2 siblings, 1 reply; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-25 17:41 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Thu, Nov 24, 2011 at 08:03:08PM +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> Add a printk.console trace point to record any printk
> messages into the trace, regardless of the current
> console loglevel. This can help correlate (existing)
> printk debugging with other tracing.
> 
> Signed-off-by: Johannes Berg <johannes.berg@intel.com>

Thanks!

Acked-by: Frederic Weisbecker <fweisbec@gmail.com>

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-24 19:00                                       ` Johannes Berg
@ 2011-11-25 17:43                                         ` Frederic Weisbecker
  2011-11-25 18:11                                           ` Johannes Berg
  0 siblings, 1 reply; 47+ messages in thread
From: Frederic Weisbecker @ 2011-11-25 17:43 UTC (permalink / raw)
  To: Johannes Berg; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Thu, Nov 24, 2011 at 08:00:16PM +0100, Johannes Berg wrote:
> On Thu, 2011-11-24 at 16:45 +0100, Frederic Weisbecker wrote:
> 
> > > I don't really feel comfortable modifying the _call_console_drivers()
> > > function to not handle start > end (modulo log buf size of course), but
> > > at the same time I don't feel comfortable putting code into it that
> > > doesn't handle it.
> > 
> > So, the:
> > 
> > 	BUG_ON(((int)(start - end)) > 0);
> > 
> > check is there to ensure we haven't wrapped INT_MAX. If we have reached
> > that point it definetly means we have a bug because log_buf_len is itself
> > an int and we shouldn't overlap INT_MAX.
> 
> Ok that makes sense.
> 
> > The care on the wrapping that is done in _call_console_drivers() is
> > different and concerns log_buf_len itself. If log_buf_len = 8, start = 7
> > and end = 9, then you will enter the "((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK))"
> > condition that handle the wrap on LOG_BUF_MASK to print the two chars.
> > But this is totally different from "start > end" which would mean we have
> > a bug.
> 
> Oh. So we get end = 9 in that case? That seems confusing ... I would
> have expected end = 1 then! Which is the whole reason I got confused I
> guess.

end = 9 but (end & LOG_BUF_MASK) = 1

> 
> > So, in your tracepoint you can safely use "end - start" as a length for your
> > dynamic array. But the rest of your tracepoint (all the fast assign part)
> > still needs the masks as you did.
> 
> Oh, that's all you were trying to say?

Yeah I first thought my comment applied to all the mask game in the tracepoint but then
I started to feel ashamed when I realized it was only on the dynamic array declaration :)

> I can see that, ok. I just didn't
> see that end would be 9 instead of 1 and tried to handle that. The
> _call_console_drivers() code is a bit different I guess.
> 
> I'll send a new version.

Thanks.

> 
> johannes
> 

^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v2] printk: add console output tracing
  2011-11-25 17:43                                         ` Frederic Weisbecker
@ 2011-11-25 18:11                                           ` Johannes Berg
  0 siblings, 0 replies; 47+ messages in thread
From: Johannes Berg @ 2011-11-25 18:11 UTC (permalink / raw)
  To: Frederic Weisbecker; +Cc: Steven Rostedt, Christoph Hellwig, LKML, Ingo Molnar

On Fri, 2011-11-25 at 18:43 +0100, Frederic Weisbecker wrote:

> > > So, in your tracepoint you can safely use "end - start" as a length for your
> > > dynamic array. But the rest of your tracepoint (all the fast assign part)
> > > still needs the masks as you did.
> > 
> > Oh, that's all you were trying to say?
> 
> Yeah I first thought my comment applied to all the mask game in the tracepoint but then
> I started to feel ashamed when I realized it was only on the dynamic array declaration :)

Well it did actually apply to the memcpy length in one of the cases
too :)

johannes


^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v3] printk: add console output tracing
  2011-11-25 17:41                                         ` Frederic Weisbecker
@ 2011-12-02 18:05                                           ` Steven Rostedt
  0 siblings, 0 replies; 47+ messages in thread
From: Steven Rostedt @ 2011-12-02 18:05 UTC (permalink / raw)
  To: Frederic Weisbecker
  Cc: Johannes Berg, Christoph Hellwig, LKML, Ingo Molnar, Peter Zijlstra

On Fri, 2011-11-25 at 18:41 +0100, Frederic Weisbecker wrote:
> On Thu, Nov 24, 2011 at 08:03:08PM +0100, Johannes Berg wrote:
> > From: Johannes Berg <johannes.berg@intel.com>
> > 
> > Add a printk.console trace point to record any printk
> > messages into the trace, regardless of the current
> > console loglevel. This can help correlate (existing)
> > printk debugging with other tracing.
> > 
> > Signed-off-by: Johannes Berg <johannes.berg@intel.com>
> 
> Thanks!
> 
> Acked-by: Frederic Weisbecker <fweisbec@gmail.com>

Is everyone happy with this change?

Should I pull it into my queue for 3.3?

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v3] printk: add console output tracing
  2011-11-24 19:03                                       ` [PATCH v3] " Johannes Berg
  2011-11-25 17:41                                         ` Frederic Weisbecker
@ 2012-02-13 17:30                                         ` Steven Rostedt
  2012-02-13 17:33                                           ` Johannes Berg
  2012-02-17 13:52                                         ` [tip:perf/core] printk/tracing: Add " tip-bot for Johannes Berg
  2 siblings, 1 reply; 47+ messages in thread
From: Steven Rostedt @ 2012-02-13 17:30 UTC (permalink / raw)
  To: Johannes Berg
  Cc: Frederic Weisbecker, Christoph Hellwig, LKML, Ingo Molnar,
	Peter Zijlstra, Thomas Gleixner

On Thu, 2011-11-24 at 20:03 +0100, Johannes Berg wrote:
> From: Johannes Berg <johannes.berg@intel.com>
> 
> Add a printk.console trace point to record any printk
> messages into the trace, regardless of the current
> console loglevel. This can help correlate (existing)
> printk debugging with other tracing.
> 

Looks like this patch got lost in the x-mas parade.

Is this the last version of the patch?

In the thread I also see:

Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Acked-by-me (Thomas Gleixner)

-- Steve


> Signed-off-by: Johannes Berg <johannes.berg@intel.com>
> ---
> v2: remove extra file
> v3: simplify length of __dynamic_array, thanks Frederic
> 
>  include/trace/events/printk.h |   41 +++++++++++++++++++++++++++++++++++++++++
>  kernel/printk.c               |    5 +++++
>  2 files changed, 46 insertions(+)
> 
> --- /dev/null	1970-01-01 00:00:00.000000000 +0000
> +++ b/include/trace/events/printk.h	2011-11-24 20:02:21.000000000 +0100
> @@ -0,0 +1,41 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM printk
> +
> +#if !defined(_TRACE_PRINTK_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_PRINTK_H
> +
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT_CONDITION(console,
> +	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
> +		 unsigned log_buf_len),
> +
> +	TP_ARGS(log_buf, start, end, log_buf_len),
> +
> +	TP_CONDITION(start != end),
> +
> +	TP_STRUCT__entry(
> +		__dynamic_array(char, msg, end - start + 1)
> +	),
> +
> +	TP_fast_assign(
> +		if ((start & (log_buf_len - 1)) > (end & (log_buf_len - 1))) {
> +			memcpy(__get_dynamic_array(msg),
> +			       log_buf + (start & (log_buf_len - 1)),
> +			       log_buf_len - (start & (log_buf_len - 1)));
> +			memcpy((char *)__get_dynamic_array(msg) +
> +			       log_buf_len - (start & (log_buf_len - 1)),
> +			       log_buf, end & (log_buf_len - 1));
> +		} else
> +			memcpy(__get_dynamic_array(msg),
> +			       log_buf + (start & (log_buf_len - 1)),
> +			       end - start);
> +		((char *)__get_dynamic_array(msg))[end - start] = 0;
> +	),
> +
> +	TP_printk("%s", __get_str(msg))
> +);
> +#endif /* _TRACE_PRINTK_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> --- a/kernel/printk.c	2011-11-24 09:38:53.000000000 +0100
> +++ b/kernel/printk.c	2011-11-24 09:42:37.000000000 +0100
> @@ -44,6 +44,9 @@
>  
>  #include <asm/uaccess.h>
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/printk.h>
> +
>  /*
>   * Architectures can override it:
>   */
> @@ -542,6 +545,8 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
>  static void _call_console_drivers(unsigned start,
>  				unsigned end, int msg_log_level)
>  {
> +	trace_console(&LOG_BUF(0), start, end, log_buf_len);
> +
>  	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
>  			console_drivers && start != end) {
>  		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
> 



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v3] printk: add console output tracing
  2012-02-13 17:30                                         ` Steven Rostedt
@ 2012-02-13 17:33                                           ` Johannes Berg
  2012-02-13 17:42                                             ` Steven Rostedt
  0 siblings, 1 reply; 47+ messages in thread
From: Johannes Berg @ 2012-02-13 17:33 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Frederic Weisbecker, Christoph Hellwig, LKML, Ingo Molnar,
	Peter Zijlstra, Thomas Gleixner

On Mon, 2012-02-13 at 12:30 -0500, Steven Rostedt wrote:
> On Thu, 2011-11-24 at 20:03 +0100, Johannes Berg wrote:
> > From: Johannes Berg <johannes.berg@intel.com>
> > 
> > Add a printk.console trace point to record any printk
> > messages into the trace, regardless of the current
> > console loglevel. This can help correlate (existing)
> > printk debugging with other tracing.
> > 
> 
> Looks like this patch got lost in the x-mas parade.
> 
> Is this the last version of the patch?
> 
> In the thread I also see:
> 
> Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
> Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Acked-by-me (Thomas Gleixner)

I don't think I made a newer version, in fact, I dropped it from my
local tree already :)

johannes



^ permalink raw reply	[flat|nested] 47+ messages in thread

* Re: [PATCH v3] printk: add console output tracing
  2012-02-13 17:33                                           ` Johannes Berg
@ 2012-02-13 17:42                                             ` Steven Rostedt
  0 siblings, 0 replies; 47+ messages in thread
From: Steven Rostedt @ 2012-02-13 17:42 UTC (permalink / raw)
  To: Johannes Berg
  Cc: Frederic Weisbecker, Christoph Hellwig, LKML, Ingo Molnar,
	Peter Zijlstra, Thomas Gleixner

On Mon, 2012-02-13 at 18:33 +0100, Johannes Berg wrote:
> On Mon, 2012-02-13 at 12:30 -0500, Steven Rostedt wrote:
> > On Thu, 2011-11-24 at 20:03 +0100, Johannes Berg wrote:
> > > From: Johannes Berg <johannes.berg@intel.com>
> > > 
> > > Add a printk.console trace point to record any printk
> > > messages into the trace, regardless of the current
> > > console loglevel. This can help correlate (existing)
> > > printk debugging with other tracing.
> > > 
> > 
> > Looks like this patch got lost in the x-mas parade.
> > 
> > Is this the last version of the patch?
> > 
> > In the thread I also see:
> > 
> > Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
> > Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > Acked-by-me (Thomas Gleixner)
> 
> I don't think I made a newer version, in fact, I dropped it from my
> local tree already :)

Well, then, I'll add it to my current queue then. I'll include the above
acked-bys too if no one is against it. Speak now if you are! ;-)

-- Steve



^ permalink raw reply	[flat|nested] 47+ messages in thread

* [tip:perf/core] printk/tracing: Add console output tracing
  2011-11-24 19:03                                       ` [PATCH v3] " Johannes Berg
  2011-11-25 17:41                                         ` Frederic Weisbecker
  2012-02-13 17:30                                         ` Steven Rostedt
@ 2012-02-17 13:52                                         ` tip-bot for Johannes Berg
  2 siblings, 0 replies; 47+ messages in thread
From: tip-bot for Johannes Berg @ 2012-02-17 13:52 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: linux-kernel, hpa, mingo, a.p.zijlstra, hch, fweisbec, rostedt,
	johannes.berg, tglx

Commit-ID:  95100358491abaa2e9a5483811370059bbca4645
Gitweb:     http://git.kernel.org/tip/95100358491abaa2e9a5483811370059bbca4645
Author:     Johannes Berg <johannes.berg@intel.com>
AuthorDate: Thu, 24 Nov 2011 20:03:08 +0100
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Mon, 13 Feb 2012 13:46:05 -0500

printk/tracing: Add console output tracing

Add a printk.console trace point to record any printk
messages into the trace, regardless of the current
console loglevel. This can help correlate (existing)
printk debugging with other tracing.

Link: http://lkml.kernel.org/r/1322161388.5366.54.camel@jlt3.sipsolutions.net

Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Christoph Hellwig <hch@infradead.org>
Cc: Ingo Molnar <mingo@redhat.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Acked-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Johannes Berg <johannes.berg@intel.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/printk.h |   41 +++++++++++++++++++++++++++++++++++++++++
 kernel/printk.c               |    5 +++++
 2 files changed, 46 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
new file mode 100644
index 0000000..94ec79c
--- /dev/null
+++ b/include/trace/events/printk.h
@@ -0,0 +1,41 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM printk
+
+#if !defined(_TRACE_PRINTK_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PRINTK_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT_CONDITION(console,
+	TP_PROTO(const char *log_buf, unsigned start, unsigned end,
+		 unsigned log_buf_len),
+
+	TP_ARGS(log_buf, start, end, log_buf_len),
+
+	TP_CONDITION(start != end),
+
+	TP_STRUCT__entry(
+		__dynamic_array(char, msg, end - start + 1)
+	),
+
+	TP_fast_assign(
+		if ((start & (log_buf_len - 1)) > (end & (log_buf_len - 1))) {
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       log_buf_len - (start & (log_buf_len - 1)));
+			memcpy((char *)__get_dynamic_array(msg) +
+			       log_buf_len - (start & (log_buf_len - 1)),
+			       log_buf, end & (log_buf_len - 1));
+		} else
+			memcpy(__get_dynamic_array(msg),
+			       log_buf + (start & (log_buf_len - 1)),
+			       end - start);
+		((char *)__get_dynamic_array(msg))[end - start] = 0;
+	),
+
+	TP_printk("%s", __get_str(msg))
+);
+#endif /* _TRACE_PRINTK_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/printk.c b/kernel/printk.c
index 13c0a11..cb8a6bd 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -44,6 +44,9 @@
 
 #include <asm/uaccess.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/printk.h>
+
 /*
  * Architectures can override it:
  */
@@ -542,6 +545,8 @@ MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to"
 static void _call_console_drivers(unsigned start,
 				unsigned end, int msg_log_level)
 {
+	trace_console(&LOG_BUF(0), start, end, log_buf_len);
+
 	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
 			console_drivers && start != end) {
 		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {

^ permalink raw reply	[flat|nested] 47+ messages in thread

end of thread, other threads:[~2012-02-17 13:53 UTC | newest]

Thread overview: 47+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2011-11-16 10:18 [PATCH] tracing: add trace console Johannes Berg
2011-11-16 14:15 ` Steven Rostedt
2011-11-16 14:25   ` Peter Zijlstra
2011-11-16 14:30     ` Johannes Berg
2011-11-16 14:41       ` Peter Zijlstra
2011-11-16 14:48       ` Steven Rostedt
2011-11-16 14:50         ` Peter Zijlstra
2011-11-16 14:51         ` Johannes Berg
2011-11-16 15:17           ` Steven Rostedt
2011-11-16 14:32   ` Thomas Gleixner
2011-11-16 14:35   ` Frederic Weisbecker
2011-11-16 15:09   ` [PATCH v2] " Johannes Berg
2011-11-16 15:17     ` Peter Zijlstra
2011-11-16 15:19     ` Steven Rostedt
2011-11-16 15:10 ` [PATCH] " Christoph Hellwig
2011-11-16 15:17   ` Johannes Berg
2011-11-16 16:41     ` Steven Rostedt
2011-11-16 16:45       ` Johannes Berg
2011-11-16 17:00         ` Steven Rostedt
2011-11-16 17:05           ` Steven Rostedt
2011-11-16 18:33           ` Johannes Berg
2011-11-16 19:57             ` Steven Rostedt
2011-11-16 20:12               ` Johannes Berg
2011-11-16 21:25               ` [PATCH] printk: add console output tracing Johannes Berg
2011-11-17  1:01                 ` Steven Rostedt
2011-11-17 14:55                 ` Frederic Weisbecker
2011-11-17 14:57                   ` Johannes Berg
2011-11-17 15:00                     ` Frederic Weisbecker
2011-11-17 15:17                       ` Steven Rostedt
2011-11-17 15:21                       ` [PATCH v2] " Johannes Berg
2011-11-18 18:44                         ` Frederic Weisbecker
2011-11-18 18:46                           ` Johannes Berg
2011-11-18 18:54                             ` Frederic Weisbecker
2011-11-18 18:59                               ` Johannes Berg
2011-11-23 13:16                                 ` Frederic Weisbecker
2011-11-24 13:21                                   ` Johannes Berg
2011-11-24 15:45                                     ` Frederic Weisbecker
2011-11-24 19:00                                       ` Johannes Berg
2011-11-25 17:43                                         ` Frederic Weisbecker
2011-11-25 18:11                                           ` Johannes Berg
2011-11-24 19:03                                       ` [PATCH v3] " Johannes Berg
2011-11-25 17:41                                         ` Frederic Weisbecker
2011-12-02 18:05                                           ` Steven Rostedt
2012-02-13 17:30                                         ` Steven Rostedt
2012-02-13 17:33                                           ` Johannes Berg
2012-02-13 17:42                                             ` Steven Rostedt
2012-02-17 13:52                                         ` [tip:perf/core] printk/tracing: Add " tip-bot for Johannes Berg

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.