[RESEND RFC PATCH 0/5] Add a hash value for each line in /dev/kmsg

[RESEND RFC PATCH 0/5] Add a hash value for each line in /dev/kmsg

[Hidehiro Kawai]

Hello,

I resend patches as there was no reply.  Any comments are welcome.

Changes from the previous post:
- Rebased to 3.11-rc2
- Update the explanation in the cover mail a bit

Brief description
=================
This patch series adds hash values of printk format strings into
each line of /dev/kmsg outputs as follows:

        6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs

These hash values allow use space to identify messages easily and
do valuable things.  There is no guarantee that the hash values
are unique.  However, user space can know which one collides to
others from a message-and-hash catalog generated at build time, so
finally it should be able to identify the messages.  User space
can also use filename:lineno information to do that, although the
information is not portable among various kernel versions.


Background
==========
We sometimes want to identify each kernel message automatically
because of the following purposes:

(1) Show more detailed information about the message by cooperating
    with external system
(2) Take actions automatically depending on the message, for example
    trigger a fail over or collect related information to analyze the
    problem

However, most of printk messages have dynamically generated parts,
so it is difficult to identify the messages.  Even if you can, it will
be expensive.

To solve this issue, this patch series add a hash value of each
printk format string.  A catalog file which consists of hash, location,
and format string lines is also generated at the kernel build time.
User space tools can easily identify kernel messages by utilizing the
catalog file.


Design
======
Hash values are displayed only when reading /dev/kmsg.  Console and
/proc/kmsg outputs are not affected by this feature.

The format in /dev/kmsg output is like this:

        6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs

The 5th field is added, and it means "<32-bit hash>@<filename>:<lineno>".
If you disable this feature (CONFIG_KMSG_HASH=n) or any cases the
hash value is not calculated, the 5th field shows '-'.

The function printk() is replaced with macro version to create
a metadata table which is used to calculate and keep hash values.
Hash value calculation is done at the kernel build time, but not
execution time.  scripts/msghash tools scan the metadata table in
vmlinux, calculate hash values, and put them back into the table.
At the same time, msghash creates a catalog file named
"<objfile>.msglist".  Here is an example of its contents:

    ...
    b6be0058@init/main.c:180,"Parameter %s is obsolete, ignored"
    72dfe336@init/main.c:403,"Malformed early option '%s'"
    85788d36@init/do_mounts.c:573,"Waiting for root device %s..."
    ...

The format is <32-bit hash>@<filename>:<lineno>,"<message format>".
Similar to /dev/kmsg, unprintable characters in message formats
are escaped and a trailing newline is dropped.


Restrictions
============
Currently, only printk, pr_xxx, dev_printk, and dev_xxx are supported
except for pr_debug with dynamic printk.  Other printk variants won't
show meaningful hash values.  I'm going to support some of them in
the future patches.

KERN_CONT cases are not dealt with well.  Only the first printk's
hash is output and continued printks are ignored.

Kernel module support has not been implemented yet.  I'm going to do
this in the future patches.


Note
====
When CONFIG_KMSG_HASH=y, a metadata table and additional file name
strings are allocated in object files, and it increases the kernel
size.  Below is the difference of CONFIG_KMSG_HASH=n/y in some
configuration.  The total size increases about 2%.

   text    data     bss     dec     hex filename
8135284 2395144 2211840 12742268         c26e7c vmlinux_hash_disabled
8255079 2519368 2211840 12986287         c627af vmlinux_hash_enabled


Thanks,
---

Hidehiro Kawai (5):
      printk: Add msghash support for dev_printk
      msghash: Add userland msghash tool
      tools/include: Add jhash.h
      printk: add message hash values in /dev/kmsg output
      printk: make printk a macro


 .gitignore                        |    1 
 Makefile                          |    7 +
 drivers/base/core.c               |   57 ++-------
 drivers/usb/storage/debug.c       |    2 
 include/asm-generic/vmlinux.lds.h |    5 +
 include/linux/device.h            |   73 +++++++----
 include/linux/kmsghash.h          |   19 +++
 include/linux/printk.h            |   31 ++++-
 kernel/printk.c                   |   81 +++++++++---
 lib/Kconfig.debug                 |   22 +++
 lib/dynamic_debug.c               |    4 -
 net/core/dev.c                    |    2 
 scripts/Makefile                  |    1 
 scripts/link-vmlinux.sh           |    5 +
 scripts/msghash/.gitignore        |    1 
 scripts/msghash/Makefile          |    7 +
 scripts/msghash/msghash.c         |  241 +++++++++++++++++++++++++++++++++++++
 scripts/msghash/msghash.sh        |   45 +++++++
 tools/include/tools/jhash.h       |  192 +++++++++++++++++++++++++++++
 19 files changed, 698 insertions(+), 98 deletions(-)
 create mode 100644 include/linux/kmsghash.h
 create mode 100644 scripts/msghash/.gitignore
 create mode 100644 scripts/msghash/Makefile
 create mode 100644 scripts/msghash/msghash.c
 create mode 100755 scripts/msghash/msghash.sh
 create mode 100644 tools/include/tools/jhash.h

-- 
Hidehiro Kawai
Hitach, Yokohama Research Laboratory
Linux Technology Center

[RESEND RFC PATCH 2/5] printk: add message hash values in /dev/kmsg output

[Hidehiro Kawai]

This patch adds the hash value for each printk line when reading
/dev/kmsg as bellow:

	6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs

Here, the 5th field is the 32-bit hash value followed by
@<filename>:<lineno>.  If this feature is disabled, i.e.
CONFIG_KMSG_HASH=n, or the hash value hasn't be calculated, the 5th
field simply shows '-'.  Hash values don't appear in other than
/dev/kmsg, thus they are not't displayed on the console and won't be
written to /var/log/messages.

A metadata table which includes pointers to the format strings and
location info of printk is placed between __start___kmsg_meta to
__stop___kmsg_meta.  Since the kernel doesn't calculate hash values
dynamically, userland tools need to calculate hash values and place
them into the table before running the kernel.  To save the space,
the pointers to the format strings are replaced with the calculated
hash values.

In the current implementation, KERN_CONT cases are not dealt with
well.  Only a hash value of the first printk in the sequence is
printed.

Signed-off-by: Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
---

 drivers/base/core.c               |    3 +-
 include/asm-generic/vmlinux.lds.h |    4 ++
 include/linux/kmsghash.h          |   19 ++++++++++
 include/linux/printk.h            |   29 ++++++++++++++--
 kernel/printk.c                   |   69 ++++++++++++++++++++++++++++---------
 lib/Kconfig.debug                 |   17 +++++++++
 6 files changed, 122 insertions(+), 19 deletions(-)
 create mode 100644 include/linux/kmsghash.h

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 8856d74..e2bf2af 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -2153,7 +2153,8 @@ int dev_vprintk_emit(int level, const struct device *dev,
 
 	hdrlen = create_syslog_header(dev, hdr, sizeof(hdr));
 
-	return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen, fmt, args);
+	return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen,
+			    fmt, args, NULL);
 }
 EXPORT_SYMBOL(dev_vprintk_emit);
 
diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index 0162017..d5003a3 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -188,6 +188,10 @@
 	VMLINUX_SYMBOL(__start___verbose) = .;                          \
 	*(__verbose)                                                    \
 	VMLINUX_SYMBOL(__stop___verbose) = .;				\
+	. = ALIGN(8);							\
+	VMLINUX_SYMBOL(__start___kmsg_meta) = .;			\
+	*(__kmsg_meta)							\
+	VMLINUX_SYMBOL(__stop___kmsg_meta) = .;				\
 	LIKELY_PROFILE()		       				\
 	BRANCH_PROFILE()						\
 	TRACE_PRINTKS()
diff --git a/include/linux/kmsghash.h b/include/linux/kmsghash.h
new file mode 100644
index 0000000..6cfe373
--- /dev/null
+++ b/include/linux/kmsghash.h
@@ -0,0 +1,19 @@
+#ifndef _LINUX_KMSGHASH_H
+#define _LINUX_KMSGHASH_H
+
+/* kernel message metadata flags */
+#define KMSG_FLAGS_HASH_VALID	(1<<0)
+#define KMSG_FLAGS_DEFAULT	0
+
+struct kmsg_meta {
+	const char *filename;
+	union {
+		/* format is replaced with hash at build time */
+		const char *format;
+		u32 hash;
+	} u;
+	unsigned int lineno:18;
+	unsigned int flags:8;
+} __attribute__((aligned(8)));
+
+#endif
diff --git a/include/linux/printk.h b/include/linux/printk.h
index c7a8c6b..fe6b350 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -5,6 +5,7 @@
 #include <linux/init.h>
 #include <linux/kern_levels.h>
 #include <linux/linkage.h>
+#include <linux/kmsghash.h>
 
 extern const char linux_banner[];
 extern const char linux_proc_banner[];
@@ -110,7 +111,7 @@ void early_printk(const char *s, ...) { }
 asmlinkage __printf(5, 0)
 int vprintk_emit(int facility, int level,
 		 const char *dict, size_t dictlen,
-		 const char *fmt, va_list args);
+		 const char *fmt, va_list args, struct kmsg_meta *meta);
 
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
@@ -123,7 +124,31 @@ asmlinkage int printk_emit(int facility, int level,
 asmlinkage __printf(1, 2) __cold
 int _printk(const char *fmt, ...);
 
-#define printk(fmt, args...) _printk(fmt, ## args)
+__printf(2, 3) __cold
+int __printk(struct kmsg_meta *meta, const char *fmt, ...);
+
+#ifdef CONFIG_KMSG_HASH
+#define DEFINE_KMSG_METADATA(name, fmt)					\
+	static struct kmsg_meta __aligned(8)				\
+	__attribute__((section("__kmsg_meta"))) name = {		\
+		.filename = __FILE__,					\
+		.u.format = __builtin_constant_p(fmt) ? (fmt) : 0,	\
+		.lineno = __LINE__,					\
+		.flags = KMSG_FLAGS_DEFAULT,				\
+	}
+
+#define printk_(fmt, args...)				\
+({							\
+	DEFINE_KMSG_METADATA(_meta, (fmt));		\
+	__printk(&_meta, (fmt), ##args);		\
+})
+
+#define printk(fmt, args...) printk_(fmt, ##args)
+
+#else
+
+#define printk(fmt, args...) __printk(0, fmt, ##args)
+#endif /* CONFIG_KMSG_HASH */
 
 /*
  * Special printk facility for scheduler use only, _DO_NOT_USE_ !
diff --git a/kernel/printk.c b/kernel/printk.c
index 4cf26ea..57db1a7 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -208,6 +208,7 @@ struct log {
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */
+	struct kmsg_meta *meta;	/* kmsg metadata */
 };
 
 /*
@@ -306,7 +307,7 @@ static u32 log_next(u32 idx)
 static void log_store(int facility, int level,
 		      enum log_flags flags, u64 ts_nsec,
 		      const char *dict, u16 dict_len,
-		      const char *text, u16 text_len)
+		      const char *text, u16 text_len, struct kmsg_meta *meta)
 {
 	struct log *msg;
 	u32 size, pad_len;
@@ -357,6 +358,7 @@ static void log_store(int facility, int level,
 		msg->ts_nsec = local_clock();
 	memset(log_dict(msg) + dict_len, 0, pad_len);
 	msg->len = sizeof(struct log) + text_len + dict_len + pad_len;
+	msg->meta = meta;
 
 	/* insert message */
 	log_next_idx += msg->len;
@@ -535,9 +537,16 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 		 ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
 		cont = '+';
 
-	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
-		      (msg->facility << 3) | msg->level,
-		      user->seq, ts_usec, cont);
+	if (msg->meta && (msg->meta->flags & KMSG_FLAGS_HASH_VALID))
+		len = sprintf(user->buf, "%u,%llu,%llu,%c,%08x@%s:%d;",
+			      (msg->facility << 3) | msg->level,
+			      user->seq, ts_usec, cont, msg->meta->u.hash,
+			      msg->meta->filename, msg->meta->lineno);
+	else
+		len = sprintf(user->buf, "%u,%llu,%llu,%c,-;",
+			      (msg->facility << 3) | msg->level,
+			      user->seq, ts_usec, cont);
+
 	user->prev = msg->flags;
 
 	/* escape non-printable characters */
@@ -1405,6 +1414,7 @@ static struct cont {
 	u8 facility;			/* log level of first message */
 	enum log_flags flags;		/* prefix, newline flags */
 	bool flushed:1;			/* buffer sealed and committed */
+	struct kmsg_meta *meta;		/* kmsg metadata */
 } cont;
 
 static void cont_flush(enum log_flags flags)
@@ -1421,7 +1431,8 @@ static void cont_flush(enum log_flags flags)
 		 * line. LOG_NOCONS suppresses a duplicated output.
 		 */
 		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
-			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
+			  cont.ts_nsec, NULL, 0, cont.buf, cont.len,
+			  cont.meta);
 		cont.flags = flags;
 		cont.flushed = true;
 	} else {
@@ -1430,12 +1441,13 @@ static void cont_flush(enum log_flags flags)
 		 * just submit it to the store and free the buffer.
 		 */
 		log_store(cont.facility, cont.level, flags, 0,
-			  NULL, 0, cont.buf, cont.len);
+			  NULL, 0, cont.buf, cont.len, cont.meta);
 		cont.len = 0;
 	}
 }
 
-static bool cont_add(int facility, int level, const char *text, size_t len)
+static bool cont_add(int facility, int level, const char *text, size_t len,
+	struct kmsg_meta *meta)
 {
 	if (cont.len && cont.flushed)
 		return false;
@@ -1454,6 +1466,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.flags = 0;
 		cont.cons = 0;
 		cont.flushed = false;
+		cont.meta = meta;
 	}
 
 	memcpy(cont.buf + cont.len, text, len);
@@ -1489,13 +1502,15 @@ static size_t cont_print_text(char *text, size_t size)
 			text[textlen++] = '\n';
 		/* got everything, release buffer */
 		cont.len = 0;
+		cont.meta = NULL;
 	}
 	return textlen;
 }
 
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
-			    const char *fmt, va_list args)
+			    const char *fmt, va_list args,
+			    struct kmsg_meta *meta)
 {
 	static int recursion_bug;
 	static char textbuf[LOG_LINE_MAX];
@@ -1543,7 +1558,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		printed_len += strlen(recursion_msg);
 		/* emit KERN_CRIT message */
 		log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-			  NULL, 0, recursion_msg, printed_len);
+			  NULL, 0, recursion_msg, printed_len, NULL);
 	}
 
 	/*
@@ -1593,9 +1608,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 			cont_flush(LOG_NEWLINE);
 
 		/* buffer line if possible, otherwise store it right away */
-		if (!cont_add(facility, level, text, text_len))
+		if (!cont_add(facility, level, text, text_len, meta))
 			log_store(facility, level, lflags | LOG_CONT, 0,
-				  dict, dictlen, text, text_len);
+				  dict, dictlen, text, text_len, meta);
 	} else {
 		bool stored = false;
 
@@ -1607,13 +1622,14 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (cont.len && cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, text, text_len);
+				stored = cont_add(facility, level, text,
+						  text_len, meta);
 			cont_flush(LOG_NEWLINE);
 		}
 
 		if (!stored)
 			log_store(facility, level, lflags, 0,
-				  dict, dictlen, text, text_len);
+				  dict, dictlen, text, text_len, meta);
 	}
 	printed_len += text_len;
 
@@ -1638,7 +1654,7 @@ EXPORT_SYMBOL(vprintk_emit);
 
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
-	return vprintk_emit(0, -1, NULL, 0, fmt, args);
+	return vprintk_emit(0, -1, NULL, 0, fmt, args, NULL);
 }
 EXPORT_SYMBOL(vprintk);
 
@@ -1650,7 +1666,7 @@ asmlinkage int printk_emit(int facility, int level,
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk_emit(facility, level, dict, dictlen, fmt, args);
+	r = vprintk_emit(facility, level, dict, dictlen, fmt, args, NULL);
 	va_end(args);
 
 	return r;
@@ -1696,13 +1712,34 @@ asmlinkage int _printk(const char *fmt, ...)
 	}
 #endif
 	va_start(args, fmt);
-	r = vprintk_emit(0, -1, NULL, 0, fmt, args);
+	r = vprintk_emit(0, -1, NULL, 0, fmt, args, NULL);
 	va_end(args);
 
 	return r;
 }
 EXPORT_SYMBOL(_printk);
 
+int __printk(struct kmsg_meta *meta, const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+#ifdef CONFIG_KGDB_KDB
+	if (unlikely(kdb_trap_printk)) {
+		va_start(args, fmt);
+		r = vkdb_printf(fmt, args);
+		va_end(args);
+		return r;
+	}
+#endif
+	va_start(args, fmt);
+	r = vprintk_emit(0, -1, NULL, 0, fmt, args, meta);
+	va_end(args);
+
+	return r;
+}
+EXPORT_SYMBOL(__printk);
+
 #else /* CONFIG_PRINTK */
 
 #define LOG_LINE_MAX		0
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 1501aa5..907f8cf 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -15,6 +15,23 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/kernel-parameters.txt
 
+config KMSG_HASH
+	bool "Show the hash value of each printk message format"
+	depends on PRINTK
+	default n
+	help
+	  If you say y here, the hash value of each printk message
+	  format is displayed when reading /dev/kmsg as bellow:
+
+	    6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs
+
+	  Here, the 5th field is the 32-bit hash value followed by
+	  @<location>.  If this feature is disabled or the hash value
+	  couldn't be calculated, the 5th field simply shows '-'.
+
+	  Please note that the kernel image size gets larger by
+	  hundres Kbytes when this feature is enabled.
+
 config DEFAULT_MESSAGE_LOGLEVEL
 	int "Default message log level (1-7)"
 	range 1 7

[RESEND RFC PATCH 1/5] printk: make printk a macro

[Hidehiro Kawai]

To allow building up metadata transparently for each printk(), make
printk() a macro while keeping printk()'s API.  Then, printk() calls
_printk() which implements the original printk() function.

printk() is used from assembly sources, but they don't include printk.h
and don't use this new printk() macro.  This is addressed by assigning
the printk symbol to _printk in the linker script.

Signed-off-by: Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
---

 include/asm-generic/vmlinux.lds.h |    1 +
 include/linux/printk.h            |    4 +++-
 kernel/printk.c                   |   12 ++++++++----
 3 files changed, 12 insertions(+), 5 deletions(-)

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index 69732d2..0162017 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -393,6 +393,7 @@
 		*(.text.hot)						\
 		*(.text)						\
 		*(.ref.text)						\
+		VMLINUX_SYMBOL(printk) = VMLINUX_SYMBOL(_printk);	\
 	MEM_KEEP(init.text)						\
 	MEM_KEEP(exit.text)						\
 		*(.text.unlikely)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 22c7052..c7a8c6b 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -121,7 +121,9 @@ asmlinkage int printk_emit(int facility, int level,
 			   const char *fmt, ...);
 
 asmlinkage __printf(1, 2) __cold
-int printk(const char *fmt, ...);
+int _printk(const char *fmt, ...);
+
+#define printk(fmt, args...) _printk(fmt, ## args)
 
 /*
  * Special printk facility for scheduler use only, _DO_NOT_USE_ !
diff --git a/kernel/printk.c b/kernel/printk.c
index 69b0890..4cf26ea 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1658,10 +1658,14 @@ asmlinkage int printk_emit(int facility, int level,
 EXPORT_SYMBOL(printk_emit);
 
 /**
- * printk - print a kernel message
+ * _printk - print a kernel message
  * @fmt: format string
  *
- * This is printk(). It can be called from any context. We want it to work.
+ * Now, printk() is a macro defined in include/linux/printk.h, and this
+ * function is its body.  It can be called from any context, but please
+ * use printk() macro.  Directly calling _printk() is not recommended.
+ * In assembly sources, you can call printk as in the past because the
+ * linker program links the printk symbol in assembly sources to _printk.
  *
  * We try to grab the console_lock. If we succeed, it's easy - we log the
  * output and call the console drivers.  If we fail to get the semaphore, we
@@ -1678,7 +1682,7 @@ EXPORT_SYMBOL(printk_emit);
  *
  * See the vsnprintf() documentation for format string extensions over C99.
  */
-asmlinkage int printk(const char *fmt, ...)
+asmlinkage int _printk(const char *fmt, ...)
 {
 	va_list args;
 	int r;
@@ -1697,7 +1701,7 @@ asmlinkage int printk(const char *fmt, ...)
 
 	return r;
 }
-EXPORT_SYMBOL(printk);
+EXPORT_SYMBOL(_printk);
 
 #else /* CONFIG_PRINTK */
 

[RESEND RFC PATCH 3/5] tools/include: Add jhash.h

[Hidehiro Kawai]

Copy include/linux/jhash.h to tools/include/tools/ for userland
tools.  The original jhash.h includes a couple of header files
which is not suitable for userland.  So unfold the only necessary
part in those header files to the copied jhash.h

Signed-off-by: Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
---

 tools/include/tools/jhash.h |  192 +++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 192 insertions(+), 0 deletions(-)
 create mode 100644 tools/include/tools/jhash.h

diff --git a/tools/include/tools/jhash.h b/tools/include/tools/jhash.h
new file mode 100644
index 0000000..872d7f9
--- /dev/null
+++ b/tools/include/tools/jhash.h
@@ -0,0 +1,192 @@
+#ifndef _TOOLS_JHASH_H
+#define _TOOLS_JHASH_H
+
+/* jhash.h: Jenkins hash support.
+ *
+ * Copyright (C) 2006. Bob Jenkins (bob_jenkins@burtleburtle.net)
+ *
+ * http://burtleburtle.net/bob/hash/
+ *
+ * These are the credits from Bob's sources:
+ *
+ * lookup3.c, by Bob Jenkins, May 2006, Public Domain.
+ *
+ * These are functions for producing 32-bit hashes for hash table lookup.
+ * hashword(), hashlittle(), hashlittle2(), hashbig(), mix(), and final()
+ * are externally useful functions.  Routines to test the hash are included
+ * if SELF_TEST is defined.  You can use this free for any purpose.  It's in
+ * the public domain.  It has no warranty.
+ *
+ * Copyright (C) 2009-2010 Jozsef Kadlecsik (kadlec@blackhole.kfki.hu)
+ *
+ * I've modified Bob's hash to be useful in the Linux kernel, and
+ * any bugs present are my fault.
+ * Jozsef
+ */
+
+#define __packed	__attribute__((packed))
+
+/*
+ * __get_unaligned_cpu32 was copied from
+ * include/linux/unaligned/packed_struct.h
+ */
+struct __una_u32 { u32 x; } __packed;
+static inline u32 __get_unaligned_cpu32(const void *p)
+{
+	const struct __una_u32 *ptr = (const struct __una_u32 *)p;
+	return ptr->x;
+}
+
+/* rol32 was copied from include/linux/bitops.h */
+/**
+ * rol32 - rotate a 32-bit value left
+ * @word: value to rotate
+ * @shift: bits to roll
+ */
+static inline u32 rol32(u32 word, unsigned int shift)
+{
+	return (word << shift) | (word >> (32 - shift));
+}
+
+/* Best hash sizes are of power of two */
+#define jhash_size(n)   ((u32)1<<(n))
+/* Mask the hash value, i.e (value & jhash_mask(n)) instead of (value % n) */
+#define jhash_mask(n)   (jhash_size(n)-1)
+
+/* __jhash_mix -- mix 3 32-bit values reversibly. */
+#define __jhash_mix(a, b, c)			\
+{						\
+	a -= c;  a ^= rol32(c, 4);  c += b;	\
+	b -= a;  b ^= rol32(a, 6);  a += c;	\
+	c -= b;  c ^= rol32(b, 8);  b += a;	\
+	a -= c;  a ^= rol32(c, 16); c += b;	\
+	b -= a;  b ^= rol32(a, 19); a += c;	\
+	c -= b;  c ^= rol32(b, 4);  b += a;	\
+}
+
+/* __jhash_final - final mixing of 3 32-bit values (a,b,c) into c */
+#define __jhash_final(a, b, c)			\
+{						\
+	c ^= b; c -= rol32(b, 14);		\
+	a ^= c; a -= rol32(c, 11);		\
+	b ^= a; b -= rol32(a, 25);		\
+	c ^= b; c -= rol32(b, 16);		\
+	a ^= c; a -= rol32(c, 4);		\
+	b ^= a; b -= rol32(a, 14);		\
+	c ^= b; c -= rol32(b, 24);		\
+}
+
+/* An arbitrary initial parameter */
+#define JHASH_INITVAL		0xdeadbeef
+
+/* jhash - hash an arbitrary key
+ * @k: sequence of bytes as key
+ * @length: the length of the key
+ * @initval: the previous hash, or an arbitray value
+ *
+ * The generic version, hashes an arbitrary sequence of bytes.
+ * No alignment or length assumptions are made about the input key.
+ *
+ * Returns the hash value of the key. The result depends on endianness.
+ */
+static inline u32 jhash(const void *key, u32 length, u32 initval)
+{
+	u32 a, b, c;
+	const u8 *k = key;
+
+	/* Set up the internal state */
+	a = b = c = JHASH_INITVAL + length + initval;
+
+	/* All but the last block: affect some 32 bits of (a,b,c) */
+	while (length > 12) {
+		a += __get_unaligned_cpu32(k);
+		b += __get_unaligned_cpu32(k + 4);
+		c += __get_unaligned_cpu32(k + 8);
+		__jhash_mix(a, b, c);
+		length -= 12;
+		k += 12;
+	}
+	/* Last block: affect all 32 bits of (c) */
+	/* All the case statements fall through */
+	switch (length) {
+	case 12: c += (u32)k[11]<<24;
+	case 11: c += (u32)k[10]<<16;
+	case 10: c += (u32)k[9]<<8;
+	case 9:  c += k[8];
+	case 8:  b += (u32)k[7]<<24;
+	case 7:  b += (u32)k[6]<<16;
+	case 6:  b += (u32)k[5]<<8;
+	case 5:  b += k[4];
+	case 4:  a += (u32)k[3]<<24;
+	case 3:  a += (u32)k[2]<<16;
+	case 2:  a += (u32)k[1]<<8;
+	case 1:  a += k[0];
+		 __jhash_final(a, b, c);
+	case 0: /* Nothing left to add */
+		break;
+	}
+
+	return c;
+}
+
+/* jhash2 - hash an array of u32's
+ * @k: the key which must be an array of u32's
+ * @length: the number of u32's in the key
+ * @initval: the previous hash, or an arbitray value
+ *
+ * Returns the hash value of the key.
+ */
+static inline u32 jhash2(const u32 *k, u32 length, u32 initval)
+{
+	u32 a, b, c;
+
+	/* Set up the internal state */
+	a = b = c = JHASH_INITVAL + (length<<2) + initval;
+
+	/* Handle most of the key */
+	while (length > 3) {
+		a += k[0];
+		b += k[1];
+		c += k[2];
+		__jhash_mix(a, b, c);
+		length -= 3;
+		k += 3;
+	}
+
+	/* Handle the last 3 u32's: all the case statements fall through */
+	switch (length) {
+	case 3: c += k[2];
+	case 2: b += k[1];
+	case 1: a += k[0];
+		__jhash_final(a, b, c);
+	case 0:	/* Nothing left to add */
+		break;
+	}
+
+	return c;
+}
+
+
+/* jhash_3words - hash exactly 3, 2 or 1 word(s) */
+static inline u32 jhash_3words(u32 a, u32 b, u32 c, u32 initval)
+{
+	a += JHASH_INITVAL;
+	b += JHASH_INITVAL;
+	c += initval;
+
+	__jhash_final(a, b, c);
+
+	return c;
+}
+
+static inline u32 jhash_2words(u32 a, u32 b, u32 initval)
+{
+	return jhash_3words(a, b, 0, initval);
+}
+
+static inline u32 jhash_1word(u32 a, u32 initval)
+{
+	return jhash_3words(a, 0, 0, initval);
+}
+
+#endif /* _TOOLS_JHASH_H */

[RESEND RFC PATCH 5/5] printk: Add msghash support for dev_printk

[Hidehiro Kawai]

Add msghash support for dev_printk and its variants (dev_xxx).
Without this patch, no kmsg_meta data are passed to vprintk_emit,
and this means no hash value is output.

To pass the metadata, this patch changes dev_printk and its
variants to macros which construct the metadata in the similar way
of printk.  No API of those functions are changed.

Signed-off-by: Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
---

 drivers/base/core.c         |   56 +++++++++------------------------
 drivers/usb/storage/debug.c |    2 +
 include/linux/device.h      |   73 +++++++++++++++++++++++++------------------
 lib/dynamic_debug.c         |    4 +-
 net/core/dev.c              |    2 +
 5 files changed, 62 insertions(+), 75 deletions(-)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index e2bf2af..ebe742f 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -2145,8 +2145,8 @@ create_syslog_header(const struct device *dev, char *hdr, size_t hdrlen)
 }
 EXPORT_SYMBOL(create_syslog_header);
 
-int dev_vprintk_emit(int level, const struct device *dev,
-		     const char *fmt, va_list args)
+int dev_vprintk_emit(struct kmsg_meta *meta, int level,
+		     const struct device *dev, const char *fmt, va_list args)
 {
 	char hdr[128];
 	size_t hdrlen;
@@ -2154,18 +2154,19 @@ int dev_vprintk_emit(int level, const struct device *dev,
 	hdrlen = create_syslog_header(dev, hdr, sizeof(hdr));
 
 	return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen,
-			    fmt, args, NULL);
+			    fmt, args, meta);
 }
 EXPORT_SYMBOL(dev_vprintk_emit);
 
-int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...)
+int dev_printk_emit(struct kmsg_meta *meta, int level,
+		    const struct device *dev, const char *fmt, ...)
 {
 	va_list args;
 	int r;
 
 	va_start(args, fmt);
 
-	r = dev_vprintk_emit(level, dev, fmt, args);
+	r = dev_vprintk_emit(meta, level, dev, fmt, args);
 
 	va_end(args);
 
@@ -2173,19 +2174,20 @@ int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...)
 }
 EXPORT_SYMBOL(dev_printk_emit);
 
-static int __dev_printk(const char *level, const struct device *dev,
-			struct va_format *vaf)
+static int __dev_printk(struct kmsg_meta *meta, const char *level,
+			const struct device *dev, struct va_format *vaf)
 {
 	if (!dev)
-		return printk("%s(NULL device *): %pV", level, vaf);
+		return __printk(meta, "%s(NULL device *): %pV", level, vaf);
 
-	return dev_printk_emit(level[1] - '0', dev,
+	return dev_printk_emit(meta, level[1] - '0', dev,
 			       "%s %s: %pV",
 			       dev_driver_string(dev), dev_name(dev), vaf);
 }
 
-int dev_printk(const char *level, const struct device *dev,
-	       const char *fmt, ...)
+__printf(4, 5)
+int _dev_printk(struct kmsg_meta *meta, const char *level,
+		const struct device *dev, const char *fmt, ...)
 {
 	struct va_format vaf;
 	va_list args;
@@ -2196,40 +2198,12 @@ int dev_printk(const char *level, const struct device *dev,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	r = __dev_printk(level, dev, &vaf);
+	r = __dev_printk(meta, level, dev, &vaf);
 
 	va_end(args);
 
 	return r;
 }
-EXPORT_SYMBOL(dev_printk);
-
-#define define_dev_printk_level(func, kern_level)		\
-int func(const struct device *dev, const char *fmt, ...)	\
-{								\
-	struct va_format vaf;					\
-	va_list args;						\
-	int r;							\
-								\
-	va_start(args, fmt);					\
-								\
-	vaf.fmt = fmt;						\
-	vaf.va = &args;						\
-								\
-	r = __dev_printk(kern_level, dev, &vaf);		\
-								\
-	va_end(args);						\
-								\
-	return r;						\
-}								\
-EXPORT_SYMBOL(func);
-
-define_dev_printk_level(dev_emerg, KERN_EMERG);
-define_dev_printk_level(dev_alert, KERN_ALERT);
-define_dev_printk_level(dev_crit, KERN_CRIT);
-define_dev_printk_level(dev_err, KERN_ERR);
-define_dev_printk_level(dev_warn, KERN_WARNING);
-define_dev_printk_level(dev_notice, KERN_NOTICE);
-define_dev_printk_level(_dev_info, KERN_INFO);
+EXPORT_SYMBOL(_dev_printk);
 
 #endif
diff --git a/drivers/usb/storage/debug.c b/drivers/usb/storage/debug.c
index e08f647..22e1115 100644
--- a/drivers/usb/storage/debug.c
+++ b/drivers/usb/storage/debug.c
@@ -186,7 +186,7 @@ int usb_stor_dbg(const struct us_data *us, const char *fmt, ...)
 
 	va_start(args, fmt);
 
-	r = dev_vprintk_emit(7, &us->pusb_dev->dev, fmt, args);
+	r = dev_vprintk_emit(NULL, 7, &us->pusb_dev->dev, fmt, args);
 
 	va_end(args);
 
diff --git a/include/linux/device.h b/include/linux/device.h
index 22b546a..ba15810 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -984,42 +984,55 @@ extern const char *dev_driver_string(const struct device *dev);
 
 #ifdef CONFIG_PRINTK
 
-extern __printf(3, 0)
-int dev_vprintk_emit(int level, const struct device *dev,
-		     const char *fmt, va_list args);
-extern __printf(3, 4)
-int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...);
-
-extern __printf(3, 4)
-int dev_printk(const char *level, const struct device *dev,
-	       const char *fmt, ...);
-extern __printf(2, 3)
-int dev_emerg(const struct device *dev, const char *fmt, ...);
-extern __printf(2, 3)
-int dev_alert(const struct device *dev, const char *fmt, ...);
-extern __printf(2, 3)
-int dev_crit(const struct device *dev, const char *fmt, ...);
-extern __printf(2, 3)
-int dev_err(const struct device *dev, const char *fmt, ...);
-extern __printf(2, 3)
-int dev_warn(const struct device *dev, const char *fmt, ...);
-extern __printf(2, 3)
-int dev_notice(const struct device *dev, const char *fmt, ...);
-extern __printf(2, 3)
-int _dev_info(const struct device *dev, const char *fmt, ...);
+extern __printf(4, 0)
+int dev_vprintk_emit(struct kmsg_meta *meta, int level,
+		     const struct device *dev, const char *fmt, va_list args);
+extern __printf(4, 5)
+int dev_printk_emit(struct kmsg_meta *meta, int level,
+		    const struct device *dev, const char *fmt, ...);
+
+extern __printf(4, 5)
+int _dev_printk(struct kmsg_meta *_meta, const char *level,
+		const struct device *dev, const char *fmt, ...);
+
+#ifdef CONFIG_KMSG_HASH
+#define dev_printk(level, dev, fmt, args...)			\
+({								\
+	DEFINE_KMSG_METADATA(_meta, (fmt));			\
+	_dev_printk(&_meta, (level), (dev), (fmt), ##args);	\
+})
+#else
+#define dev_printk(level, dev, fmt, args...) \
+	_dev_printk(NULL, (level), (dev), (fmt), ##args)
+#endif
 
+#define dev_emerg(dev, fmt, args...) \
+	dev_printk(KERN_EMERG, (dev), (fmt), ##args)
+#define dev_alert(dev, fmt, args...) \
+	dev_printk(KERN_ALERT, (dev), (fmt), ##args)
+#define dev_crit(dev, fmt, args...) \
+	dev_printk(KERN_CRIT, (dev), (fmt), ##args)
+#define dev_err(dev, fmt, args...) \
+	dev_printk(KERN_ERR, (dev), (fmt), ##args)
+#define dev_warn(dev, fmt, args...) \
+	dev_printk(KERN_WARNING, (dev), (fmt), ##args)
+#define dev_notice(dev, fmt, args...) \
+	dev_printk(KERN_NOTICE, (dev), (fmt), ##args)
+#define _dev_info(dev, fmt, args...) \
+	dev_printk(KERN_INFO, (dev), (fmt), ##args)
 #else
 
-static inline __printf(3, 0)
-int dev_vprintk_emit(int level, const struct device *dev,
-		     const char *fmt, va_list args)
+static inline __printf(4, 0)
+int dev_vprintk_emit(struct kmsg_meta *meta, int level,
+		     const struct device *dev, const char *fmt, va_list args)
 { return 0; }
-static inline __printf(3, 4)
-int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...)
+static inline __printf(4, 5)
+int dev_printk_emit(struct kmsg_meta *meta, int level,
+		    const struct device *dev, const char *fmt, ...)
 { return 0; }
 
-static inline int __dev_printk(const char *level, const struct device *dev,
-			       struct va_format *vaf)
+static inline int __dev_printk(struct kmsg_meta *meta, const char *level,
+			       const struct device *dev, struct va_format *vaf)
 { return 0; }
 static inline __printf(3, 4)
 int dev_printk(const char *level, const struct device *dev,
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 99fec3a..46283dd 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -578,7 +578,7 @@ int __dynamic_dev_dbg(struct _ddebug *descriptor,
 	} else {
 		char buf[PREFIX_SIZE];
 
-		res = dev_printk_emit(7, dev, "%s%s %s: %pV",
+		res = dev_printk_emit(NULL, 7, dev, "%s%s %s: %pV",
 				      dynamic_emit_prefix(descriptor, buf),
 				      dev_driver_string(dev), dev_name(dev),
 				      &vaf);
@@ -610,7 +610,7 @@ int __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	if (dev && dev->dev.parent) {
 		char buf[PREFIX_SIZE];
 
-		res = dev_printk_emit(7, dev->dev.parent,
+		res = dev_printk_emit(NULL, 7, dev->dev.parent,
 				      "%s%s %s %s: %pV",
 				      dynamic_emit_prefix(descriptor, buf),
 				      dev_driver_string(dev->dev.parent),
diff --git a/net/core/dev.c b/net/core/dev.c
index 26755dd..2df020e 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -6258,7 +6258,7 @@ static int __netdev_printk(const char *level, const struct net_device *dev,
 	int r;
 
 	if (dev && dev->dev.parent) {
-		r = dev_printk_emit(level[1] - '0',
+		r = dev_printk_emit(NULL, level[1] - '0',
 				    dev->dev.parent,
 				    "%s %s %s: %pV",
 				    dev_driver_string(dev->dev.parent),

[RESEND RFC PATCH 4/5] msghash: Add userland msghash tool

[Hidehiro Kawai]

This patch adds scripts/msghash/msghash.  msghash scans a kmsg_meta
table between __start___kmsg_meta to __stop___kmsg_meta in the
target object file (vmlinux), computes a hash value for each
message format string, then replaces the format string with the
hash value.  Valid flags are also set to entries in the kmsg_meta
table.  When computing the hash value, prefixed loglevel characters
are ignored.

Even if configured with CONFIG_KMSG_HASH=y, without running msghash,
no hash values are output via /dev/kmsg.  So msghash is executed
during the build process, just after generating vmlinux.

msghash also generate a Hash-and-message catalog named
"<objfile>.msglist".  Each line in the .msglist file is output
in the form of:
<hash in hex>@<file>:<lineno>,<message format>

.msglist file is useful to match /dev/kmsg messages with messages
you concern.

Here is the example of .msglist:
...
b6be0058@init/main.c:180,"Parameter %s is obsolete, ignored"
72dfe336@init/main.c:403,"Malformed early option '%s'"
85788d36@init/do_mounts.c:573,"Waiting for root device %s..."
...

Currently, only vmlinux is supported.  msghash can't update
the kmsg_meta tables of kernel modules.

Signed-off-by: Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
---

 .gitignore                 |    1 
 Makefile                   |    7 +
 lib/Kconfig.debug          |    5 +
 scripts/Makefile           |    1 
 scripts/link-vmlinux.sh    |    5 +
 scripts/msghash/.gitignore |    1 
 scripts/msghash/Makefile   |    7 +
 scripts/msghash/msghash.c  |  241 ++++++++++++++++++++++++++++++++++++++++++++
 scripts/msghash/msghash.sh |   45 ++++++++
 9 files changed, 312 insertions(+), 1 deletions(-)
 create mode 100644 scripts/msghash/.gitignore
 create mode 100644 scripts/msghash/Makefile
 create mode 100644 scripts/msghash/msghash.c
 create mode 100755 scripts/msghash/msghash.sh

diff --git a/.gitignore b/.gitignore
index 3b8b9b3..3bb5735 100644
--- a/.gitignore
+++ b/.gitignore
@@ -32,6 +32,7 @@ modules.builtin
 *.lzo
 *.patch
 *.gcno
+*.msglist
 
 #
 # Top-level generic files
diff --git a/Makefile b/Makefile
index a35f72a..6d11a09 100644
--- a/Makefile
+++ b/Makefile
@@ -766,6 +766,10 @@ vmlinux-deps := $(KBUILD_LDS) $(KBUILD_VMLINUX_INIT) $(KBUILD_VMLINUX_MAIN)
       cmd_link-vmlinux = $(CONFIG_SHELL) $< $(LD) $(LDFLAGS) $(LDFLAGS_vmlinux)
 quiet_cmd_link-vmlinux = LINK    $@
 
+# Remove old .msglist
+      cmd_rm-msglist = echo rm -f $@.msglist
+quiet_cmd_rm-msglist = CLEAN   $@.msglist
+
 # Include targets which we want to
 # execute if the rest of the kernel build went well.
 vmlinux: scripts/link-vmlinux.sh $(vmlinux-deps) FORCE
@@ -1274,7 +1278,8 @@ clean: $(clean-dirs)
 		-o -name '.*.d' -o -name '.*.tmp' -o -name '*.mod.c' \
 		-o -name '*.symtypes' -o -name 'modules.order' \
 		-o -name modules.builtin -o -name '.tmp_*.o.*' \
-		-o -name '*.gcno' \) -type f -print | xargs rm -f
+		-o -name '*.gcno' -o -name '*.msglist' \) -type f -print |\
+		xargs rm -f
 
 # Generate tags for editors
 # ---------------------------------------------------------------------------
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 907f8cf..78d60f0 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -12,6 +12,11 @@ config PRINTK_TIME
 	  to /dev/kmsg. This flag just specifies if the timestamp should
 	  be included, not that the timestamp is recorded.
 
+	  Hash values are calculated during the build process and
+	  put into a table in object files.  Hash-and-message catalogs
+	  named <objfile>.msglist are also generated for convenience
+	  in message handling in userland.
+
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/kernel-parameters.txt
 
diff --git a/scripts/Makefile b/scripts/Makefile
index 01e7adb..7568e35 100644
--- a/scripts/Makefile
+++ b/scripts/Makefile
@@ -37,6 +37,7 @@ subdir-$(CONFIG_MODVERSIONS) += genksyms
 subdir-y                     += mod
 subdir-$(CONFIG_SECURITY_SELINUX) += selinux
 subdir-$(CONFIG_DTC)         += dtc
+subdir-$(CONFIG_KMSG_HASH) += msghash
 
 # Let clean descend into subdirs
 subdir-	+= basic kconfig package selinux
diff --git a/scripts/link-vmlinux.sh b/scripts/link-vmlinux.sh
index 0149949..575c2bb 100644
--- a/scripts/link-vmlinux.sh
+++ b/scripts/link-vmlinux.sh
@@ -228,5 +228,10 @@ if [ -n "${CONFIG_KALLSYMS}" ]; then
 	fi
 fi
 
+if [ -n "${CONFIG_KMSG_HASH}" ]; then
+	rm -f vmlinux.msglist
+	${srctree}/scripts/msghash/msghash.sh vmlinux || exit 1
+fi
+
 # We made a new kernel - delete old version file
 rm -f .old_version
diff --git a/scripts/msghash/.gitignore b/scripts/msghash/.gitignore
new file mode 100644
index 0000000..8bcfa1d
--- /dev/null
+++ b/scripts/msghash/.gitignore
@@ -0,0 +1 @@
+msghash
diff --git a/scripts/msghash/Makefile b/scripts/msghash/Makefile
new file mode 100644
index 0000000..add1e14
--- /dev/null
+++ b/scripts/msghash/Makefile
@@ -0,0 +1,7 @@
+hostprogs-y	:= msghash
+
+HOST_EXTRACFLAGS += -I$(srctree)/tools/include -I$(srctree)/include
+
+always		:= $(hostprogs-y)
+clean-files	:= $(hostprogs-y)
+
diff --git a/scripts/msghash/msghash.c b/scripts/msghash/msghash.c
new file mode 100644
index 0000000..832fdb9
--- /dev/null
+++ b/scripts/msghash/msghash.c
@@ -0,0 +1,241 @@
+/*
+ * msghash.c: calculate hash values of printk messages and update the
+ *            kmsg_meta table in the target object file.
+ *
+ * Copyright 2013 Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
+ *
+ * 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 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.
+ */
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <sys/mman.h>
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <unistd.h>
+#include <fcntl.h>
+
+typedef u_int8_t u8;
+typedef u_int16_t u16;
+typedef u_int32_t u32;
+typedef u_int64_t u64;
+
+#include <linux/kmsghash.h>
+#include <tools/jhash.h>
+
+#define KERN_SOH_ASCII	'\001'
+static inline char *printk_skip_level(char *buffer)
+{
+	if (buffer[0] == KERN_SOH_ASCII && buffer[1]) {
+		switch (buffer[1]) {
+		case '0' ... '7':
+		case 'd':	/* KERN_DEFAULT */
+			return buffer + 2;
+		}
+	}
+	return buffer;
+}
+
+static unsigned long rodata_addr;
+static unsigned long rodata_off;
+static FILE *outfp;
+struct msghash_stat {
+	int updated;	/* number of entries updated successfully */
+	int skipped;	/* skipped entries because of having a valid hash */
+	int invalid;	/* entries whoes format string is not constant */
+} st;
+
+static inline unsigned long addr_to_offset(unsigned long addr)
+{
+	return  addr - rodata_addr + rodata_off;
+}
+
+static void usage(void)
+{
+	fprintf(stderr,
+	"Usage: msghash [-o <outfile>] <objfile> <start_meta> <stop_meta>\n"
+	"               <rodata_addr> <rodata_offset>\n");
+}
+
+/*
+ * Update the hash value of a given kmsg_meta object and write out
+ * a Hash-and-message line to the specified file.
+ */
+static void update_and_print_hash(char *buf, struct kmsg_meta *meta)
+{
+	static char fmtbuf[4096];
+	u_int32_t hash;
+	char *str;
+	int len;
+	int i, j, c;
+
+	if (meta->flags & KMSG_FLAGS_HASH_VALID) {
+		st.skipped++;
+		return;
+	}
+
+	/* Non-constant format case, skip it. */
+	if (!meta->u.format) {
+		st.invalid++;
+		return;
+	}
+
+	str = buf + addr_to_offset((unsigned long)meta->u.format);
+	str = printk_skip_level(str);
+	len = strlen(str);
+	hash = jhash(str, len, 0);
+	meta->u.format = 0;
+	meta->u.hash = hash;
+	meta->flags |= KMSG_FLAGS_HASH_VALID;
+
+	/*
+	 * We output the kmsg metadata info only if the hash value
+	 * has just been updated because a pointer to the format string
+	 * is overwritten with a hash value.
+	 */
+	if (outfp) {
+		/* Don't printout a newline at the tail. */
+		if (str[len - 1] == '\n')
+			len--;
+
+		/* Escape special codes same as reading /dev/kmsg */
+		for (i = 0, j = 0; i < len; i++) {
+			c = str[i];
+
+			if (c < ' ' || c >= 127 || c == '\\')
+				j += sprintf(fmtbuf + j, "\\x%02x", c);
+			else
+				fmtbuf[j++] = c;
+		}
+		fmtbuf[j] = 0;
+		fprintf(outfp, "%08x@%s:%d,\"%s\"\n", meta->u.hash,
+			buf + addr_to_offset((unsigned long)meta->filename),
+			meta->lineno, fmtbuf);
+	}
+
+	st.updated++;
+}
+
+/*
+ * Calculate hash values of printk message formats and replace it with
+ * the hash values.  This means we modify kmsg_meta table in .rodata
+ * section of the target file (vmlinux).
+ */
+static void walk_kmsg_meta(char *buf, unsigned long start, unsigned long end)
+{
+	char *p;
+
+	for (p = buf + start; p < buf + end; p += sizeof(struct kmsg_meta))
+		update_and_print_hash(buf, (struct kmsg_meta *)p);
+}
+
+static char *do_mmap_objfile(const char *filename, size_t *len)
+{
+	int fd;
+	struct stat sb;
+	char *buf;
+
+	fd = open(filename, O_RDWR | O_APPEND);
+	if (fd < 0) {
+		perror("msghash: open");
+		return NULL;
+	}
+
+	if (fstat(fd, &sb) < 0) {
+		perror("msghash: fstat");
+		return NULL;
+	}
+
+	buf = mmap(0, sb.st_size, PROT_READ|PROT_WRITE, MAP_SHARED, fd, 0);
+	if (buf == MAP_FAILED) {
+		perror("msghash: mmap");
+		return NULL;
+	}
+	*len = sb.st_size;
+
+	return buf;
+}
+
+int main(int argc, char *argv[])
+{
+	unsigned long start_meta, stop_meta, start, end;
+	char *outfile = NULL;
+	char *buf;
+	size_t len;
+	int total;
+	int c;
+	int ret;
+
+	while ((c = getopt(argc, argv, "o:")) >= 0) {
+		switch (c) {
+		case 'o':
+			outfile = optarg;
+			break;
+		default:
+			usage();
+			return 1;
+		}
+	}
+
+	if (argc - optind < 5) {
+		usage();
+		return 1;
+	}
+
+	start_meta = strtoul(argv[optind + 1], NULL, 0);
+	stop_meta = strtoul(argv[optind + 2], NULL, 0);
+	rodata_addr = strtoul(argv[optind + 3], NULL, 0);
+	rodata_off = strtoul(argv[optind + 4], NULL, 0);
+
+	/* Do some sanity checks. */
+	if (!start_meta || !stop_meta || start_meta > stop_meta) {
+		fprintf(stderr, "msghash: Invalid arguments\n");
+		fprintf(stderr, "  start_meta:  0x%08lx\n", start_meta);
+		fprintf(stderr, "  stop_meta:   0x%08lx\n", stop_meta);
+		fprintf(stderr, "  rodata_addr: 0x%08lx\n", rodata_addr);
+		fprintf(stderr, "  rodata_off:  0x%08lx\n", rodata_off);
+		return 1;
+	}
+
+	if (start_meta == stop_meta) {
+		/* There is nothing to do. */
+		return 0;
+	}
+
+	buf = do_mmap_objfile(argv[optind], &len);
+	if (!buf)
+		return 1;
+	outfp = fopen(outfile, "w");
+	if (outfp < 0) {
+		perror("msghash: fopen output file");
+		return 1;
+	}
+
+	start = addr_to_offset(start_meta);
+	end = addr_to_offset(stop_meta);
+
+	walk_kmsg_meta(buf, start, end);
+	ret = msync(buf, len, MS_SYNC);
+	if (ret < 0) {
+		perror("msghash: msync");
+		return 1;
+	}
+
+	total = st.updated + st.skipped + st.invalid;
+	printf("msghash: %d/%d entries updated, %d skipped, %d invalid\n",
+	       st.updated, total, st.skipped, st.invalid);
+
+	return 0;
+}
diff --git a/scripts/msghash/msghash.sh b/scripts/msghash/msghash.sh
new file mode 100755
index 0000000..a0b749f7
--- /dev/null
+++ b/scripts/msghash/msghash.sh
@@ -0,0 +1,45 @@
+#!/bin/sh
+#
+# msghash.sh -- calculate hash values of printk messages and update
+#               the kmsg_meta table in a given object file.
+#               A Message-and-hash catalog named <object file>.msglist
+#               is also created.
+#
+# Usage: msghash.sh <object file>
+#
+# Copyright 2013 Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
+#
+# 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 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.
+
+MSGHASH=${srctree}/scripts/msghash/msghash
+target="$1"
+outfile="${target}.msglist"
+
+start_meta=`nm "$target" | grep ' __start___kmsg_meta' | awk '{print "0x"$1}'`
+stop_meta=`nm "$target" | grep ' __stop___kmsg_meta' | awk '{print "0x"$1}'`
+tmp=`objdump -h "$target" | grep ' .rodata '`
+eval `echo "$tmp" | awk '{print "rodata_addr=0x"$4"; rodata_offset=0x"$6}'`
+
+if [ -z "$start_meta" -o -z "$stop_meta" ]; then
+    echo "msghash: Couldn't find the kmsg_meta table."
+    exit 1
+fi
+if [ -z "$rodata_addr" -o -z "$rodata_offset" ]; then
+    echo "msghash: Failed to get .rodata section info."
+    exit 1
+fi
+
+$MSGHASH -o $outfile "$target" $start_meta $stop_meta $rodata_addr $rodata_offset
+
+exit $?

Re: [RESEND RFC PATCH 0/5] Add a hash value for each line in /dev/kmsg

[Joe Perches]

On Thu, 2013-07-25 at 17:37 +0900, Hidehiro Kawai wrote:
> ================
> This patch series adds hash values of printk format strings into
> each line of /dev/kmsg outputs as follows:
> 
>         6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs
> 
> These hash values allow use space to identify messages easily and
> do valuable things.  There is no guarantee that the hash values
> are unique.  However, user space can know which one collides to
> others from a message-and-hash catalog generated at build time, so
> finally it should be able to identify the messages.  User space
> can also use filename:lineno information to do that, although the
> information is not portable among various kernel versions.
> 
> 
> Background
> ==========
> We sometimes want to identify each kernel message automatically
> because of the following purposes:
> 
> (1) Show more detailed information about the message by cooperating
>     with external system
> (2) Take actions automatically depending on the message, for example
>     trigger a fail over or collect related information to analyze the
>     problem

If there are really "take action" uses, perhaps
it'd be better to mark the specific areas of code
where this needs to be done and add a notifier
function there instead of depending on post effect
processing.

Re: [RESEND RFC PATCH 0/5] Add a hash value for each line in /dev/kmsg

[Hidehiro Kawai]

Hello,

(2013/07/25 23:56), Kazuo Ito wrote:> Hello,
>
> On Thu, Jul 25, 2013 at 5:37 PM, Hidehiro Kawai <
> hidehiro.kawai.ez@hitachi.com> wrote:
>
>>  .gitignore                        |    1
>>  Makefile                          |    7 +
>>  drivers/base/core.c               |   57 ++-------
>>  drivers/usb/storage/debug.c       |    2
>>  include/asm-generic/vmlinux.lds.h |    5 +
>>  include/linux/device.h            |   73 +++++++----
>>  include/linux/kmsghash.h          |   19 +++
>>  include/linux/printk.h            |   31 ++++-
>>  kernel/printk.c                   |   81 +++++++++---
>>  lib/Kconfig.debug                 |   22 +++
>>  lib/dynamic_debug.c               |    4 -
>>  net/core/dev.c                    |    2
>>  scripts/Makefile                  |    1
>>  scripts/link-vmlinux.sh           |    5 +
>>  scripts/msghash/.gitignore        |    1
>>  scripts/msghash/Makefile          |    7 +
>>  scripts/msghash/msghash.c         |  241
>> +++++++++++++++++++++++++++++++++++++
>>  scripts/msghash/msghash.sh        |   45 +++++++
>>  tools/include/tools/jhash.h       |  192 +++++++++++++++++++++++++++++
>>  19 files changed, 698 insertions(+), 98 deletions(-)
>>  create mode 100644 include/linux/kmsghash.h
>>  create mode 100644 scripts/msghash/.gitignore
>>  create mode 100644 scripts/msghash/Makefile
>>  create mode 100644 scripts/msghash/msghash.c
>>  create mode 100755 scripts/msghash/msghash.sh
>>  create mode 100644 tools/include/tools/jhash.h
>>
>
> As for one that once tried to implement a similar idea (in vein
> at LinuxCon Japan a couple of years ago), I heartily welcome this patch
> while feeling amount of changes might be perceived to be too much,
> requiring some tradeoff analysis with other implementation options.

I agreed.  The current implementation has advantages and drawbacks,
and there are some implementation options.  We have to find a convincing
way.

> This patch precalculates hash values and wraps
> callers of printk around in macros so that it hardly ever
> causes runtime overhead, it could avoid hash collisions
> if needs be, and many creative uses of printk
> can be dealt with, in particular nested formats in %pV,
> which was my downfall... The cost is numbers of required changes.
>
> Calculating hash values in vprink_* would make spreading changes
> across all the printk-derived functions and macros unnecessary,
> but would preclude use of elaborate hash functions and, in cases
> like dev_printk(), would require a way to find or extract
> an appropriate format string. The latter requires complex pattern
> matching, lots of guess-work, has to deal with %pV, and will never
> be perfect.

Actually, in my first prototype implementation (but not published),
hash values are calculated dynamically when vprintk_emit is called.
Changed lines are less than this implementation, and it can also
handle %pV cases.  But as you say, extracting messages and
calculating hashes preliminarily is the difficult part.  I thought
this difficulty will make people not use this feature.  So I took
a way manipulating metadata in printk macros.

Regards,
--
Hidehiro Kawai
Hitachi, Yokohama Research Laboratory
Linux Technology Center

Re: [RESEND RFC PATCH 2/5] printk: add message hash values in /dev/kmsg output

[Hidehiro Kawai]

Hello,

(2013/07/26 0:01), Kazuo Ito wrote:> Hello, again.
>
> On Thu, Jul 25, 2013 at 5:37 PM, Hidehiro Kawai <
> hidehiro.kawai.ez@hitachi.com> wrote:
>
>> diff --git a/drivers/base/core.c b/drivers/base/core.c
>> index 8856d74..e2bf2af 100644
>> --- a/drivers/base/core.c
>> +++ b/drivers/base/core.c
>> @@ -2153,7 +2153,8 @@ int dev_vprintk_emit(int level, const struct device
>> *dev,
>>
>>         hdrlen = create_syslog_header(dev, hdr, sizeof(hdr));
>>
>> -       return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen, fmt,
>> args);
>> +       return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen,
>> +                           fmt, args, NULL);
>>  }
>>  EXPORT_SYMBOL(dev_vprintk_emit);
>>
>
>
>
> Position of struct kmsg_meta * arguments can be made more
> consistent. Because it can occur with va_list which comes
> last by convention, it should be brought to front of these
> lists of arguments. 

You are right.  It should be consistent.

So I will place kmsg_meta * in the front of fmt in the next version.
It would be preferred that the format string immediately followed by
variable arguments.

Regards,
-- 
Hidehiro Kawai
Hitachi, Yokohama Research Laboratory
Linux Technology Center

Re: Re: [RESEND RFC PATCH 0/5] Add a hash value for each line in /dev/kmsg

[Hidehiro Kawai]

Hello,

(2013/07/26 1:51), Joe Perches wrote:> On Thu, 2013-07-25 at 17:37 +0900, Hidehiro Kawai wrote:
>> ================
>> This patch series adds hash values of printk format strings into
>> each line of /dev/kmsg outputs as follows:
>>
>>         6,154,325061,-,b7db707c@kernel/smp.c:554;Brought up 4 CPUs
>>
>> These hash values allow use space to identify messages easily and
>> do valuable things.  There is no guarantee that the hash values
>> are unique.  However, user space can know which one collides to
>> others from a message-and-hash catalog generated at build time, so
>> finally it should be able to identify the messages.  User space
>> can also use filename:lineno information to do that, although the
>> information is not portable among various kernel versions.
>>
>>
>> Background
>> ==========
>> We sometimes want to identify each kernel message automatically
>> because of the following purposes:
>>
>> (1) Show more detailed information about the message by cooperating
>>     with external system
>> (2) Take actions automatically depending on the message, for example
>>     trigger a fail over or collect related information to analyze the
>>     problem
>
> If there are really "take action" uses, perhaps
> it'd be better to mark the specific areas of code
> where this needs to be done and add a notifier
> function there instead of depending on post effect
> processing.

It is one of the solution if we can add such notifiers easily, but I think
it's not true.  Adding a notifier means that it gives the portion of
the codes fixed meaning.  This is similar to adding a tracepoint.
Maintainer and developers have to keep the meaning consistent, but they
wouldn't like to do that so much.  Moreover, events users want to
handle differ depending on users and system vendors.  As the result,
we would have to add many notifiers into many places.

On the other hand, printk message handling is a flexible, readily
available and multipurpose way.

Regards,
-- 
Hidehiro Kawai
Hitachi, Yokohama Research Laboratory
Linux Technology Center