All of lore.kernel.org
 help / color / mirror / Atom feed
From: Changki Kim <changki.kim@samsung.com>
To: pmladek@suse.com
Cc: sergey.senozhatsky@gmail.com, rostedt@goodmis.org,
	john.ogness@linutronix.de, changbin.du@intel.com,
	masahiroy@kernel.org, rd.dunlap@gmail.com,
	gregkh@linuxfoundation.org, krzk@kernel.org,
	linux-kernel@vger.kernel.org,
	Changki Kim <changki.kim@samsung.com>
Subject: printk: Add process name information to printk() output.
Date: Fri,  4 Sep 2020 17:24:38 +0900	[thread overview]
Message-ID: <20200904082438.20707-1-changki.kim@samsung.com> (raw)
In-Reply-To: CGME20200904082449epcas2p4420d5df2083325b328a182c79f5c0948@epcas2p4.samsung.com

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@samsung.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


       reply	other threads:[~2020-09-04  8:25 UTC|newest]

Thread overview: 19+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
     [not found] <CGME20200904082449epcas2p4420d5df2083325b328a182c79f5c0948@epcas2p4.samsung.com>
2020-09-04  8:24 ` Changki Kim [this message]
2020-09-04  9:05   ` printk: Add process name information to printk() output Greg KH
2020-09-04  9:31     ` 김창기
2020-09-04 10:34       ` 'Greg KH'
2020-09-07  1:48         ` 김창기
2020-09-04  9:47   ` John Ogness
2020-09-04 10:35     ` Greg KH
2020-09-04 19:27       ` Joe Perches
2020-09-04 12:45     ` Petr Mladek
2020-09-04 13:17       ` John Ogness
2020-09-04 15:13         ` Petr Mladek
2020-09-04 23:27           ` John Ogness
2020-09-07  9:28             ` 김창기
2020-09-07  9:54             ` Petr Mladek
2020-09-07 10:30               ` John Ogness
2020-09-07 15:47                 ` Petr Mladek
2020-09-11  9:50       ` [POC] printk: Convert dict ring into array Petr Mladek
2020-09-11 10:32         ` Petr Mladek
2020-09-11 11:09           ` John Ogness

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20200904082438.20707-1-changki.kim@samsung.com \
    --to=changki.kim@samsung.com \
    --cc=changbin.du@intel.com \
    --cc=gregkh@linuxfoundation.org \
    --cc=john.ogness@linutronix.de \
    --cc=krzk@kernel.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=masahiroy@kernel.org \
    --cc=pmladek@suse.com \
    --cc=rd.dunlap@gmail.com \
    --cc=rostedt@goodmis.org \
    --cc=sergey.senozhatsky@gmail.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.