linux-kernel - [PATCH] printk: Print cpu number along with time

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-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20140424194024.GA25446@logfs.org>
Date:	Thu, 24 Apr 2014 15:40:24 -0400
From:	Jörn Engel <joern@...fs.org>
To:	Jiri Kosina <jkosina@...e.cz>
Cc:	Rik van Riel <riel@...hat.com>, linux-kernel@...r.kernel.org,
	peterz@...radead.org, akpm@...ux-foundation.org, cxie@...hat.com,
	Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
	Jiri Slaby <jslaby@...e.cz>
Subject: [PATCH] printk: Print cpu number along with time

On Wed, 23 April 2014 20:52:47 -0400, Jörn Engel wrote:
> 
> I use the patch below for some time now.  While it doesn't avoid the
> log pollution in the first place, it lessens the impact somewhat.

Added a config option and ported it to current -linus.  Andrew, would
you take this patch?

---

Sometimes the printk log is heavily interleaving between different cpus.
This is particularly bad when you have two backtraces at the same time,
but can be annoying in other cases as well.  With an explicit cpu
number, a simple grep can disentangle the mess for you.

Signed-off-by: Joern Engel <joern@...fs.org>
---
 kernel/printk/printk.c | 19 ++++++++++++++++---
 lib/Kconfig.debug      |  9 +++++++++
 2 files changed, 25 insertions(+), 3 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a45b50962295..b9e464924825 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -200,6 +200,7 @@ struct printk_log {
 	u16 len;		/* length of entire record */
 	u16 text_len;		/* length of text buffer */
 	u16 dict_len;		/* length of dictionary buffer */
+	u16 cpu;		/* cpu the message was generated on */
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */
@@ -346,6 +347,7 @@ static void log_store(int facility, int level,
 	msg->facility = facility;
 	msg->level = level & 7;
 	msg->flags = flags & 0x1f;
+	msg->cpu = smp_processor_id();
 	if (ts_nsec > 0)
 		msg->ts_nsec = ts_nsec;
 	else
@@ -859,7 +861,7 @@ static bool printk_time;
 #endif
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t print_time(u64 ts, char *buf)
+static size_t print_time(u64 ts, u16 cpu, char *buf)
 {
 	unsigned long rem_nsec;
 
@@ -868,11 +870,20 @@ static size_t print_time(u64 ts, char *buf)
 
 	rem_nsec = do_div(ts, 1000000000);
 
+#ifdef CONFIG_PRINTK_CPU
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",
+				(unsigned long)ts, cpu);
+
+	return sprintf(buf, "[%5lu.%06lu,%02x] ",
+			(unsigned long)ts, rem_nsec / 1000, cpu);
+#else
 	if (!buf)
 		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
 
 	return sprintf(buf, "[%5lu.%06lu] ",
 		       (unsigned long)ts, rem_nsec / 1000);
+#endif
 }
 
 static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
@@ -894,7 +905,7 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
 		}
 	}
 
-	len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+	len += print_time(msg->ts_nsec, msg->cpu, buf ? buf + len : NULL);
 	return len;
 }
 
@@ -1391,6 +1402,7 @@ static struct cont {
 	size_t cons;			/* bytes written to console */
 	struct task_struct *owner;	/* task of first print*/
 	u64 ts_nsec;			/* time of first print */
+	u16 cpu;			/* cpu the message was generated on */
 	u8 level;			/* log level of first message */
 	u8 facility;			/* log level of first message */
 	enum log_flags flags;		/* prefix, newline flags */
@@ -1440,6 +1452,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
+		cont.cpu = smp_processor_id();
 		cont.ts_nsec = local_clock();
 		cont.flags = 0;
 		cont.cons = 0;
@@ -1461,7 +1474,7 @@ static size_t cont_print_text(char *text, size_t size)
 	size_t len;
 
 	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
-		textlen += print_time(cont.ts_nsec, text);
+		textlen += print_time(cont.ts_nsec, cont.cpu, text);
 		size -= textlen;
 	}
 
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 819ac51202c0..bdec67eca521 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -15,6 +15,15 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/kernel-parameters.txt
 
+config PRINTK_CPU
+	bool "Show CPU number along with timing information"
+	depends on PRINTK_TIME
+	help
+	  Selecting this option adds the CPU number to be added to
+	  timestamps of printk() messages.  This can be useful when
+	  messages from several CPUs are interleaved, in particular
+	  for stack traces.
+
 config DEFAULT_MESSAGE_LOGLEVEL
 	int "Default message log level (1-7)"
 	range 1 7
-- 
2.0.0.rc0.1.g7b2ba98

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/