summaryrefslogtreecommitdiffstats
path: root/kernel/printk
diff options
context:
space:
mode:
authorTetsuo Handa <penguin-kernel@i-love.sakura.ne.jp>2018-12-18 06:05:04 +0900
committerPetr Mladek <pmladek@suse.com>2018-12-18 10:53:14 +0100
commit15ff2069cb7f967dae6a8f8c176ba51447c75f00 (patch)
treeb3e4f0437c240668ad73e32b194d4e827669dbaa /kernel/printk
parent07c17732bd687567802aaa5fa5c101c2776565d1 (diff)
downloadlinux-15ff2069cb7f967dae6a8f8c176ba51447c75f00.tar.gz
linux-15ff2069cb7f967dae6a8f8c176ba51447c75f00.tar.bz2
linux-15ff2069cb7f967dae6a8f8c176ba51447c75f00.zip
printk: Add caller information to printk() output.
Sometimes we want to print a series of printk() messages to consoles without being disturbed by concurrent printk() from interrupts and/or other threads. But we can't enforce printk() callers to use their local buffers because we need to ask them to make too much changes. Also, even buffering up to one line inside printk() might cause failing to emit an important clue under critical situation. Therefore, instead of trying to help buffering, let's try to help reconstructing messages by saving caller information as of calling log_store() and adding it as "[T$thread_id]" or "[C$processor_id]" upon printing to consoles. Some examples for console output: [ 1.222773][ T1] x86: Booting SMP configuration: [ 2.779635][ T1] pci 0000:00:01.0: PCI bridge to [bus 01] [ 5.069193][ T268] Fusion MPT base driver 3.04.20 [ 9.316504][ C2] random: fast init done [ 13.413336][ T3355] Initialized host personality Some examples for /dev/kmsg output: 6,496,1222773,-,caller=T1;x86: Booting SMP configuration: 6,968,2779635,-,caller=T1;pci 0000:00:01.0: PCI bridge to [bus 01] SUBSYSTEM=pci DEVICE=+pci:0000:00:01.0 6,1353,5069193,-,caller=T268;Fusion MPT base driver 3.04.20 5,1526,9316504,-,caller=C2;random: fast init done 6,1575,13413336,-,caller=T3355;Initialized host personality Note that this patch changes max length of messages which can be printed by printk() or written to /dev/kmsg interface from 992 bytes to 976 bytes, based on an assumption that userspace won't try to write messages hitting that border line to /dev/kmsg interface. Link: http://lkml.kernel.org/r/93f19e57-5051-c67d-9af4-b17624062d44@i-love.sakura.ne.jp Cc: Dmitry Vyukov <dvyukov@google.com> Cc: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Linus Torvalds <torvalds@linux-foundation.org> Cc: Andrew Morton <akpm@linux-foundation.org> Cc: LKML <linux-kernel@vger.kernel.org> Cc: syzkaller <syzkaller@googlegroups.com> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com> Signed-off-by: Petr Mladek <pmladek@suse.com>
Diffstat (limited to 'kernel/printk')
-rw-r--r--kernel/printk/printk.c55
1 files changed, 51 insertions, 4 deletions
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 91db332ccf4d..e3d977bbc7ab 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -357,6 +357,9 @@ struct printk_log {
u8 facility; /* syslog facility */
u8 flags:5; /* internal record flags */
u8 level:3; /* syslog level */
+#ifdef CONFIG_PRINTK_CALLER
+ u32 caller_id; /* thread id or processor id */
+#endif
}
#ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
__packed __aligned(4)
@@ -423,7 +426,11 @@ static u64 exclusive_console_stop_seq;
static u64 clear_seq;
static u32 clear_idx;
+#ifdef CONFIG_PRINTK_CALLER
+#define PREFIX_MAX 48
+#else
#define PREFIX_MAX 32
+#endif
#define LOG_LINE_MAX (1024 - PREFIX_MAX)
#define LOG_LEVEL(v) ((v) & 0x07)
@@ -626,6 +633,12 @@ static int log_store(int facility, int level,
msg->ts_nsec = ts_nsec;
else
msg->ts_nsec = local_clock();
+#ifdef CONFIG_PRINTK_CALLER
+ if (in_task())
+ msg->caller_id = task_pid_nr(current);
+ else
+ msg->caller_id = 0x80000000 + raw_smp_processor_id();
+#endif
memset(log_dict(msg) + dict_len, 0, pad_len);
msg->len = size;
@@ -689,12 +702,21 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
struct printk_log *msg, u64 seq)
{
u64 ts_usec = msg->ts_nsec;
+ char caller[20];
+#ifdef CONFIG_PRINTK_CALLER
+ u32 id = msg->caller_id;
+
+ snprintf(caller, sizeof(caller), ",caller=%c%u",
+ id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+#else
+ caller[0] = '\0';
+#endif
do_div(ts_usec, 1000);
- return scnprintf(buf, size, "%u,%llu,%llu,%c;",
- (msg->facility << 3) | msg->level, seq, ts_usec,
- msg->flags & LOG_CONT ? 'c' : '-');
+ return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
+ (msg->facility << 3) | msg->level, seq, ts_usec,
+ msg->flags & LOG_CONT ? 'c' : '-', caller);
}
static ssize_t msg_print_ext_body(char *buf, size_t size,
@@ -1039,6 +1061,9 @@ void log_buf_vmcoreinfo_setup(void)
VMCOREINFO_OFFSET(printk_log, len);
VMCOREINFO_OFFSET(printk_log, text_len);
VMCOREINFO_OFFSET(printk_log, dict_len);
+#ifdef CONFIG_PRINTK_CALLER
+ VMCOREINFO_OFFSET(printk_log, caller_id);
+#endif
}
#endif
@@ -1237,10 +1262,23 @@ static size_t print_time(u64 ts, char *buf)
{
unsigned long rem_nsec = do_div(ts, 1000000000);
- return sprintf(buf, "[%5lu.%06lu] ",
+ return sprintf(buf, "[%5lu.%06lu]",
(unsigned long)ts, rem_nsec / 1000);
}
+#ifdef CONFIG_PRINTK_CALLER
+static size_t print_caller(u32 id, char *buf)
+{
+ char caller[12];
+
+ snprintf(caller, sizeof(caller), "%c%u",
+ id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+ return sprintf(buf, "[%6s]", caller);
+}
+#else
+#define print_caller(id, buf) 0
+#endif
+
static size_t print_prefix(const struct printk_log *msg, bool syslog,
bool time, char *buf)
{
@@ -1248,8 +1286,17 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,
if (syslog)
len = print_syslog((msg->facility << 3) | msg->level, buf);
+
if (time)
len += print_time(msg->ts_nsec, buf + len);
+
+ len += print_caller(msg->caller_id, buf + len);
+
+ if (IS_ENABLED(CONFIG_PRINTK_CALLER) || time) {
+ buf[len++] = ' ';
+ buf[len] = '\0';
+ }
+
return len;
}