LKML Archive on lore.kernel.org
 help / Atom feed
* [PATCH] printk: Add caller information to printk() output.
@ 2018-11-24  7:37 Tetsuo Handa
  2018-11-30 15:40 ` Petr Mladek
  0 siblings, 1 reply; 22+ messages in thread
From: Tetsuo Handa @ 2018-11-24  7:37 UTC (permalink / raw)
  To: Petr Mladek, Sergey Senozhatsky, Sergey Senozhatsky,
	Dmitriy Vyukov, Steven Rostedt, Linus Torvalds, Andrew Morton
  Cc: LKML, Tetsuo Handa

Sometimes we want to print a whole line without being disturbed by
concurrent printk() from interrupts and/or other threads, for printk()
which does not end with '\n' can be disturbed.

We tried to allow printk() callers to explicitly use their local buffer
in order to make sure that a whole line is printed by one printk() call.
But it turned out that it is not realistic to ask printk() callers to
update their function arguments only for handling rare race conditions.
Also, like Steven Rostedt mentioned at [1], buffering sometimes makes
the situation worse. Therefore, we should not enforce buffering in a way
that requires modification of printk() callers.

I need to give up (at least for now) manipulating text which will be
passed to printk(). Instead, I propose allow saving caller information
as of calling log_store() and adding it as "T$thread_id" or
"C$processor_id" upon printing each line of printk() output.


Some examples for console output:

  [    0.293000] [T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
  [    0.299733] [T1] Performance Events: Haswell events, core PMU driver.
  [    2.813808] [T35] clocksource: Switched to clocksource tsc
  [    2.893984] [C0] random: fast init done

Some examples for /dev/kmsg output:

  6,21,0,-,from=T0;NX (Execute Disable) protection: active
  6,22,0,-,from=T0;SMBIOS 2.7 present.
  6,23,0,-,from=T0;DMI: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 05/19/2017
  6,24,0,-,from=T0;tsc: Fast TSC calibration using PIT
  6,25,0,-,from=T0;tsc: Detected 2793.552 MHz processor
  7,26,858,-,from=T0;e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
  7,27,864,-,from=T0;e820: remove [mem 0x000a0000-0x000fffff] usable
  6,28,882,-,from=T0;last_pfn = 0x140000 max_arch_pfn = 0x400000000
  7,29,953,-,from=T0;MTRR default type: uncachable
  6,512,753757,-,from=T1;PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
  6,513,757721,-,from=T1;ACPI: Enabled 4 GPEs in block 00 to 0F
  6,514,984829,-,from=T1;ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-7f])
  6,515,985728,-,from=T1;acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI]
   SUBSYSTEM=acpi
   DEVICE=+acpi:PNP0A03:00
  6,516,987723,-,from=T1;acpi PNP0A03:00: _OSC: platform does not support [AER LTR]
   SUBSYSTEM=acpi
   DEVICE=+acpi:PNP0A03:00
  6,517,989723,-,from=T1;acpi PNP0A03:00: _OSC: OS now controls [PCIeHotplug PME PCIeCapability]
   SUBSYSTEM=acpi
   DEVICE=+acpi:PNP0A03:00
  5,1493,2893984,-,from=C0;random: fast init done


[1] https://lkml.kernel.org/r/20181123105634.4956c255@vmware.local.home

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
 kernel/printk/printk.c | 33 +++++++++++++++++++++++++++++++++
 lib/Kconfig.debug      | 17 +++++++++++++++++
 2 files changed, 50 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 5c2079d..5ace5ba 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -356,6 +356,9 @@ struct printk_log {
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */
+#ifdef CONFIG_PRINTK_FROM
+	u32 from_id;            /* thread id or processor id */
+#endif
 }
 #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
 __packed __aligned(4)
@@ -609,6 +612,12 @@ static int log_store(int facility, int level,
 
 	/* fill message */
 	msg = (struct printk_log *)(log_buf + log_next_idx);
+#ifdef CONFIG_PRINTK_FROM
+	if (in_task())
+		msg->from_id = current->pid;
+	else
+		msg->from_id = 0x80000000 + raw_smp_processor_id();
+#endif
 	memcpy(log_text(msg), text, text_len);
 	msg->text_len = text_len;
 	if (trunc_msg_len) {
@@ -690,9 +699,17 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
 
 	do_div(ts_usec, 1000);
 
+#ifdef CONFIG_PRINTK_FROM
+	return scnprintf(buf, size, "%u,%llu,%llu,%c,from=%c%u;",
+			 (msg->facility << 3) | msg->level, seq, ts_usec,
+			 msg->flags & LOG_CONT ? 'c' : '-',
+			 msg->from_id & 0x80000000 ? 'C' : 'T',
+			 msg->from_id & ~0x80000000);
+#else
 	return scnprintf(buf, size, "%u,%llu,%llu,%c;",
 		       (msg->facility << 3) | msg->level, seq, ts_usec,
 		       msg->flags & LOG_CONT ? 'c' : '-');
+#endif
 }
 
 static ssize_t msg_print_ext_body(char *buf, size_t size,
@@ -1037,6 +1054,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_FROM
+	VMCOREINFO_OFFSET(printk_log, from_id);
+#endif
 }
 #endif
 
@@ -1242,6 +1262,16 @@ static size_t print_time(u64 ts, char *buf)
 		       (unsigned long)ts, rem_nsec / 1000);
 }
 
+#ifdef CONFIG_PRINTK_FROM
+static size_t print_from(u32 id, char *buf)
+{
+	char tmp[16];
+
+	return sprintf(buf ? buf : tmp, "[%c%u] ", id & 0x80000000 ? 'C' : 'T',
+		       id & ~0x80000000);
+}
+#endif
+
 static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
 {
 	size_t len = 0;
@@ -1262,6 +1292,9 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
 	}
 
 	len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+#ifdef CONFIG_PRINTK_FROM
+	len += print_from(msg->from_id, buf ? buf + len : NULL);
+#endif
 	return len;
 }
 
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 1af29b8..bf84fdc 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -17,6 +17,23 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
 
+config PRINTK_FROM
+	bool "Show caller information on printks"
+	depends on PRINTK
+	help
+	  Selecting this option causes "thread id" (if in task context) or
+	  "processor id" (if not in task context) of the printk() messages
+	  to be added.
+
+	  This option is intended for environments where multiple threads
+	  concurrently call printk() for many times, for it is difficult to
+	  interpret without knowing where these lines (or sometimes individual
+	  line which was divided into multiple lines due to race) came from.
+
+	  Since this is currently an experimental functionality which might be
+	  changed/reverted in the future, there is no option to enable/disable
+	  at the kernel command line parameter or sysfs interface.
+
 config CONSOLE_LOGLEVEL_DEFAULT
 	int "Default console loglevel (1-15)"
 	range 1 15
-- 
1.8.3.1


^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-11-24  7:37 [PATCH] printk: Add caller information to printk() output Tetsuo Handa
@ 2018-11-30 15:40 ` Petr Mladek
  2018-12-01 14:44   ` Tetsuo Handa
  0 siblings, 1 reply; 22+ messages in thread
From: Petr Mladek @ 2018-11-30 15:40 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Dmitriy Vyukov,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML

On Sat 2018-11-24 16:37:55, Tetsuo Handa wrote:
> Sometimes we want to print a whole line without being disturbed by
> concurrent printk() from interrupts and/or other threads, for printk()
> which does not end with '\n' can be disturbed.
> 
> We tried to allow printk() callers to explicitly use their local buffer
> in order to make sure that a whole line is printed by one printk() call.
> But it turned out that it is not realistic to ask printk() callers to
> update their function arguments only for handling rare race conditions.
> Also, like Steven Rostedt mentioned at [1], buffering sometimes makes
> the situation worse. Therefore, we should not enforce buffering in a way
> that requires modification of printk() callers.
> 
> I need to give up (at least for now) manipulating text which will be
> passed to printk(). Instead, I propose allow saving caller information
> as of calling log_store() and adding it as "T$thread_id" or
> "C$processor_id" upon printing each line of printk() output.

It looks like the best solution that I can think of at the moment.
I suggest only few cosmetic changes.

> 
> Some examples for console output:
> 
>   [    0.293000] [T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
>   [    0.299733] [T1] Performance Events: Haswell events, core PMU driver.
>   [    2.813808] [T35] clocksource: Switched to clocksource tsc
>   [    2.893984] [C0] random: fast init done
                  ^

Please, remove the space between the timestamp and the from field.

>  kernel/printk/printk.c | 33 +++++++++++++++++++++++++++++++++
>  lib/Kconfig.debug      | 17 +++++++++++++++++
>  2 files changed, 50 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 5c2079d..5ace5ba 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -609,6 +612,12 @@ static int log_store(int facility, int level,
>  
>  	/* fill message */
>  	msg = (struct printk_log *)(log_buf + log_next_idx);
> +#ifdef CONFIG_PRINTK_FROM
> +	if (in_task())
> +		msg->from_id = current->pid;
> +	else
> +		msg->from_id = 0x80000000 + raw_smp_processor_id();
> +#endif

Please, move this below. It better fits after msg->ts_nsec assignment.

>  	memcpy(log_text(msg), text, text_len);
>  	msg->text_len = text_len;
>  	if (trunc_msg_len) {
> @@ -690,9 +699,17 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,
>  
>  	do_div(ts_usec, 1000);
>  
> +#ifdef CONFIG_PRINTK_FROM
> +	return scnprintf(buf, size, "%u,%llu,%llu,%c,from=%c%u;",
> +			 (msg->facility << 3) | msg->level, seq, ts_usec,
> +			 msg->flags & LOG_CONT ? 'c' : '-',
> +			 msg->from_id & 0x80000000 ? 'C' : 'T',
> +			 msg->from_id & ~0x80000000);
> +#else
>  	return scnprintf(buf, size, "%u,%llu,%llu,%c;",
>  		       (msg->facility << 3) | msg->level, seq, ts_usec,
>  		       msg->flags & LOG_CONT ? 'c' : '-');

Please, avoid cut&pasting.

> +#endif
>  }
>  
>  static ssize_t msg_print_ext_body(char *buf, size_t size,
> @@ -1037,6 +1054,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_FROM
> +	VMCOREINFO_OFFSET(printk_log, from_id);
> +#endif

The crash tool would need to be updated if anyone wanted to read
the log from the extended structure. Well, it might be done later
if people start using it more widely.

I think about adding one more filed "u8 version". It would help
to solve the external compatibility in the long term.


Anyway, I like this feature. It is compatible with /dev/kmsg
format. dmesg works well. It helps to sort any mixed output
from both full and continuous lines.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-11-30 15:40 ` Petr Mladek
@ 2018-12-01 14:44   ` Tetsuo Handa
  2018-12-02 11:23     ` Tetsuo Handa
  2018-12-03 15:06     ` Petr Mladek
  0 siblings, 2 replies; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-01 14:44 UTC (permalink / raw)
  To: Petr Mladek, Dmitry Vyukov
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Steven Rostedt,
	Linus Torvalds, Andrew Morton, LKML

On 2018/12/01 0:40, Petr Mladek wrote:
>> Some examples for console output:
>>
>>   [    0.293000] [T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
>>   [    0.299733] [T1] Performance Events: Haswell events, core PMU driver.
>>   [    2.813808] [T35] clocksource: Switched to clocksource tsc
>>   [    2.893984] [C0] random: fast init done
>                   ^
> 
> Please, remove the space between the timestamp and the from field.

This space was emitted by print_time(). Do we want to modify print_time()
not to emit this space if the from field is printed?

If we modify print_time(), I think that the leading spaces inserted by "%5lu"
makes little sense, for "%5lu" is too small for systems with uptime >= 1.16 days
and parsers after all cannot assume fixed length for the timestamp field. Then,
we could change from "%5lu.%06lu" to "%lu.%06lu" so that parsers (like /bin/awk)
can get prefix part using white spaces as a delimiter.

If we want to reduce space, do we want to do like

  [0.293000@T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
  [0.299733@T1] Performance Events: Haswell events, core PMU driver.
  [2.813808@T35] clocksource: Switched to clocksource tsc
  [2.893984@C0] random: fast init done

(if printk_time = true) or

  [@T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
  [@T1] Performance Events: Haswell events, core PMU driver.
  [@T35] clocksource: Switched to clocksource tsc
  [@C0] random: fast init done

(if printk_time = false) ?

Dmitry, what format/delimiter is convenient for parsing by syzbot?

>> @@ -1037,6 +1054,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_FROM
>> +	VMCOREINFO_OFFSET(printk_log, from_id);
>> +#endif
> 
> The crash tool would need to be updated if anyone wanted to read
> the log from the extended structure. Well, it might be done later
> if people start using it more widely.

Since syzbot can utilize output from only normal consoles, I can
keep extended records unmodified for now.

> 
> I think about adding one more filed "u8 version". It would help
> to solve the external compatibility in the long term.

/dev/kmsg format allows adding more fields, but that format did not define
how to tell what fields are there. If fields are conditionally added by
kernel config options, I don't think that "u8 version" field helps.
Unless we add fields unconditionally, we will need to use $name=$value
(where $name and $value must not contain ',' and ';') representation.

> Anyway, I like this feature. It is compatible with /dev/kmsg
> format. dmesg works well. It helps to sort any mixed output
> from both full and continuous lines.

OK, let's refine this approach.


^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-01 14:44   ` Tetsuo Handa
@ 2018-12-02 11:23     ` Tetsuo Handa
  2018-12-04  2:02       ` Sergey Senozhatsky
  2018-12-03 15:06     ` Petr Mladek
  1 sibling, 1 reply; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-02 11:23 UTC (permalink / raw)
  To: Petr Mladek, Dmitry Vyukov
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Steven Rostedt,
	Linus Torvalds, Andrew Morton, LKML

On 2018/12/01 23:44, Tetsuo Handa wrote:
> On 2018/12/01 0:40, Petr Mladek wrote:
>>> Some examples for console output:
>>>
>>>   [    0.293000] [T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
>>>   [    0.299733] [T1] Performance Events: Haswell events, core PMU driver.
>>>   [    2.813808] [T35] clocksource: Switched to clocksource tsc
>>>   [    2.893984] [C0] random: fast init done
>>                   ^
>>
>> Please, remove the space between the timestamp and the from field.
> 
> This space was emitted by print_time(). Do we want to modify print_time()
> not to emit this space if the from field is printed?
> 
> If we modify print_time(), I think that the leading spaces inserted by "%5lu"
> makes little sense, for "%5lu" is too small for systems with uptime >= 1.16 days
> and parsers after all cannot assume fixed length for the timestamp field. Then,
> we could change from "%5lu.%06lu" to "%lu.%06lu" so that parsers (like /bin/awk)
> can get prefix part using white spaces as a delimiter.
> 
> If we want to reduce space, do we want to do like
> 
>   [0.293000@T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
>   [0.299733@T1] Performance Events: Haswell events, core PMU driver.
>   [2.813808@T35] clocksource: Switched to clocksource tsc
>   [2.893984@C0] random: fast init done
> 
> (if printk_time = true) or
> 
>   [@T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
>   [@T1] Performance Events: Haswell events, core PMU driver.
>   [@T35] clocksource: Switched to clocksource tsc
>   [@C0] random: fast init done
> 
> (if printk_time = false) ?
> 
> Dmitry, what format/delimiter is convenient for parsing by syzbot?

Here is an updated patch (which uses appropriate PREFIX_MAX definition
after "[PATCH v2] printk: fix printk_time race." is applied).

From 48603394cc0c8c5ad9ee57bc665dfd2c421e923b Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: Sun, 2 Dec 2018 19:41:02 +0900
Subject: [PATCH v2] 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:

  [    0.919699]@T1 x86: Booting SMP configuration:
  [    4.152681]@T271 Fusion MPT base driver 3.04.20
  [    5.070470]@C0 random: fast init done
  [    6.587900]@C3 random: crng init done

# Not yet signed-off in order to silence build-bot error reports.
---
 kernel/printk/printk.c | 62 ++++++++++++++++++++++++++++++--------------------
 lib/Kconfig.debug      | 17 ++++++++++++++
 2 files changed, 54 insertions(+), 25 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0b47e34..31151e8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -356,6 +356,9 @@ struct printk_log {
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */
+#ifdef CONFIG_PRINTK_FROM
+	u32 from_id;            /* thread id or processor id */
+#endif
 }
 #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
 __packed __aligned(4)
@@ -422,8 +425,14 @@ __packed __aligned(4)
 static u64 clear_seq;
 static u32 clear_idx;
 
+#ifdef CONFIG_PRINTK_FROM
+#define PREFIX_FROM_MAX		16
+#define PREFIX_MAX		(32 + PREFIX_FROM_MAX)
+#define LOG_LINE_MAX		(1024 - 32)
+#else
 #define PREFIX_MAX		32
 #define LOG_LINE_MAX		(1024 - PREFIX_MAX)
+#endif
 
 #define LOG_LEVEL(v)		((v) & 0x07)
 #define LOG_FACILITY(v)		((v) >> 3 & 0xff)
@@ -625,6 +634,12 @@ static int log_store(int facility, int level,
 		msg->ts_nsec = ts_nsec;
 	else
 		msg->ts_nsec = local_clock();
+#ifdef CONFIG_PRINTK_FROM
+	if (in_task())
+		msg->from_id = current->pid;
+	else
+		msg->from_id = 0x80000000 + raw_smp_processor_id();
+#endif
 	memset(log_dict(msg) + dict_len, 0, pad_len);
 	msg->len = size;
 
@@ -1227,39 +1242,36 @@ static inline void boot_delay_msec(int level)
 static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t print_time(u64 ts, char *buf)
-{
-	unsigned long rem_nsec = do_div(ts, 1000000000);
-
-	if (!buf)
-		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
-
-	return sprintf(buf, "[%5lu.%06lu] ",
-		       (unsigned long)ts, rem_nsec / 1000);
-}
-
 static size_t print_prefix(const struct printk_log *msg, bool syslog,
 			   bool time, char *buf)
 {
 	size_t len = 0;
-	unsigned int prefix = (msg->facility << 3) | msg->level;
+	char tmp[PREFIX_MAX];
 
+	if (!buf)
+		buf = tmp;
 	if (syslog) {
-		if (buf) {
-			len += sprintf(buf, "<%u>", prefix);
-		} else {
-			len += 3;
-			if (prefix > 999)
-				len += 3;
-			else if (prefix > 99)
-				len += 2;
-			else if (prefix > 9)
-				len++;
-		}
+		unsigned int prefix = (msg->facility << 3) | msg->level;
+
+		len += sprintf(buf, "<%u>", prefix);
+	}
+	if (time) {
+		u64 ts = msg->ts_nsec;
+		unsigned long rem_nsec = do_div(ts, 1000000000);
+
+		len += sprintf(buf + len, "[%5lu.%06lu]", (unsigned long)ts,
+			       rem_nsec / 1000);
 	}
+#ifdef CONFIG_PRINTK_FROM
+	{
+		u32 id = msg->from_id;
 
-	if (time)
-		len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+		len += sprintf(buf + len, "@%c%u",
+			       id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+	}
+#endif
+	if (IS_ENABLED(CONFIG_PRINTK_FROM) || time)
+		buf[len++] = ' ';
 	return len;
 }
 
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index d312188..a403e11 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -17,6 +17,23 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
 
+config PRINTK_FROM
+	bool "Show caller information on printks"
+	depends on PRINTK
+	help
+	  Selecting this option causes "thread id" (if in task context) or
+	  "processor id" (if not in task context) of the printk() messages
+	  to be added.
+
+	  This option is intended for environments where multiple threads
+	  concurrently call printk() for many times, for it is difficult to
+	  interpret without knowing where these lines (or sometimes individual
+	  line which was divided into multiple lines due to race) came from.
+
+	  Since this is currently an experimental functionality which might be
+	  changed/reverted in the future, there is no option to enable/disable
+	  at the kernel command line parameter or sysfs interface.
+
 config CONSOLE_LOGLEVEL_DEFAULT
 	int "Default console loglevel (1-15)"
 	range 1 15
-- 
1.8.3.1


^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-01 14:44   ` Tetsuo Handa
  2018-12-02 11:23     ` Tetsuo Handa
@ 2018-12-03 15:06     ` Petr Mladek
  2018-12-03 21:10       ` Tetsuo Handa
  1 sibling, 1 reply; 22+ messages in thread
From: Petr Mladek @ 2018-12-03 15:06 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML

On Sat 2018-12-01 23:44:37, Tetsuo Handa wrote:
> On 2018/12/01 0:40, Petr Mladek wrote:
> >> Some examples for console output:
> >>
> >>   [    0.293000] [T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
> >>   [    0.299733] [T1] Performance Events: Haswell events, core PMU driver.
> >>   [    2.813808] [T35] clocksource: Switched to clocksource tsc
> >>   [    2.893984] [C0] random: fast init done
> >                   ^
> > 
> > Please, remove the space between the timestamp and the from field.
> 
> This space was emitted by print_time(). Do we want to modify print_time()
> not to emit this space if the from field is printed?

Exactly. This is what I thought about.
 
> If we modify print_time(), I think that the leading spaces inserted by "%5lu"
> makes little sense, for "%5lu" is too small for systems with uptime >= 1.16 days
> and parsers after all cannot assume fixed length for the timestamp field. Then,
> we could change from "%5lu.%06lu" to "%lu.%06lu" so that parsers (like /bin/awk)
> can get prefix part using white spaces as a delimiter.

My primary concern was a human readability. The different header columns
are separated by brackets and the message itself is separated by the space.

awk could easily use \[ as the separator.

But you made a good point about the column width. The text might be
hard to read when every line of text starts on a different column. And
the might be bigger differences for the task id. It might be useful to
add some reasonable default width also for the for the "from_id" column.

> If we want to reduce space, do we want to do like
> 
>   [0.293000@T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
>   [0.299733@T1] Performance Events: Haswell events, core PMU driver.
>   [2.813808@T35] clocksource: Switched to clocksource tsc
>   [2.893984@C0] random: fast init done

Hmm, this is pretty hard to parse by my eyes. Also it changes the format
of the timestamp column.

I think that the following might give the best human user experience:

[    0.293000][     T1] smpboot: CPU0: Intel(R) Core(TM) i5-4440S CPU @ 2.80GHz (family: 0x6, model: 0x3c, stepping: 0x3)
[    0.299733][     T1] Performance Events: Haswell events, core PMU driver.
[    2.813808][    T35] clocksource: Switched to clocksource tsc
[    2.893984][     C0] random: fast init done


> >> @@ -1037,6 +1054,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_FROM
> >> +	VMCOREINFO_OFFSET(printk_log, from_id);
> >> +#endif
> > 
> > The crash tool would need to be updated if anyone wanted to read
> > the log from the extended structure. Well, it might be done later
> > if people start using it more widely.
> 
> Since syzbot can utilize output from only normal consoles, I can
> keep extended records unmodified for now.

Please, add VMCOREINFO_OFFSET(printk_log, from_id) so that crashdump
can be updated when necessary.

> > 
> > I think about adding one more filed "u8 version". It would help
> > to solve the external compatibility in the long term.
> 
> /dev/kmsg format allows adding more fields, but that format did not define
> how to tell what fields are there. If fields are conditionally added by
> kernel config options, I don't think that "u8 version" field helps.
> Unless we add fields unconditionally, we will need to use $name=$value
> (where $name and $value must not contain ',' and ';') representation.

/dev/kmsg uses key=value notation. It does not need any version. The
version filed was intended for crashdump. It would make the life
easier for its maintainers.

Well, I do not resist on it. Let's put the version field aside for now.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-03 15:06     ` Petr Mladek
@ 2018-12-03 21:10       ` Tetsuo Handa
  2018-12-04 15:27         ` Petr Mladek
  0 siblings, 1 reply; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-03 21:10 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML

On 2018/12/04 0:06, Petr Mladek wrote:
>> If we modify print_time(), I think that the leading spaces inserted by "%5lu"
>> makes little sense, for "%5lu" is too small for systems with uptime >= 1.16 days
>> and parsers after all cannot assume fixed length for the timestamp field. Then,
>> we could change from "%5lu.%06lu" to "%lu.%06lu" so that parsers (like /bin/awk)
>> can get prefix part using white spaces as a delimiter.
> 
> My primary concern was a human readability. The different header columns
> are separated by brackets and the message itself is separated by the space.

PID_MAX_LIMIT is 4194304, which can take up to 10 bytes if [T%u] is used.
But unless a race occurs, each series of printk() lines are printed with
same width. My concern is how to minimize number of characters written to
consoles, for writing to consoles are slow, and userspace usually uses
/dev/kmsg rather than netconsole as a source. For normal users who do not
need to directly parse console/netconsole output, saving spaces in the header
fields will be OK.

> /dev/kmsg uses key=value notation. It does not need any version. The
> version filed was intended for crashdump. It would make the life
> easier for its maintainers.

If the version field is for crashdump rather than for netconsole, we can
get it from some vmcoreinfo variable rather than appending to every record.


^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-02 11:23     ` Tetsuo Handa
@ 2018-12-04  2:02       ` Sergey Senozhatsky
  2018-12-04 10:16         ` Tetsuo Handa
  0 siblings, 1 reply; 22+ messages in thread
From: Sergey Senozhatsky @ 2018-12-04  2:02 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Petr Mladek, Dmitry Vyukov, Sergey Senozhatsky,
	Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Andrew Morton, LKML

On (12/02/18 20:23), Tetsuo Handa wrote:
> 
> Some examples for console output:
> 
>   [    0.919699]@T1 x86: Booting SMP configuration:
>   [    4.152681]@T271 Fusion MPT base driver 3.04.20
>   [    5.070470]@C0 random: fast init done
>   [    6.587900]@C3 random: crng init done

This is hard to read. Let's have a fixed width space for from_id.

> +#ifdef CONFIG_PRINTK_FROM
> +	if (in_task())
> +		msg->from_id = current->pid;

Let's use task_pid_nr().

> -static size_t print_time(u64 ts, char *buf)
> -{
> -	unsigned long rem_nsec = do_div(ts, 1000000000);
> -
> -	if (!buf)
> -		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
> -
> -	return sprintf(buf, "[%5lu.%06lu] ",
> -		       (unsigned long)ts, rem_nsec / 1000);
> -}

OK, this patch depends on printk_time patch.

> +config PRINTK_FROM
> +	bool "Show caller information on printks"
> +	depends on PRINTK

Wasn't it supposed to also depend on DEBUG_AID_FOR_SYZBOT?

	-ss

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-04  2:02       ` Sergey Senozhatsky
@ 2018-12-04 10:16         ` Tetsuo Handa
  2018-12-04 10:38           ` Sergey Senozhatsky
  2018-12-04 15:31           ` Petr Mladek
  0 siblings, 2 replies; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-04 10:16 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Dmitry Vyukov, Sergey Senozhatsky, Steven Rostedt,
	Linus Torvalds, Andrew Morton, LKML

On 2018/12/04 11:02, Sergey Senozhatsky wrote:
> On (12/02/18 20:23), Tetsuo Handa wrote:
>>
>> Some examples for console output:
>>
>>   [    0.919699]@T1 x86: Booting SMP configuration:
>>   [    4.152681]@T271 Fusion MPT base driver 3.04.20
>>   [    5.070470]@C0 random: fast init done
>>   [    6.587900]@C3 random: crng init done
> 
> This is hard to read. Let's have a fixed width space for from_id.

Console might be only 80 columns. When we have to check from screen capture of
crash, triggering needless newlines due to occupying columns more than needed
will not be nice. Also, syzbot has file size limit for saving console output.
Wasting with needless spaces increases possibility of loosing past lines.
Given that said, do you still want to waste precious columns with spaces?

> 
>> +config PRINTK_FROM
>> +	bool "Show caller information on printks"
>> +	depends on PRINTK
> 
> Wasn't it supposed to also depend on DEBUG_AID_FOR_SYZBOT?

CONFIG_DEBUG_AID_FOR_SYZBOT is currently linux-next only option.
This feature will be useful for non-syzbot environments.


^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-04 10:16         ` Tetsuo Handa
@ 2018-12-04 10:38           ` Sergey Senozhatsky
  2018-12-04 15:31           ` Petr Mladek
  1 sibling, 0 replies; 22+ messages in thread
From: Sergey Senozhatsky @ 2018-12-04 10:38 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Sergey Senozhatsky, Petr Mladek, Dmitry Vyukov,
	Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Andrew Morton, LKML

On (12/04/18 19:16), Tetsuo Handa wrote:
> On 2018/12/04 11:02, Sergey Senozhatsky wrote:
> > On (12/02/18 20:23), Tetsuo Handa wrote:
> >>
> >> Some examples for console output:
> >>
> >>   [    0.919699]@T1 x86: Booting SMP configuration:
> >>   [    4.152681]@T271 Fusion MPT base driver 3.04.20
> >>   [    5.070470]@C0 random: fast init done
> >>   [    6.587900]@C3 random: crng init done
> > 
> > This is hard to read. Let's have a fixed width space for from_id.
> 
> Console might be only 80 columns. When we have to check from screen capture of
> crash, triggering needless newlines due to occupying columns more than needed
> will not be nice. Also, syzbot has file size limit for saving console output.
> Wasting with needless spaces increases possibility of loosing past lines.
> Given that said, do you still want to waste precious columns with spaces?

Well, if the feature will be useful for non-syzbot cases as well, as
you mention below, then I'd say let's make the output human readable.
To some extent, at least.

I think we consume much more bytes on pr_fmt prefixes; and not all of them
are very useful all the time.

[..]
[    1.223872] nouveau 0000:01:00.0: DRM: DCB outp 00: 01000f02 00020030
[    1.224090] nouveau 0000:01:00.0: DRM: DCB outp 01: 02011f62 00020010
[..]
[    2.676030] snd_hda_codec_realtek hdaudioC0D0: autoconfig for ALC662 rev3: line_outs=1 (0x14/0x0/0x0/0x0/0x0) type:line
[    2.676643] snd_hda_codec_realtek hdaudioC0D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    2.677258] snd_hda_codec_realtek hdaudioC0D0:    hp_outs=1 (0x1b/0x0/0x0/0x0/0x0)
[    2.677879] snd_hda_codec_realtek hdaudioC0D0:    mono: mono_out=0x0
[    2.678578] snd_hda_codec_realtek hdaudioC0D0:    inputs:
[    2.679150] snd_hda_codec_realtek hdaudioC0D0:      Front Mic=0x19
[..]
[  430.768498] rndis_host 1-1:1.0 enp0s20f0u1: unregister 'rndis_host' usb-0000:00:14.0-1, RNDIS device


So, to me, PRINTK_FROM probably does not look like a really bad
serial console abuser. How many bytes do we need for PRINTK_FROM?
7-8?

> CONFIG_DEBUG_AID_FOR_SYZBOT is currently linux-next only option.
> This feature will be useful for non-syzbot environments.

	-ss

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-03 21:10       ` Tetsuo Handa
@ 2018-12-04 15:27         ` Petr Mladek
  2018-12-05 10:42           ` Tetsuo Handa
  0 siblings, 1 reply; 22+ messages in thread
From: Petr Mladek @ 2018-12-04 15:27 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML

On Tue 2018-12-04 06:10:40, Tetsuo Handa wrote:
> On 2018/12/04 0:06, Petr Mladek wrote:
> >> If we modify print_time(), I think that the leading spaces inserted by "%5lu"
> >> makes little sense, for "%5lu" is too small for systems with uptime >= 1.16 days
> >> and parsers after all cannot assume fixed length for the timestamp field. Then,
> >> we could change from "%5lu.%06lu" to "%lu.%06lu" so that parsers (like /bin/awk)
> >> can get prefix part using white spaces as a delimiter.
> > 
> > My primary concern was a human readability. The different header columns
> > are separated by brackets and the message itself is separated by the space.
> 
> PID_MAX_LIMIT is 4194304, which can take up to 10 bytes if [T%u] is used.

4194304 is the worst case. I would use the same approach as with the
timestamp seconds. It uses 5 characters as the minimum. But it might
eventully get bigger.

IMHO, [T%5u] looks like a reasonable default.


> But unless a race occurs, each series of printk() lines are printed with
> same width.

It is not about series of printk() lines. It is about readability of the
entire log.


> My concern is how to minimize number of characters written to
> consoles, for writing to consoles are slow, and userspace usually uses
> /dev/kmsg rather than netconsole as a source. For normal users who do not
> need to directly parse console/netconsole output, saving spaces in the header
> fields will be OK.

The number of characters is important. But we do not need to get to the
extreme. Readability by humans is important.


> > /dev/kmsg uses key=value notation. It does not need any version. The
> > version filed was intended for crashdump. It would make the life
> > easier for its maintainers.
> 
> If the version field is for crashdump rather than for netconsole, we can
> get it from some vmcoreinfo variable rather than appending to every record.

Exactly. And I asked you to add back
VMCOREINFO_OFFSET(printk_log, from_id).

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-04 10:16         ` Tetsuo Handa
  2018-12-04 10:38           ` Sergey Senozhatsky
@ 2018-12-04 15:31           ` Petr Mladek
  1 sibling, 0 replies; 22+ messages in thread
From: Petr Mladek @ 2018-12-04 15:31 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Sergey Senozhatsky, Dmitry Vyukov, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML

On Tue 2018-12-04 19:16:56, Tetsuo Handa wrote:
> On 2018/12/04 11:02, Sergey Senozhatsky wrote:
> >> +config PRINTK_FROM
> >> +	bool "Show caller information on printks"
> >> +	depends on PRINTK
> > 
> > Wasn't it supposed to also depend on DEBUG_AID_FOR_SYZBOT?
> 
> CONFIG_DEBUG_AID_FOR_SYZBOT is currently linux-next only option.
> This feature will be useful for non-syzbot environments.

Yup, the feature is useful in general.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-04 15:27         ` Petr Mladek
@ 2018-12-05 10:42           ` Tetsuo Handa
  2018-12-05 11:50             ` Sergey Senozhatsky
  2018-12-10 13:09             ` Petr Mladek
  0 siblings, 2 replies; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-05 10:42 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML, syzkaller

On 2018/12/05 0:27, Petr Mladek wrote:
> On Tue 2018-12-04 06:10:40, Tetsuo Handa wrote:
>> On 2018/12/04 0:06, Petr Mladek wrote:
>>>> If we modify print_time(), I think that the leading spaces inserted by "%5lu"
>>>> makes little sense, for "%5lu" is too small for systems with uptime >= 1.16 days
>>>> and parsers after all cannot assume fixed length for the timestamp field. Then,
>>>> we could change from "%5lu.%06lu" to "%lu.%06lu" so that parsers (like /bin/awk)
>>>> can get prefix part using white spaces as a delimiter.
>>>
>>> My primary concern was a human readability. The different header columns
>>> are separated by brackets and the message itself is separated by the space.
>>
>> PID_MAX_LIMIT is 4194304, which can take up to 10 bytes if [T%u] is used.
> 
> 4194304 is the worst case. I would use the same approach as with the
> timestamp seconds. It uses 5 characters as the minimum. But it might
> eventully get bigger.
> 
> IMHO, [T%5u] looks like a reasonable default.
> 

While "%5lu.%06lu" for uptime does not decrease over time (and hence changing
to "%lu.%06lu" does not cause wavy output), "[%6s]" for T$thread_id will cause
wavy output after PID reached 100000. Isn't it hard to parse after all?

From 22a5c966651095d12ab1572f6d35dc86d5671ea5 Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: Wed, 5 Dec 2018 16:53:08 +0900
Subject: [PATCH v3] 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,-,from=T1;x86: Booting SMP configuration:
  6,968,2779635,-,from=T1;pci 0000:00:01.0: PCI bridge to [bus 01]
   SUBSYSTEM=pci
   DEVICE=+pci:0000:00:01.0
  6,1353,5069193,-,from=T268;Fusion MPT base driver 3.04.20
  5,1526,9316504,-,from=C2;random: fast init done
  6,1575,13413336,-,from=T3355;Initialized host personality

# Not yet signed-off in order to silence build-bot error reports.
---
 kernel/printk/printk.c | 82 +++++++++++++++++++++++++++++++++-----------------
 lib/Kconfig.debug      | 17 +++++++++++
 2 files changed, 71 insertions(+), 28 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 4f18472..f9812f6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -356,6 +356,9 @@ struct printk_log {
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */
+#ifdef CONFIG_PRINTK_FROM
+	u32 from_id;            /* thread id or processor id */
+#endif
 }
 #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
 __packed __aligned(4)
@@ -422,8 +425,14 @@ __packed __aligned(4)
 static u64 clear_seq;
 static u32 clear_idx;
 
+#ifdef CONFIG_PRINTK_FROM
+#define PREFIX_FROM_MAX		16
+#define PREFIX_MAX		(32 + PREFIX_FROM_MAX)
+#define LOG_LINE_MAX		(1024 - 32)
+#else
 #define PREFIX_MAX		32
 #define LOG_LINE_MAX		(1024 - PREFIX_MAX)
+#endif
 
 #define LOG_LEVEL(v)		((v) & 0x07)
 #define LOG_FACILITY(v)		((v) >> 3 & 0xff)
@@ -625,6 +634,12 @@ static int log_store(int facility, int level,
 		msg->ts_nsec = ts_nsec;
 	else
 		msg->ts_nsec = local_clock();
+#ifdef CONFIG_PRINTK_FROM
+	if (in_task())
+		msg->from_id = task_pid_nr(current);
+	else
+		msg->from_id = 0x80000000 + raw_smp_processor_id();
+#endif
 	memset(log_dict(msg) + dict_len, 0, pad_len);
 	msg->len = size;
 
@@ -688,12 +703,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 from[18];
+#ifdef CONFIG_PRINTK_FROM
+	u32 id = msg->from_id;
+
+	snprintf(from, sizeof(from), ",from=%c%u",
+		 id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+#else
+	from[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' : '-', from);
 }
 
 static ssize_t msg_print_ext_body(char *buf, size_t size,
@@ -1038,6 +1062,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_FROM
+	VMCOREINFO_OFFSET(printk_log, from_id);
+#endif
 }
 #endif
 
@@ -1227,39 +1254,38 @@ static inline void boot_delay_msec(int level)
 static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t print_time(u64 ts, char *buf)
-{
-	unsigned long rem_nsec = do_div(ts, 1000000000);
-
-	if (!buf)
-		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
-
-	return sprintf(buf, "[%5lu.%06lu] ",
-		       (unsigned long)ts, rem_nsec / 1000);
-}
-
 static size_t print_prefix(const struct printk_log *msg, bool syslog,
 			   bool time, char *buf)
 {
 	size_t len = 0;
-	unsigned int prefix = (msg->facility << 3) | msg->level;
+	char tmp[PREFIX_MAX];
 
+	if (!buf)
+		buf = tmp;
 	if (syslog) {
-		if (buf) {
-			len += sprintf(buf, "<%u>", prefix);
-		} else {
-			len += 3;
-			if (prefix > 999)
-				len += 3;
-			else if (prefix > 99)
-				len += 2;
-			else if (prefix > 9)
-				len++;
-		}
+		unsigned int prefix = (msg->facility << 3) | msg->level;
+
+		len += sprintf(buf, "<%u>", prefix);
+	}
+	if (time) {
+		u64 ts = msg->ts_nsec;
+		unsigned long rem_nsec = do_div(ts, 1000000000);
+
+		len += sprintf(buf + len, "[%5lu.%06lu]", (unsigned long)ts,
+			       rem_nsec / 1000);
 	}
+#ifdef CONFIG_PRINTK_FROM
+	{
+		u32 id = msg->from_id;
+		char from[12];
 
-	if (time)
-		len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+		snprintf(from, sizeof(from), "%c%u",
+			 id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+		len += sprintf(buf + len, "[%6s]", from);
+	}
+#endif
+	if (IS_ENABLED(CONFIG_PRINTK_FROM) || time)
+		buf[len++] = ' ';
 	return len;
 }
 
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index d312188..a403e11 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -17,6 +17,23 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
 
+config PRINTK_FROM
+	bool "Show caller information on printks"
+	depends on PRINTK
+	help
+	  Selecting this option causes "thread id" (if in task context) or
+	  "processor id" (if not in task context) of the printk() messages
+	  to be added.
+
+	  This option is intended for environments where multiple threads
+	  concurrently call printk() for many times, for it is difficult to
+	  interpret without knowing where these lines (or sometimes individual
+	  line which was divided into multiple lines due to race) came from.
+
+	  Since this is currently an experimental functionality which might be
+	  changed/reverted in the future, there is no option to enable/disable
+	  at the kernel command line parameter or sysfs interface.
+
 config CONSOLE_LOGLEVEL_DEFAULT
 	int "Default console loglevel (1-15)"
 	range 1 15
-- 
1.8.3.1


^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-05 10:42           ` Tetsuo Handa
@ 2018-12-05 11:50             ` Sergey Senozhatsky
  2018-12-07  4:58               ` Tetsuo Handa
  2018-12-10 13:09             ` Petr Mladek
  1 sibling, 1 reply; 22+ messages in thread
From: Sergey Senozhatsky @ 2018-12-05 11:50 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Petr Mladek, Dmitry Vyukov, Sergey Senozhatsky,
	Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Andrew Morton, LKML, syzkaller

On (12/05/18 19:42), Tetsuo Handa wrote:
> >>
> >> PID_MAX_LIMIT is 4194304, which can take up to 10 bytes if [T%u] is used.
> > 
> > 4194304 is the worst case. I would use the same approach as with the
> > timestamp seconds. It uses 5 characters as the minimum. But it might
> > eventully get bigger.
> > 
> > IMHO, [T%5u] looks like a reasonable default.
> > 
> 
> While "%5lu.%06lu" for uptime does not decrease over time (and hence changing
> to "%lu.%06lu" does not cause wavy output), "[%6s]" for T$thread_id will cause
> wavy output after PID reached 100000. Isn't it hard to parse after all?

100000 is a lot. So I'd say we are fine.

A side note:

Do we need PIDs at all?
PIDs don't tell that much. When you are grepping serial log you can't
actually tell if PID 15000 there and PID 15000 here, 200000 log lines
apart, are same processes; or did PIDs wrap around? And you probably
don't even care. All you need is a way to reconstruct a message around
some very specific place in the log - say in a range [-500, +500] lines,
assuming that a backtrace you are trying to reconstruct is badly fragmented.
I think, even 3 lower digits of a PID should do the trick.

	-ss

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-05 11:50             ` Sergey Senozhatsky
@ 2018-12-07  4:58               ` Tetsuo Handa
  2018-12-07  5:31                 ` Sergey Senozhatsky
  0 siblings, 1 reply; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-07  4:58 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Dmitry Vyukov, Sergey Senozhatsky,
	Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Andrew Morton, LKML, syzkaller

Sergey Senozhatsky wrote:
> Do we need PIDs at all?

Yes. I don't like truncating caller information, for I think that PID is
used for not only reconstructing messages but also serving as a clue for
understanding what the process was doing.

> PIDs don't tell that much. When you are grepping serial log you can't
> actually tell if PID 15000 there and PID 15000 here, 200000 log lines
> apart, are same processes; or did PIDs wrap around? And you probably
> don't even care.

I don't care whether PIDs wrapped around. If the goal were to check whether PIDs
wrapped around, we would print "struct task_struct"->[real_]start_time together.

>                  All you need is a way to reconstruct a message around
> some very specific place in the log - say in a range [-500, +500] lines,
> assuming that a backtrace you are trying to reconstruct is badly fragmented.
> I think, even 3 lower digits of a PID should do the trick.

3 lower digits is insufficient for reconstructing PID of interest; it can
conflict at 1/1000 probability.
3 lower hexadecimal digits might be better but is insufficient; it can still
conflict at 1/4096.

3 lower base64 characters might be sufficient; it conflicts at only 1/262144.
4 base64 characters is sufficient, for 64*64*64*64 > PID_MAX_LIMIT.
But what do you feel from example output shown below? While no truncation of
caller information, it is hard for humans to understand.

----------------------------------------
@@ -1227,39 +1254,47 @@ static inline void boot_delay_msec(int level)
 static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t print_time(u64 ts, char *buf)
-{
-	unsigned long rem_nsec = do_div(ts, 1000000000);
-
-	if (!buf)
-		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
-
-	return sprintf(buf, "[%5lu.%06lu] ",
-		       (unsigned long)ts, rem_nsec / 1000);
-}
-
 static size_t print_prefix(const struct printk_log *msg, bool syslog,
 			   bool time, char *buf)
 {
 	size_t len = 0;
-	unsigned int prefix = (msg->facility << 3) | msg->level;
+	char tmp[PREFIX_MAX];
 
+	if (!buf)
+		buf = tmp;
 	if (syslog) {
-		if (buf) {
-			len += sprintf(buf, "<%u>", prefix);
-		} else {
-			len += 3;
-			if (prefix > 999)
-				len += 3;
-			else if (prefix > 99)
-				len += 2;
-			else if (prefix > 9)
-				len++;
-		}
+		unsigned int prefix = (msg->facility << 3) | msg->level;
+
+		len += sprintf(buf, "<%u>", prefix);
 	}
+#ifdef CONFIG_PRINTK_FROM
+	buf[len++] = '[';
+	if (time) {
+		u64 ts = msg->ts_nsec;
+		unsigned long rem_nsec = do_div(ts, 1000000000);
 
-	if (time)
-		len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+		len += sprintf(buf + len, "%lu.%06lu", (unsigned long)ts,
+			       rem_nsec / 1000);
+	}
+	{
+		static const char base64[64] = "ABCDEFGHIJKLMNOPQRSTUVWXYZ"
+			"abcdefghijklmnopqrstuvwxyz0123456789+/";
+		u32 id = msg->from_id;
+
+		len += sprintf(buf + len, "%c%c%c%c%c] ",
+			       (id & 0x80000000 ? 'C' : 'T'),
+			       base64[(id >> 18) & 63], base64[(id >> 12) & 63],
+			       base64[(id >> 6) & 63], base64[id & 63]);
+	}
+#else
+	if (time) {
+		u64 ts = msg->ts_nsec;
+		unsigned long rem_nsec = do_div(ts, 1000000000);
+
+		len += sprintf(buf + len, "[%5lu.%06lu] ", (unsigned long)ts,
+			       rem_nsec / 1000);
+	}
+#endif
 	return len;
 }
 
----------------------------------------

----------------------------------------
[0.000000TAAAA] Disabled fast string operations
[1.023286TAAAB] Performance Events: Skylake events, core PMU driver.
[5.624742TAACc] systemd-fstab-g (156) used greatest stack depth: 13656 bytes left
[5.680184TAAA+] input: ImPS/2 Generic Wheel Mouse as /devices/platform/i8042/serio1/input/input3
[5.681783TAACb] dracut-rootfs-g (155) used greatest stack depth: 13640 bytes left
[9.299727TAAu+] ata8: SATA link down (SStatus 0 SControl 300)
[15.922239TABI/] e1000: ens32 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
[15.923927TABYb] IPv6: ADDRCONF(NETDEV_UP): ens32: link is not ready
[15.930537TABI/] IPv6: ADDRCONF(NETDEV_CHANGE): ens32: link becomes ready
[40.506011CAAAA] random: crng init done
[926.716687TAAAB] reboot: Power down
----------------------------------------

After all, printing all digits without truncation will be the better.

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-07  4:58               ` Tetsuo Handa
@ 2018-12-07  5:31                 ` Sergey Senozhatsky
  0 siblings, 0 replies; 22+ messages in thread
From: Sergey Senozhatsky @ 2018-12-07  5:31 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Sergey Senozhatsky, Petr Mladek, Dmitry Vyukov,
	Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Andrew Morton, LKML, syzkaller

On (12/07/18 13:58), Tetsuo Handa wrote:
> >                  All you need is a way to reconstruct a message around
> > some very specific place in the log - say in a range [-500, +500] lines,
> > assuming that a backtrace you are trying to reconstruct is badly fragmented.
> > I think, even 3 lower digits of a PID should do the trick.
> 
> 3 lower digits is insufficient for reconstructing PID of interest; it can
> conflict at 1/1000 probability.

OK. So you want to "trace" PID, not just a way to reconstruct fragmented
backtraces in particular places of a serial log file; that's a different
story.

> [15.922239TABI/] e1000: ens32 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
> [15.923927TABYb] IPv6: ADDRCONF(NETDEV_UP): ens32: link is not ready
> [15.930537TABI/] IPv6: ADDRCONF(NETDEV_CHANGE): ens32: link becomes ready
> [40.506011CAAAA] random: crng init done
> [926.716687TAAAB] reboot: Power down
> ----------------------------------------

Please, no.

PIDs, fixed size area, human readable. Just like Petr suggested.

[  123.12312][    T234] apic: boom

	-ss

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-05 10:42           ` Tetsuo Handa
  2018-12-05 11:50             ` Sergey Senozhatsky
@ 2018-12-10 13:09             ` Petr Mladek
  2018-12-10 14:01               ` Tetsuo Handa
  1 sibling, 1 reply; 22+ messages in thread
From: Petr Mladek @ 2018-12-10 13:09 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML, syzkaller

On Wed 2018-12-05 19:42:22, Tetsuo Handa wrote:
> From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Date: Wed, 5 Dec 2018 16:53:08 +0900
> Subject: [PATCH v3] 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

I like this formating. IMHO, the limit 100000 for the right formating
is good enough. Also I think that the process ID might give a clue.
IMHO, ID reusing is rather rare.

> Some examples for /dev/kmsg output:
> 
>   6,496,1222773,-,from=T1;x86: Booting SMP configuration:
>   6,968,2779635,-,from=T1;pci 0000:00:01.0: PCI bridge to [bus 01]
>    SUBSYSTEM=pci
>    DEVICE=+pci:0000:00:01.0
>   6,1353,5069193,-,from=T268;Fusion MPT base driver 3.04.20
>   5,1526,9316504,-,from=C2;random: fast init done
>   6,1575,13413336,-,from=T3355;Initialized host personality
> 
> # Not yet signed-off in order to silence build-bot error reports.
> ---
>  kernel/printk/printk.c | 82 +++++++++++++++++++++++++++++++++-----------------
>  lib/Kconfig.debug      | 17 +++++++++++
>  2 files changed, 71 insertions(+), 28 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 4f18472..f9812f6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -422,8 +425,14 @@ __packed __aligned(4)
>  static u64 clear_seq;
>  static u32 clear_idx;
>  
> +#ifdef CONFIG_PRINTK_FROM
> +#define PREFIX_FROM_MAX		16
> +#define PREFIX_MAX		(32 + PREFIX_FROM_MAX)
> +#define LOG_LINE_MAX		(1024 - 32)

This looks suspicious. We either need to limit LOG_LINE_MAX
by the real PREFIX_MAX (48). Or we must make sure that
the code is able to handle an eventual overflow.

For example, msg_print_text() would just ignore the line
when it overflows, see:

			if (print_prefix(msg, syslog, time, NULL) +
			    text_len + 1 >= size - len)
				break;

BTW: The limit 48 looks right. If I count correctly, the longest
prefix might be:

    <2048>[4294967296,xxxxxx][T4294967296]

38 = 6+19+13

IMHO, LOG_LINE_MAX defined as (1024 - 48) is perfectly fine. Most
lines are under 80 characters. I doubt that any goes close
to the existing limit.


> +#else
>  #define PREFIX_MAX		32
>  #define LOG_LINE_MAX		(1024 - PREFIX_MAX)
> +#endif
>  
>  #define LOG_LEVEL(v)		((v) & 0x07)
>  #define LOG_FACILITY(v)		((v) >> 3 & 0xff)

[...]

> @@ -1227,39 +1254,38 @@ static inline void boot_delay_msec(int level)
>  static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
>  module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
>  
> -static size_t print_time(u64 ts, char *buf)
> -{
> -	unsigned long rem_nsec = do_div(ts, 1000000000);
> -
> -	if (!buf)
> -		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
> -
> -	return sprintf(buf, "[%5lu.%06lu] ",
> -		       (unsigned long)ts, rem_nsec / 1000);
> -}
> -
>  static size_t print_prefix(const struct printk_log *msg, bool syslog,
>  			   bool time, char *buf)
>  {
>  	size_t len = 0;
> -	unsigned int prefix = (msg->facility << 3) | msg->level;
> +	char tmp[PREFIX_MAX];
>  
> +	if (!buf)
> +		buf = tmp;

Please, add empty lines between the if-sections. It will better
split the logical parts.

I would personally create three helper functions (print_level(),
print_time(), and print_from(). But adding the empty lines
is fine as well.

>  	if (syslog) {
> -		if (buf) {
> -			len += sprintf(buf, "<%u>", prefix);
> -		} else {
> -			len += 3;
> -			if (prefix > 999)
> -				len += 3;
> -			else if (prefix > 99)
> -				len += 2;
> -			else if (prefix > 9)
> -				len++;
> -		}
> +		unsigned int prefix = (msg->facility << 3) | msg->level;
> +
> +		len += sprintf(buf, "<%u>", prefix);
> +	}
> +	if (time) {
> +		u64 ts = msg->ts_nsec;
> +		unsigned long rem_nsec = do_div(ts, 1000000000);
> +
> +		len += sprintf(buf + len, "[%5lu.%06lu]", (unsigned long)ts,
> +			       rem_nsec / 1000);
>  	}
> +#ifdef CONFIG_PRINTK_FROM
> +	{
> +		u32 id = msg->from_id;
> +		char from[12];
>  
> -	if (time)
> -		len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
> +		snprintf(from, sizeof(from), "%c%u",
> +			 id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
> +		len += sprintf(buf + len, "[%6s]", from);
> +	}
> +#endif
> +	if (IS_ENABLED(CONFIG_PRINTK_FROM) || time)
> +		buf[len++] = ' ';

Please, add also the trailing '\0'. I know that it is not strictly
necessary but...

I consider it a good practice. It prevents a potential misuse.
For example, people might want use the output in their own
debug messages.


Otherwise, the patch looks good to me. Please, send the next
revision as a proper patch.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-10 13:09             ` Petr Mladek
@ 2018-12-10 14:01               ` Tetsuo Handa
  2018-12-11 10:26                 ` Tetsuo Handa
  0 siblings, 1 reply; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-10 14:01 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML, syzkaller

On 2018/12/10 22:09, Petr Mladek wrote:
>> +#ifdef CONFIG_PRINTK_FROM
>> +#define PREFIX_FROM_MAX		16
>> +#define PREFIX_MAX		(32 + PREFIX_FROM_MAX)
>> +#define LOG_LINE_MAX		(1024 - 32)
> 
> This looks suspicious. We either need to limit LOG_LINE_MAX
> by the real PREFIX_MAX (48). Or we must make sure that
> the code is able to handle an eventual overflow.

Reducing LOG_LINE_MAX makes devkmsg_write() to return -EINVAL.
Is such user visible change acceptable?

> BTW: The limit 48 looks right. If I count correctly, the longest
> prefix might be:
> 
>     <2048>[4294967296,xxxxxx][T4294967296]
> 
> 38 = 6+19+13

Theoretical max (based on variable's bit width) is
6 + 20 + 13 + 1 (for space) + 1 (for '\0') = 41.

We allocate 32 for "<2047>[18446744073.709551] ". Thus,
I chose 48 for "<2047>[18446744073.709551][T4294967295] ".


^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-10 14:01               ` Tetsuo Handa
@ 2018-12-11 10:26                 ` Tetsuo Handa
  2018-12-12  2:25                   ` Sergey Senozhatsky
  2018-12-13 12:18                   ` Petr Mladek
  0 siblings, 2 replies; 22+ messages in thread
From: Tetsuo Handa @ 2018-12-11 10:26 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML, syzkaller

From bdb80508390694456f3f864f9651d047ded109bf Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: Tue, 11 Dec 2018 19:23:30 +0900
Subject: [PATCH v4] 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,-,from=T1;x86: Booting SMP configuration:
  6,968,2779635,-,from=T1;pci 0000:00:01.0: PCI bridge to [bus 01]
   SUBSYSTEM=pci
   DEVICE=+pci:0000:00:01.0
  6,1353,5069193,-,from=T268;Fusion MPT base driver 3.04.20
  5,1526,9316504,-,from=C2;random: fast init done
  6,1575,13413336,-,from=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.

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
 kernel/printk/printk.c | 50 ++++++++++++++++++++++++++++++++++++++++++++++----
 lib/Kconfig.debug      | 17 +++++++++++++++++
 2 files changed, 63 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1306fe0..84e5425 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -356,6 +356,9 @@ struct printk_log {
 	u8 facility;		/* syslog facility */
 	u8 flags:5;		/* internal record flags */
 	u8 level:3;		/* syslog level */
+#ifdef CONFIG_PRINTK_FROM
+	u32 from_id;            /* thread id or processor id */
+#endif
 }
 #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
 __packed __aligned(4)
@@ -422,7 +425,11 @@ __packed __aligned(4)
 static u64 clear_seq;
 static u32 clear_idx;
 
+#ifdef CONFIG_PRINTK_FROM
+#define PREFIX_MAX		48
+#else
 #define PREFIX_MAX		32
+#endif
 #define LOG_LINE_MAX		(1024 - PREFIX_MAX)
 
 #define LOG_LEVEL(v)		((v) & 0x07)
@@ -625,6 +632,12 @@ static int log_store(int facility, int level,
 		msg->ts_nsec = ts_nsec;
 	else
 		msg->ts_nsec = local_clock();
+#ifdef CONFIG_PRINTK_FROM
+	if (in_task())
+		msg->from_id = task_pid_nr(current);
+	else
+		msg->from_id = 0x80000000 + raw_smp_processor_id();
+#endif
 	memset(log_dict(msg) + dict_len, 0, pad_len);
 	msg->len = size;
 
@@ -688,12 +701,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 from[18];
+#ifdef CONFIG_PRINTK_FROM
+	u32 id = msg->from_id;
+
+	snprintf(from, sizeof(from), ",from=%c%u",
+		 id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+#else
+	from[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' : '-', from);
 }
 
 static ssize_t msg_print_ext_body(char *buf, size_t size,
@@ -1038,6 +1060,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_FROM
+	VMCOREINFO_OFFSET(printk_log, from_id);
+#endif
 }
 #endif
 
@@ -1236,10 +1261,21 @@ 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_FROM
+static size_t print_from(u32 id, char *buf)
+{
+	char from[12];
+
+	snprintf(from, sizeof(from), "%c%u",
+		 id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+	return sprintf(buf, "[%6s]", from);
+}
+#endif
+
 static size_t print_prefix(const struct printk_log *msg, bool syslog,
 			   bool time, char *buf)
 {
@@ -1249,6 +1285,12 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,
 		len = print_syslog((msg->facility << 3) | msg->level, buf);
 	if (time)
 		len += print_time(msg->ts_nsec, buf + len);
+#ifdef CONFIG_PRINTK_FROM
+	len += print_from(msg->from_id, buf + len);
+#endif
+	if (IS_ENABLED(CONFIG_PRINTK_FROM) || time)
+		buf[len++] = ' ';
+	buf[len] = '\0'; /* For safety in case of accessed as a string. */
 	return len;
 }
 
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index d312188..e626bd7 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -17,6 +17,23 @@ config PRINTK_TIME
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
 
+config PRINTK_FROM
+	bool "Show caller information on printks"
+	depends on PRINTK
+	help
+	  Selecting this option causes "thread id" (if in task context) or
+	  "processor id" (if not in task context) of the printk() messages
+	  to be added.
+
+	  This option is intended for environments where multiple threads
+	  concurrently call printk() for many times, for it is difficult to
+	  interpret without knowing where these lines (or sometimes individual
+	  line which was divided into multiple lines due to race) came from.
+
+	  Since toggling after boot makes the code racy, currently there is
+	  no option to enable/disable at the kernel command line parameter or
+	  sysfs interface.
+
 config CONSOLE_LOGLEVEL_DEFAULT
 	int "Default console loglevel (1-15)"
 	range 1 15
-- 
1.8.3.1



^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-11 10:26                 ` Tetsuo Handa
@ 2018-12-12  2:25                   ` Sergey Senozhatsky
  2018-12-12  2:29                     ` Sergey Senozhatsky
  2018-12-13 12:18                   ` Petr Mladek
  1 sibling, 1 reply; 22+ messages in thread
From: Sergey Senozhatsky @ 2018-12-12  2:25 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Petr Mladek, Dmitry Vyukov, Sergey Senozhatsky,
	Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Andrew Morton, LKML, syzkaller

On (12/11/18 19:26), Tetsuo Handa wrote:
> @@ -688,12 +701,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 from[18];

[..]

> +#ifdef CONFIG_PRINTK_FROM
> +static size_t print_from(u32 id, char *buf)
> +{
> +	char from[12];

Are those supposed to be of different sizes: 18 and 12?

	-ss

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-12  2:25                   ` Sergey Senozhatsky
@ 2018-12-12  2:29                     ` Sergey Senozhatsky
  0 siblings, 0 replies; 22+ messages in thread
From: Sergey Senozhatsky @ 2018-12-12  2:29 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Petr Mladek, Dmitry Vyukov, Sergey Senozhatsky, Steven Rostedt,
	Linus Torvalds, Andrew Morton, LKML, syzkaller,
	Sergey Senozhatsky

On (12/12/18 11:25), Sergey Senozhatsky wrote:
> On (12/11/18 19:26), Tetsuo Handa wrote:
> > @@ -688,12 +701,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 from[18];
> 
> [..]
> 
> > +#ifdef CONFIG_PRINTK_FROM
> > +static size_t print_from(u32 id, char *buf)
> > +{
> > +	char from[12];
> 
> Are those supposed to be of different sizes: 18 and 12?

Yeah, they are. strlen(",from="). Sorry for the noise.

The patch looks good to me.

	-ss

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-11 10:26                 ` Tetsuo Handa
  2018-12-12  2:25                   ` Sergey Senozhatsky
@ 2018-12-13 12:18                   ` Petr Mladek
  2018-12-13 12:42                     ` Sergey Senozhatsky
  1 sibling, 1 reply; 22+ messages in thread
From: Petr Mladek @ 2018-12-13 12:18 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Dmitry Vyukov, Sergey Senozhatsky, Sergey Senozhatsky,
	Steven Rostedt, Linus Torvalds, Andrew Morton, LKML, syzkaller

On Tue 2018-12-11 19:26:48, Tetsuo Handa wrote:
> >From bdb80508390694456f3f864f9651d047ded109bf Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Date: Tue, 11 Dec 2018 19:23:30 +0900
> Subject: [PATCH v4] 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.
> 
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>

The patch looks fine to me:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Sergey, would you mind to ack this patch as well?


From my point of view, the patch is ready to go into
linux-next. Well, I would prefer to keep it there one more
release cycle. There is no rush. The patch is primary for
0-day robot. We are very close to the next merge window
that will be problematic because of the holidays.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 22+ messages in thread

* Re: [PATCH] printk: Add caller information to printk() output.
  2018-12-13 12:18                   ` Petr Mladek
@ 2018-12-13 12:42                     ` Sergey Senozhatsky
  0 siblings, 0 replies; 22+ messages in thread
From: Sergey Senozhatsky @ 2018-12-13 12:42 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Tetsuo Handa, Dmitry Vyukov, Sergey Senozhatsky,
	Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Andrew Morton, LKML, syzkaller

On (12/13/18 13:18), Petr Mladek wrote:
> > 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.
> > 
> > Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> 
> The patch looks fine to me:
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>
> 
> Sergey, would you mind to ack this patch as well?

Sure, Petr

Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

> From my point of view, the patch is ready to go into
> linux-next. Well, I would prefer to keep it there one more
> release cycle.

No objections.

	-ss

^ permalink raw reply	[flat|nested] 22+ messages in thread

end of thread, back to index

Thread overview: 22+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-11-24  7:37 [PATCH] printk: Add caller information to printk() output Tetsuo Handa
2018-11-30 15:40 ` Petr Mladek
2018-12-01 14:44   ` Tetsuo Handa
2018-12-02 11:23     ` Tetsuo Handa
2018-12-04  2:02       ` Sergey Senozhatsky
2018-12-04 10:16         ` Tetsuo Handa
2018-12-04 10:38           ` Sergey Senozhatsky
2018-12-04 15:31           ` Petr Mladek
2018-12-03 15:06     ` Petr Mladek
2018-12-03 21:10       ` Tetsuo Handa
2018-12-04 15:27         ` Petr Mladek
2018-12-05 10:42           ` Tetsuo Handa
2018-12-05 11:50             ` Sergey Senozhatsky
2018-12-07  4:58               ` Tetsuo Handa
2018-12-07  5:31                 ` Sergey Senozhatsky
2018-12-10 13:09             ` Petr Mladek
2018-12-10 14:01               ` Tetsuo Handa
2018-12-11 10:26                 ` Tetsuo Handa
2018-12-12  2:25                   ` Sergey Senozhatsky
2018-12-12  2:29                     ` Sergey Senozhatsky
2018-12-13 12:18                   ` Petr Mladek
2018-12-13 12:42                     ` Sergey Senozhatsky

LKML Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/lkml/0 lkml/git/0.git
	git clone --mirror https://lore.kernel.org/lkml/1 lkml/git/1.git
	git clone --mirror https://lore.kernel.org/lkml/2 lkml/git/2.git
	git clone --mirror https://lore.kernel.org/lkml/3 lkml/git/3.git
	git clone --mirror https://lore.kernel.org/lkml/4 lkml/git/4.git
	git clone --mirror https://lore.kernel.org/lkml/5 lkml/git/5.git
	git clone --mirror https://lore.kernel.org/lkml/6 lkml/git/6.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 lkml lkml/ https://lore.kernel.org/lkml \
		linux-kernel@vger.kernel.org linux-kernel@archiver.kernel.org
	public-inbox-index lkml


Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-kernel


AGPL code for this site: git clone https://public-inbox.org/ public-inbox