[PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

Add a halt_delay module parameter in printk.c used to read the printk
messages in halt/poweroff/restart phase, delay each printk messages
by halt_delay milliseconds. It is useful for debugging if there's no
other way to dump kernel messages that time.

The halt_delay max value is 65535, default value is 0, change it by:

echo xxx > /sys/module/printk/parameters/halt_delay

Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
---
Documentation/kernel-parameters.txt |    5 +++++
kernel/printk.c                     |   17 +++++++++++++++++
2 files changed, 22 insertions(+)

--- linux-2.6.orig/kernel/printk.c	2009-06-08 13:55:35.000000000 +0800
+++ linux-2.6/kernel/printk.c	2009-06-08 13:56:23.000000000 +0800
@@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
 }
 #endif

+/* msecs delay after each halt/poweroff/restart phase printk,
+ unsigned short is enough for delay in milliseconds */
+static unsigned short halt_delay;
+
+static inline void halt_delay_msec(void)
+{
+	if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
+				|| system_state == SYSTEM_POWER_OFF
+				|| system_state == SYSTEM_RESTART)))
+		return;
+
+	mdelay(halt_delay);
+}
+
+module_param(halt_delay, ushort, S_IRUGO | S_IWUSR);
+
 /*
  * Commands to do_syslog:
  *
@@ -649,6 +665,7 @@ asmlinkage int vprintk(const char *fmt,
 	char *p;

 	boot_delay_msec();
+	halt_delay_msec();

 	preempt_disable();
 	/* This stops the holder of console_sem just where we want him */
--- linux-2.6.orig/Documentation/kernel-parameters.txt	2009-05-28
08:40:42.000000000 +0800
+++ linux-2.6/Documentation/kernel-parameters.txt	2009-06-08
14:06:47.000000000 +0800
@@ -1897,6 +1897,11 @@ and is between 256 and 4096 characters.
 	printk.time=	Show timing data prefixed to each printk message line
 			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)

+	printk.halt_delay=
+			Milliseconds to delay each printk during
+			halt/poweroff/restart phase.
+			Format: <ushort>
+
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
 			max_cstate=9 overrides any DMI blacklist limit.

[tip:core/printk] printk: Add halt_delay=<msecs> parameter for printk delay in halt phase

[tip-bot for Dave Young]

Commit-ID:  f43a6b1611aff688e21f323b64b98b57f8b7f721
Gitweb:     http://git.kernel.org/tip/f43a6b1611aff688e21f323b64b98b57f8b7f721
Author:     Dave Young <hidave.darkstar@gmail.com>
AuthorDate: Mon, 8 Jun 2009 15:40:07 +0800
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Mon, 8 Jun 2009 10:10:34 +0200

printk: Add halt_delay=<msecs> parameter for printk delay in halt phase

Add a halt_delay module parameter in printk.c used to read the
printk messages in halt/poweroff/restart phase, delay each
printk messages by halt_delay milliseconds.

It is useful for debugging if there's no other way to dump kernel
messages at that time. (if a system has no serial port - and if
netconsole has already gone down at that stage where the messages
are printed.)

The halt_delay max value is 65535, default value is 0. To add
a halt-day of 10 seconds, change it by:

    echo 10000 > /sys/module/printk/parameters/halt_delay

Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
LKML-Reference: <a8e1da0906080040k7852f770v1e2aa2ebb0f52369@mail.gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 Documentation/kernel-parameters.txt |    5 +++++
 kernel/printk.c                     |   17 +++++++++++++++++
 2 files changed, 22 insertions(+), 0 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 6172e43..0630428 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -1847,6 +1847,11 @@ and is between 256 and 4096 characters. It is defined in the file
 	printk.time=	Show timing data prefixed to each printk message line
 			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
 
+	printk.halt_delay=
+			Milliseconds to delay each printk during
+			halt/poweroff/restart phase.
+			Format: <ushort>
+
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
 			max_cstate=9 overrides any DMI blacklist limit.
diff --git a/kernel/printk.c b/kernel/printk.c
index 5052b54..2114231 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
 }
 #endif
 
+/* msecs delay after each halt/poweroff/restart phase printk,
+ unsigned short is enough for delay in milliseconds */
+static unsigned short halt_delay;
+
+static inline void halt_delay_msec(void)
+{
+	if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
+				|| system_state == SYSTEM_POWER_OFF
+				|| system_state == SYSTEM_RESTART)))
+		return;
+
+	mdelay(halt_delay);
+}
+
+module_param(halt_delay, ushort, S_IRUGO | S_IWUSR);
+
 /*
  * Commands to do_syslog:
  *
@@ -649,6 +665,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	char *p;
 
 	boot_delay_msec();
+	halt_delay_msec();
 
 	preempt_disable();
 	/* This stops the holder of console_sem just where we want him */

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Ingo Molnar]

* Dave Young <hidave.darkstar@gmail.com> wrote:

> Add a halt_delay module parameter in printk.c used to read the 
> printk messages in halt/poweroff/restart phase, delay each printk 
> messages by halt_delay milliseconds. It is useful for debugging if 
> there's no other way to dump kernel messages that time.
> 
> The halt_delay max value is 65535, default value is 0, change it 
> by:
> 
> echo xxx > /sys/module/printk/parameters/halt_delay
> 
> Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
> ---
> Documentation/kernel-parameters.txt |    5 +++++
> kernel/printk.c                     |   17 +++++++++++++++++
> 2 files changed, 22 insertions(+)
> 
> --- linux-2.6.orig/kernel/printk.c	2009-06-08 13:55:35.000000000 +0800
> +++ linux-2.6/kernel/printk.c	2009-06-08 13:56:23.000000000 +0800
> @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
>  }
>  #endif
> 
> +/* msecs delay after each halt/poweroff/restart phase printk,
> + unsigned short is enough for delay in milliseconds */
> +static unsigned short halt_delay;
> +
> +static inline void halt_delay_msec(void)
> +{
> +	if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
> +				|| system_state == SYSTEM_POWER_OFF
> +				|| system_state == SYSTEM_RESTART)))
> +		return;

This is a tiny bit ugly (and goes into the vprintf path) but i can 
see no other way either - a system_state > SYSTEM_RUNNING check 
would needlessly include the suspend-to-disk state (which we dont 
want to include here).

In theory we could turn system_state into a bitmask and have a 
print_delay_mask check instead of these flags ... but that is a far 
wider change and i'm not sure it's a net step forwards.

I've applied your patch to tip:core/printk with small edits to the 
changelog - Linus & Andrew is Cc:ed, should they have any 
objections.

	Ingo

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Andrew Morton]

On Mon, 8 Jun 2009 10:14:39 +0200 Ingo Molnar <mingo@elte.hu> wrote:

> 
> * Dave Young <hidave.darkstar@gmail.com> wrote:
> 
> > Add a halt_delay module parameter in printk.c used to read the 
> > printk messages in halt/poweroff/restart phase, delay each printk 
> > messages by halt_delay milliseconds. It is useful for debugging if 
> > there's no other way to dump kernel messages that time.
> > 
> > The halt_delay max value is 65535, default value is 0, change it 
> > by:
> > 
> > echo xxx > /sys/module/printk/parameters/halt_delay
> > 
> > Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
> > ---
> > Documentation/kernel-parameters.txt |    5 +++++
> > kernel/printk.c                     |   17 +++++++++++++++++
> > 2 files changed, 22 insertions(+)
> > 
> > --- linux-2.6.orig/kernel/printk.c	2009-06-08 13:55:35.000000000 +0800
> > +++ linux-2.6/kernel/printk.c	2009-06-08 13:56:23.000000000 +0800
> > @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
> >  }
> >  #endif
> > 
> > +/* msecs delay after each halt/poweroff/restart phase printk,
> > + unsigned short is enough for delay in milliseconds */
> > +static unsigned short halt_delay;
> > +
> > +static inline void halt_delay_msec(void)
> > +{
> > +	if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
> > +				|| system_state == SYSTEM_POWER_OFF
> > +				|| system_state == SYSTEM_RESTART)))
> > +		return;
> 
> This is a tiny bit ugly (and goes into the vprintf path) but i can 
> see no other way either - a system_state > SYSTEM_RUNNING check 
> would needlessly include the suspend-to-disk state (which we dont 
> want to include here).
> 
> In theory we could turn system_state into a bitmask and have a 
> print_delay_mask check instead of these flags ... but that is a far 
> wider change and i'm not sure it's a net step forwards.
> 
> I've applied your patch to tip:core/printk with small edits to the 
> changelog - Linus & Andrew is Cc:ed, should they have any 
> objections.

Could we not put just a single delay in there, immediately prior to halting,
restarting or poweroffing?

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Mon, Jun 8, 2009 at 4:14 PM, Ingo Molnar<mingo@elte.hu> wrote:
>
> * Dave Young <hidave.darkstar@gmail.com> wrote:
>
>> Add a halt_delay module parameter in printk.c used to read the
>> printk messages in halt/poweroff/restart phase, delay each printk
>> messages by halt_delay milliseconds. It is useful for debugging if
>> there's no other way to dump kernel messages that time.
>>
>> The halt_delay max value is 65535, default value is 0, change it
>> by:
>>
>> echo xxx > /sys/module/printk/parameters/halt_delay
>>
>> Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
>> ---
>> Documentation/kernel-parameters.txt |    5 +++++
>> kernel/printk.c                     |   17 +++++++++++++++++
>> 2 files changed, 22 insertions(+)
>>
>> --- linux-2.6.orig/kernel/printk.c    2009-06-08 13:55:35.000000000 +0800
>> +++ linux-2.6/kernel/printk.c 2009-06-08 13:56:23.000000000 +0800
>> @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
>>  }
>>  #endif
>>
>> +/* msecs delay after each halt/poweroff/restart phase printk,
>> + unsigned short is enough for delay in milliseconds */
>> +static unsigned short halt_delay;
>> +
>> +static inline void halt_delay_msec(void)
>> +{
>> +     if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
>> +                             || system_state == SYSTEM_POWER_OFF
>> +                             || system_state == SYSTEM_RESTART)))
>> +             return;
>
> This is a tiny bit ugly (and goes into the vprintf path) but i can
> see no other way either - a system_state > SYSTEM_RUNNING check
> would needlessly include the suspend-to-disk state (which we dont
> want to include here).

Can we move suspend-to-disk before halt state?

>
> In theory we could turn system_state into a bitmask and have a
> print_delay_mask check instead of these flags ... but that is a far
> wider change and i'm not sure it's a net step forwards.
>
> I've applied your patch to tip:core/printk with small edits to the
> changelog - Linus & Andrew is Cc:ed, should they have any
> objections.
>
>        Ingo
>



-- 
Regards
dave

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Mon, Jun 8, 2009 at 4:28 PM, Andrew Morton<akpm@linux-foundation.org> wrote:
> On Mon, 8 Jun 2009 10:14:39 +0200 Ingo Molnar <mingo@elte.hu> wrote:
>
>>
>> * Dave Young <hidave.darkstar@gmail.com> wrote:
>>
>> > Add a halt_delay module parameter in printk.c used to read the
>> > printk messages in halt/poweroff/restart phase, delay each printk
>> > messages by halt_delay milliseconds. It is useful for debugging if
>> > there's no other way to dump kernel messages that time.
>> >
>> > The halt_delay max value is 65535, default value is 0, change it
>> > by:
>> >
>> > echo xxx > /sys/module/printk/parameters/halt_delay
>> >
>> > Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
>> > ---
>> > Documentation/kernel-parameters.txt |    5 +++++
>> > kernel/printk.c                     |   17 +++++++++++++++++
>> > 2 files changed, 22 insertions(+)
>> >
>> > --- linux-2.6.orig/kernel/printk.c  2009-06-08 13:55:35.000000000 +0800
>> > +++ linux-2.6/kernel/printk.c       2009-06-08 13:56:23.000000000 +0800
>> > @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
>> >  }
>> >  #endif
>> >
>> > +/* msecs delay after each halt/poweroff/restart phase printk,
>> > + unsigned short is enough for delay in milliseconds */
>> > +static unsigned short halt_delay;
>> > +
>> > +static inline void halt_delay_msec(void)
>> > +{
>> > +   if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
>> > +                           || system_state == SYSTEM_POWER_OFF
>> > +                           || system_state == SYSTEM_RESTART)))
>> > +           return;
>>
>> This is a tiny bit ugly (and goes into the vprintf path) but i can
>> see no other way either - a system_state > SYSTEM_RUNNING check
>> would needlessly include the suspend-to-disk state (which we dont
>> want to include here).
>>
>> In theory we could turn system_state into a bitmask and have a
>> print_delay_mask check instead of these flags ... but that is a far
>> wider change and i'm not sure it's a net step forwards.
>>
>> I've applied your patch to tip:core/printk with small edits to the
>> changelog - Linus & Andrew is Cc:ed, should they have any
>> objections.
>
> Could we not put just a single delay in there, immediately prior to halting,
> restarting or poweroffing?

But, then prink messages will still flush too fast for us to see the detail.

-- 
Regards
dave

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Ingo Molnar]

* Dave Young <hidave.darkstar@gmail.com> wrote:

> On Mon, Jun 8, 2009 at 4:14 PM, Ingo Molnar<mingo@elte.hu> wrote:
> >
> > * Dave Young <hidave.darkstar@gmail.com> wrote:
> >
> >> Add a halt_delay module parameter in printk.c used to read the
> >> printk messages in halt/poweroff/restart phase, delay each printk
> >> messages by halt_delay milliseconds. It is useful for debugging if
> >> there's no other way to dump kernel messages that time.
> >>
> >> The halt_delay max value is 65535, default value is 0, change it
> >> by:
> >>
> >> echo xxx > /sys/module/printk/parameters/halt_delay
> >>
> >> Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
> >> ---
> >> Documentation/kernel-parameters.txt |    5 +++++
> >> kernel/printk.c                     |   17 +++++++++++++++++
> >> 2 files changed, 22 insertions(+)
> >>
> >> --- linux-2.6.orig/kernel/printk.c    2009-06-08 13:55:35.000000000 +0800
> >> +++ linux-2.6/kernel/printk.c 2009-06-08 13:56:23.000000000 +0800
> >> @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
> >>  }
> >>  #endif
> >>
> >> +/* msecs delay after each halt/poweroff/restart phase printk,
> >> + unsigned short is enough for delay in milliseconds */
> >> +static unsigned short halt_delay;
> >> +
> >> +static inline void halt_delay_msec(void)
> >> +{
> >> +     if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
> >> +                             || system_state == SYSTEM_POWER_OFF
> >> +                             || system_state == SYSTEM_RESTART)))
> >> +             return;
> >
> > This is a tiny bit ugly (and goes into the vprintf path) but i 
> > can see no other way either - a system_state > SYSTEM_RUNNING 
> > check would needlessly include the suspend-to-disk state (which 
> > we dont want to include here).
> 
> Can we move suspend-to-disk before halt state?

Yes, we could do that - if all system_state uses are checked for 
side-effects - in particular comparisons. We have a few places that 
do 'if (system_state > SYSTEM_RUNNING)' - to designate 'shutdown 
state'. Now, if we have any use of > SYSTEM_SHUTDOWN that might 
break from such a reordering.

I wouldnt expect such usage really, but it has to be checked. That 
would make this patch quite a bit cleaner.

Mind sending a followup delta patch with this cleanup?

	Ingo

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Ingo Molnar]

* Dave Young <hidave.darkstar@gmail.com> wrote:

> On Mon, Jun 8, 2009 at 4:28 PM, Andrew Morton<akpm@linux-foundation.org> wrote:
> > On Mon, 8 Jun 2009 10:14:39 +0200 Ingo Molnar <mingo@elte.hu> wrote:
> >
> >>
> >> * Dave Young <hidave.darkstar@gmail.com> wrote:
> >>
> >> > Add a halt_delay module parameter in printk.c used to read the
> >> > printk messages in halt/poweroff/restart phase, delay each printk
> >> > messages by halt_delay milliseconds. It is useful for debugging if
> >> > there's no other way to dump kernel messages that time.
> >> >
> >> > The halt_delay max value is 65535, default value is 0, change it
> >> > by:
> >> >
> >> > echo xxx > /sys/module/printk/parameters/halt_delay
> >> >
> >> > Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
> >> > ---
> >> > Documentation/kernel-parameters.txt |    5 +++++
> >> > kernel/printk.c                     |   17 +++++++++++++++++
> >> > 2 files changed, 22 insertions(+)
> >> >
> >> > --- linux-2.6.orig/kernel/printk.c  2009-06-08 13:55:35.000000000 +0800
> >> > +++ linux-2.6/kernel/printk.c       2009-06-08 13:56:23.000000000 +0800
> >> > @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
> >> >  }
> >> >  #endif
> >> >
> >> > +/* msecs delay after each halt/poweroff/restart phase printk,
> >> > + unsigned short is enough for delay in milliseconds */
> >> > +static unsigned short halt_delay;
> >> > +
> >> > +static inline void halt_delay_msec(void)
> >> > +{
> >> > +   if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
> >> > +                           || system_state == SYSTEM_POWER_OFF
> >> > +                           || system_state == SYSTEM_RESTART)))
> >> > +           return;
> >>
> >> This is a tiny bit ugly (and goes into the vprintf path) but i can
> >> see no other way either - a system_state > SYSTEM_RUNNING check
> >> would needlessly include the suspend-to-disk state (which we dont
> >> want to include here).
> >>
> >> In theory we could turn system_state into a bitmask and have a
> >> print_delay_mask check instead of these flags ... but that is a far
> >> wider change and i'm not sure it's a net step forwards.
> >>
> >> I've applied your patch to tip:core/printk with small edits to the
> >> changelog - Linus & Andrew is Cc:ed, should they have any
> >> objections.
> >
> > Could we not put just a single delay in there, immediately prior to halting,
> > restarting or poweroffing?
> 
> But, then prink messages will still flush too fast for us to see 
> the detail.

Plus often there's a loop in architecture code that tries various 
methods of reboot. We dont know which one works - and any of them 
could produce warning messages. (and this happened a number of times 
in the past)

So this would mean having to find up to a hundred of 'reboot now' 
places in a two dozen architectures (and keeping them all maintained 
ongoing as well). Does not seem like a good choice to me.

	Ingo

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Mon, Jun 8, 2009 at 4:46 PM, Ingo Molnar<mingo@elte.hu> wrote:
>
> * Dave Young <hidave.darkstar@gmail.com> wrote:
>
>> On Mon, Jun 8, 2009 at 4:14 PM, Ingo Molnar<mingo@elte.hu> wrote:
>> >
>> > * Dave Young <hidave.darkstar@gmail.com> wrote:
>> >
>> >> Add a halt_delay module parameter in printk.c used to read the
>> >> printk messages in halt/poweroff/restart phase, delay each printk
>> >> messages by halt_delay milliseconds. It is useful for debugging if
>> >> there's no other way to dump kernel messages that time.
>> >>
>> >> The halt_delay max value is 65535, default value is 0, change it
>> >> by:
>> >>
>> >> echo xxx > /sys/module/printk/parameters/halt_delay
>> >>
>> >> Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
>> >> ---
>> >> Documentation/kernel-parameters.txt |    5 +++++
>> >> kernel/printk.c                     |   17 +++++++++++++++++
>> >> 2 files changed, 22 insertions(+)
>> >>
>> >> --- linux-2.6.orig/kernel/printk.c    2009-06-08 13:55:35.000000000 +0800
>> >> +++ linux-2.6/kernel/printk.c 2009-06-08 13:56:23.000000000 +0800
>> >> @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
>> >>  }
>> >>  #endif
>> >>
>> >> +/* msecs delay after each halt/poweroff/restart phase printk,
>> >> + unsigned short is enough for delay in milliseconds */
>> >> +static unsigned short halt_delay;
>> >> +
>> >> +static inline void halt_delay_msec(void)
>> >> +{
>> >> +     if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
>> >> +                             || system_state == SYSTEM_POWER_OFF
>> >> +                             || system_state == SYSTEM_RESTART)))
>> >> +             return;
>> >
>> > This is a tiny bit ugly (and goes into the vprintf path) but i
>> > can see no other way either - a system_state > SYSTEM_RUNNING
>> > check would needlessly include the suspend-to-disk state (which
>> > we dont want to include here).
>>
>> Can we move suspend-to-disk before halt state?
>
> Yes, we could do that - if all system_state uses are checked for
> side-effects - in particular comparisons. We have a few places that
> do 'if (system_state > SYSTEM_RUNNING)' - to designate 'shutdown
> state'. Now, if we have any use of > SYSTEM_SHUTDOWN that might
> break from such a reordering.
>
> I wouldnt expect such usage really, but it has to be checked. That
> would make this patch quite a bit cleaner.
>
> Mind sending a followup delta patch with this cleanup?

I'm glad to check the system_state usage, then write a followup patch.

>
>        Ingo
>



-- 
Regards
dave

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Ingo Molnar]

* Dave Young <hidave.darkstar@gmail.com> wrote:

> On Mon, Jun 8, 2009 at 4:46 PM, Ingo Molnar<mingo@elte.hu> wrote:
> >
> > * Dave Young <hidave.darkstar@gmail.com> wrote:
> >
> >> On Mon, Jun 8, 2009 at 4:14 PM, Ingo Molnar<mingo@elte.hu> wrote:
> >> >
> >> > * Dave Young <hidave.darkstar@gmail.com> wrote:
> >> >
> >> >> Add a halt_delay module parameter in printk.c used to read the
> >> >> printk messages in halt/poweroff/restart phase, delay each printk
> >> >> messages by halt_delay milliseconds. It is useful for debugging if
> >> >> there's no other way to dump kernel messages that time.
> >> >>
> >> >> The halt_delay max value is 65535, default value is 0, change it
> >> >> by:
> >> >>
> >> >> echo xxx > /sys/module/printk/parameters/halt_delay
> >> >>
> >> >> Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
> >> >> ---
> >> >> Documentation/kernel-parameters.txt |    5 +++++
> >> >> kernel/printk.c                     |   17 +++++++++++++++++
> >> >> 2 files changed, 22 insertions(+)
> >> >>
> >> >> --- linux-2.6.orig/kernel/printk.c    2009-06-08 13:55:35.000000000 +0800
> >> >> +++ linux-2.6/kernel/printk.c 2009-06-08 13:56:23.000000000 +0800
> >> >> @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
> >> >>  }
> >> >>  #endif
> >> >>
> >> >> +/* msecs delay after each halt/poweroff/restart phase printk,
> >> >> + unsigned short is enough for delay in milliseconds */
> >> >> +static unsigned short halt_delay;
> >> >> +
> >> >> +static inline void halt_delay_msec(void)
> >> >> +{
> >> >> +     if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
> >> >> +                             || system_state == SYSTEM_POWER_OFF
> >> >> +                             || system_state == SYSTEM_RESTART)))
> >> >> +             return;
> >> >
> >> > This is a tiny bit ugly (and goes into the vprintf path) but i
> >> > can see no other way either - a system_state > SYSTEM_RUNNING
> >> > check would needlessly include the suspend-to-disk state (which
> >> > we dont want to include here).
> >>
> >> Can we move suspend-to-disk before halt state?
> >
> > Yes, we could do that - if all system_state uses are checked for
> > side-effects - in particular comparisons. We have a few places that
> > do 'if (system_state > SYSTEM_RUNNING)' - to designate 'shutdown
> > state'. Now, if we have any use of > SYSTEM_SHUTDOWN that might
> > break from such a reordering.
> >
> > I wouldnt expect such usage really, but it has to be checked. That
> > would make this patch quite a bit cleaner.
> >
> > Mind sending a followup delta patch with this cleanup?
> 
> I'm glad to check the system_state usage, then write a followup patch.

I'd also suggest to add a comment to the constants, to make sure 
that when new system states are added, the ordering assumptions are 
not broken.

	Ingo

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Mon, Jun 8, 2009 at 4:58 PM, Ingo Molnar<mingo@elte.hu> wrote:
>
> * Dave Young <hidave.darkstar@gmail.com> wrote:
>
>> On Mon, Jun 8, 2009 at 4:46 PM, Ingo Molnar<mingo@elte.hu> wrote:
>> >
>> > * Dave Young <hidave.darkstar@gmail.com> wrote:
>> >
>> >> On Mon, Jun 8, 2009 at 4:14 PM, Ingo Molnar<mingo@elte.hu> wrote:
>> >> >
>> >> > * Dave Young <hidave.darkstar@gmail.com> wrote:
>> >> >
>> >> >> Add a halt_delay module parameter in printk.c used to read the
>> >> >> printk messages in halt/poweroff/restart phase, delay each printk
>> >> >> messages by halt_delay milliseconds. It is useful for debugging if
>> >> >> there's no other way to dump kernel messages that time.
>> >> >>
>> >> >> The halt_delay max value is 65535, default value is 0, change it
>> >> >> by:
>> >> >>
>> >> >> echo xxx > /sys/module/printk/parameters/halt_delay
>> >> >>
>> >> >> Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
>> >> >> ---
>> >> >> Documentation/kernel-parameters.txt |    5 +++++
>> >> >> kernel/printk.c                     |   17 +++++++++++++++++
>> >> >> 2 files changed, 22 insertions(+)
>> >> >>
>> >> >> --- linux-2.6.orig/kernel/printk.c    2009-06-08 13:55:35.000000000 +0800
>> >> >> +++ linux-2.6/kernel/printk.c 2009-06-08 13:56:23.000000000 +0800
>> >> >> @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
>> >> >>  }
>> >> >>  #endif
>> >> >>
>> >> >> +/* msecs delay after each halt/poweroff/restart phase printk,
>> >> >> + unsigned short is enough for delay in milliseconds */
>> >> >> +static unsigned short halt_delay;
>> >> >> +
>> >> >> +static inline void halt_delay_msec(void)
>> >> >> +{
>> >> >> +     if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
>> >> >> +                             || system_state == SYSTEM_POWER_OFF
>> >> >> +                             || system_state == SYSTEM_RESTART)))
>> >> >> +             return;
>> >> >
>> >> > This is a tiny bit ugly (and goes into the vprintf path) but i
>> >> > can see no other way either - a system_state > SYSTEM_RUNNING
>> >> > check would needlessly include the suspend-to-disk state (which
>> >> > we dont want to include here).
>> >>
>> >> Can we move suspend-to-disk before halt state?
>> >
>> > Yes, we could do that - if all system_state uses are checked for
>> > side-effects - in particular comparisons. We have a few places that
>> > do 'if (system_state > SYSTEM_RUNNING)' - to designate 'shutdown
>> > state'. Now, if we have any use of > SYSTEM_SHUTDOWN that might
>> > break from such a reordering.
>> >
>> > I wouldnt expect such usage really, but it has to be checked. That
>> > would make this patch quite a bit cleaner.
>> >
>> > Mind sending a followup delta patch with this cleanup?
>>
>> I'm glad to check the system_state usage, then write a followup patch.
>
> I'd also suggest to add a comment to the constants, to make sure
> that when new system states are added, the ordering assumptions are
> not broken.

Fine.

>
>        Ingo
>



-- 
Regards
dave

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Andrew Morton]

On Mon, 8 Jun 2009 10:48:07 +0200 Ingo Molnar <mingo@elte.hu> wrote:

> 
> * Dave Young <hidave.darkstar@gmail.com> wrote:
> 
> > On Mon, Jun 8, 2009 at 4:28 PM, Andrew Morton<akpm@linux-foundation.org> wrote:
> > > On Mon, 8 Jun 2009 10:14:39 +0200 Ingo Molnar <mingo@elte.hu> wrote:
> > >
> > >>
> > >> * Dave Young <hidave.darkstar@gmail.com> wrote:
> > >>
> > >> > Add a halt_delay module parameter in printk.c used to read the
> > >> > printk messages in halt/poweroff/restart phase, delay each printk
> > >> > messages by halt_delay milliseconds. It is useful for debugging if
> > >> > there's no other way to dump kernel messages that time.
> > >> >
> > >> > The halt_delay max value is 65535, default value is 0, change it
> > >> > by:
> > >> >
> > >> > echo xxx > /sys/module/printk/parameters/halt_delay
> > >> >
> > >> > Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
> > >> > ---
> > >> > Documentation/kernel-parameters.txt | __ __5 +++++
> > >> > kernel/printk.c __ __ __ __ __ __ __ __ __ __ | __ 17 +++++++++++++++++
> > >> > 2 files changed, 22 insertions(+)
> > >> >
> > >> > --- linux-2.6.orig/kernel/printk.c __2009-06-08 13:55:35.000000000 +0800
> > >> > +++ linux-2.6/kernel/printk.c __ __ __ 2009-06-08 13:56:23.000000000 +0800
> > >> > @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
> > >> > __}
> > >> > __#endif
> > >> >
> > >> > +/* msecs delay after each halt/poweroff/restart phase printk,
> > >> > + unsigned short is enough for delay in milliseconds */
> > >> > +static unsigned short halt_delay;
> > >> > +
> > >> > +static inline void halt_delay_msec(void)
> > >> > +{
> > >> > + __ if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
> > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_POWER_OFF
> > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_RESTART)))
> > >> > + __ __ __ __ __ return;
> > >>
> > >> This is a tiny bit ugly (and goes into the vprintf path) but i can
> > >> see no other way either - a system_state > SYSTEM_RUNNING check
> > >> would needlessly include the suspend-to-disk state (which we dont
> > >> want to include here).
> > >>
> > >> In theory we could turn system_state into a bitmask and have a
> > >> print_delay_mask check instead of these flags ... but that is a far
> > >> wider change and i'm not sure it's a net step forwards.
> > >>
> > >> I've applied your patch to tip:core/printk with small edits to the
> > >> changelog - Linus & Andrew is Cc:ed, should they have any
> > >> objections.
> > >
> > > Could we not put just a single delay in there, immediately prior to halting,
> > > restarting or poweroffing?
> > 
> > But, then prink messages will still flush too fast for us to see 
> > the detail.

Only if there are so many unlogged messages that they scroll of the
screen.  Is that the case?

> Plus often there's a loop in architecture code that tries various 
> methods of reboot. We dont know which one works - and any of them 
> could produce warning messages. (and this happened a number of times 
> in the past)
> 
> So this would mean having to find up to a hundred of 'reboot now' 
> places in a two dozen architectures (and keeping them all maintained 
> ongoing as well). Does not seem like a good choice to me.
> 

hm.  If we need to actually capture all of those.

questions: is it possible for interrupts to be disabled at this time? 
If so, can we get an NMI watchdog hit?

Is the softlockup detector still running and if so, can it trigger?

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Ingo Molnar]

* Andrew Morton <akpm@linux-foundation.org> wrote:

> On Mon, 8 Jun 2009 10:48:07 +0200 Ingo Molnar <mingo@elte.hu> wrote:
> 
> > 
> > * Dave Young <hidave.darkstar@gmail.com> wrote:
> > 
> > > On Mon, Jun 8, 2009 at 4:28 PM, Andrew Morton<akpm@linux-foundation.org> wrote:
> > > > On Mon, 8 Jun 2009 10:14:39 +0200 Ingo Molnar <mingo@elte.hu> wrote:
> > > >
> > > >>
> > > >> * Dave Young <hidave.darkstar@gmail.com> wrote:
> > > >>
> > > >> > Add a halt_delay module parameter in printk.c used to read the
> > > >> > printk messages in halt/poweroff/restart phase, delay each printk
> > > >> > messages by halt_delay milliseconds. It is useful for debugging if
> > > >> > there's no other way to dump kernel messages that time.
> > > >> >
> > > >> > The halt_delay max value is 65535, default value is 0, change it
> > > >> > by:
> > > >> >
> > > >> > echo xxx > /sys/module/printk/parameters/halt_delay
> > > >> >
> > > >> > Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
> > > >> > ---
> > > >> > Documentation/kernel-parameters.txt | __ __5 +++++
> > > >> > kernel/printk.c __ __ __ __ __ __ __ __ __ __ | __ 17 +++++++++++++++++
> > > >> > 2 files changed, 22 insertions(+)
> > > >> >
> > > >> > --- linux-2.6.orig/kernel/printk.c __2009-06-08 13:55:35.000000000 +0800
> > > >> > +++ linux-2.6/kernel/printk.c __ __ __ 2009-06-08 13:56:23.000000000 +0800
> > > >> > @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
> > > >> > __}
> > > >> > __#endif
> > > >> >
> > > >> > +/* msecs delay after each halt/poweroff/restart phase printk,
> > > >> > + unsigned short is enough for delay in milliseconds */
> > > >> > +static unsigned short halt_delay;
> > > >> > +
> > > >> > +static inline void halt_delay_msec(void)
> > > >> > +{
> > > >> > + __ if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
> > > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_POWER_OFF
> > > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_RESTART)))
> > > >> > + __ __ __ __ __ return;
> > > >>
> > > >> This is a tiny bit ugly (and goes into the vprintf path) but i can
> > > >> see no other way either - a system_state > SYSTEM_RUNNING check
> > > >> would needlessly include the suspend-to-disk state (which we dont
> > > >> want to include here).
> > > >>
> > > >> In theory we could turn system_state into a bitmask and have a
> > > >> print_delay_mask check instead of these flags ... but that is a far
> > > >> wider change and i'm not sure it's a net step forwards.
> > > >>
> > > >> I've applied your patch to tip:core/printk with small edits to the
> > > >> changelog - Linus & Andrew is Cc:ed, should they have any
> > > >> objections.
> > > >
> > > > Could we not put just a single delay in there, immediately prior to halting,
> > > > restarting or poweroffing?
> > > 
> > > But, then prink messages will still flush too fast for us to see 
> > > the detail.
> 
> Only if there are so many unlogged messages that they scroll of the
> screen.  Is that the case?

i have such an example in my logs:

[  390.206118] md: stopping all md devices.
[  391.208259] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  391.214877] igb 0000:01:00.1: PCI INT B disabled
[  391.220445] igb 0000:01:00.0: PCI INT A disabled
[  391.225897] Restarting system.
[  391.229213] machine restart
[  391.232833] ------------[ cut here ]------------
[  391.237718] WARNING: at arch/x86/kernel/smp.c:117 native_smp_send_reschedule+0x55/0x83()
[  391.246276] Hardware name: X8DTN
[  391.249762] Modules linked in:
[  391.253146] Pid: 19807, comm: reboot Not tainted 2.6.30-rc8-tip #8
[  391.259580] Call Trace:
[  391.262287]  <IRQ>  [<ffffffff81021525>] ? native_smp_send_reschedule+0x55/0x83
[  391.270136]  [<ffffffff8104a316>] warn_slowpath_common+0x77/0xa4
[  391.276395]  [<ffffffff8104a352>] warn_slowpath_null+0xf/0x11
[  391.282399]  [<ffffffff81021525>] native_smp_send_reschedule+0x55/0x83
[  391.289182]  [<ffffffff8103629f>] resched_task+0x60/0x62
[  391.294752]  [<ffffffff8103d976>] resched_cpu+0x4a/0x5e
[  391.300237]  [<ffffffff8104627f>] scheduler_tick+0x19a/0x249
[  391.306154]  [<ffffffff81054576>] update_process_times+0x4f/0x5f
[  391.312417]  [<ffffffff8106ad80>] tick_sched_timer+0x76/0x96
[  391.318331]  [<ffffffff8106ad0a>] ? tick_sched_timer+0x0/0x96
[  391.324334]  [<ffffffff81061ea2>] __run_hrtimer+0x80/0xb4
[  391.329993]  [<ffffffff81062abe>] hrtimer_interrupt+0xe7/0x145
[  391.336081]  [<ffffffff81022801>] smp_apic_timer_interrupt+0x83/0x96
[  391.342692]  [<ffffffff8100c6d3>] apic_timer_interrupt+0x13/0x20
[  391.348953]  <EOI>  [<ffffffff81022a7c>] ? default_send_IPI_mask_allbutself_phys+0x67/0x73
[  391.357752]  [<ffffffff8102532d>] ? physflat_send_IPI_allbutself+0x14/0x16
[  391.364877]  [<ffffffff8102166a>] ? native_send_call_func_ipi+0x83/0xa5
[  391.371747]  [<ffffffff81070cff>] ? smp_call_function_many+0x19b/0x1bb
[  391.378529]  [<ffffffff810128b0>] ? stop_this_cpu+0x0/0x1c
[  391.384270]  [<ffffffff81070d3f>] ? smp_call_function+0x20/0x24
[  391.390448]  [<ffffffff81021575>] ? native_smp_send_stop+0x22/0x30
[  391.396882]  [<ffffffff81020f93>] ? native_machine_shutdown+0x49/0x62
[  391.403578]  [<ffffffff81020d62>] ? native_machine_restart+0x21/0x33
[  391.410187]  [<ffffffff81020cd9>] ? machine_restart+0xa/0xc
[  391.416016]  [<ffffffff81059d67>] ? kernel_restart+0x3f/0x43
[  391.421935]  [<ffffffff81059eb8>] ? sys_reboot+0x140/0x174
[  391.427677]  [<ffffffff810628c6>] ? hrtimer_nanosleep+0x104/0x119
[  391.434025]  [<ffffffff81061e01>] ? hrtimer_wakeup+0x0/0x21
[  391.439857]  [<ffffffff8106272d>] ? hrtimer_start_range_ns+0xf/0x11
[  391.446379]  [<ffffffff8106292f>] ? sys_nanosleep+0x54/0x6c
[  391.452210]  [<ffffffff8100bbeb>] ? system_call_fastpath+0x16/0x1b
[  391.458643] ---[ end trace 4b05cad362f39345 ]---

that's 44 lines so yes it can happen.

> > Plus often there's a loop in architecture code that tries various 
> > methods of reboot. We dont know which one works - and any of them 
> > could produce warning messages. (and this happened a number of times 
> > in the past)
> > 
> > So this would mean having to find up to a hundred of 'reboot now' 
> > places in a two dozen architectures (and keeping them all maintained 
> > ongoing as well). Does not seem like a good choice to me.
> > 
> 
> hm.  If we need to actually capture all of those.
> 
> questions: is it possible for interrupts to be disabled at this 
> time? If so, can we get an NMI watchdog hit?

no, we generally turn off the nmi watchdog during shutdown, disable 
the lapic and io-apic, etc.

> Is the softlockup detector still running and if so, can it 
> trigger?

in (non-emergency) reboot, last i checked, we stopped all other CPUs 
first, and then killed the current one. There's no chance for the 
watchdog thread to run.

Anyway ... you seem to be uncomfortable about this patch - should i 
delay it for now to let it all play out? We are close to the merge 
window.

	Ingo

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Andrew Morton]

On Mon, 8 Jun 2009 19:15:01 +0200
Ingo Molnar <mingo@elte.hu> wrote:

> > questions: is it possible for interrupts to be disabled at this 
> > time? If so, can we get an NMI watchdog hit?
> 
> no, we generally turn off the nmi watchdog during shutdown, disable 
> the lapic and io-apic, etc.

Is x86 the only architecture which implements an NMI watchdog?

> > Is the softlockup detector still running and if so, can it 
> > trigger?
> 
> in (non-emergency) reboot, last i checked, we stopped all other CPUs 
> first, and then killed the current one. There's no chance for the 
> watchdog thread to run.

OK, but...  See below.

> Anyway ... you seem to be uncomfortable about this patch - should i 
> delay it for now to let it all play out? We are close to the merge 
> window.

I'm OK - I'm just bouncing ideas and questions off you guys, to make sure
that we've thought this through all the way.

Here's another: why is it a boot option rather than a runtime-tunable? 
A /proc tweakable is generally preferable because it avoids the
oh-crap-i-forgot-to-edit-grub.conf thing.  And we could perhaps then
remove all those system_state tests: userspace sets printk_delay
immediately prior to running halt/reboot/etc?

Plus the feature becomes more general - perhaps there are use cases
where people want to slow down printks, such as: kernel goes oops, data
scrolls off, serial console/netconsole unavailable.  pause_on_oops is
supposed to help here but last time I tried it, it kinda didn't work,
plus pause_on_oops doesn't solve the data-scrolled-off problem.

Thirdly, if we do this as a general /proc/printk_delay thing, perhaps
it can be consolidated with the existing boot_delay= implementation.

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Ingo Molnar]

* Andrew Morton <akpm@linux-foundation.org> wrote:

> On Mon, 8 Jun 2009 19:15:01 +0200
> Ingo Molnar <mingo@elte.hu> wrote:
> 
> > > questions: is it possible for interrupts to be disabled at this 
> > > time? If so, can we get an NMI watchdog hit?
> > 
> > no, we generally turn off the nmi watchdog during shutdown, 
> > disable the lapic and io-apic, etc.
> 
> Is x86 the only architecture which implements an NMI watchdog?

Sparc64 does too IIRC.

> > > Is the softlockup detector still running and if so, can it 
> > > trigger?
> > 
> > in (non-emergency) reboot, last i checked, we stopped all other 
> > CPUs first, and then killed the current one. There's no chance 
> > for the watchdog thread to run.
> 
> OK, but...  See below.
> 
> > Anyway ... you seem to be uncomfortable about this patch - 
> > should i delay it for now to let it all play out? We are close 
> > to the merge window.
> 
> I'm OK - I'm just bouncing ideas and questions off you guys, to 
> make sure that we've thought this through all the way.
> 
> Here's another: why is it a boot option rather than a 
> runtime-tunable? A /proc tweakable is generally preferable because 
> it avoids the oh-crap-i-forgot-to-edit-grub.conf thing.  And we 
> could perhaps then remove all those system_state tests: userspace 
> sets printk_delay immediately prior to running halt/reboot/etc?
> 
> Plus the feature becomes more general - perhaps there are use 
> cases where people want to slow down printks, such as: kernel goes 
> oops, data scrolls off, serial console/netconsole unavailable.  
> pause_on_oops is supposed to help here but last time I tried it, 
> it kinda didn't work, plus pause_on_oops doesn't solve the 
> data-scrolled-off problem.
> 
> Thirdly, if we do this as a general /proc/printk_delay thing, 
> perhaps it can be consolidated with the existing boot_delay= 
> implementation.

Consolidatig with the existing boot delay implementation was one of 
my first suggestions.

The /proc thing definitely makes sense - the boot option was just 
symmetry to the existing boot-delay approach.

I've unapplied this patch - i agree that it needs a bit more work 
and i dont want to hold up other changes in the core/printk branch.

	Ingo

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Andrew Morton]

On Tue, 9 Jun 2009 00:02:53 +0200
Ingo Molnar <mingo@elte.hu> wrote:

> The /proc thing definitely makes sense - the boot option was just 
> symmetry to the existing boot-delay approach.

ok.  btw, if we do decide to go with a general printk_delay then we'll
need a touch_nmi_watchdog() in there to keep the NMI watchdog and
softlockup detector away.

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Ingo Molnar]

* Andrew Morton <akpm@linux-foundation.org> wrote:

> Plus the feature becomes more general - perhaps there are use 
> cases where people want to slow down printks, such as: kernel goes 
> oops, data scrolls off, serial console/netconsole unavailable.  
> pause_on_oops is supposed to help here but last time I tried it, 
> it kinda didn't work, plus pause_on_oops doesn't solve the 
> data-scrolled-off problem.

btw, i solved that particular problem in one of my kernels by adding 
a pause_on_oops_head and pause_on_oops_tail hack some time ago. (It 
properly and well deservedly died an entropic death.)

So the problem space is real, and our tools for it suck to a certain 
degree. Your generalization would certainly help.

	Ingo

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Tue, Jun 9, 2009 at 1:15 AM, Ingo Molnar<mingo@elte.hu> wrote:
>
> * Andrew Morton <akpm@linux-foundation.org> wrote:
>
>> On Mon, 8 Jun 2009 10:48:07 +0200 Ingo Molnar <mingo@elte.hu> wrote:
>>
>> >
>> > * Dave Young <hidave.darkstar@gmail.com> wrote:
>> >
>> > > On Mon, Jun 8, 2009 at 4:28 PM, Andrew Morton<akpm@linux-foundation.org> wrote:
>> > > > On Mon, 8 Jun 2009 10:14:39 +0200 Ingo Molnar <mingo@elte.hu> wrote:
>> > > >
>> > > >>
>> > > >> * Dave Young <hidave.darkstar@gmail.com> wrote:
>> > > >>
>> > > >> > Add a halt_delay module parameter in printk.c used to read the
>> > > >> > printk messages in halt/poweroff/restart phase, delay each printk
>> > > >> > messages by halt_delay milliseconds. It is useful for debugging if
>> > > >> > there's no other way to dump kernel messages that time.
>> > > >> >
>> > > >> > The halt_delay max value is 65535, default value is 0, change it
>> > > >> > by:
>> > > >> >
>> > > >> > echo xxx > /sys/module/printk/parameters/halt_delay
>> > > >> >
>> > > >> > Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
>> > > >> > ---
>> > > >> > Documentation/kernel-parameters.txt | __ __5 +++++
>> > > >> > kernel/printk.c __ __ __ __ __ __ __ __ __ __ | __ 17 +++++++++++++++++
>> > > >> > 2 files changed, 22 insertions(+)
>> > > >> >
>> > > >> > --- linux-2.6.orig/kernel/printk.c __2009-06-08 13:55:35.000000000 +0800
>> > > >> > +++ linux-2.6/kernel/printk.c __ __ __ 2009-06-08 13:56:23.000000000 +0800
>> > > >> > @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
>> > > >> > __}
>> > > >> > __#endif
>> > > >> >
>> > > >> > +/* msecs delay after each halt/poweroff/restart phase printk,
>> > > >> > + unsigned short is enough for delay in milliseconds */
>> > > >> > +static unsigned short halt_delay;
>> > > >> > +
>> > > >> > +static inline void halt_delay_msec(void)
>> > > >> > +{
>> > > >> > + __ if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
>> > > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_POWER_OFF
>> > > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_RESTART)))
>> > > >> > + __ __ __ __ __ return;
>> > > >>
>> > > >> This is a tiny bit ugly (and goes into the vprintf path) but i can
>> > > >> see no other way either - a system_state > SYSTEM_RUNNING check
>> > > >> would needlessly include the suspend-to-disk state (which we dont
>> > > >> want to include here).
>> > > >>
>> > > >> In theory we could turn system_state into a bitmask and have a
>> > > >> print_delay_mask check instead of these flags ... but that is a far
>> > > >> wider change and i'm not sure it's a net step forwards.
>> > > >>
>> > > >> I've applied your patch to tip:core/printk with small edits to the
>> > > >> changelog - Linus & Andrew is Cc:ed, should they have any
>> > > >> objections.
>> > > >
>> > > > Could we not put just a single delay in there, immediately prior to halting,
>> > > > restarting or poweroffing?
>> > >
>> > > But, then prink messages will still flush too fast for us to see
>> > > the detail.
>>
>> Only if there are so many unlogged messages that they scroll of the
>> screen.  Is that the case?
>
> i have such an example in my logs:
>
> [  390.206118] md: stopping all md devices.
> [  391.208259] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> [  391.214877] igb 0000:01:00.1: PCI INT B disabled
> [  391.220445] igb 0000:01:00.0: PCI INT A disabled
> [  391.225897] Restarting system.
> [  391.229213] machine restart
> [  391.232833] ------------[ cut here ]------------
> [  391.237718] WARNING: at arch/x86/kernel/smp.c:117 native_smp_send_reschedule+0x55/0x83()
> [  391.246276] Hardware name: X8DTN
> [  391.249762] Modules linked in:
> [  391.253146] Pid: 19807, comm: reboot Not tainted 2.6.30-rc8-tip #8
> [  391.259580] Call Trace:
> [  391.262287]  <IRQ>  [<ffffffff81021525>] ? native_smp_send_reschedule+0x55/0x83
> [  391.270136]  [<ffffffff8104a316>] warn_slowpath_common+0x77/0xa4
> [  391.276395]  [<ffffffff8104a352>] warn_slowpath_null+0xf/0x11
> [  391.282399]  [<ffffffff81021525>] native_smp_send_reschedule+0x55/0x83
> [  391.289182]  [<ffffffff8103629f>] resched_task+0x60/0x62
> [  391.294752]  [<ffffffff8103d976>] resched_cpu+0x4a/0x5e
> [  391.300237]  [<ffffffff8104627f>] scheduler_tick+0x19a/0x249
> [  391.306154]  [<ffffffff81054576>] update_process_times+0x4f/0x5f
> [  391.312417]  [<ffffffff8106ad80>] tick_sched_timer+0x76/0x96
> [  391.318331]  [<ffffffff8106ad0a>] ? tick_sched_timer+0x0/0x96
> [  391.324334]  [<ffffffff81061ea2>] __run_hrtimer+0x80/0xb4
> [  391.329993]  [<ffffffff81062abe>] hrtimer_interrupt+0xe7/0x145
> [  391.336081]  [<ffffffff81022801>] smp_apic_timer_interrupt+0x83/0x96
> [  391.342692]  [<ffffffff8100c6d3>] apic_timer_interrupt+0x13/0x20
> [  391.348953]  <EOI>  [<ffffffff81022a7c>] ? default_send_IPI_mask_allbutself_phys+0x67/0x73
> [  391.357752]  [<ffffffff8102532d>] ? physflat_send_IPI_allbutself+0x14/0x16
> [  391.364877]  [<ffffffff8102166a>] ? native_send_call_func_ipi+0x83/0xa5
> [  391.371747]  [<ffffffff81070cff>] ? smp_call_function_many+0x19b/0x1bb
> [  391.378529]  [<ffffffff810128b0>] ? stop_this_cpu+0x0/0x1c
> [  391.384270]  [<ffffffff81070d3f>] ? smp_call_function+0x20/0x24
> [  391.390448]  [<ffffffff81021575>] ? native_smp_send_stop+0x22/0x30
> [  391.396882]  [<ffffffff81020f93>] ? native_machine_shutdown+0x49/0x62
> [  391.403578]  [<ffffffff81020d62>] ? native_machine_restart+0x21/0x33
> [  391.410187]  [<ffffffff81020cd9>] ? machine_restart+0xa/0xc
> [  391.416016]  [<ffffffff81059d67>] ? kernel_restart+0x3f/0x43
> [  391.421935]  [<ffffffff81059eb8>] ? sys_reboot+0x140/0x174
> [  391.427677]  [<ffffffff810628c6>] ? hrtimer_nanosleep+0x104/0x119
> [  391.434025]  [<ffffffff81061e01>] ? hrtimer_wakeup+0x0/0x21
> [  391.439857]  [<ffffffff8106272d>] ? hrtimer_start_range_ns+0xf/0x11
> [  391.446379]  [<ffffffff8106292f>] ? sys_nanosleep+0x54/0x6c
> [  391.452210]  [<ffffffff8100bbeb>] ? system_call_fastpath+0x16/0x1b
> [  391.458643] ---[ end trace 4b05cad362f39345 ]---
>
> that's 44 lines so yes it can happen.

For lockdep issue, there will be more

>
>> > Plus often there's a loop in architecture code that tries various
>> > methods of reboot. We dont know which one works - and any of them
>> > could produce warning messages. (and this happened a number of times
>> > in the past)
>> >
>> > So this would mean having to find up to a hundred of 'reboot now'
>> > places in a two dozen architectures (and keeping them all maintained
>> > ongoing as well). Does not seem like a good choice to me.
>> >
>>
>> hm.  If we need to actually capture all of those.
>>
>> questions: is it possible for interrupts to be disabled at this
>> time? If so, can we get an NMI watchdog hit?
>
> no, we generally turn off the nmi watchdog during shutdown, disable
> the lapic and io-apic, etc.
>
>> Is the softlockup detector still running and if so, can it
>> trigger?
>
> in (non-emergency) reboot, last i checked, we stopped all other CPUs
> first, and then killed the current one. There's no chance for the
> watchdog thread to run.
>
> Anyway ... you seem to be uncomfortable about this patch - should i
> delay it for now to let it all play out? We are close to the merge
> window.
>
>        Ingo
>



-- 
Regards
dave

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Tue, Jun 9, 2009 at 5:39 AM, Andrew Morton<akpm@linux-foundation.org> wrote:
> On Mon, 8 Jun 2009 19:15:01 +0200
> Ingo Molnar <mingo@elte.hu> wrote:
>
>> > questions: is it possible for interrupts to be disabled at this
>> > time? If so, can we get an NMI watchdog hit?
>>
>> no, we generally turn off the nmi watchdog during shutdown, disable
>> the lapic and io-apic, etc.
>
> Is x86 the only architecture which implements an NMI watchdog?
>
>> > Is the softlockup detector still running and if so, can it
>> > trigger?
>>
>> in (non-emergency) reboot, last i checked, we stopped all other CPUs
>> first, and then killed the current one. There's no chance for the
>> watchdog thread to run.
>
> OK, but...  See below.
>
>> Anyway ... you seem to be uncomfortable about this patch - should i
>> delay it for now to let it all play out? We are close to the merge
>> window.
>
> I'm OK - I'm just bouncing ideas and questions off you guys, to make sure
> that we've thought this through all the way.
>
> Here's another: why is it a boot option rather than a runtime-tunable?
> A /proc tweakable is generally preferable because it avoids the
> oh-crap-i-forgot-to-edit-grub.conf thing.  And we could perhaps then
> remove all those system_state tests: userspace sets printk_delay
> immediately prior to running halt/reboot/etc?

Andrew, thanks your comments.
I original intention is to use not boot options but sysfs interface.
Do you perfer proc?
without system_state testing we will have to consider the NMI watchdog
and softlockup issue.

>
> Plus the feature becomes more general - perhaps there are use cases
> where people want to slow down printks, such as: kernel goes oops, data
> scrolls off, serial console/netconsole unavailable.  pause_on_oops is
> supposed to help here but last time I tried it, it kinda didn't work,
> plus pause_on_oops doesn't solve the data-scrolled-off problem.

Seems make sense.

>
> Thirdly, if we do this as a general /proc/printk_delay thing, perhaps
> it can be consolidated with the existing boot_delay= implementation.
>



-- 
Regards
dave

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Tue, Jun 9, 2009 at 9:01 AM, Dave Young<hidave.darkstar@gmail.com> wrote:
> On Tue, Jun 9, 2009 at 5:39 AM, Andrew Morton<akpm@linux-foundation.org> wrote:
>> On Mon, 8 Jun 2009 19:15:01 +0200
>> Ingo Molnar <mingo@elte.hu> wrote:
>>
>>> > questions: is it possible for interrupts to be disabled at this
>>> > time? If so, can we get an NMI watchdog hit?
>>>
>>> no, we generally turn off the nmi watchdog during shutdown, disable
>>> the lapic and io-apic, etc.
>>
>> Is x86 the only architecture which implements an NMI watchdog?
>>
>>> > Is the softlockup detector still running and if so, can it
>>> > trigger?
>>>
>>> in (non-emergency) reboot, last i checked, we stopped all other CPUs
>>> first, and then killed the current one. There's no chance for the
>>> watchdog thread to run.
>>
>> OK, but...  See below.
>>
>>> Anyway ... you seem to be uncomfortable about this patch - should i
>>> delay it for now to let it all play out? We are close to the merge
>>> window.
>>
>> I'm OK - I'm just bouncing ideas and questions off you guys, to make sure
>> that we've thought this through all the way.
>>
>> Here's another: why is it a boot option rather than a runtime-tunable?
>> A /proc tweakable is generally preferable because it avoids the
>> oh-crap-i-forgot-to-edit-grub.conf thing.  And we could perhaps then
>> remove all those system_state tests: userspace sets printk_delay
>> immediately prior to running halt/reboot/etc?
>
> Andrew, thanks your comments.
> I original intention is to use not boot options but sysfs interface.
> Do you perfer proc?
> without system_state testing we will have to consider the NMI watchdog
> and softlockup issue.
>
>>
>> Plus the feature becomes more general - perhaps there are use cases
>> where people want to slow down printks, such as: kernel goes oops, data
>> scrolls off, serial console/netconsole unavailable.  pause_on_oops is
>> supposed to help here but last time I tried it, it kinda didn't work,
>> plus pause_on_oops doesn't solve the data-scrolled-off problem.
>
> Seems make sense

And, if making it a general feature, I think maybe delay per screen
(ie. 25 lines) is a good way.

>
>>
>> Thirdly, if we do this as a general /proc/printk_delay thing, perhaps
>> it can be consolidated with the existing boot_delay= implementation.
>>
>
>
>
> --
> Regards
> dave
>



-- 
Regards
dave

Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Andrew Morton]

On Tue, 9 Jun 2009 09:01:19 +0800 Dave Young <hidave.darkstar@gmail.com> wrote:

> On Tue, Jun 9, 2009 at 5:39 AM, Andrew Morton<akpm@linux-foundation.org> wrote:
> > On Mon, 8 Jun 2009 19:15:01 +0200
> > Ingo Molnar <mingo@elte.hu> wrote:
> >
> >> > questions: is it possible for interrupts to be disabled at this
> >> > time? If so, can we get an NMI watchdog hit?
> >>
> >> no, we generally turn off the nmi watchdog during shutdown, disable
> >> the lapic and io-apic, etc.
> >
> > Is x86 the only architecture which implements an NMI watchdog?
> >
> >> > Is the softlockup detector still running and if so, can it
> >> > trigger?
> >>
> >> in (non-emergency) reboot, last i checked, we stopped all other CPUs
> >> first, and then killed the current one. There's no chance for the
> >> watchdog thread to run.
> >
> > OK, but... __See below.
> >
> >> Anyway ... you seem to be uncomfortable about this patch - should i
> >> delay it for now to let it all play out? We are close to the merge
> >> window.
> >
> > I'm OK - I'm just bouncing ideas and questions off you guys, to make sure
> > that we've thought this through all the way.
> >
> > Here's another: why is it a boot option rather than a runtime-tunable?
> > A /proc tweakable is generally preferable because it avoids the
> > oh-crap-i-forgot-to-edit-grub.conf thing. __And we could perhaps then
> > remove all those system_state tests: userspace sets printk_delay
> > immediately prior to running halt/reboot/etc?
> 
> Andrew, thanks your comments.
> I original intention is to use not boot options but sysfs interface.
> Do you perfer proc?

sysfs is OK, if there's a logical place for it.  /sys/kernel/, I suppose.

> without system_state testing we will have to consider the NMI watchdog
> and softlockup issue.

Yup.