Skip to contentSkip to conversation

tracing: add trace console

PATCH Superseded Johannes Berg 8 participants 47 messages Nov 16, 2011 – Feb 17, 2012 Tracing

lore
Share & tools
lore

Johannes Berg

author
#0 lore raw

PATCH 1/1 tracing: add trace console

From: Johannes Berg <[email protected]>

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 <[email protected]>
---
 kernel/trace/Kconfig         |   13 ++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 70 insertions(+)
kernel/trace/Kconfig +13 -0
@@ -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
kernel/trace/Makefile +2 -0
@@ -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
kernel/trace/trace-console.c new file +55 -0

55 lines not on this page · raw message

maintainer
#1 lore raw

[ Added Peter, Thomas and Andrew ]

Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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

Quoted 98 lines
Signed-off-by Johannes Berg <[email protected]>
---
 kernel/trace/Kconfig         |   13 ++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 70 insertions(+)
kernel/trace/Kconfig +13 -0
@@ -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
kernel/trace/Makefile +2 -0
@@ -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
kernel/trace/trace-console.c new file +55 -0
@@ -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 <[email protected]>
+ */
+#include <linux/init.h>
+#include <linux/module.h>
+#include <linux/console.h>
+
+MODULE_AUTHOR("Johannes Berg <[email protected]>");
+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);
#2 lore raw
Quoted 16 lines · Steven Rostedt

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

-- Steve

Quoted 12 lines
Signed-off-by Johannes Berg <[email protected]>
---
 kernel/trace/Kconfig         |   13 ++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 70 insertions(+)
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +0 -0
@@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
Quoted 6 lines

kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 config BLK_DEV_IO_TRACE · line 374

Quoted 6 lines
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +4 -0
        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?

Quoted 5 lines

to be able

Quoted 4 lines
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +4 -0
+       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".
author
#3 lore raw
Quoted 9 lines · Peter Zijlstra
Quoted 9 lines
Quoted 9 lines
 kernel/trace/Kconfig         |   13 ++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 70 insertions(+)
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +0 -0
@@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
Quoted 8 lines
Quoted 6 lines

kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 config BLK_DEV_IO_TRACE · line 374

Quoted 6 lines
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +4 -0
        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

#4 lore raw
Quoted 10 lines · Johannes Berg
Quoted 6 lines
Quoted 4 lines

kernel/trace/Kconfig config BLK_DEV_IO_TRACE

Quoted 4 lines
kernel/trace/Kconfig +4 -0
+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 ;-)

maintainer
#5 lore raw
In reply to Johannes Berg
Quoted 20 lines · Johannes Berg
Quoted 9 lines · Peter Zijlstra
Quoted 9 lines
Quoted 9 lines
 kernel/trace/Kconfig         |   13 ++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 70 insertions(+)
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +0 -0
@@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
Quoted 8 lines
Quoted 6 lines

kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 config BLK_DEV_IO_TRACE · line 374

Quoted 6 lines
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +4 -0
        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?

Quoted 3 lines

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

#6 lore raw
Quoted 7 lines · Steven Rostedt
Quoted 3 lines

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.

author
#7 lore raw
In reply to Steven Rostedt
Quoted 21 lines · Steven Rostedt
Quoted 20 lines · Johannes Berg
Quoted 17 lines · Peter Zijlstra
Quoted 9 lines
Quoted 9 lines
 kernel/trace/Kconfig         |   13 ++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 70 insertions(+)
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +0 -0
@@ -368,6 +368,19 @@ config BLK_DEV_IO_TRACE
Quoted 6 lines

kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 config BLK_DEV_IO_TRACE · line 374

Quoted 6 lines
kernel/trace/Kconfig 2011-11-16 11:11:35.000000000 +0100 renamed from kernel/trace/Kconfig 2011-11-16 11:11:27.000000000 +0100 +4 -0
        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?

Quoted 7 lines
Quoted 3 lines

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

maintainer
#8 lore raw
Quoted 4 lines · Johannes Berg

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

#9 lore raw
In reply to Steven Rostedt
Quoted 5 lines · Steven Rostedt

[ Added Peter, Thomas and Andrew ]

Quoted 2 lines · Johannes Berg

From: Johannes Berg <[email protected]>

Quoted 7 lines
Quoted 5 lines

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

Acked-by
#10 lore raw
In reply to Steven Rostedt
Quoted 5 lines · Steven Rostedt

[ Added Peter, Thomas and Andrew ]

Quoted 2 lines · Johannes Berg

From: Johannes Berg <[email protected]>

Quoted 7 lines
Quoted 5 lines

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 <[email protected]>

Thanks.

author
#11 lore raw

PATCH v2 1/1 tracing: add trace console

In reply to Steven Rostedt

From: Johannes Berg <[email protected]>

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 <[email protected]>

---
v2: change Kconfig wording

 kernel/trace/Kconfig         |   15 +++++++++++
 kernel/trace/Makefile        |    2 +
 kernel/trace/trace-console.c |   55 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 72 insertions(+)
kernel/trace/Kconfig +15 -0
@@ -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
kernel/trace/Makefile +2 -0
@@ -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
kernel/trace/trace-console.c new file +55 -0

55 lines not on this page · raw message

maintainer
#13 lore raw
In reply to Johannes Berg
Quoted 4 lines · Johannes Berg

From: Johannes Berg <[email protected]>

kernel/trace/Kconfig +2 -0
+config TRACE_CONSOLE
+	tristate "Support for a tracing console"

kernel/trace/Kconfig config BLK_DEV_IO_TRACE · line 382

Quoted 10 lines
kernel/trace/Kconfig +10 -0
+	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

#14 lore raw
In reply to Johannes Berg
Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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.

author
#15 lore raw
Quoted 11 lines · Christoph Hellwig
Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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

maintainer
#16 lore raw
Quoted 13 lines · Johannes Berg
Quoted 11 lines · Christoph Hellwig
Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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.

Quoted 7 lines

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

author
#17 lore raw
Quoted 10 lines · Steven Rostedt
Quoted 7 lines

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

maintainer
#18 lore raw
Quoted 4 lines · Johannes Berg

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:

kernel/printk.c +1 -0
index 1455a0d..4b8445a 100644
@@ -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

#19 lore raw

kernel/printk.c MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to" · line 545

Quoted 9 lines · Steven Rostedt
kernel/printk.c +1 -0
index 1455a0d..4b8445a 100644
@@ -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

Quoted 4 lines
kernel/printk.c +0 -0
 	if ((msg_log_level < console_loglevel || ignore_loglevel) &&
 			console_drivers && start != end) {
 		if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
author
#20 lore raw
In reply to Steven Rostedt
Quoted 23 lines · Steven Rostedt
Quoted 4 lines · Johannes Berg

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:

kernel/printk.c +1 -0
index 1455a0d..4b8445a 100644
@@ -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)) {
Quoted 2 lines

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

maintainer
#21 lore raw
Quoted 24 lines · Johannes Berg
Quoted 23 lines · Steven Rostedt
Quoted 4 lines · Johannes Berg

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:

kernel/printk.c +1 -0
index 1455a0d..4b8445a 100644
@@ -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)) {
Quoted 7 lines
Quoted 2 lines

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

author
#22 lore raw
Quoted 33 lines · Steven Rostedt
Quoted 24 lines · Johannes Berg
Quoted 23 lines · Steven Rostedt
Quoted 4 lines · Johannes Berg

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:

kernel/printk.c +1 -0
index 1455a0d..4b8445a 100644
@@ -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)) {
Quoted 7 lines
Quoted 2 lines

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.

Quoted 2 lines

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

author
#23 lore raw

PATCH 1/1 printk: add console output tracing

In reply to Steven Rostedt

From: Johannes Berg <[email protected]>

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 <[email protected]>
---
 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(+)
include/trace/events/printk.h new file +44 -0
@@ -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>
kernel/printk.c +3 -0
@@ -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)) {
kernel/trace/printk-trace.c new file +14 -0
@@ -0,0 +1,14 @@
+/*
+ * printk trace points
+ *
+ * Copyright (C) 2011 Johannes Berg <[email protected]>
+ */
+
+#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>
kernel/trace/Makefile +1 -0
@@ -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
maintainer
#24 lore raw

Re: [PATCH] printk: add console output tracing

Thomas, Peter, Frederic, Christoph,

Would you ack this patch please.

Thanks,

-- Steve

Quoted 109 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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 <[email protected]>
---
 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(+)
include/trace/events/printk.h new file +44 -0
@@ -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>
kernel/printk.c +3 -0
@@ -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)) {
kernel/trace/printk-trace.c new file +14 -0
@@ -0,0 +1,14 @@
+/*
+ * printk trace points
+ *
+ * Copyright (C) 2011 Johannes Berg <[email protected]>
+ */
+
+#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>
kernel/trace/Makefile +1 -0
@@ -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
#25 lore raw

Re: [PATCH] printk: add console output tracing

In reply to Johannes Berg
Quoted 14 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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 <[email protected]>
---
 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>

Quoted 7 lines
kernel/trace/printk-trace.c new file +4 -0
@@ -0,0 +1,14 @@
+/*
+ * printk trace points
+ *
+ * Copyright (C) 2011 Johannes Berg <[email protected]>

kernel/trace/printk-trace.c line 14

Quoted 10 lines
kernel/trace/printk-trace.c new file +10 -0
+ */
+
+#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 ?

author
#26 lore raw

Re: [PATCH] printk: add console output tracing

Quoted 10 lines · Frederic Weisbecker
Quoted 10 lines

+++ b/kernel/trace/printk-trace.c 2011-11-16 21:22:20.000000000 +0100

kernel/trace/printk-trace.c new file +8 -0
@@ -0,0 +1,14 @@
+/*
+ * printk trace points
+ *
+ * Copyright (C) 2011 Johannes Berg <[email protected]>
+ */
+
+#include <linux/string.h>
+#include <linux/types.h>
Quoted 8 lines

kernel/trace/printk-trace.c line 14

Quoted 6 lines
kernel/trace/printk-trace.c new file +6 -0
+#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

#27 lore raw

Re: [PATCH] printk: add console output tracing

Quoted 21 lines · Johannes Berg
Quoted 10 lines · Frederic Weisbecker
Quoted 10 lines

+++ b/kernel/trace/printk-trace.c 2011-11-16 21:22:20.000000000 +0100

kernel/trace/printk-trace.c new file +8 -0
@@ -0,0 +1,14 @@
+/*
+ * printk trace points
+ *
+ * Copyright (C) 2011 Johannes Berg <[email protected]>
+ */
+
+#include <linux/string.h>
+#include <linux/types.h>
Quoted 8 lines

kernel/trace/printk-trace.c line 14

Quoted 6 lines
kernel/trace/printk-trace.c new file +6 -0
+#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 ?

Quoted 7 lines

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.

maintainer
#28 lore raw

Re: [PATCH] printk: add console output tracing

Quoted 13 lines · Frederic Weisbecker
Quoted 12 lines · Johannes Berg
Quoted 10 lines · Frederic Weisbecker
Quoted 10 lines

+++ b/kernel/trace/printk-trace.c 2011-11-16 21:22:20.000000000 +0100

kernel/trace/printk-trace.c new file +8 -0
@@ -0,0 +1,14 @@
+/*
+ * printk trace points
+ *
+ * Copyright (C) 2011 Johannes Berg <[email protected]>
+ */
+
+#include <linux/string.h>
+#include <linux/types.h>
Quoted 8 lines
Quoted 8 lines
Quoted 8 lines

kernel/trace/printk-trace.c line 14

Quoted 6 lines
kernel/trace/printk-trace.c new file +6 -0
+#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 ;-)

Quoted 11 lines
Quoted 8 lines

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:

Quoted 7 lines

#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

author
#29 lore raw

PATCH v2 1/1 printk: add console output tracing

In reply to Frederic Weisbecker

From: Johannes Berg <[email protected]>

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 <[email protected]>

---
v2: remove extra file

 include/trace/events/printk.h |   44 ++++++++++++++++++++++++++++++++++++++++++
 kernel/printk.c               |    5 ++++
 2 files changed, 49 insertions(+)
include/trace/events/printk.h new file +44 -0
@@ -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>
kernel/printk.c +5 -0
@@ -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)) {
#30 lore raw

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

Quoted 28 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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 <[email protected]>

---
v2: remove extra file

 include/trace/events/printk.h |   44 ++++++++++++++++++++++++++++++++++++++++++
 kernel/printk.c               |    5 ++++
 2 files changed, 49 insertions(+)
include/trace/events/printk.h new file +10 -0
@@ -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,

include/trace/events/printk.h line 20

Quoted 10 lines
include/trace/events/printk.h new file +10 -0
+		 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.

Quoted 47 lines
include/trace/events/printk.h new file +24 -0
+	),
+
+	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>
kernel/printk.c +5 -0
@@ -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)) {
author
#31 lore raw

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

Quoted 8 lines · Frederic Weisbecker
Quoted 8 lines
include/trace/events/printk.h new file +8 -0
+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),
+
Quoted 8 lines

include/trace/events/printk.h line 20

Quoted 4 lines
include/trace/events/printk.h new file +4 -0
+	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

#32 lore raw

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

Quoted 19 lines · Johannes Berg
Quoted 8 lines · Frederic Weisbecker
Quoted 8 lines
include/trace/events/printk.h new file +8 -0
+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),
+
Quoted 8 lines

include/trace/events/printk.h line 20

Quoted 4 lines
include/trace/events/printk.h new file +4 -0
+	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()

Quoted 2 lines

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)
author
#33 lore raw

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

Quoted 20 lines · Frederic Weisbecker
Quoted 19 lines · Johannes Berg
Quoted 16 lines · Frederic Weisbecker

include/trace/events/printk.h line 20

Quoted 12 lines
include/trace/events/printk.h new file +12 -0
+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()

Quoted 8 lines
Quoted 2 lines

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

#34 lore raw

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

Quoted 24 lines · Johannes Berg
Quoted 23 lines · Frederic Weisbecker
Quoted 21 lines · Johannes Berg
Quoted 8 lines · Frederic Weisbecker
Quoted 8 lines
include/trace/events/printk.h new file +8 -0
+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),
+
Quoted 8 lines

include/trace/events/printk.h line 20

Quoted 4 lines
include/trace/events/printk.h new file +4 -0
+	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.

Quoted 7 lines
Quoted 5 lines

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.

Quoted 3 lines

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

Quoted 3 lines

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

Quoted 1 line

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

author
#35 lore raw

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

Quoted 6 lines · Frederic Weisbecker
Quoted 2 lines

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?

Quoted 5 lines
Quoted 2 lines

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

:-)

Quoted 5 lines
Quoted 1 line

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

#36 lore raw

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

Quoted 11 lines · Johannes Berg
Quoted 6 lines · Frederic Weisbecker
Quoted 2 lines

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.

Quoted 15 lines
Quoted 6 lines
Quoted 3 lines

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

:-)

Quoted 5 lines
Quoted 1 line

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

Quoted 6 lines

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

author
#37 lore raw

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

Quoted 5 lines · Frederic Weisbecker
Quoted 4 lines

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.

Quoted 7 lines

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.

Quoted 6 lines

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.

Quoted 3 lines

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

#38 lore raw

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

Quoted 24 lines · Johannes Berg
Quoted 5 lines · Frederic Weisbecker
Quoted 4 lines

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.

Quoted 7 lines

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.

Quoted 6 lines

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.

Quoted 3 lines

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

Quoted 6 lines
Quoted 4 lines

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

Quoted 5 lines

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.

Quoted 3 lines

johannes

author
#39 lore raw

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

Quoted 8 lines · Frederic Weisbecker
Quoted 5 lines
Quoted 3 lines

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

author
#40 lore raw

PATCH v3 1/1 printk: add console output tracing

In reply to Frederic Weisbecker

From: Johannes Berg <[email protected]>

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 <[email protected]>

---
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(+)
include/trace/events/printk.h new file +41 -0
@@ -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>
kernel/printk.c +5 -0
@@ -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)) {
maintainer
#42 lore raw

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

Quoted 8 lines · Frederic Weisbecker
Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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.

Quoted 5 lines
Quoted 1 line
Signed-off-by Johannes Berg <[email protected]>

Thanks!

Acked-by Frederic Weisbecker <[email protected]>

Is everyone happy with this change?

Should I pull it into my queue for 3.3?

-- Steve

maintainer Acked-by Frederic Weisbecker Acked-by Peter Zijlstra on v3 1/1
#43 lore raw

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

In reply to Johannes Berg
Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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 <[email protected]>
Acked-by Peter Zijlstra <[email protected]>

Acked-by-me (Thomas Gleixner)

-- Steve

Quoted 75 lines
Signed-off-by Johannes Berg <[email protected]>

---
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(+)
include/trace/events/printk.h new file +41 -0
@@ -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>
kernel/printk.c +5 -0
@@ -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)) {
author
#44 lore raw

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

Quoted 11 lines · Steven Rostedt
Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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.

Quoted 7 lines

Is this the last version of the patch?

In the thread I also see:

Acked-by Frederic Weisbecker <[email protected]>
Acked-by Peter Zijlstra <[email protected]>

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

maintainer
#45 lore raw

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

Quoted 14 lines · Johannes Berg
Quoted 13 lines · Steven Rostedt
Quoted 7 lines · Johannes Berg

From: Johannes Berg <[email protected]>

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?

Quoted 8 lines
Quoted 5 lines

In the thread I also see:

Acked-by Frederic Weisbecker <[email protected]>
Acked-by Peter Zijlstra <[email protected]>

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

#46 lore raw

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

In reply to Johannes Berg
Commit-ID:  95100358491abaa2e9a5483811370059bbca4645
Gitweb:     http://git.kernel.org/tip/95100358491abaa2e9a5483811370059bbca4645
Author:     Johannes Berg <[email protected]>
AuthorDate: Thu, 24 Nov 2011 20:03:08 +0100
Committer:  Steven Rostedt <[email protected]>
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/[email protected] open here
Acked-by Frederic Weisbecker <[email protected]>
Cc Christoph Hellwig <[email protected]>
Cc Ingo Molnar <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Acked-by Thomas Gleixner <[email protected]>
Signed-off-by Johannes Berg <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 include/trace/events/printk.h |   41 +++++++++++++++++++++++++++++++++++++++++
 kernel/printk.c               |    5 +++++
 2 files changed, 46 insertions(+), 0 deletions(-)
include/trace/events/printk.h new file +41 -0
new file mode 100644
index 0000000..94ec79c
@@ -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>
kernel/printk.c +5 -0
index 13c0a11..cb8a6bd 100644
@@ -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)) {