Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1611720 > unrolled thread

[RFC][PATCHv2 0/8] printk: introduce printing kernel thread

Back to article view | Back to linux.kernel

Contents

  [RFC][PATCHv2 0/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
    [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
      Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Petr Mladek <pmladek@suse.com> - 2017-04-04 11:10 +0200
        Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-04 11:40 +0200
      Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:20 +0200
        Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 07:20 +0200
          Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-07 09:30 +0200
            Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 10:20 +0200
              Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-07 14:10 +0200
    [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
      Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in  unsafe places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:40 +0200
        Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in  unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-01 02:10 +0200
    [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Petr Mladek <pmladek@suse.com> - 2017-03-31 15:20 +0200
        Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Peter Zijlstra <peterz@infradead.org> - 2017-03-31 15:40 +0200
          Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-03 13:30 +0200
            Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Petr Mladek <pmladek@suse.com> - 2017-04-03 14:50 +0200
    [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in  unsafe places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:40 +0200
    [RFC][PATCHv2 8/8] printk: enable printk offloading Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-03-31 04:40 +0200
        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-03-31 06:10 +0200
          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Ye Xiaolong <xiaolong.ye@intel.com> - 2017-03-31 08:50 +0200
            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-31 16:50 +0200
              Re: [printk]  fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage ebiederm@xmission.com (Eric W. Biederman) - 2017-03-31 17:40 +0200
                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Jan Kara <jack@suse.cz> - 2017-04-03 11:40 +0200
                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-03 12:10 +0200
                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:40 +0200
                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 06:50 +0200
                      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 09:20 +0200
                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 09:50 +0200
                          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 10:20 +0200
                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 14:20 +0200
                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 14:50 +0200
                                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Steven Rostedt <rostedt@goodmis.org> - 2017-04-07 16:50 +0200
                                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-07 17:20 +0200
                                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Peter Zijlstra <peterz@infradead.org> - 2017-04-07 17:30 +0200
                                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-07 17:50 +0200
                                      Re: [printk]  fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage ebiederm@xmission.com (Eric W. Biederman) - 2017-04-09 20:30 +0200
                                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-10 06:50 +0200
                                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-09 12:20 +0200
                                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-10 07:00 +0200
                                      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-10 14:00 +0200
                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Steven Rostedt <rostedt@goodmis.org> - 2017-04-07 16:40 +0200
                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-09 12:00 +0200
                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-03 13:00 +0200
            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Ye Xiaolong <xiaolong.ye@intel.com> - 2017-04-05 09:40 +0200
              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-05 10:50 +0200
      Re: [RFC][PATCHv2 8/8] printk: enable printk offloading Petr Mladek <pmladek@suse.com> - 2017-04-03 17:50 +0200
        Re: [RFC][PATCHv2 8/8] printk: enable printk offloading Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-04 14:30 +0200
    [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:10 +0200
      Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:30 +0200
        Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Andreas Mohr <andi@lisas.de> - 2017-04-09 13:00 +0200
          Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Petr Mladek <pmladek@suse.com> - 2017-04-10 14:30 +0200
            Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-10 16:40 +0200
    [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Petr Mladek <pmladek@suse.com> - 2017-04-03 17:30 +0200
        Re: [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-04 10:30 +0200

Page 2 of 3 — ← Prev page 1 [2] 3  Next page →

#1613579 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (03/31/17 05:38), kernel test robot wrote:
> FYI, we noticed the following commit:
> 
> commit: fbc14616f483788afabe77d05bfb99883dc66c73 ("printk: enable printk offloading")
> url: https://github.com/0day-ci/linux/commits/Sergey-Senozhatsky/printk-introduce-printing-kernel-thread/20170330-185752

thanks for the report!

[..]
> +-------------------------------------------------+------------+------------+
> |                                                 | fd8b6b120c | fbc14616f4 |
> +-------------------------------------------------+------------+------------+
> | boot_successes                                  | 8          | 8          |
> | boot_failures                                   | 0          | 6          |
> | BUG:kernel_reboot-without-warning_in_test_stage | 0          | 4          |
> | BUG:kernel_hang_in_test_stage                   | 0          | 2          |
> +-------------------------------------------------+------------+------------+
> 
> 
> 
> [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
> [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
> [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
> 
> Elapsed time: 310
> BUG: kernel reboot-without-warning in test stage

so as far as I understand, this is the "missing kernel messages"
type of bug report. a worst case scenario.

	-ss

[toc] | [prev] | [next] | [standalone]

#1613624 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (03/31/17 11:35), Sergey Senozhatsky wrote:
[..]
> > [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
> > [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
> > [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
> > 
> > Elapsed time: 310
> > BUG: kernel reboot-without-warning in test stage
> 
> so as far as I understand, this is the "missing kernel messages"
> type of bug report. a worst case scenario.

panic() should have called console_flush_on_panic(), which sould have
flushed the messages regardless the printk_kthread state. so it probably
was not panic() that rebooted the kernel. (probably).

kernel_restart() and kernel_halt() have pr_emerg() messages, printk switches
to printk_emergency mode the first time it sees EMERG level message. (may be
we switch to late).

on the other hand, there is a emergency_restart(), where we don't switch
to printk_emergency mode and don't flush the existing kernel messages.
there is a bunch of places that call emergency_restart(), including sysrq.

may I ask you, how do you usually restart the vm after the test?
`echo X > /proc/sysrq-trigger'?

does this patch make it any better?

---
 drivers/tty/sysrq.c | 8 ++------
 1 file changed, 2 insertions(+), 6 deletions(-)

diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 817dfb69914d..069f5540be36 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -240,7 +240,6 @@ static DECLARE_WORK(sysrq_showallcpus, sysrq_showregs_othercpus);
 
 static void sysrq_handle_showallcpus(int key)
 {
-	printk_emergency_begin();
 	/*
 	 * Fall back to the workqueue based printing if the
 	 * backtrace printing did not succeed or the
@@ -255,7 +254,6 @@ static void sysrq_handle_showallcpus(int key)
 		}
 		schedule_work(&sysrq_showallcpus);
 	}
-	printk_emergency_end();
 }
 
 static struct sysrq_key_op sysrq_showallcpus_op = {
@@ -282,10 +280,8 @@ static struct sysrq_key_op sysrq_showregs_op = {
 
 static void sysrq_handle_showstate(int key)
 {
-	printk_emergency_begin();
 	show_state();
 	show_workqueue_state();
-	printk_emergency_end();
 }
 static struct sysrq_key_op sysrq_showstate_op = {
 	.handler	= sysrq_handle_showstate,
@@ -296,9 +292,7 @@ static struct sysrq_key_op sysrq_showstate_op = {
 
 static void sysrq_handle_showstate_blocked(int key)
 {
-	printk_emergency_begin();
 	show_state_filter(TASK_UNINTERRUPTIBLE);
-	printk_emergency_end();
 }
 static struct sysrq_key_op sysrq_showstate_blocked_op = {
 	.handler	= sysrq_handle_showstate_blocked,
@@ -537,6 +531,7 @@ void __handle_sysrq(int key, bool check_mask)
 	int orig_log_level;
 	int i;
 
+	printk_emergency_begin();
 	rcu_sysrq_start();
 	rcu_read_lock();
 	/*
@@ -582,6 +577,7 @@ void __handle_sysrq(int key, bool check_mask)
 	}
 	rcu_read_unlock();
 	rcu_sysrq_end();
+	printk_emergency_end();
 }
 
 void handle_sysrq(int key)
-- 
2.12.2

[toc] | [prev] | [next] | [standalone]

#1613665 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On 03/31, Sergey Senozhatsky wrote:
>On (03/31/17 11:35), Sergey Senozhatsky wrote:
>[..]
>> > [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
>> > [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
>> > [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
>> > 
>> > Elapsed time: 310
>> > BUG: kernel reboot-without-warning in test stage
>> 
>> so as far as I understand, this is the "missing kernel messages"
>> type of bug report. a worst case scenario.
>
>panic() should have called console_flush_on_panic(), which sould have
>flushed the messages regardless the printk_kthread state. so it probably
>was not panic() that rebooted the kernel. (probably).
>
>kernel_restart() and kernel_halt() have pr_emerg() messages, printk switches
>to printk_emergency mode the first time it sees EMERG level message. (may be
>we switch to late).
>
>on the other hand, there is a emergency_restart(), where we don't switch
>to printk_emergency mode and don't flush the existing kernel messages.
>there is a bunch of places that call emergency_restart(), including sysrq.
>
>may I ask you, how do you usually restart the vm after the test?
>`echo X > /proc/sysrq-trigger'?

Yes.

>
>does this patch make it any better?

I am trying it and will post the result once I get it.

Thanks,
Xiaolong
>
>---
> drivers/tty/sysrq.c | 8 ++------
> 1 file changed, 2 insertions(+), 6 deletions(-)
>
>diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
>index 817dfb69914d..069f5540be36 100644
>--- a/drivers/tty/sysrq.c
>+++ b/drivers/tty/sysrq.c
>@@ -240,7 +240,6 @@ static DECLARE_WORK(sysrq_showallcpus, sysrq_showregs_othercpus);
> 
> static void sysrq_handle_showallcpus(int key)
> {
>-	printk_emergency_begin();
> 	/*
> 	 * Fall back to the workqueue based printing if the
> 	 * backtrace printing did not succeed or the
>@@ -255,7 +254,6 @@ static void sysrq_handle_showallcpus(int key)
> 		}
> 		schedule_work(&sysrq_showallcpus);
> 	}
>-	printk_emergency_end();
> }
> 
> static struct sysrq_key_op sysrq_showallcpus_op = {
>@@ -282,10 +280,8 @@ static struct sysrq_key_op sysrq_showregs_op = {
> 
> static void sysrq_handle_showstate(int key)
> {
>-	printk_emergency_begin();
> 	show_state();
> 	show_workqueue_state();
>-	printk_emergency_end();
> }
> static struct sysrq_key_op sysrq_showstate_op = {
> 	.handler	= sysrq_handle_showstate,
>@@ -296,9 +292,7 @@ static struct sysrq_key_op sysrq_showstate_op = {
> 
> static void sysrq_handle_showstate_blocked(int key)
> {
>-	printk_emergency_begin();
> 	show_state_filter(TASK_UNINTERRUPTIBLE);
>-	printk_emergency_end();
> }
> static struct sysrq_key_op sysrq_showstate_blocked_op = {
> 	.handler	= sysrq_handle_showstate_blocked,
>@@ -537,6 +531,7 @@ void __handle_sysrq(int key, bool check_mask)
> 	int orig_log_level;
> 	int i;
> 
>+	printk_emergency_begin();
> 	rcu_sysrq_start();
> 	rcu_read_lock();
> 	/*
>@@ -582,6 +577,7 @@ void __handle_sysrq(int key, bool check_mask)
> 	}
> 	rcu_read_unlock();
> 	rcu_sysrq_end();
>+	printk_emergency_end();
> }
> 
> void handle_sysrq(int key)
>-- 
>2.12.2
>

[toc] | [prev] | [next] | [standalone]

#1614083 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (03/31/17 14:39), Ye Xiaolong wrote:
> On 03/31, Sergey Senozhatsky wrote:
> >On (03/31/17 11:35), Sergey Senozhatsky wrote:
> >[..]
> >> > [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
> >> > [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
> >> > [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
> >> > 
> >> > Elapsed time: 310
> >> > BUG: kernel reboot-without-warning in test stage
> >> 
> >> so as far as I understand, this is the "missing kernel messages"
> >> type of bug report. a worst case scenario.
> >
> >panic() should have called console_flush_on_panic(), which sould have
> >flushed the messages regardless the printk_kthread state. so it probably
> >was not panic() that rebooted the kernel. (probably).
> >
> >kernel_restart() and kernel_halt() have pr_emerg() messages, printk switches
> >to printk_emergency mode the first time it sees EMERG level message. (may be
> >we switch to late).
> >
> >on the other hand, there is a emergency_restart(), where we don't switch
> >to printk_emergency mode and don't flush the existing kernel messages.
> >there is a bunch of places that call emergency_restart(), including sysrq.
> >
> >may I ask you, how do you usually restart the vm after the test?
> >`echo X > /proc/sysrq-trigger'?
> 
> Yes.
> 
> >
> >does this patch make it any better?
> 
> I am trying it and will post the result once I get it.


... I'd also probably add pr_emerg() print-out to emergency_restart(),
the same way kernel_restart()/kernel_halt()/kernel_power_off() do.

for those cases when emergency_restart() is called with printk in
kthreaded mode, not in emergency mode.

---

diff --git a/kernel/reboot.c b/kernel/reboot.c
index e4ced883d8de..5bce29da913b 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -60,6 +60,7 @@ void (*pm_power_off_prepare)(void);
  */
 void emergency_restart(void)
 {
+	pr_emerg("Emergency restart\n");
 	kmsg_dump(KMSG_DUMP_EMERG);
 	machine_emergency_restart();
 }

[toc] | [prev] | [next] | [standalone]

#1614118 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

Sergey Senozhatsky <sergey.senozhatsky@gmail.com> writes:

> On (03/31/17 14:39), Ye Xiaolong wrote:
>> On 03/31, Sergey Senozhatsky wrote:
>> >On (03/31/17 11:35), Sergey Senozhatsky wrote:
>> >[..]
>> >> > [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
>> >> > [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
>> >> > [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
>> >> > 
>> >> > Elapsed time: 310
>> >> > BUG: kernel reboot-without-warning in test stage
>> >> 
>> >> so as far as I understand, this is the "missing kernel messages"
>> >> type of bug report. a worst case scenario.
>> >
>> >panic() should have called console_flush_on_panic(), which sould have
>> >flushed the messages regardless the printk_kthread state. so it probably
>> >was not panic() that rebooted the kernel. (probably).
>> >
>> >kernel_restart() and kernel_halt() have pr_emerg() messages, printk switches
>> >to printk_emergency mode the first time it sees EMERG level message. (may be
>> >we switch to late).
>> >
>> >on the other hand, there is a emergency_restart(), where we don't switch
>> >to printk_emergency mode and don't flush the existing kernel messages.
>> >there is a bunch of places that call emergency_restart(), including sysrq.
>> >
>> >may I ask you, how do you usually restart the vm after the test?
>> >`echo X > /proc/sysrq-trigger'?
>> 
>> Yes.
>> 
>> >
>> >does this patch make it any better?
>> 
>> I am trying it and will post the result once I get it.
>
>
> ... I'd also probably add pr_emerg() print-out to emergency_restart(),
> the same way kernel_restart()/kernel_halt()/kernel_power_off() do.
>
> for those cases when emergency_restart() is called with printk in
> kthreaded mode, not in emergency mode.

No. No. No.

emergency_restart should be the equivalent of a watchdog going off.
AKA it is long past the point where you want to be coordinating
with other parts of the kernel.  Rebooting is the priority.
A print statement absolutely does not belong in emergency_restart.

The fact that nothing managed to get printed out without magic flushing
code is highly disturbing.

Looking from the outside this patchset appears to be broken by design.

If you don't want kernel functions suffering from the overhead of
printing to a slow output device, don't do that then.

The point of printk is to give debugging output.  You have fundamentally
incapacitated printk from serving it's primary purpose.

NAK to the entire concept.

Eric

[toc] | [prev] | [next] | [standalone]

#1615033 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On Fri 31-03-17 10:28:15, Eric W. Biederman wrote:
> Sergey Senozhatsky <sergey.senozhatsky@gmail.com> writes:
> 
> > On (03/31/17 14:39), Ye Xiaolong wrote:
> >> On 03/31, Sergey Senozhatsky wrote:
> >> >On (03/31/17 11:35), Sergey Senozhatsky wrote:
> >> >[..]
> >> >> > [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
> >> >> > [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
> >> >> > [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
> >> >> > 
> >> >> > Elapsed time: 310
> >> >> > BUG: kernel reboot-without-warning in test stage
> >> >> 
> >> >> so as far as I understand, this is the "missing kernel messages"
> >> >> type of bug report. a worst case scenario.
> >> >
> >> >panic() should have called console_flush_on_panic(), which sould have
> >> >flushed the messages regardless the printk_kthread state. so it probably
> >> >was not panic() that rebooted the kernel. (probably).
> >> >
> >> >kernel_restart() and kernel_halt() have pr_emerg() messages, printk switches
> >> >to printk_emergency mode the first time it sees EMERG level message. (may be
> >> >we switch to late).
> >> >
> >> >on the other hand, there is a emergency_restart(), where we don't switch
> >> >to printk_emergency mode and don't flush the existing kernel messages.
> >> >there is a bunch of places that call emergency_restart(), including sysrq.
> >> >
> >> >may I ask you, how do you usually restart the vm after the test?
> >> >`echo X > /proc/sysrq-trigger'?
> >> 
> >> Yes.
> >> 
> >> >
> >> >does this patch make it any better?
> >> 
> >> I am trying it and will post the result once I get it.
> >
> >
> > ... I'd also probably add pr_emerg() print-out to emergency_restart(),
> > the same way kernel_restart()/kernel_halt()/kernel_power_off() do.
> >
> > for those cases when emergency_restart() is called with printk in
> > kthreaded mode, not in emergency mode.
> 
> No. No. No.
> 
> emergency_restart should be the equivalent of a watchdog going off.
> AKA it is long past the point where you want to be coordinating
> with other parts of the kernel.  Rebooting is the priority.
> A print statement absolutely does not belong in emergency_restart.
>
> The fact that nothing managed to get printed out without magic flushing
> code is highly disturbing.
> 
> Looking from the outside this patchset appears to be broken by design.
> 
> If you don't want kernel functions suffering from the overhead of
> printing to a slow output device, don't do that then.

Sorry, but the above is just contradictory. On one hand you say that
missing messages is disturbing and on the other hand you say we should have
no messages to avoid the overhead of printing. The fact is kernel has tons
of messages because people want to see what happens to possibly debug stuff.
And I don't see as viable to reduce amount of messages as it is neverending
fight and always someone will be unhappy. As a result currently some machines
are not able to boot due to printk traffic and there are other nasty
effects from CPUs getting stuck printing messages to serial console (and
this really bothers people as is proved by the fact that about every 6
months someone comes with a hack to printk to fix the particular lockup he
is hitting).

This patch set gives up part of the printk() reliability for bounded
latency (at least unless we detect we are really in trouble) which is IMHO
a good trade-off for lots of users (and others can just turn this feature
off).

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1615057 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On Mon 2017-04-03 11:31:52, Jan Kara wrote:
> On Fri 31-03-17 10:28:15, Eric W. Biederman wrote:
> > Sergey Senozhatsky <sergey.senozhatsky@gmail.com> writes:
> > 
> > > On (03/31/17 14:39), Ye Xiaolong wrote:
> > >> On 03/31, Sergey Senozhatsky wrote:
> > >> >On (03/31/17 11:35), Sergey Senozhatsky wrote:
> > >> >[..]
> > >> >> > [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
> > >> >> > [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
> > >> >> > [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
> > >> >> > 
> > >> >> > Elapsed time: 310
> > >> >> > BUG: kernel reboot-without-warning in test stage
> > >> >> 
> > >> >> so as far as I understand, this is the "missing kernel messages"
> > >> >> type of bug report. a worst case scenario.
> > >> >
> > >> >panic() should have called console_flush_on_panic(), which sould have
> > >> >flushed the messages regardless the printk_kthread state. so it probably
> > >> >was not panic() that rebooted the kernel. (probably).
> > >> >
> > >> >kernel_restart() and kernel_halt() have pr_emerg() messages, printk switches
> > >> >to printk_emergency mode the first time it sees EMERG level message. (may be
> > >> >we switch to late).
> > >> >
> > >> >on the other hand, there is a emergency_restart(), where we don't switch
> > >> >to printk_emergency mode and don't flush the existing kernel messages.
> > >> >there is a bunch of places that call emergency_restart(), including sysrq.
> > >> >
> > >> >may I ask you, how do you usually restart the vm after the test?
> > >> >`echo X > /proc/sysrq-trigger'?
> > >> 
> > >> Yes.
> > >> 
> > >> >
> > >> >does this patch make it any better?
> > >> 
> > >> I am trying it and will post the result once I get it.
> > >
> > >
> > > ... I'd also probably add pr_emerg() print-out to emergency_restart(),
> > > the same way kernel_restart()/kernel_halt()/kernel_power_off() do.
> > >
> > > for those cases when emergency_restart() is called with printk in
> > > kthreaded mode, not in emergency mode.
> > 
> > No. No. No.
> > 
> > emergency_restart should be the equivalent of a watchdog going off.
> > AKA it is long past the point where you want to be coordinating
> > with other parts of the kernel.  Rebooting is the priority.
> > A print statement absolutely does not belong in emergency_restart.

Sergey suggested to add pr_emerg() because it would signalize
emergency situation, printk kthread would be disabled and all
messages would be printed to the console directly (the old way).
It will _not_ be necessary to wakeup the kthread.

Note that the we could do it also _without_ pr_emerg().
Instead we could call simple/fast printk_emergency_begin()
as we do in other similar situations, for example during
kexec, suspend, see 4th and 6th patch of this patchset.


> > The fact that nothing managed to get printed out without magic flushing
> > code is highly disturbing.
> > 
> > Looking from the outside this patchset appears to be broken by design.
> > 
> > If you don't want kernel functions suffering from the overhead of
> > printing to a slow output device, don't do that then.
> 
> Sorry, but the above is just contradictory. On one hand you say that
> missing messages is disturbing and on the other hand you say we should have
> no messages to avoid the overhead of printing. The fact is kernel has tons
> of messages because people want to see what happens to possibly debug stuff.
> And I don't see as viable to reduce amount of messages as it is neverending
> fight and always someone will be unhappy. As a result currently some machines
> are not able to boot due to printk traffic and there are other nasty
> effects from CPUs getting stuck printing messages to serial console (and
> this really bothers people as is proved by the fact that about every 6
> months someone comes with a hack to printk to fix the particular lockup he
> is hitting).

Yup, the fact is that there are situations when printk() itself brings
the system into problems, for example when too many messages are
flushed to a slow console in interrupt context.


> This patch set gives up part of the printk() reliability for bounded
> latency (at least unless we detect we are really in trouble) which is IMHO
> a good trade-off for lots of users (and others can just turn this feature
> off).

My view of this patchset is the following:

Deferred console output is perfectly fine when the system is in
reasonable state. The deferring is needed to keep the system safe
in some situations.

Of course, the view is different when the deferring is not longer
reliable (panic, kexec, suspend, restart). We try to detect these
situations, disable deferring, and push the messages the old way.
We call this emergency mode.

I am sure that we miss some situations. Also they might be hard
to detect. For this case, there is the kernel parameter, sysfs
knob that will allow to keep the old mode all the time, see
7th patch.

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1618219 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Multipart message — attachments visible in raw view] — view raw

Hi!

> This patch set gives up part of the printk() reliability for bounded
> latency (at least unless we detect we are really in trouble) which is IMHO
> a good trade-off for lots of users (and others can just turn this feature
> off).

If they can ever realize they were bitten by this feature.

Can we go for different tradeoff?

In console_unlock(), if you detect too much work, print "Too many
messages to print, %d bytes delayed" and wake up kernel thread.

You still get the latency, and people bitten by this feature will at
least get fair warning.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1618476 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

Hello,

On (04/06/17 19:33), Pavel Machek wrote:
> > This patch set gives up part of the printk() reliability for bounded
> > latency (at least unless we detect we are really in trouble) which is IMHO
> > a good trade-off for lots of users (and others can just turn this feature
> > off).
> 
> If they can ever realize they were bitten by this feature.
> 
> Can we go for different tradeoff?
> 
> In console_unlock(), if you detect too much work, print "Too many
> messages to print, %d bytes delayed" and wake up kernel thread.

"too many messages" is undefined. console_unlock() can be called from
IRQ handler or with preemtion disabled, or under spin_lock, or under
RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
from console_unlock() it may be already too late.

besides, this does not really address any of the concerns you have
pointed out in other emails. we might be unable to wake_up printk_kthread
(because there is a misbehaving higher prio process, or because the
scheduler is misbehaving, etc. etc.) so the "emergency mode" is still
here and still requires special handling.

	-ss

[toc] | [prev] | [next] | [standalone]

#1618515 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Multipart message — attachments visible in raw view] — view raw

On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> Hello,
> 
> On (04/06/17 19:33), Pavel Machek wrote:
> > > This patch set gives up part of the printk() reliability for bounded
> > > latency (at least unless we detect we are really in trouble) which is IMHO
> > > a good trade-off for lots of users (and others can just turn this feature
> > > off).
> > 
> > If they can ever realize they were bitten by this feature.
> > 
> > Can we go for different tradeoff?
> > 
> > In console_unlock(), if you detect too much work, print "Too many
> > messages to print, %d bytes delayed" and wake up kernel thread.
> 
> "too many messages" is undefined. console_unlock() can be called from
> IRQ handler or with preemtion disabled, or under spin_lock, or under
> RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> from console_unlock() it may be already too late.

So lets define "too many messages" as 240 characters. We know printk
worked rather well for us for more than 20 years. Kernel code is used
to printk taking few miliseconds. 

> besides, this does not really address any of the concerns you have
> pointed out in other emails. we might be unable to wake_up printk_kthread
> (because there is a misbehaving higher prio process, or because the
> scheduler is misbehaving, etc. etc.) so the "emergency mode" is still
> here and still requires special handling.

Yeah? So you know modified printk() does not work, that's why
"emergency mode" exists. Unfortunately, you can't rely on fact that
you can detect half-crashed machines by printk levels. You usually
can't.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1618552 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/07/17 09:15), Pavel Machek wrote:
> On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> > Hello,
> > 
> > On (04/06/17 19:33), Pavel Machek wrote:
> > > > This patch set gives up part of the printk() reliability for bounded
> > > > latency (at least unless we detect we are really in trouble) which is IMHO
> > > > a good trade-off for lots of users (and others can just turn this feature
> > > > off).
> > > 
> > > If they can ever realize they were bitten by this feature.
> > > 
> > > Can we go for different tradeoff?
> > > 
> > > In console_unlock(), if you detect too much work, print "Too many
> > > messages to print, %d bytes delayed" and wake up kernel thread.
> > 
> > "too many messages" is undefined. console_unlock() can be called from
> > IRQ handler or with preemtion disabled, or under spin_lock, or under
> > RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> > from console_unlock() it may be already too late.
> 
> So lets define "too many messages" as 240 characters. We know printk
> worked rather well for us for more than 20 years. Kernel code is used
> to printk taking few miliseconds.

serial console can be quite slow. and port->lock, that is acquired by
console_unlock()->call_console_drivers()->write(), is also accessible
by serial driver's IRQ handler, and this lock may be busy long
enough -- as long as that IRQ handler transmits/receives chars. but
that's not the point.

[..]
> Yeah? So you know modified printk() does not work, that's why
> "emergency mode" exists. Unfortunately, you can't rely on fact that
> you can detect half-crashed machines by printk levels. You usually
> can't.

I'm not happy with those printk_emergency_begin()/end(), sure. but that's
the reality -- every single solution that would offload printing duty implies
that there will be cases when offloading would not be possible. either
PENDING_PRINTK_IPI to other CPUs, or irq_work(PENDING_OUTPUT) on a local CPU,
or anything else (um... what it is?... softirq? tasklet? print one logbuf
entry from every IRQ handler? dunno, anything else?). There will be cases
when we won't be able to expect that something will take over and finish
printing for us. Well, may be I'm missing some other solution that would
offload printing, eliminating lockup conditions, and at the same time work
in 100% of the cases.

	-ss

[toc] | [prev] | [next] | [standalone]

#1618561 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Multipart message — attachments visible in raw view] — view raw

On Fri 2017-04-07 16:46:34, Sergey Senozhatsky wrote:
> On (04/07/17 09:15), Pavel Machek wrote:
> > On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> > > Hello,
> > > 
> > > On (04/06/17 19:33), Pavel Machek wrote:
> > > > > This patch set gives up part of the printk() reliability for bounded
> > > > > latency (at least unless we detect we are really in trouble) which is IMHO
> > > > > a good trade-off for lots of users (and others can just turn this feature
> > > > > off).
> > > > 
> > > > If they can ever realize they were bitten by this feature.
> > > > 
> > > > Can we go for different tradeoff?
> > > > 
> > > > In console_unlock(), if you detect too much work, print "Too many
> > > > messages to print, %d bytes delayed" and wake up kernel thread.
> > > 
> > > "too many messages" is undefined. console_unlock() can be called from
> > > IRQ handler or with preemtion disabled, or under spin_lock, or under
> > > RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> > > from console_unlock() it may be already too late.
> > 
> > So lets define "too many messages" as 240 characters. We know printk
> > worked rather well for us for more than 20 years. Kernel code is used
> > to printk taking few miliseconds.
> 
> serial console can be quite slow. and port->lock, that is acquired by
> console_unlock()->call_console_drivers()->write(), is also accessible
> by serial driver's IRQ handler, and this lock may be busy long
> enough -- as long as that IRQ handler transmits/receives chars. but
> that's not the point.

Well. This is what we had for 20 years.

> [..]
> > Yeah? So you know modified printk() does not work, that's why
> > "emergency mode" exists. Unfortunately, you can't rely on fact that
> > you can detect half-crashed machines by printk levels. You usually
> > can't.
> 
> I'm not happy with those printk_emergency_begin()/end(), sure. but that's
> the reality -- every single solution that would offload printing duty implies
> that there will be cases when offloading would not be possible. either
> PENDING_PRINTK_IPI to other CPUs, or irq_work(PENDING_OUTPUT) on a local CPU,
> or anything else (um... what it is?... softirq? tasklet? print one logbuf
> entry from every IRQ handler? dunno, anything else?). There will be cases
> when we won't be able to expect that something will take over and finish
> printing for us. Well, may be I'm missing some other solution that would
> offload printing, eliminating lockup conditions, and at the same time work
> in 100% of the cases.

I don't have magic solution in my sleeve. You made a good case that
spending 30 seconds in printk() is a bad idea. I agree with that. Your
solution is to introduce printk_emergency_begin()/end(). I don't agree
there.

I believe "spend at most 2 seconds in printk(), then print a warning
and offload" is a solution closer to what we had before.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1618721 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/07/17 10:14), Pavel Machek wrote:
[..]
> Well. This is what we had for 20 years.

I guess it's not just me who is a bit unhappy with printk. ask
Peter Zijlstra what's the first word that comes into his mind
when we reads "printk"  :)


[..]
> I believe "spend at most 2 seconds in printk(), then print a warning
> and offload" is a solution closer to what we had before.

a warning here can be very noisy.

it's quite common that serial console (`console_seq') is a bit behind
the logbuf head (`log_next_seq'). because log_store() can be much faster
that call into console drivers.

another case is that  printk() != console_unlock().  console_sem can be
locked by VT, TTY, fbdev, (not to mention that some other CPU might be
doing printing), etc. etc. all printk()-s in the meantime will just
log_store() messages, so we can have a bunch on pending messsges in
logbuf, it's normal. the CPU that owns the console_sem will print all
those pending messages from console_unlock() path. the distance between
`log_next_seq' and `console_seq' can be much bigger than 2 seconds or
240/320/etc chars. so wrong offloading can leave with nothing valuable
in the serial output, even if we would defer it.

well, I'm not arguing. just saying that it's not so easy to do everything
right here.

what we have been thinking about is something like printk-stall detection.
we probably (there are some if-s) can detect in printk() that offloading
does not work and we must automatically switch to printk_emergency mode.
that, in theory, can relax our dependency on printk_emergency_begin/end
being in the right place at the right time. need to think more about it.

	-ss

[toc] | [prev] | [next] | [standalone]

#1618743 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Multipart message — attachments visible in raw view] — view raw

On Fri 2017-04-07 21:10:21, Sergey Senozhatsky wrote:
> On (04/07/17 10:14), Pavel Machek wrote:
> [..]
> > Well. This is what we had for 20 years.
> 
> I guess it's not just me who is a bit unhappy with printk. ask
> Peter Zijlstra what's the first word that comes into his mind
> when we reads "printk"  :)

Well, still we should make sure we are improving.

> [..]
> > I believe "spend at most 2 seconds in printk(), then print a warning
> > and offload" is a solution closer to what we had before.
> 
> a warning here can be very noisy.

Well, on normally-configured it should be ok. We don't commonly see
printk problems... If it is too noisy, perhaps we should increase from
2 seconds, but I don't think it will be problem.

> it's quite common that serial console (`console_seq') is a bit behind
> the logbuf head (`log_next_seq'). because log_store() can be much faster
> that call into console drivers.
> 
> another case is that  printk() != console_unlock().  console_sem can be
> locked by VT, TTY, fbdev, (not to mention that some other CPU might be
> doing printing), etc. etc. all printk()-s in the meantime will just
> log_store() messages, so we can have a bunch on pending messsges in
> logbuf, it's normal. the CPU that owns the console_sem will print all
> those pending messages from console_unlock() path. the distance between
> `log_next_seq' and `console_seq' can be much bigger than 2 seconds or
> 240/320/etc chars. so wrong offloading can leave with nothing valuable
> in the serial output, even if we would defer it.
> 
> well, I'm not arguing. just saying that it's not so easy to do everything
> right here.
>

Well, I have to agree here. This is 20 years worth of mess :-(.

> what we have been thinking about is something like printk-stall detection.
> we probably (there are some if-s) can detect in printk() that offloading
> does not work and we must automatically switch to printk_emergency mode.
> that, in theory, can relax our dependency on printk_emergency_begin/end
> being in the right place at the right time. need to think more about it.

So... I don't really like the begin/end interface. I would rather have
printk_emergency(KERN_ ...).

Second... I don't think "stuck detector" is that helpful. What I
usually seen was some rather innocent kernel message followed by
hard-lock. That's where "message delayed" is useful..
								Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1618870 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On Fri, 7 Apr 2017 14:44:55 +0200
Pavel Machek <pavel@ucw.cz> wrote:

> Well, I have to agree here. This is 20 years worth of mess :-(.

Maybe someone should propose a micro-conf at Linux Plumbers where we
can brain storm a way to re-invent printk()? Seems it can do with a
completely new rewrite. ;-)

-- Steve

[toc] | [prev] | [next] | [standalone]

#1618901 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/07/17 14:44), Pavel Machek wrote:
[..]
> > [..]
> > > I believe "spend at most 2 seconds in printk(), then print a warning
> > > and offload" is a solution closer to what we had before.
> > 
> > a warning here can be very noisy.
> 
> Well, on normally-configured it should be ok. We don't commonly see
> printk problems... If it is too noisy, perhaps we should increase from
> 2 seconds, but I don't think it will be problem.

we are looking at different typical setups :) serial console being 45
seconds behind logbuf does not surprise me anymore.

[..]
> > what we have been thinking about is something like printk-stall detection.
> > we probably (there are some if-s) can detect in printk() that offloading
> > does not work and we must automatically switch to printk_emergency mode.
> > that, in theory, can relax our dependency on printk_emergency_begin/end
> > being in the right place at the right time. need to think more about it.
> 
> So... I don't really like the begin/end interface. I would rather have
> printk_emergency(KERN_ ...).

you mean a single printk_emergency() switches printk to emergency mode
or printk_emergency(KERN_ ... ) is a single message that must be printed
in emergency mode?

printk() depends on console_trylock(). we can't expect printk_emergency(KERN_ ...)
to always do more than just log_store().

the idea behind begin/end interface is that you can do

	emergency_begin
	printk
	pr_cont
	pr_cont
	pr_cont
	printk
	dump_stack
	emergency_end

with out the need of rewriting dump_stack() or anything else to use
printk_emergency(). we, for example, do this in sysrq patch from this
series.

> Second... I don't think "stuck detector" is that helpful. What I
> usually seen was some rather innocent kernel message followed by
> hard-lock. That's where "message delayed" is useful..

a side note,
that's rather unclear to me how would "message delayed" really help.
if your system hard-lockup so badly and there are no printk messages
even from NMI watchdog, then we won't be able to print that message.
we had sort of similar type of issue years ago. cpu could receive
STOP_IPI while holding console_sem and we couldn't print anything
(that was before we learned the console_trylock();console_unlock()
trick). if you, on the other hand, can access vmcore, then you know
where to look for the messages anyway.

but let's keep it for later. this nuance is not really important now.

	-ss

[toc] | [prev] | [next] | [standalone]

#1618907 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On Sat, Apr 08, 2017 at 12:13:06AM +0900, Sergey Senozhatsky wrote:
> On (04/07/17 14:44), Pavel Machek wrote:
> [..]
> > > [..]
> > > > I believe "spend at most 2 seconds in printk(), then print a warning
> > > > and offload" is a solution closer to what we had before.
> > > 
> > > a warning here can be very noisy.
> > 
> > Well, on normally-configured it should be ok. We don't commonly see
> > printk problems... If it is too noisy, perhaps we should increase from
> > 2 seconds, but I don't think it will be problem.
> 
> we are looking at different typical setups :) serial console being 45
> seconds behind logbuf does not surprise me anymore.

That does sound like you're doing something wrong and should look at
reducing printk() more than anything else.

[toc] | [prev] | [next] | [standalone]

#1618918 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/07/17 17:23), Peter Zijlstra wrote:
[..]
> > we are looking at different typical setups :) serial console being 45
> > seconds behind logbuf does not surprise me anymore.
> 
> That does sound like you're doing something wrong and should look at
> reducing printk() more than anything else.

yeah, 45sec is an extreme case that simply doesn't surprise me anymore ;)
that's not a normal/usual delay, of course, we are not this mad. on average
it's much better and may be not so far 2 seconds after all. a massive OOM
report, of course, appends logbuf messages at a much higher rate than UART
serial console can swallow, so the delay is getting larger, expectedly.
and, no, I don't add any printk-s, I'm looking at the lockup reports

	-ss

[toc] | [prev] | [next] | [standalone]

#1619534 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

Sergey Senozhatsky <sergey.senozhatsky@gmail.com> writes:

> On (04/07/17 17:23), Peter Zijlstra wrote:
> [..]
>> > we are looking at different typical setups :) serial console being 45
>> > seconds behind logbuf does not surprise me anymore.
>> 
>> That does sound like you're doing something wrong and should look at
>> reducing printk() more than anything else.
>
> yeah, 45sec is an extreme case that simply doesn't surprise me anymore ;)
> that's not a normal/usual delay, of course, we are not this mad. on average
> it's much better and may be not so far 2 seconds after all. a massive OOM
> report, of course, appends logbuf messages at a much higher rate than UART
> serial console can swallow, so the delay is getting larger, expectedly.
> and, no, I don't add any printk-s, I'm looking at the lockup reports

Are you running your serial consoles at 9600 baud?

I would think the first thing to do would be to up your serial console
baud rate to 115200 or at least 38400.

Similarly anything the kernel is certain to survive I would set loglevel
such that it is logging somewhere with syslog rather than printk.

Of course my expectation on a production machine is to have panic on oom
set, to print the huge OOM message and then reboot.  So I don't possibly
see how offloading to another thread and then switching right back to
emergency mode is at all practical to solve the delay for a serious
situation like OOM.

It sounds like you are blaming printk when the problem is a very slow
logging device.

Eric

[toc] | [prev] | [next] | [standalone]

#1619631 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

Hello Eric,

On (04/09/17 13:21), Eric W. Biederman wrote:
[..]
> It sounds like you are blaming printk when the problem is a very slow
> logging device.

sure, slow logging device definitely adds up to the problem. if there
is no delay in call_console_driver() then printk()->console_unlock()
take no time. anything (uart, fbdev, etc.) that makes call_console_drivers()
slower makes printk() slower. the patch set is not about offloading during
panic(), when offloading make no sense, as you mentioned, or about
uncommon/extreme/impossible cases of 45sec delays in printk. no.

but about the fact that printk() called from inappropriate context
can introduce delays/timeouts/stalls and lockups. several CPUs may call
printk simultaneously, but we don't have any mechanism that would grant
console_sem ownership to a CPU in !atomic context. the winner (the CPU
that first acquires console_sem) prints it all, as long as there are
pending messages.

e.g.
 lkml.kernel.org/r/20160701165959.GR12473@ubuntu
e.g.
 https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/kernel/printk/printk.c?id=8d91f8b15361dfb438ab6eb3b319e2ded43458ff

and so on.

I've even seen when printk->console_unlock() invoked from RCU read side
caused OOM condition (some RCU protected objects are small, but some are
big -- e.g. slab pages: kmem_rcu_free()). that's very rare, but I've seen
it.

so there are too many uncertainties and too many inappropriate contexts
for printk.

but yes, you are right, if there is nothing that makes call_console_driver()
slow, then there is no issue.

	-ss

[toc] | [prev] | [next] | [standalone]

Page 2 of 3 — ← Prev page 1 [2] 3  Next page →

Back to top | Article view | linux.kernel

csiph-web