Re: [PATCH] printk: Add caller information to printk() output.
Petr Mladek writes: > On Thu 2019-03-21 13:59:53, Michael Ellerman wrote: >> Tetsuo Handa writes: >> ... >> > From 91f85d2bd494df2f73c605d8b4747e8cc0a61ae2 Mon Sep 17 00:00:00 2001 >> > From: Tetsuo Handa >> > 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 :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 :00:01.0: PCI bridge to [bus 01] >> >SUBSYSTEM=pci >> >DEVICE=+pci::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. >> >> Do you have any plans to update dmesg or other userspace tools to show >> the caller information? > > dmesg already works via the syslog interface, try dmesg -S. Oh nice, thanks. > The current implementation does not pass the information into > the /dev/kmsg interface. It has the following format: > > ",,,[,additional_values, ... > ];\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
Re: [PATCH] printk: Add caller information to printk() output.
On Thu 2019-03-21 13:59:53, Michael Ellerman wrote: > Hi Tetsuo, > > Thanks for implementing this, it's really helpful. > > Tetsuo Handa writes: > ... > > From 91f85d2bd494df2f73c605d8b4747e8cc0a61ae2 Mon Sep 17 00:00:00 2001 > > From: Tetsuo Handa > > 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 :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 :00:01.0: PCI bridge to [bus 01] > >SUBSYSTEM=pci > >DEVICE=+pci::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. > > Do you have any plans to update dmesg or other userspace tools to show > the caller information? 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: ",,,[,additional_values, ... ];\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
Re: [PATCH] printk: Add caller information to printk() output.
Hi Tetsuo, Thanks for implementing this, it's really helpful. Tetsuo Handa writes: ... > From 91f85d2bd494df2f73c605d8b4747e8cc0a61ae2 Mon Sep 17 00:00:00 2001 > From: Tetsuo Handa > 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 :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 :00:01.0: PCI bridge to [bus 01] >SUBSYSTEM=pci >DEVICE=+pci::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. Do you have any plans to update dmesg or other userspace tools to show the caller information? cheers
Re: [PATCH] printk: Add caller information to printk() output.
Dmitry Vyukov writes: > On Wed, Jan 2, 2019 at 5:09 PM Dmitry Vyukov wrote: >> >> On Tue, Dec 18, 2018 at 9:58 AM Sergey Senozhatsky >> wrote: >> > >> > 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 >> > >> > >> > One final question - can syzbot folks confirm that the patch >> > helps? Just curious. >> >> 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. > > 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. Yes, will definitely give it a try. Kevin
Re: [PATCH] printk: Add caller information to printk() output.
On 2018/12/18 17:58, Sergey Senozhatsky wrote: > 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 > > > One final question - can syzbot folks confirm that the patch > helps? Just curious. 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. ;-)
Re: [PATCH] printk: Add caller information to printk() output.
On Thu, Jan 03, 2019 at 07:27:41PM +0100, Dmitry Vyukov wrote: On Wed, Jan 2, 2019 at 5:09 PM Dmitry Vyukov wrote: On Tue, Dec 18, 2018 at 9:58 AM Sergey Senozhatsky wrote: > > 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 > > > One final question - can syzbot folks confirm that the patch > helps? Just curious. 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. 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. Thanks! We'll try out CONFIG_PRINTK_CALLER. Regards, Fengguang
Re: [PATCH] printk: Add caller information to printk() output.
On Wed, Jan 2, 2019 at 5:09 PM Dmitry Vyukov wrote: > > On Tue, Dec 18, 2018 at 9:58 AM Sergey Senozhatsky > wrote: > > > > 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 > > > > > > One final question - can syzbot folks confirm that the patch > > helps? Just curious. > > 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. 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.
Re: [PATCH] printk: Add caller information to printk() output.
On Tue, Dec 18, 2018 at 9:58 AM Sergey Senozhatsky wrote: > > 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 > > > One final question - can syzbot folks confirm that the patch > helps? Just curious. 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.
Re: [PATCH] printk: Add caller information to printk() output.
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
Re: [PATCH] printk: Add caller information to printk() output.
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 & 0x8000 ? 'C' : 'T', id & ~0x8000); > > + 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.
Re: [PATCH] printk: Add caller information to printk() output.
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 One final question - can syzbot folks confirm that the patch helps? Just curious. -ss
Re: [PATCH] printk: Add caller information to printk() output.
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 & 0x8000 ? 'C' : 'T', id & ~0x8000); > + 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
Re: [PATCH] printk: Add caller information to printk() output.
On Tue 2018-12-18 06:05:04, Tetsuo Handa wrote: > >From 91f85d2bd494df2f73c605d8b4747e8cc0a61ae2 Mon Sep 17 00:00:00 2001 > From: Tetsuo Handa > 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 :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 :00:01.0: PCI bridge to [bus 01] >SUBSYSTEM=pci >DEVICE=+pci::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 > Cc: Steven Rostedt > Cc: Dmitry Vyukov > Cc: Linus Torvalds > Cc: Andrew Morton > Signed-off-by: Tetsuo Handa > Signed-off-by: Petr Mladek Sergey, are you okay with this squashed patch, please? Best Regards, Petr
Re: [PATCH] printk: Add caller information to printk() output.
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 >> >> Acked-by: Sergey Senozhatsky >> >>> 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 & 0x8000 ? 'C' : 'T', id & ~0x8000); 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 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 :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 :00:01.0: PCI bridge to [bus 01] SUBSYSTEM=pci DEVICE=+pci::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 Cc: Steven Rostedt Cc: Dmitry Vyukov Cc: Linus Torvalds Cc: Andrew Morton Signed-off-by: Tetsuo Handa Signed-off-by: Petr Mladek --- 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
Re: [PATCH] printk: Add caller information to printk() output.
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
Re: [PATCH] printk: Add caller information to printk() output.
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 > > Acked-by: Sergey Senozhatsky > > > 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 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 --- 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 = 0x8000 + raw_smp_processor_id(); + msg->caller_id = 0x8000 + 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 & 0x8000 ? 'C' : 'T', id & ~0x8000); #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); }
Re: [PATCH] printk: Add caller information to printk() output.
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 > > The patch looks fine to me: > > Reviewed-by: Petr Mladek > > Sergey, would you mind to ack this patch as well? Sure, Petr Acked-by: Sergey Senozhatsky > 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
Re: [PATCH] printk: Add caller information to printk() output.
On Tue 2018-12-11 19:26:48, Tetsuo Handa wrote: > >From bdb80508390694456f3f864f9651d047ded109bf Mon Sep 17 00:00:00 2001 > From: Tetsuo Handa > 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 The patch looks fine to me: Reviewed-by: Petr Mladek 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
Re: [PATCH] printk: Add caller information to printk() output.
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
Re: [PATCH] printk: Add caller information to printk() output.
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
Re: [PATCH] printk: Add caller information to printk() output.
>From bdb80508390694456f3f864f9651d047ded109bf Mon Sep 17 00:00:00 2001 From: Tetsuo Handa 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 :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 :00:01.0: PCI bridge to [bus 01] SUBSYSTEM=pci DEVICE=+pci::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 --- 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 = 0x8000 + 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 & 0x8000 ? 'C' : 'T', id & ~0x8000); +#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, 10); - 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 & 0x8000 ? 'C' : 'T', id & ~0x8000); + return sprintf(buf, "
Re: [PATCH] printk: Add caller information to printk() output.
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,xx][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] ".
Re: [PATCH] printk: Add caller information to printk() output.
On Wed 2018-12-05 19:42:22, Tetsuo Handa wrote: > From: Tetsuo Handa > 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 :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 10 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 :00:01.0: PCI bridge to [bus 01] >SUBSYSTEM=pci >DEVICE=+pci::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,xx][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, 10); > - > - if (!buf) > - return snprintf(NULL, 0, "[%5lu.00] ", (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
Re: [PATCH] printk: Add caller information to printk() output.
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.506011C] 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
Re: [PATCH] printk: Add caller information to printk() output.
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, 20 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, 10); - - if (!buf) - return snprintf(NULL, 0, "[%5lu.00] ", (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, 10); - 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 & 0x8000 ? '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, 10); + + len += sprintf(buf + len, "[%5lu.%06lu] ", (unsigned long)ts, + rem_nsec / 1000); + } +#endif return len; } [0.00T] 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.506011C] random: crng init done [926.716687TAAAB] reboot: Power down After all, printing all digits without truncation will be the better.
Re: [PATCH] printk: Add caller information to printk() output.
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 10. Isn't it hard to parse after all? 10 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, 20 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
Re: [PATCH] printk: Add caller information to printk() output.
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 10. Isn't it hard to parse after all? >From 22a5c966651095d12ab1572f6d35dc86d5671ea5 Mon Sep 17 00:00:00 2001 From: Tetsuo Handa 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 :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 :00:01.0: PCI bridge to [bus 01] SUBSYSTEM=pci DEVICE=+pci::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_MAX16 +#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 = 0x8000 + 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 & 0x8000 ? 'C' : 'T', id & ~0x8000); +#else + from[0] = '\0'; +#endif do_div(ts_usec, 1000); - return scnprintf(buf, size, "%u,%llu,%llu,%c;", - (msg->fa
Re: [PATCH] printk: Add caller information to printk() output.
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
Re: [PATCH] printk: Add caller information to printk() output.
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
Re: [PATCH] printk: Add caller information to printk() output.
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 :01:00.0: DRM: DCB outp 00: 01000f02 00020030 [1.224090] nouveau :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-: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
Re: [PATCH] printk: Add caller information to printk() output.
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.
Re: [PATCH] printk: Add caller information to printk() output.
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, 10); > - > - if (!buf) > - return snprintf(NULL, 0, "[%5lu.00] ", (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
Re: [PATCH] printk: Add caller information to printk() output.
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.
Re: [PATCH] printk: Add caller information to printk() output.
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
Re: [PATCH] printk: Add caller information to printk() output.
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 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_MAX16 +#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 = 0x8000 + 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, 10); - - if (!bu
Re: [PATCH] printk: Add caller information to printk() output.
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.
Re: [PATCH] printk: Add caller information to printk() output.
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 = 0x8000 + 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 & 0x8000 ? 'C' : 'T', > + msg->from_id & ~0x8000); > +#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
[PATCH] printk: Add caller information to printk() output.
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 0x-0x0fff] usable ==> reserved 7,27,864,-,from=T0;e820: remove [mem 0x000a-0x000f] usable 6,28,882,-,from=T0;last_pfn = 0x14 max_arch_pfn = 0x4 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 [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.4956c...@vmware.local.home Signed-off-by: Tetsuo Handa --- 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 = 0x8000 + 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 & 0x8000 ? 'C' : 'T', +msg->from_id & ~0x8000); +#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, re