Re: [PATCH] printk: Add caller information to printk() output.

[Tetsuo Handa]

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

[Sergey Senozhatsky]

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

[Tetsuo Handa]

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)

+#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.

[Sergey Senozhatsky]

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

[Petr Mladek]

On Wed 2018-12-05 19:42:22, Tetsuo Handa wrote:
> From: Tetsuo Handa <penguin...@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.

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

[Tetsuo Handa]

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] ".

[Tetsuo Handa]

From bdb80508390694456f3f864f9651d047ded109bf Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin...@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...@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.

[Sergey Senozhatsky]

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

[Sergey Senozhatsky]

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

The patch looks good to me.

-ss

[Petr Mladek]

On Tue 2018-12-11 19:26:48, Tetsuo Handa wrote:
> >From bdb80508390694456f3f864f9651d047ded109bf Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa <penguin...@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...@I-love.SAKURA.ne.jp>

The patch looks fine to me:

Reviewed-by: Petr Mladek <pml...@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

[Sergey Senozhatsky]

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...@I-love.SAKURA.ne.jp>
>
> The patch looks fine to me:
>
> Reviewed-by: Petr Mladek <pml...@suse.com>
>
> Sergey, would you mind to ack this patch as well?

Sure, Petr

Acked-by: Sergey Senozhatsky <sergey.se...@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

[Petr Mladek]

On Thu 2018-12-13 21:42:55, Sergey Senozhatsky wrote:
> 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.
> > >

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

>
> Acked-by: Sergey Senozhatsky <sergey.se...@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.

I have pushed the patch into printk.git, for-4.22 branch.


Now, I always felt that the "from" name was a bit strange but
nothing better came to my mind until today.

I would like to rename "from" to "caller", see the patch below.
If you agree, I could push it on top or I could even squash it
into the original patch.

What do you think about it, please?


From 230cbd8efaf46e6e132a53768cc746b88589c738 Mon Sep 17 00:00:00 2001
From: Petr Mladek <pml...@suse.com>
Date: Mon, 17 Dec 2018 14:12:32 +0100
Subject: [PATCH] printk: Rename CONFIG_PRINTK_FROM to CONFIG_PRINTK_CALLER

The name printk_from is a bit unusual and I have troubles
to imagine what it exactly means. For example, @from is used
also for the iterator parameter in devkmsg_write().

I believe that printk_caller is easier to understand.

This patch does not change the existing behavior except
for the names related to PRINTK_FROM feature.

Signed-off-by: Petr Mladek <pml...@suse.com>
---
kernel/printk/printk.c | 47 ++++++++++++++++++++++++++---------------------
lib/Kconfig.debug | 2 +-
2 files changed, 27 insertions(+), 22 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f8fd63254ca3..b6c5128a1a82 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -357,8 +357,8 @@ 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 */
+#ifdef CONFIG_PRINTK_CALLER
+ u32 caller_id; /* thread id or processor id */
#endif
}
#ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
@@ -426,7 +426,7 @@ static u64 exclusive_console_stop_seq;

static u64 clear_seq;
static u32 clear_idx;

-#ifdef CONFIG_PRINTK_FROM
+#ifdef CONFIG_PRINTK_CALLER
#define PREFIX_MAX 48
#else
#define PREFIX_MAX 32
@@ -633,11 +633,11 @@ static int log_store(int facility, int level,

msg->ts_nsec = ts_nsec;
else
msg->ts_nsec = local_clock();

-#ifdef CONFIG_PRINTK_FROM
+#ifdef CONFIG_PRINTK_CALLER
if (in_task())
- msg->from_id = task_pid_nr(current);
+ msg->caller_id = task_pid_nr(current);
else
- msg->from_id = 0x80000000 + raw_smp_processor_id();
+ msg->caller_id = 0x80000000 + raw_smp_processor_id();

#endif
memset(log_dict(msg) + dict_len, 0, pad_len);
msg->len = size;

@@ -702,21 +702,21 @@ static ssize_t msg_print_ext_header(char *buf, size_t size,

struct printk_log *msg, u64 seq)
{
u64 ts_usec = msg->ts_nsec;

- char from[18];
-#ifdef CONFIG_PRINTK_FROM
- u32 id = msg->from_id;
+ char caller[18];
+#ifdef CONFIG_PRINTK_CALLER
+ u32 id = msg->caller_id;

- snprintf(from, sizeof(from), ",from=%c%u",
+ snprintf(caller, sizeof(caller), ",caller=%c%u",

id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);

#else
- from[0] = '\0';
+ caller[0] = '\0';
#endif

do_div(ts_usec, 1000);

return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",

(msg->facility << 3) | msg->level, seq, ts_usec,

- msg->flags & LOG_CONT ? 'c' : '-', from);
+ msg->flags & LOG_CONT ? 'c' : '-', caller);

}

static ssize_t msg_print_ext_body(char *buf, size_t size,

@@ -1061,8 +1061,8 @@ 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);
+#ifdef CONFIG_PRINTK_CALLER
+ VMCOREINFO_OFFSET(printk_log, caller_id);
#endif
}
#endif
@@ -1266,8 +1266,8 @@ 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)
+#ifdef CONFIG_PRINTK_CALLER
+static size_t print_caller(u32 id, char *buf)
{
char from[12];

@@ -1275,6 +1275,8 @@ static size_t print_from(u32 id, char *buf)

id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);

return sprintf(buf, "[%6s]", from);
}

+#else
+#define print_caller(id, buf) 0
#endif

static size_t print_prefix(const struct printk_log *msg, bool syslog,

@@ -1284,14 +1286,17 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,

if (syslog)

len = print_syslog((msg->facility << 3) | msg->level, buf);

+

if (time)
len += print_time(msg->ts_nsec, buf + len);

-#ifdef CONFIG_PRINTK_FROM
- len += print_from(msg->from_id, buf + len);
-#endif
- if (IS_ENABLED(CONFIG_PRINTK_FROM) || time)
+
+ len += print_caller(msg->caller_id, buf + len);
+
+ if (IS_ENABLED(CONFIG_PRINTK_CALLER) || time) {
buf[len++] = ' ';
- buf[len] = '\0'; /* For safety in case of accessed as a string. */

+ buf[len] = '\0';

+ }
+

return len;
}

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug

index 3e8e69e0b3bb..6b1ecd6b67a6 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -17,7 +17,7 @@ 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
+config PRINTK_CALLER

bool "Show caller information on printks"

depends on PRINTK
help
--
2.13.7

[Sergey Senozhatsky]

On (12/17/18 15:54), Petr Mladek wrote:
> Now, I always felt that the "from" name was a bit strange but
> nothing better came to my mind until today.

Could be printk_caller, could be printk_origin. I don't have strong
preferences.

> I would like to rename "from" to "caller", see the patch below.
> If you agree, I could push it on top or I could even squash it
> into the original patch.

Can we please squash or, better yet, ask Tetsuo to resend a new, renamed
version? An immediate follow up patch that completely renames a just added
feature feels like as if we failed to communicate it the usual way.

-ss

[Tetsuo Handa]

On 2018/12/17 23:54, Petr Mladek wrote:
> On Thu 2018-12-13 21:42:55, Sergey Senozhatsky wrote:
>> 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.
>>>>
>>> Reviewed-by: Petr Mladek <pml...@suse.com>
>>
>> Acked-by: Sergey Senozhatsky <sergey.se...@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.
>
> I have pushed the patch into printk.git, for-4.22 branch.

Thank you.

>
>
> Now, I always felt that the "from" name was a bit strange but
> nothing better came to my mind until today.
>
> I would like to rename "from" to "caller", see the patch below.
> If you agree, I could push it on top or I could even squash it
> into the original patch.
>
> What do you think about it, please?

No problem. Squashed version attached.

> - char from[18];
> -#ifdef CONFIG_PRINTK_FROM
> - u32 id = msg->from_id;
> + char caller[18];
> +#ifdef CONFIG_PRINTK_CALLER
> + u32 id = msg->caller_id;
>
> - snprintf(from, sizeof(from), ",from=%c%u",
> + snprintf(caller, sizeof(caller), ",caller=%c%u",
> id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);

Updated to [20] in case memory corruption like

CPU: 0 PID: -2035180937 Comm: L ����� Not tainted 4.20.0-rc6+ #344

happened.



From 91f85d2bd494df2f73c605d8b4747e8cc0a61ae2 Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin...@I-love.SAKURA.ne.jp>
Date: Tue, 18 Dec 2018 05:53:04 +0900
Subject: [PATCH] printk: Add caller information to printk() output.

Sometimes we want to print a series of printk() messages to consoles
without being disturbed by concurrent printk() from interrupts and/or
other threads. But we can't enforce printk() callers to use their local
buffers because we need to ask them to make too much changes. Also, even
buffering up to one line inside printk() might cause failing to emit
an important clue under critical situation.

Therefore, instead of trying to help buffering, let's try to help
reconstructing messages by saving caller information as of calling
log_store() and adding it as "[T$thread_id]" or "[C$processor_id]"
upon printing to consoles.

Some examples for console output:

[ 1.222773][ T1] x86: Booting SMP configuration:
[ 2.779635][ T1] pci 0000:00:01.0: PCI bridge to [bus 01]
[ 5.069193][ T268] Fusion MPT base driver 3.04.20
[ 9.316504][ C2] random: fast init done
[ 13.413336][ T3355] Initialized host personality

Some examples for /dev/kmsg output:

6,496,1222773,-,caller=T1;x86: Booting SMP configuration:
6,968,2779635,-,caller=T1;pci 0000:00:01.0: PCI bridge to [bus 01]

SUBSYSTEM=pci
DEVICE=+pci:0000:00:01.0

6,1353,5069193,-,caller=T268;Fusion MPT base driver 3.04.20
5,1526,9316504,-,caller=C2;random: fast init done
6,1575,13413336,-,caller=T3355;Initialized host personality

Note that this patch changes max length of messages which can be printed
by printk() or written to /dev/kmsg interface from 992 bytes to 976 bytes,
based on an assumption that userspace won't try to write messages hitting
that border line to /dev/kmsg interface.

Cc: Sergey Senozhatsky <sergey.seno...@gmail.com>
Cc: Steven Rostedt <ros...@goodmis.org>
Cc: Dmitry Vyukov <dvy...@google.com>
Cc: Linus Torvalds <torv...@linux-foundation.org>
Cc: Andrew Morton <ak...@linux-foundation.org>
Signed-off-by: Tetsuo Handa <penguin...@I-love.SAKURA.ne.jp>

Signed-off-by: Petr Mladek <pml...@suse.com>
---

kernel/printk/printk.c | 55 ++++++++++++++++++++++++++++++++++++++++++++++----
lib/Kconfig.debug | 17 ++++++++++++++++
2 files changed, 68 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1306fe0..7eb79702 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_CALLER
+ u32 caller_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_CALLER

+#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_CALLER
+ if (in_task())

+ msg->caller_id = task_pid_nr(current);

+ else

+ msg->caller_id = 0x80000000 + raw_smp_processor_id();

+#endif

memset(log_dict(msg) + dict_len, 0, pad_len);
msg->len = size;

@@ -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 caller[20];

+#ifdef CONFIG_PRINTK_CALLER
+ u32 id = msg->caller_id;

+

+ snprintf(caller, sizeof(caller), ",caller=%c%u",

+ id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+#else

+ caller[0] = '\0';

+#endif

do_div(ts_usec, 1000);

- return scnprintf(buf, size, "%u,%llu,%llu,%c;",

- (msg->facility << 3) | msg->level, seq, ts_usec,
- msg->flags & LOG_CONT ? 'c' : '-');
+ return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
+ (msg->facility << 3) | msg->level, seq, ts_usec,

+ msg->flags & LOG_CONT ? 'c' : '-', caller);
}

static ssize_t msg_print_ext_body(char *buf, size_t size,

@@ -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_CALLER
+ VMCOREINFO_OFFSET(printk_log, caller_id);

+#endif
}
#endif

@@ -1236,10 +1261,23 @@ static size_t print_time(u64 ts, char *buf)

{
unsigned long rem_nsec = do_div(ts, 1000000000);

- return sprintf(buf, "[%5lu.%06lu] ",
+ return sprintf(buf, "[%5lu.%06lu]",

(unsigned long)ts, rem_nsec / 1000);
}

+#ifdef CONFIG_PRINTK_CALLER
+static size_t print_caller(u32 id, char *buf)

+{
+ char from[12];
+
+ snprintf(from, sizeof(from), "%c%u",

+ id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+ return sprintf(buf, "[%6s]", from);

+}
+#else
+#define print_caller(id, buf) 0

+#endif
+

static size_t print_prefix(const struct printk_log *msg, bool syslog,

bool time, char *buf)
{
@@ -1247,8 +1285,17 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,

if (syslog)
len = print_syslog((msg->facility << 3) | msg->level, buf);
+
if (time)
len += print_time(msg->ts_nsec, buf + len);

+
+ len += print_caller(msg->caller_id, buf + len);
+
+ if (IS_ENABLED(CONFIG_PRINTK_CALLER) || time) {

+ buf[len++] = ' ';

+ buf[len] = '\0';
+ }
+
return len;
}

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug

index 9638656..608c355 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_CALLER

[Petr Mladek]

Sergey, are you okay with this squashed patch, please?

Best Regards,
Petr

[Sergey Senozhatsky]

On (12/18/18 06:05), Tetsuo Handa wrote:
> +#ifdef CONFIG_PRINTK_CALLER
> +static size_t print_caller(u32 id, char *buf)
> +{
> + char from[12];
> +
> + snprintf(from, sizeof(from), "%c%u",
> + id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
> + return sprintf(buf, "[%6s]", from);
> +}

A nitpick:

s/from/caller/g :)

> + 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.

Would the following wording be a bit simpler?

"Selecting this option causes printk() to add a caller "thread id" (if
in task context) or a caller "processor id" (if not in task context)
to every message."

-ss

[Sergey Senozhatsky]

On (12/18/18 09:39), Petr Mladek wrote:
>
> Sergey, are you okay with this squashed patch, please?
>

Yeah. There are several minor nitpicks, but here is my
Acked-by: Sergey Senozhatsky <sergey.se...@gmail.com>


One final question - can syzbot folks confirm that the patch
helps? Just curious.

-ss

[Petr Mladek]

On Tue 2018-12-18 17:55:24, Sergey Senozhatsky wrote:
> On (12/18/18 06:05), Tetsuo Handa wrote:
> > +#ifdef CONFIG_PRINTK_CALLER
> > +static size_t print_caller(u32 id, char *buf)
> > +{
> > + char from[12];
> > +
> > + snprintf(from, sizeof(from), "%c%u",
> > + id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
> > + return sprintf(buf, "[%6s]", from);
> > +}
>
> A nitpick:
>
> s/from/caller/g :)

Great catch!

>
> > + 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.
>
> Would the following wording be a bit simpler?
>
> "Selecting this option causes printk() to add a caller "thread id" (if
> in task context) or a caller "processor id" (if not in task context)
> to every message."

It sounds good to me.

I have updated the patch in printk.git, for-4.22 branch.

Best Regards,
Petr

PS: I think that I have rushed the patch probably too much.
I did too much nitpicking in the past and am trying to find
a better balance now.

[Sergey Senozhatsky]

On (12/18/18 11:01), Petr Mladek wrote:
> I have updated the patch in printk.git, for-4.22 branch.

Thanks.

> PS: I think that I have rushed the patch probably too much.
> I did too much nitpicking in the past and am trying to find
> a better balance now.

It's all good.

-ss

[Dmitry Vyukov]

This slip through the cracks. Tetsuo pinged me and I am testing now.
Need to create a set of tests and update parsing code to handle this.

[Dmitry Vyukov]

I've pushed support for CONFIG_PRINTK_CALLER to syzkaller/syzbot:
https://github.com/google/syzkaller/commit/7da2392541a49c3f17b2e7d24e04b84d72b965fb
Let's see what happens. Limited local testing shows that it's working
as intended and significatly improves quality of reports and ability
to make sense out of kernel output.

Tetsuo, thanks for your great persistence with this change!
Sergey, Petr, thanks for reviews!

+Fengguang, Kevin, maybe you will find this useful for 0-day/kernel-ci.

[Fengguang Wu]

Thanks! We'll try out CONFIG_PRINTK_CALLER.

Regards,
Fengguang

[Tetsuo Handa]

syzbot started utilizing this patch in linux-next.git. And surprisingly,
almost all reports which were previously treated as "corrupted report" are
now appropriately reported. I can hardly wait for arrival at linux.git.
Even if we revert from linux.git at 5.0-rc7, having this patch temporarily
available until 5.0-rc7 in linux.git would be so helpful. ;-)

[Kevin Hilman]

Yes, will definitely give it a try.

Kevin

[Michael Ellerman]

Hi Tetsuo,

Thanks for implementing this, it's really helpful.

Tetsuo Handa <penguin...@i-love.sakura.ne.jp> writes:
...

Do you have any plans to update dmesg or other userspace tools to show
the caller information?

cheers

[Petr Mladek]

dmesg already works via the syslog interface, try dmesg -S.

The current implementation does not pass the information into
the /dev/kmsg interface. It has the following format:

"<level>,<sequnum>,<timestamp>,<contflag>[,additional_values, ... ];<message text>\n"

It would be possible to add it as an additional value. To be hones
I am not sure how they are handled by userspace tools.

Best Regards,
Petr

[Michael Ellerman]

Oh nice, thanks.

> The current implementation does not pass the information into
> the /dev/kmsg interface. It has the following format:
>
> "<level>,<sequnum>,<timestamp>,<contflag>[,additional_values, ... ];<message text>\n"
>
> It would be possible to add it as an additional value. To be hones
> I am not sure how they are handled by userspace tools.

OK, yeah I guess there's the potential for a backward compatibility can
of worms there.

I'm happy with dmesg -S :)

cheers