linux-kernel - printk: Add process name information to printk() output.

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-Id: <20200904082438.20707-1-changki.kim@samsung.com>
Date:   Fri,  4 Sep 2020 17:24:38 +0900
From:   Changki Kim <changki.kim@...sung.com>
To:     pmladek@...e.com
Cc:     sergey.senozhatsky@...il.com, rostedt@...dmis.org,
        john.ogness@...utronix.de, changbin.du@...el.com,
        masahiroy@...nel.org, rd.dunlap@...il.com,
        gregkh@...uxfoundation.org, krzk@...nel.org,
        linux-kernel@...r.kernel.org, Changki Kim <changki.kim@...sung.com>
Subject: printk: Add process name information to printk() output.

Printk() meesages are the most basic and useful debug method.
However, additional information needs in multi-processor.
If we add messages with processor id and process name, we can find
a problem only with messages when the problem occurs with H/W IP or CPU.
This is very useful in narrowing down the scope of the problems.

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 "[$processor_id: $process_name: $thread_id]"
upon printing to consoles.

Some examples for console output:

  [    0.059580] [0:      swapper/0:    1] CPU: All CPU(s) started at EL1i
  [    2.153157] [5:           init:    1] migov: complete to probe migov
  [    7.441317] [4:           init:    1] NET: Registered protocol family 39
  [   22.793389] [5:  kworker/u16:1:  184] SMP: stopping secondary CPUs

Signed-off-by: Changki Kim <changki.kim@...sung.com>
---
 kernel/printk/printk.c            | 20 ++++++++++++++++++--
 kernel/printk/printk_ringbuffer.h |  7 +++++++
 lib/Kconfig.debug                 | 16 ++++++++++++++++
 3 files changed, 41 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ad8d1dfe5fbe..b8e7a263b123 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -408,7 +408,7 @@ static unsigned long console_dropped;
 /* the next printk record to read after the last 'clear' command */
 static u64 clear_seq;
 
-#ifdef CONFIG_PRINTK_CALLER
+#if defined(CONFIG_PRINTK_CALLER) || defined(CONFIG_PRINTK_PROCESS)
 #define PREFIX_MAX		48
 #else
 #define PREFIX_MAX		32
@@ -530,7 +530,12 @@ static int log_store(u32 caller_id, int facility, int level,
 	else
 		r.info->ts_nsec = local_clock();
 	r.info->caller_id = caller_id;
-
+#ifdef CONFIG_PRINTK_PROCESS
+	get_task_comm(r.info->process, current);
+	r.info->pid = task_pid_nr(current);
+	r.info->cpu_id = raw_smp_processor_id();
+	r.info->in_interrupt = in_interrupt() ? 1 : 0;
+#endif
 	/* insert message */
 	prb_commit(&e);
 
@@ -1298,6 +1303,16 @@ static size_t print_caller(u32 id, char *buf)
 #else
 #define print_caller(id, buf) 0
 #endif
+#ifdef CONFIG_PRINTK_PROCESS
+static size_t print_process(const struct printk_info *info, char *buf)
+{
+	return sprintf(buf, "%c[%1d:%15s:%5d]",
+		       info->in_interrupt ? 'I' : ' ', info->cpu_id,
+		       info->process, info->pid);
+}
+#else
+#define print_process(info, buf) 0
+#endif
 
 static size_t info_print_prefix(const struct printk_info  *info, bool syslog,
 				bool time, char *buf)
@@ -1310,6 +1325,7 @@ static size_t info_print_prefix(const struct printk_info  *info, bool syslog,
 	if (time)
 		len += print_time(info->ts_nsec, buf + len);
 
+	len += print_process(info, buf + len);
 	len += print_caller(info->caller_id, buf + len);
 
 	if (IS_ENABLED(CONFIG_PRINTK_CALLER) || time) {
diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
index e6302da041f9..fcefe9516606 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -4,6 +4,7 @@
 #define _KERNEL_PRINTK_RINGBUFFER_H
 
 #include <linux/atomic.h>
+#include <linux/sched.h>
 
 /*
  * Meta information about each stored message.
@@ -21,6 +22,12 @@ struct printk_info {
 	u8	flags:5;	/* internal record flags */
 	u8	level:3;	/* syslog level */
 	u32	caller_id;	/* thread id or processor id */
+#ifdef CONFIG_PRINTK_PROCESS
+	int	pid;			/* process id */
+	u8	cpu_id;			/* processor id */
+	u8	in_interrupt;		/* interrupt conext */
+	char process[TASK_COMM_LEN];	/* process name */
+#endif
 };
 
 /*
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index a84a41d8fadd..921d9e0eeb1a 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -35,6 +35,22 @@ config PRINTK_CALLER
 	  no option to enable/disable at the kernel command line parameter or
 	  sysfs interface.
 
+config PRINTK_PROCESS
+        bool "Show process information on printks"
+        depends on PRINTK && !PRINTK_CALLER
+        help
+          Selecting this option causes printk() to add cpu number, process name
+	  and pid to every message.
+
+	  This option is intended for environments where multiple cores and
+	  multiple processes concurrently call printk() for many times, for it
+	  is difficult to interpret without knowing where these lines came from.
+	  This option is very useful from the point of view of vendor. You can
+	  infer problems of CPU or H/W IP to the cpu number and process name.
+
+	  This option can not use with PRINK_CALLER. Because prefix is too long
+	  and has duplicate information (processor id and thread id).
+
 config CONSOLE_LOGLEVEL_DEFAULT
 	int "Default console loglevel (1-15)"
 	range 1 15
-- 
2.14.2