dmesg Support

dmesg Support

[Sascha Hauer]

Printing informations during startup is very useful, but due to slow serial
printouts it adds to the startup time of barebox. This series adds logbuffer
support and a 'dmesg' command, so it becomes possible to reduce the loglevel
while the messages are still available later. As a bonus the timestamp for
each message is recorded so that together with CONFIG_DEBUG_INITCALLS detailed
timing information of the startup process can be collected.
The dmesg support nearly compiles away when it's disabled.

Sascha

----------------------------------------------------------------
Sascha Hauer (4):
      clock: Add a variable with the first timestamp after startup
      clock: make get_time_ns() safe to be called without clocksource
      startup: Don't print multiple lines with pr_info
      Introduce message logging support

 commands/Kconfig        |   7 +++
 commands/Makefile       |   1 +
 commands/dmesg.c        | 100 +++++++++++++++++++++++++++++++++++++
 common/Kconfig          |   3 ++
 common/clock.c          |  11 +++++
 common/console_common.c | 129 ++++++++++++++++++++++++++++++++++++++++++++++--
 common/version.c        |   4 +-
 drivers/base/driver.c   |  22 ---------
 include/clock.h         |   2 +
 include/printk.h        |  17 +++++++
 10 files changed, 270 insertions(+), 26 deletions(-)
 create mode 100644 commands/dmesg.c

_______________________________________________
barebox mailing list
barebox@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/barebox

[PATCH 1/4] clock: Add a variable with the first timestamp after startup

[Sascha Hauer]

For measuring the startup time it's useful to save the first
timestamp after the clocksource has been registered.

Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
---
 common/clock.c  | 8 ++++++++
 include/clock.h | 2 ++
 2 files changed, 10 insertions(+)

diff --git a/common/clock.c b/common/clock.c
index 9c7c1ba..2dae9ff 100644
--- a/common/clock.c
+++ b/common/clock.c
@@ -29,6 +29,12 @@
 static struct clocksource *current_clock;
 static uint64_t time_ns;
 
+/*
+ * The first timestamp when the clocksource is registered.
+ * Useful for measuring the time spent in barebox.
+ */
+uint64_t time_beginning;
+
 /**
  * get_time_ns - get current timestamp in nanoseconds
  */
@@ -180,5 +186,7 @@ EXPORT_SYMBOL(mdelay);
 int init_clock(struct clocksource *cs)
 {
 	current_clock = cs;
+	time_beginning = get_time_ns();
+
 	return 0;
 }
diff --git a/include/clock.h b/include/clock.h
index a169790..691befc 100644
--- a/include/clock.h
+++ b/include/clock.h
@@ -43,6 +43,8 @@ void mdelay(unsigned long msecs);
 #define MSECOND ((uint64_t)(1000 * 1000))
 #define USECOND ((uint64_t)(1000))
 
+extern uint64_t time_beginning;
+
 /*
  * Convenience wrapper to implement a typical polling loop with
  * timeout. returns 0 if the condition became true within the
-- 
2.1.0


_______________________________________________
barebox mailing list
barebox@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/barebox

[PATCH 2/4] clock: make get_time_ns() safe to be called without clocksource

[Sascha Hauer]

make it possible to call get_time_ns() before the clocksource
has been registered. Just return 0 in this case which is still
better than crashing the system.

Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
---
 common/clock.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/common/clock.c b/common/clock.c
index 2dae9ff..76ce881 100644
--- a/common/clock.c
+++ b/common/clock.c
@@ -44,6 +44,9 @@ uint64_t get_time_ns(void)
         uint64_t cycle_now, cycle_delta;
         uint64_t ns_offset;
 
+	if (!cs)
+		return 0;
+
         /* read clocksource: */
 	cycle_now = cs->read() & cs->mask;
 
-- 
2.1.0


_______________________________________________
barebox mailing list
barebox@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/barebox

[PATCH 3/4] startup: Don't print multiple lines with pr_info

[Sascha Hauer]

Print the banner with pr_info, but the empty lines before and after
it with printf. This makes the banner show up in the log show up
properly.

Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
---
 common/version.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/common/version.c b/common/version.c
index 51d4d48..f37cb55 100644
--- a/common/version.c
+++ b/common/version.c
@@ -12,6 +12,8 @@ EXPORT_SYMBOL(release_string);
 
 void barebox_banner (void)
 {
-	pr_info("\n\n%s\n\n", version_string);
+	printf("\n\n");
+	pr_info("%s", version_string);
+	printf("\n\n");
 	pr_info("Board: %s\n", barebox_get_model());
 }
-- 
2.1.0


_______________________________________________
barebox mailing list
barebox@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/barebox

[PATCH 4/4] Introduce message logging support

[Sascha Hauer]

This adds a buffer for log messages and a 'dmesg' command to
print the messages. The log buffer is implemented as log objects
rather than a string buffer. This makes it easy to implement
limiting the messages, cleaning the buffer and timestamping
the messages.

Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
---
 commands/Kconfig        |   7 +++
 commands/Makefile       |   1 +
 commands/dmesg.c        | 100 +++++++++++++++++++++++++++++++++++++
 common/Kconfig          |   3 ++
 common/console_common.c | 129 ++++++++++++++++++++++++++++++++++++++++++++++--
 drivers/base/driver.c   |  22 ---------
 include/printk.h        |  17 +++++++
 7 files changed, 254 insertions(+), 25 deletions(-)
 create mode 100644 commands/dmesg.c

diff --git a/commands/Kconfig b/commands/Kconfig
index 3a49baf..f0cd8b2 100644
--- a/commands/Kconfig
+++ b/commands/Kconfig
@@ -84,6 +84,13 @@ config CMD_DEVINFO
 	  If called with a device path being the argument, devinfo shows more
 	  default information about this device and its parameters.
 
+config CMD_DMESG
+	tristate
+	prompt "dmesg"
+	select LOGBUF
+	help
+	  Print or control the log message buffer.
+
 config CMD_DRVINFO
 	tristate
 	default y
diff --git a/commands/Makefile b/commands/Makefile
index 52b6137..608ff5e 100644
--- a/commands/Makefile
+++ b/commands/Makefile
@@ -81,6 +81,7 @@ obj-$(CONFIG_CMD_IOMEM)		+= iomemport.o
 obj-$(CONFIG_CMD_LINUX_EXEC)	+= linux_exec.o
 obj-$(CONFIG_CMD_AUTOMOUNT)	+= automount.o
 obj-$(CONFIG_CMD_GLOBAL)	+= global.o
+obj-$(CONFIG_CMD_DMESG)		+= dmesg.o
 obj-$(CONFIG_CMD_BASENAME)	+= basename.o
 obj-$(CONFIG_CMD_DIRNAME)	+= dirname.o
 obj-$(CONFIG_CMD_READLINK)	+= readlink.o
diff --git a/commands/dmesg.c b/commands/dmesg.c
new file mode 100644
index 0000000..b2bb334
--- /dev/null
+++ b/commands/dmesg.c
@@ -0,0 +1,100 @@
+/*
+ * dmesg.c - barebox logbuffer handling
+ *
+ * Copyright (c) 2014 Sascha Hauer <s.hauer@pengutronix.de>, Pengutronix
+ *
+ * See file CREDITS for list of people who contributed to this
+ * project.
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2
+ * as published by the Free Software Foundation.
+ *
+ * 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.
+ *
+ */
+#include <common.h>
+#include <malloc.h>
+#include <command.h>
+#include <globalvar.h>
+#include <environment.h>
+#include <getopt.h>
+#include <clock.h>
+
+static int do_dmesg(int argc, char *argv[])
+{
+	int opt, i;
+	int delete_buf = 0, emit = 0;
+	unsigned flags = 0;
+
+	while ((opt = getopt(argc, argv, "ctde")) > 0) {
+		switch (opt) {
+		case 'c':
+			delete_buf = 1;
+			break;
+		case 't':
+			flags |= BAREBOX_LOG_PRINT_TIME;
+			break;
+		case 'd':
+			flags |= BAREBOX_LOG_DIFF_TIME;
+			break;
+		case 'e':
+			emit = 1;
+			break;
+		default:
+			return COMMAND_ERROR_USAGE;
+		}
+	}
+
+	if (emit) {
+		char *buf;
+		int len = 0;
+
+		for (i = optind; i < argc; i++)
+			len += strlen(argv[i]) + 1;
+
+		buf = malloc(len + 2);
+		if (!buf)
+			return -ENOMEM;
+
+		len = 0;
+
+		for (i = optind; i < argc; i++)
+			len += sprintf(buf + len, "%s ", argv[i]);
+
+		*(buf + len) = '\n';
+		*(buf + len + 1) = 0;
+
+		pr_info(buf);
+
+		free(buf);
+
+		return 0;
+	}
+
+	log_print(flags);
+
+	if (delete_buf)
+		log_clean(10);
+
+	return 0;
+}
+
+BAREBOX_CMD_HELP_START(dmesg)
+BAREBOX_CMD_HELP_TEXT("Options:")
+BAREBOX_CMD_HELP_OPT ("-c",		"Delete messages after printing them")
+BAREBOX_CMD_HELP_OPT ("-d",		"Show a time delta to the last message")
+BAREBOX_CMD_HELP_OPT ("-e <msg>",	"Emit a log message")
+BAREBOX_CMD_HELP_OPT ("-t",		"Show timestamp informations")
+BAREBOX_CMD_HELP_END
+
+BAREBOX_CMD_START(dmesg)
+	.cmd	= do_dmesg,
+	BAREBOX_CMD_DESC("Print or control log messages")
+	BAREBOX_CMD_OPTS("[-cdet]")
+	BAREBOX_CMD_GROUP(CMD_GRP_INFO)
+	BAREBOX_CMD_HELP(cmd_dmesg_help)
+BAREBOX_CMD_END
diff --git a/common/Kconfig b/common/Kconfig
index 9cc96b7..4a84cfa 100644
--- a/common/Kconfig
+++ b/common/Kconfig
@@ -66,6 +66,9 @@ config UIMAGE
 	select CRC32
 	bool
 
+config LOGBUF
+	bool
+
 config GLOBALVAR
 	bool
 
diff --git a/common/console_common.c b/common/console_common.c
index cc184df..cc25f97 100644
--- a/common/console_common.c
+++ b/common/console_common.c
@@ -27,6 +27,9 @@
 #include <globalvar.h>
 #include <magicvar.h>
 #include <password.h>
+#include <clock.h>
+#include <malloc.h>
+#include <asm-generic/div64.h>
 
 #ifndef CONFIG_CONSOLE_NONE
 
@@ -59,31 +62,151 @@ void console_allow_input(bool val)
 
 int barebox_loglevel = CONFIG_DEFAULT_LOGLEVEL;
 
+LIST_HEAD(barebox_logbuf);
+static int barebox_logbuf_num_messages;
+static int barebox_log_max_messages = 1000;
+
+static void log_del(struct log_entry *log)
+{
+	free(log->msg);
+	list_del(&log->list);
+	free(log);
+	barebox_logbuf_num_messages--;
+}
+
+/**
+ * log_clean - delete log messages from buffer
+ *
+ * @limit:	The maximum messages left in the buffer after
+ *		calling this function.
+ *
+ * This function deletes all messages in the logbuf exeeding
+ * the limit.
+ */
+void log_clean(unsigned int limit)
+{
+	struct log_entry *log, *tmp;
+
+	if (list_empty(&barebox_logbuf))
+		return;
+
+	list_for_each_entry_safe(log, tmp, &barebox_logbuf, list) {
+		if (barebox_logbuf_num_messages <= limit)
+			break;
+		log_del(log);
+	}
+}
+
+void pr_puts(int level, const char *str)
+{
+	struct log_entry *log;
+
+	if (IS_ENABLED(CONFIG_LOGBUF)) {
+		if (barebox_log_max_messages > 0)
+			log_clean(barebox_log_max_messages - 1);
+
+		if (barebox_log_max_messages >= 0) {
+			log = xzalloc(sizeof(*log));
+			log->msg = xstrdup(str);
+			log->timestamp = get_time_ns();
+			log->level = level;
+			list_add_tail(&log->list, &barebox_logbuf);
+			barebox_logbuf_num_messages++;
+		}
+	}
+
+	if (level > barebox_loglevel)
+		return;
+
+	puts(str);
+}
+
 int pr_print(int level, const char *fmt, ...)
 {
 	va_list args;
 	uint i;
 	char printbuffer[CFG_PBSIZE];
 
-	if (level > barebox_loglevel)
+	if (!IS_ENABLED(CONFIG_LOGBUF) && level > barebox_loglevel)
 		return 0;
 
 	va_start(args, fmt);
 	i = vsprintf(printbuffer, fmt, args);
 	va_end(args);
 
-	/* Print the string */
-	puts(printbuffer);
+	pr_puts(level, printbuffer);
 
 	return i;
 }
 
+int dev_printf(int level, const struct device_d *dev, const char *format, ...)
+{
+	va_list args;
+	int ret = 0;
+	char printbuffer[CFG_PBSIZE];
+
+	if (!IS_ENABLED(CONFIG_LOGBUF) && level > barebox_loglevel)
+		return 0;
+
+	if (dev->driver && dev->driver->name)
+		ret += sprintf(printbuffer, "%s ", dev->driver->name);
+
+	ret += sprintf(printbuffer + ret, "%s: ", dev_name(dev));
+
+	va_start(args, format);
+
+	ret += vsprintf(printbuffer + ret, format, args);
+
+	va_end(args);
+
+	pr_puts(level, printbuffer);
+
+	return ret;
+}
+
 static int loglevel_init(void)
 {
+	if (IS_ENABLED(CONFIG_LOGBUF))
+		globalvar_add_simple_int("log_max_messages",
+				&barebox_log_max_messages, "%d");
+
 	return globalvar_add_simple_int("loglevel", &barebox_loglevel, "%d");
 }
 device_initcall(loglevel_init);
 
+void log_print(unsigned flags)
+{
+	struct log_entry *log;
+	unsigned long last = 0;
+
+	list_for_each_entry(log, &barebox_logbuf, list) {
+		uint64_t diff = log->timestamp - time_beginning;
+		unsigned long difful;
+
+		do_div(diff, 1000);
+		difful = diff;
+
+		if (!log->timestamp)
+			difful = 0;
+
+		if (flags & (BAREBOX_LOG_PRINT_TIME | BAREBOX_LOG_DIFF_TIME))
+			printf("[");
+
+		if (flags & BAREBOX_LOG_PRINT_TIME)
+			printf("%10luus", difful);
+
+		if (flags & BAREBOX_LOG_DIFF_TIME) {
+			printf(" < %10luus", difful - last);
+			last = difful;
+		}
+
+		if (flags & (BAREBOX_LOG_PRINT_TIME | BAREBOX_LOG_DIFF_TIME))
+			printf("] ");
+
+		printf("%s", log->msg);
+	}
+}
+
 int printf(const char *fmt, ...)
 {
 	va_list args;
diff --git a/drivers/base/driver.c b/drivers/base/driver.c
index 2cf3ee6..9709415 100644
--- a/drivers/base/driver.c
+++ b/drivers/base/driver.c
@@ -377,28 +377,6 @@ const char *dev_id(const struct device_d *dev)
 	return buf;
 }
 
-int dev_printf(int level, const struct device_d *dev, const char *format, ...)
-{
-	va_list args;
-	int ret = 0;
-
-	if (level > barebox_loglevel)
-		return 0;
-
-	if (dev->driver && dev->driver->name)
-		ret += printf("%s ", dev->driver->name);
-
-	ret += printf("%s: ", dev_name(dev));
-
-	va_start(args, format);
-
-	ret += vprintf(format, args);
-
-	va_end(args);
-
-	return ret;
-}
-
 void devices_shutdown(void)
 {
 	struct device_d *dev;
diff --git a/include/printk.h b/include/printk.h
index 4543156..fb63586 100644
--- a/include/printk.h
+++ b/include/printk.h
@@ -72,4 +72,21 @@ int dev_printf(int level, const struct device_d *dev, const char *format, ...)
 #define debug(fmt, arg...)	__pr_printk(7, pr_fmt(fmt), ##arg)
 #define pr_vdebug(fmt, arg...)	__pr_printk(8, pr_fmt(fmt), ##arg)
 
+struct log_entry {
+	struct list_head list;
+	char *msg;
+	void *dummy;
+	uint64_t timestamp;
+	int level;
+};
+
+extern struct list_head barebox_logbuf;
+
+extern void log_clean(unsigned int limit);
+
+#define BAREBOX_LOG_PRINT_TIME	(1 << 0)
+#define BAREBOX_LOG_DIFF_TIME	(1 << 1)
+
+void log_print(unsigned flags);
+
 #endif
-- 
2.1.0


_______________________________________________
barebox mailing list
barebox@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/barebox