Hello,
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
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.
Userland 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
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 <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Kay Sievers <[email protected]>
Cc: "David S. Miller" <[email protected]>
---
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 ([email protected])
+ *
+ * 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 ([email protected])
+ *
+ * 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 */
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 <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Kay Sievers <[email protected]>
Cc: "David S. Miller" <[email protected]>
---
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 eb58d2d..0380add 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -416,6 +416,7 @@
*(.text.hot) \
*(.text) \
*(.ref.text) \
+ VMLINUX_SYMBOL(printk) = VMLINUX_SYMBOL(_printk); \
DEV_KEEP(init.text) \
DEV_KEEP(exit.text) \
CPU_KEEP(init.text) \
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 8212c1a..1ec264e 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 */
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 <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Kay Sievers <[email protected]>
Cc: "David S. Miller" <[email protected]>
---
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 2499cef..558017d 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -1959,7 +1959,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 0380add..3d82844 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -200,6 +200,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 1ec264e..239a159 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 566cf2b..9302ece 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -14,6 +14,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
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 <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Kay Sievers <[email protected]>
Cc: "David S. Miller" <[email protected]>
---
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 558017d..4b12e8a1 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -1951,8 +1951,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;
@@ -1960,18 +1960,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);
@@ -1979,19 +1980,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;
@@ -2002,40 +2004,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 c0a1261..89bcce8 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -938,42 +938,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 faebb39..2a16898 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -6111,7 +6111,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),
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 <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Kay Sievers <[email protected]>
Cc: "David S. Miller" <[email protected]>
---
.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 e5e3ba0..2693d7d 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 [email protected]
+quiet_cmd_rm-msglist = CLEAN [email protected]
+
# Include targets which we want to
# execute if the rest of the kernel build went well.
vmlinux: scripts/link-vmlinux.sh $(vmlinux-deps) FORCE
@@ -1273,7 +1277,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 9302ece..bd05088 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -11,6 +11,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 <[email protected]>
+ *
+ * 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 <[email protected]>
+#
+# 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 $?
On Wed, Jul 3, 2013 at 3:46 AM, Hidehiro Kawai
<[email protected]> 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
/dev/kmsg is to a certain degree a kernel ABI. Having source code
locations in exported log records might cause people / userspace tools
to rely on these strings and expect stability here. The kernel though
cannot make any promises of its source code layout.
The hash is supposed to identify the content of a message, but what if
someone fixes the string? Maybe someone just fixes a one char typo,
the hash will change and the message will not be recognizable any
more.
As much as "automated" hash creation sounds simple; I really think
adding explicit "manually" created random message ids to the bunch of
messages that are interesting is the better option long-term. It
shouldn't be that many messages, most of the printk output is not
really useful for automated inspection or to trigger specific actions.
Messages ideally should not have any direct context to the code that
emits them, they should just identify the message and add a few
structured properties to the message.
This is how userspace identifies log messages and maintains abstract
descriptions of the specific messages to act when they appear:
http://www.freedesktop.org/wiki/Software/systemd/catalog/
Connecting kernel log message texts and source code locations with
message identifiers looks quite dangerous, hard to keep stable if
things are evolving. It might cause serious problems over time.
Thanks,
Kay
Hello,
(2013/07/26 21:43), Kay Sievers wrote:> On Wed, Jul 3, 2013 at 3:46 AM, Hidehiro Kawai
> <[email protected]> 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
>
> /dev/kmsg is to a certain degree a kernel ABI. Having source code
> locations in exported log records might cause people / userspace tools
> to rely on these strings and expect stability here. The kernel though
> cannot make any promises of its source code layout.
All we have to keep as kABI is <hash>@<filename>:<lineno> of the 5th field.
I regard the 5th field including hash as just a hint; it's not guaranteed
either the hash is unique or filename:lineno is unchanged. Userspace
tools can use the hash to identify the message quickly, but if a hash
collision occurs, the user space need to do message matching in a
traditional way. Please note that userspace tools can know which ones
collide from a catalog generated at build time.
As for <filename>:<lineno>, it wouldn't be needed for the most of the cases.
So I think I can introduce an option to suppress the output of
<filename>:<lineno> to reduce memory space.
> The hash is supposed to identify the content of a message, but what if
> someone fixes the string? Maybe someone just fixes a one char typo,
> the hash will change and the message will not be recognizable any
> more.
A catalog file which includes hash, location info, and message is
generated at build time. Combining this information with diff between
two kernel versions, userspace tools will be able to track where
messages moved and which messages changed. Then, the userspace tool
updates the message DB managed by it. So I don't think it's a hard
problem.
> As much as "automated" hash creation sounds simple; I really think
> adding explicit "manually" created random message ids to the bunch of
> messages that are interesting is the better option long-term. It
> shouldn't be that many messages, most of the printk output is not
> really useful for automated inspection or to trigger specific actions.
Yes, as far as the use case goes, it may be true. But it has some
drawbacks. Please also see my reply to Joe Perches in another thread
(I resent the patches on July 25th). Also, I heard about the discussion
at the kernel summit 2 years ago. According to the article of LWN,
it seems that Linus objected your approach (i.e. adding random bit as
message ID). Were there some agreements on this issue at the kernel summit?
Regards,
--
Hidehiro Kawai
Hitachi, Yokohama Research Laboratory
Linux Technology Center
On Mon, Jul 29, 2013 at 1:54 PM, Hidehiro Kawai
<[email protected]> wrote:
> Also, I heard about the discussion
> at the kernel summit 2 years ago. According to the article of LWN,
> it seems that Linus objected your approach (i.e. adding random bit as
> message ID). Were there some agreements on this issue at the kernel summit?
No, there are no further discussions about this.
Pre-allocated, static, randomly created 128-bit IDs are just the
simplest and most robust option to identify messages. It's an
unmanaged namespace that needs no coordination, the IDs are always
stable, never change and are guaranteed to be unique. None of the
hashing-of-the strings solutions can provide that by default.
I would expect that over time, the automatic hashes would end up
becoming static numbers explicitly add to the messages anyway, because
changing the message text will change the hash, which is nothing we
really want to deal with. For that reason, I think that we can add the
ID right away, without any of the hashing; and do that only for a very
tiny fraction of the messages where such IDs make sense and add value.
Message IDs is how userspace logging works today; so from the
userspace side this would fit into the already existing
infrastructure, while possibly changing hashes which require another
type of translation catalog would not.
Kay
Hello,
(2013/07/29 21:46), Kay Sievers wrote:> On Mon, Jul 29, 2013 at 1:54 PM, Hidehiro Kawai
> <[email protected]> wrote:
>
>> Also, I heard about the discussion
>> at the kernel summit 2 years ago. According to the article of LWN,
>> it seems that Linus objected your approach (i.e. adding random bit as
>> message ID). Were there some agreements on this issue at the kernel summit?
>
> No, there are no further discussions about this.
So, how are you going to push patches to add random 128-bit IDs into upstream?
To be honest, I don't mind if we take the way of adding random IDs, because
I'm interested in only limited number of messages for my use case (taking
some actions automatically when seeing particular messages).
The reasons why I took the way of message hashing are for upstream acceptance
and flexibility for various usages.
> Pre-allocated, static, randomly created 128-bit IDs are just the
> simplest and most robust option to identify messages. It's an
> unmanaged namespace that needs no coordination, the IDs are always
> stable, never change and are guaranteed to be unique. None of the
> hashing-of-the strings solutions can provide that by default.
I think it depends on use cases and user space tools. Strict uniqueness
and stability wouldn't always be needed.
> I would expect that over time, the automatic hashes would end up
> becoming static numbers explicitly add to the messages anyway, because
> changing the message text will change the hash, which is nothing we
> really want to deal with. For that reason, I think that we can add the
> ID right away, without any of the hashing; and do that only for a very
> tiny fraction of the messages where such IDs make sense and add value.
Adding ID to particular printks will work well for some use cases, but
not all. For example, there is a web service, OSS message pedia, which
provides kernel message details edited by community. Currently, it
looks like it lists search results based on similarity with an input
string. If it utilizes message hashes or IDs, it can provide more values.
However, the fixed message ID approach wouldn't work well, because
it deals with hundreds messages at this moment.
> Message IDs is how userspace logging works today; so from the
> userspace side this would fit into the already existing
> infrastructure, while possibly changing hashes which require another
> type of translation catalog would not.
Do you say about systemd? It is one of the user space tools which
handle messages. There can be several use cases and value-added tools
regarding that, so we shouldn't assume one particular tool, I think.
Randomly generated IDs make message handling in user space simple, but
put some maintenance costs on kernel developers. Automatically
generated hashes give some complexity to user space tools, but there is
no maintenance cost for respective printks. There are tradeoffs.
The problem is which ways are acceptable for the upstream kernel
(may be both or none?).
Regards,
--
Hidehiro Kawai
Hitachi, Yokohama Research Laboratory
Linux Technology Center