[PATCH] tracing: add trace console

[PATCH] tracing: add trace console

[Johannes Berg]

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);

Re: [PATCH] tracing: add trace console

[Steven Rostedt]

[ 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);
> 

Re: [PATCH] tracing: add trace console

[Peter Zijlstra]

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". 

Re: [PATCH] tracing: add trace console

[Johannes Berg]

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

Re: [PATCH] tracing: add trace console

[Peter Zijlstra]

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 ;-)

Re: [PATCH] tracing: add trace console

[Steven Rostedt]

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

Re: [PATCH] tracing: add trace console

[Peter Zijlstra]

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.

Re: [PATCH] tracing: add trace console

[Johannes Berg]

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

Re: [PATCH] tracing: add trace console

[Steven Rostedt]

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

Re: [PATCH] tracing: add trace console

[Thomas Gleixner]

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

Re: [PATCH] tracing: add trace console

[Frederic Weisbecker]

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.

[PATCH v2] tracing: add trace console

[Johannes Berg]

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);

Re: [PATCH v2] tracing: add trace console

[Peter Zijlstra]

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>

Re: [PATCH v2] tracing: add trace console

[Steven Rostedt]

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

Re: [PATCH] tracing: add trace console

[Christoph Hellwig]

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.

Re: [PATCH] tracing: add trace console

[Johannes Berg]

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

Re: [PATCH] tracing: add trace console

[Steven Rostedt]

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

Re: [PATCH] tracing: add trace console

[Johannes Berg]

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

Re: [PATCH] tracing: add trace console

[Steven Rostedt]

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

Re: [PATCH] tracing: add trace console

[Steven Rostedt]

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)) {
> 

Re: [PATCH] tracing: add trace console

[Johannes Berg]

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

Re: [PATCH] tracing: add trace console

[Steven Rostedt]

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

Re: [PATCH] tracing: add trace console

[Johannes Berg]

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

[PATCH] printk: add console output tracing

[Johannes Berg]

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

Re: [PATCH] printk: add console output tracing

[Steven Rostedt]

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
> 

Re: [PATCH] printk: add console output tracing

[Frederic Weisbecker]

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 ?

Re: [PATCH] printk: add console output tracing

[Johannes Berg]

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

Re: [PATCH] printk: add console output tracing

[Frederic Weisbecker]

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.

Re: [PATCH] printk: add console output tracing

[Steven Rostedt]

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

[PATCH v2] printk: add console output tracing

[Johannes Berg]

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)) {

Re: [PATCH v2] printk: add console output tracing

[Frederic Weisbecker]

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)) {
> 
> 

Re: [PATCH v2] printk: add console output tracing

[Johannes Berg]

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

Re: [PATCH v2] printk: add console output tracing

[Frederic Weisbecker]

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)

Re: [PATCH v2] printk: add console output tracing

[Johannes Berg]

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

Re: [PATCH v2] printk: add console output tracing

[Frederic Weisbecker]

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...

Re: [PATCH v2] printk: add console output tracing

[Johannes Berg]

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

Re: [PATCH v2] printk: add console output tracing

[Frederic Weisbecker]

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...

Re: [PATCH v2] printk: add console output tracing

[Johannes Berg]

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

Re: [PATCH v2] printk: add console output tracing

[Frederic Weisbecker]

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
> 

Re: [PATCH v2] printk: add console output tracing

[Johannes Berg]

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

[PATCH v3] printk: add console output tracing

[Johannes Berg]

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)) {

Re: [PATCH v3] printk: add console output tracing

[Frederic Weisbecker]

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>

Re: [PATCH v3] printk: add console output tracing

[Steven Rostedt]

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

Re: [PATCH v3] printk: add console output tracing

[Steven Rostedt]

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)) {
> 

Re: [PATCH v3] printk: add console output tracing

[Johannes Berg]

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

Re: [PATCH v3] printk: add console output tracing

[Steven Rostedt]

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

[tip:perf/core] printk/tracing: Add console output tracing

[tip-bot for Johannes Berg]

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)) {