Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Shilimkar, Santosh]

Hi,

I have faced similar issue as what is being described in below with
latest kernel.

------------------------------------------------
https://patchwork.kernel.org/patch/103347/

When a secondary CPU is being brought up, it is not uncommon for
printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
case that I witnessed personally was on MIPS:

http://lkml.org/lkml/2010/5/30/4

If (can_use_console() == 0), printk() will spool its output to log_buf
and it will be visible in "dmesg", but that output will NOT be echoed to
the console until somebody calls release_console_sem() from a CPU that
is online.  Therefore, the boot time messages from the new CPU can get
stuck in "limbo" for a long time, and might suddenly appear on the
screen when a completely unrelated event (e.g. "eth0: link is down")
occurs.

This patch modifies the console code so that any pending messages are
automatically flushed out to the console whenever a CPU hotplug
operation completes successfully or aborts.

-----------------------------------------------

Above patch fixes only half of the problem. I mean the cpu online
path prints are coming on the console.

But similar problem also exist if there are prints in the cpu offline
path. I got that fixed by adding below patch on top of you patch.
 
diff --git a/kernel/printk.c b/kernel/printk.c
index d370b74..f4d7352 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -982,6 +982,9 @@ static int __cpuinit console_cpu_notify(struct notifier_bloc
        switch (action) {
        case CPU_ONLINE:
        case CPU_UP_CANCELED:
+       case CPU_DEAD:
+       case CPU_DYING:
+       case CPU_DOWN_FAILED:
                if (try_acquire_console_sem() == 0)
                        release_console_sem();
        }



Regards
Santosh

RE: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Shilimkar, Santosh]

(Adding linux-pm@lists.linux-foundation.org)

> -----Original Message-----
> From: Shilimkar, Santosh
> Sent: Tuesday, June 29, 2010 2:22 PM
> To: 'Kevin Cernekee'
> Cc: linux-kernel@vger.kernel.org; Russell King - ARM Linux
> Subject: Additional fix : (was [v2]printk: fix delayed messages from CPU
> hotplug events)
> 
> Hi,
> 
> I have faced similar issue as what is being described in below with
> latest kernel.
> 
> ------------------------------------------------
> https://patchwork.kernel.org/patch/103347/
> 
> When a secondary CPU is being brought up, it is not uncommon for
> printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
> case that I witnessed personally was on MIPS:
> 
> http://lkml.org/lkml/2010/5/30/4
> 
> If (can_use_console() == 0), printk() will spool its output to log_buf
> and it will be visible in "dmesg", but that output will NOT be echoed to
> the console until somebody calls release_console_sem() from a CPU that
> is online.  Therefore, the boot time messages from the new CPU can get
> stuck in "limbo" for a long time, and might suddenly appear on the
> screen when a completely unrelated event (e.g. "eth0: link is down")
> occurs.
> 
> This patch modifies the console code so that any pending messages are
> automatically flushed out to the console whenever a CPU hotplug
> operation completes successfully or aborts.
> 
> -----------------------------------------------
> 
> Above patch fixes only half of the problem. I mean the cpu online
> path prints are coming on the console.
> 
> But similar problem also exist if there are prints in the cpu offline
> path. I got that fixed by adding below patch on top of you patch.
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index d370b74..f4d7352 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -982,6 +982,9 @@ static int __cpuinit console_cpu_notify(struct
> notifier_bloc
>         switch (action) {
>         case CPU_ONLINE:
>         case CPU_UP_CANCELED:
> +       case CPU_DEAD:
> +       case CPU_DYING:
> +       case CPU_DOWN_FAILED:
>                 if (try_acquire_console_sem() == 0)
>                         release_console_sem();
>         }
> 
> 
> 
> Regards
> Santosh

Re: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Andrew Morton]

On Tue, 29 Jun 2010 14:22:26 +0530
"Shilimkar, Santosh" <santosh.shilimkar@ti.com> wrote:

> Hi,
> 
> I have faced similar issue as what is being described in below with
> latest kernel.
> 
> ------------------------------------------------
> https://patchwork.kernel.org/patch/103347/
> 
> When a secondary CPU is being brought up, it is not uncommon for
> printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
> case that I witnessed personally was on MIPS:
> 
> http://lkml.org/lkml/2010/5/30/4
> 
> If (can_use_console() == 0), printk() will spool its output to log_buf
> and it will be visible in "dmesg", but that output will NOT be echoed to
> the console until somebody calls release_console_sem() from a CPU that
> is online.  Therefore, the boot time messages from the new CPU can get
> stuck in "limbo" for a long time, and might suddenly appear on the
> screen when a completely unrelated event (e.g. "eth0: link is down")
> occurs.
> 
> This patch modifies the console code so that any pending messages are
> automatically flushed out to the console whenever a CPU hotplug
> operation completes successfully or aborts.
> 
> -----------------------------------------------
> 
> Above patch fixes only half of the problem. I mean the cpu online
> path prints are coming on the console.
> 
> But similar problem also exist if there are prints in the cpu offline
> path. I got that fixed by adding below patch on top of you patch.
>  
> diff --git a/kernel/printk.c b/kernel/printk.c
> index d370b74..f4d7352 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -982,6 +982,9 @@ static int __cpuinit console_cpu_notify(struct notifier_bloc
>         switch (action) {
>         case CPU_ONLINE:
>         case CPU_UP_CANCELED:
> +       case CPU_DEAD:
> +       case CPU_DYING:
> +       case CPU_DOWN_FAILED:
>                 if (try_acquire_console_sem() == 0)
>                         release_console_sem();
>         }

The patch lacked a suitable title.  I called it "console: flush log
messages for more cpu-hotplug events".

The patch lacks a Signed-off-by:.  Please send one.

The patch has its tabs replaced with spaces.  I fixed that.  Please
reconfigure your email client for next time.

The code which is being patch has changed.  It now does

                acquire_console_sem();
                release_console_sem();

so the code may no longer work - perhaps it now deadlocks (unlikely). 
Please retest?

Finally, I don't understand the patch :( Who is sending out CPU_DEAD,
CPU_DYING or CPU_DOWN_FAILED events during kernel boot?  I'd have
thought that those events simply aren't occurring, and that the patch
has no effect.  Confused - please explain further.

RE: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Shilimkar, Santosh]

[-- Attachment #1: Type: text/plain, Size: 6577 bytes --]

Thanks Andrew for looking into this.
> -----Original Message-----
> From: Andrew Morton [mailto:akpm@linux-foundation.org]
> Sent: Tuesday, August 03, 2010 4:15 AM
> To: Shilimkar, Santosh
> Cc: Kevin Cernekee; linux-kernel@vger.kernel.org; Russell King - ARM Linux
> Subject: Re: Additional fix : (was [v2]printk: fix delayed messages from
> CPU hotplug events)
> 
> On Tue, 29 Jun 2010 14:22:26 +0530
> "Shilimkar, Santosh" <santosh.shilimkar@ti.com> wrote:
> 
> > Hi,
> >
> > I have faced similar issue as what is being described in below with
> > latest kernel.
> >
> > ------------------------------------------------
> > https://patchwork.kernel.org/patch/103347/
> >
> > When a secondary CPU is being brought up, it is not uncommon for
> > printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
> > case that I witnessed personally was on MIPS:
> >
> > http://lkml.org/lkml/2010/5/30/4
> >
> > If (can_use_console() == 0), printk() will spool its output to log_buf
> > and it will be visible in "dmesg", but that output will NOT be echoed to
> > the console until somebody calls release_console_sem() from a CPU that
> > is online.  Therefore, the boot time messages from the new CPU can get
> > stuck in "limbo" for a long time, and might suddenly appear on the
> > screen when a completely unrelated event (e.g. "eth0: link is down")
> > occurs.
> >
> > This patch modifies the console code so that any pending messages are
> > automatically flushed out to the console whenever a CPU hotplug
> > operation completes successfully or aborts.
> >
> > -----------------------------------------------
> >
> > Above patch fixes only half of the problem. I mean the cpu online
> > path prints are coming on the console.
> >
> > But similar problem also exist if there are prints in the cpu offline
> > path. I got that fixed by adding below patch on top of you patch.
> >
> > diff --git a/kernel/printk.c b/kernel/printk.c
> > index d370b74..f4d7352 100644
> > --- a/kernel/printk.c
> > +++ b/kernel/printk.c
> > @@ -982,6 +982,9 @@ static int __cpuinit console_cpu_notify(struct
> notifier_bloc
> >         switch (action) {
> >         case CPU_ONLINE:
> >         case CPU_UP_CANCELED:
> > +       case CPU_DEAD:
> > +       case CPU_DYING:
> > +       case CPU_DOWN_FAILED:
> >                 if (try_acquire_console_sem() == 0)
> >                         release_console_sem();
> >         }
> 
> The patch lacked a suitable title.  I called it "console: flush log
> messages for more cpu-hotplug events".
>
This diff was on top of already posted RFC patch. I will combine them

> The patch lacks a Signed-off-by:.  Please send one.
> 
> The patch has its tabs replaced with spaces.  I fixed that.  Please
> reconfigure your email client for next time.
> 
> The code which is being patch has changed.  It now does
> 
>                 acquire_console_sem();
>                 release_console_sem();
> 
> so the code may no longer work - perhaps it now deadlocks (unlikely).
> Please retest?
Retested. No deadlock observed
> 
> Finally, I don't understand the patch :( Who is sending out CPU_DEAD,
> CPU_DYING or CPU_DOWN_FAILED events during kernel boot?  I'd have
> thought that those events simply aren't occurring, and that the patch
> has no effect.  Confused - please explain further.
These events can come during the CPU hotplug(offline). Below is the
complete patch. Also attaching it in case some email format screw
up.

-----------------------------------------------
>From b99271ce43cc82cda28447444004933d0f218ee3 Mon Sep 17 00:00:00 2001
From: Santosh Shilimkar <santosh.shilimkar@ti.com>
Date: Tue, 3 Aug 2010 12:58:22 +0530
Subject: [PATCH] console: flush delayed log messages from cpu-hotplug events

When a secondary CPU is being brought up, it is not uncommon for
printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
case that I witnessed personally was on MIPS:

http://lkml.org/lkml/2010/5/30/4

If (can_use_console() == 0), printk() will spool its output to log_buf
and it will be visible in "dmesg", but that output will NOT be echoed to
the console until somebody calls release_console_sem() from a CPU that
is online.  Therefore, the boot time messages from the new CPU can get
stuck in "limbo" for a long time, and might suddenly appear on the
screen when a completely unrelated event (e.g. "eth0: link is down")
occurs.

This patch modifies the console code so that any pending messages are
automatically flushed out to the console whenever a CPU hotplug
operation completes successfully or aborts.
This is true even when CPU is getting hot-plugged out(offline) so
need to add additional hotplug events.

The issue was seen on 2.6.34.

Signed-off-by: Santosh Shilimkar <santosh.shilimkar@ti.com>
Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
---
 kernel/printk.c |   36 ++++++++++++++++++++++++++++++++++++
 1 files changed, 36 insertions(+), 0 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 444b770..a884d81 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -37,6 +37,8 @@
 #include <linux/ratelimit.h>
 #include <linux/kmsg_dump.h>
 #include <linux/syslog.h>
+#include <linux/cpu.h>
+#include <linux/notifier.h>
 
 #include <asm/uaccess.h>
 
@@ -985,6 +987,40 @@ void resume_console(void)
 }
 
 /**
+ * console_cpu_notify - print deferred console messages after CPU hotplug
+ *
+ * If printk() is called from a CPU that is not online yet, the messages
+ * will be spooled but will not show up on the console.  This function is
+ * called when a new CPU comes online and ensures that any such output
+ * gets printed.
+ */
+static int __cpuinit console_cpu_notify(struct notifier_block *self,
+	unsigned long action, void *hcpu)
+{
+	switch (action) {
+	case CPU_ONLINE:
+	case CPU_DEAD:
+	case CPU_DYING:
+	case CPU_DOWN_FAILED:
+	case CPU_UP_CANCELED:
+		if (try_acquire_console_sem() == 0)
+			release_console_sem();
+	}
+	return NOTIFY_OK;
+}
+
+static struct notifier_block __cpuinitdata console_nb = {
+	.notifier_call		= console_cpu_notify,
+};
+
+static int __init console_notifier_init(void)
+{
+	register_cpu_notifier(&console_nb);
+	return 0;
+}
+late_initcall(console_notifier_init);
+
+/**
  * acquire_console_sem - lock the console system for exclusive use.
  *
  * Acquires a semaphore which guarantees that the caller has
-- 
1.6.0.4
-----------------------------------------------



[-- Attachment #2: console-flush-delayed-log-messages-from-cpu-hotplug.patch --]
[-- Type: application/octet-stream, Size: 2844 bytes --]

From b99271ce43cc82cda28447444004933d0f218ee3 Mon Sep 17 00:00:00 2001
From: Santosh Shilimkar <santosh.shilimkar@ti.com>
Date: Tue, 3 Aug 2010 12:58:22 +0530
Subject: [PATCH] console: flush delayed log messages from cpu-hotplug events

When a secondary CPU is being brought up, it is not uncommon for
printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
case that I witnessed personally was on MIPS:

http://lkml.org/lkml/2010/5/30/4

If (can_use_console() == 0), printk() will spool its output to log_buf
and it will be visible in "dmesg", but that output will NOT be echoed to
the console until somebody calls release_console_sem() from a CPU that
is online.  Therefore, the boot time messages from the new CPU can get
stuck in "limbo" for a long time, and might suddenly appear on the
screen when a completely unrelated event (e.g. "eth0: link is down")
occurs.

This patch modifies the console code so that any pending messages are
automatically flushed out to the console whenever a CPU hotplug
operation completes successfully or aborts.
This is true even when CPU is getting hot-plugged out(offline) so
need to add additional hotplug events.

The issue was seen on 2.6.34.

Signed-off-by: Santosh Shilimkar <santosh.shilimkar@ti.com>
Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
---
 kernel/printk.c |   36 ++++++++++++++++++++++++++++++++++++
 1 files changed, 36 insertions(+), 0 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 444b770..a884d81 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -37,6 +37,8 @@
 #include <linux/ratelimit.h>
 #include <linux/kmsg_dump.h>
 #include <linux/syslog.h>
+#include <linux/cpu.h>
+#include <linux/notifier.h>
 
 #include <asm/uaccess.h>
 
@@ -985,6 +987,40 @@ void resume_console(void)
 }
 
 /**
+ * console_cpu_notify - print deferred console messages after CPU hotplug
+ *
+ * If printk() is called from a CPU that is not online yet, the messages
+ * will be spooled but will not show up on the console.  This function is
+ * called when a new CPU comes online and ensures that any such output
+ * gets printed.
+ */
+static int __cpuinit console_cpu_notify(struct notifier_block *self,
+	unsigned long action, void *hcpu)
+{
+	switch (action) {
+	case CPU_ONLINE:
+	case CPU_DEAD:
+	case CPU_DYING:
+	case CPU_DOWN_FAILED:
+	case CPU_UP_CANCELED:
+		if (try_acquire_console_sem() == 0)
+			release_console_sem();
+	}
+	return NOTIFY_OK;
+}
+
+static struct notifier_block __cpuinitdata console_nb = {
+	.notifier_call		= console_cpu_notify,
+};
+
+static int __init console_notifier_init(void)
+{
+	register_cpu_notifier(&console_nb);
+	return 0;
+}
+late_initcall(console_notifier_init);
+
+/**
  * acquire_console_sem - lock the console system for exclusive use.
  *
  * Acquires a semaphore which guarantees that the caller has
-- 
1.6.0.4

Re: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Randy Dunlap]

On Tue, 3 Aug 2010 13:03:25 +0530 Shilimkar, Santosh wrote:

> -----------------------------------------------
> From b99271ce43cc82cda28447444004933d0f218ee3 Mon Sep 17 00:00:00 2001
> From: Santosh Shilimkar <santosh.shilimkar@ti.com>
> Date: Tue, 3 Aug 2010 12:58:22 +0530
> Subject: [PATCH] console: flush delayed log messages from cpu-hotplug events
> 
> When a secondary CPU is being brought up, it is not uncommon for
> printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
> case that I witnessed personally was on MIPS:
> 
> http://lkml.org/lkml/2010/5/30/4
> 
> If (can_use_console() == 0), printk() will spool its output to log_buf
> and it will be visible in "dmesg", but that output will NOT be echoed to
> the console until somebody calls release_console_sem() from a CPU that
> is online.  Therefore, the boot time messages from the new CPU can get
> stuck in "limbo" for a long time, and might suddenly appear on the
> screen when a completely unrelated event (e.g. "eth0: link is down")
> occurs.
> 
> This patch modifies the console code so that any pending messages are
> automatically flushed out to the console whenever a CPU hotplug
> operation completes successfully or aborts.
> This is true even when CPU is getting hot-plugged out(offline) so
> need to add additional hotplug events.
> 
> The issue was seen on 2.6.34.
> 
> Signed-off-by: Santosh Shilimkar <santosh.shilimkar@ti.com>
> Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
> ---
>  kernel/printk.c |   36 ++++++++++++++++++++++++++++++++++++
>  1 files changed, 36 insertions(+), 0 deletions(-)
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index 444b770..a884d81 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -37,6 +37,8 @@
>  #include <linux/ratelimit.h>
>  #include <linux/kmsg_dump.h>
>  #include <linux/syslog.h>
> +#include <linux/cpu.h>
> +#include <linux/notifier.h>
>  
>  #include <asm/uaccess.h>
>  
> @@ -985,6 +987,40 @@ void resume_console(void)
>  }
>  
>  /**
> + * console_cpu_notify - print deferred console messages after CPU hotplug
> + *
> + * If printk() is called from a CPU that is not online yet, the messages
> + * will be spooled but will not show up on the console.  This function is
> + * called when a new CPU comes online and ensures that any such output
> + * gets printed.
> + */
> +static int __cpuinit console_cpu_notify(struct notifier_block *self,
> +	unsigned long action, void *hcpu)
> +{


kernel-doc notation should include function parameters also, please.

---
~Randy
*** Remember to use Documentation/SubmitChecklist when testing your code ***

RE: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Shilimkar, Santosh]

[-- Attachment #1: Type: text/plain, Size: 4163 bytes --]

> -----Original Message-----
> From: Randy Dunlap [mailto:rdunlap@xenotime.net]
> Sent: Tuesday, August 03, 2010 8:55 PM
> To: Shilimkar, Santosh
> Cc: Andrew Morton; Kevin Cernekee; linux-kernel@vger.kernel.org; Russell
> King - ARM Linux
> Subject: Re: Additional fix : (was [v2]printk: fix delayed messages from
> CPU hotplug events)
> 
> On Tue, 3 Aug 2010 13:03:25 +0530 Shilimkar, Santosh wrote:
> 

<snip>

> >  /**
> > + * console_cpu_notify - print deferred console messages after CPU
> hotplug
> > + *
> > + * If printk() is called from a CPU that is not online yet, the
> messages
> > + * will be spooled but will not show up on the console.  This function
> is
> > + * called when a new CPU comes online and ensures that any such output
> > + * gets printed.
> > + */
> > +static int __cpuinit console_cpu_notify(struct notifier_block *self,
> > +	unsigned long action, void *hcpu)
> > +{
> 
> 
> kernel-doc notation should include function parameters also, please.
> 
Sure. Here is an updated version.
--------------------------------------------
>From 127c0ea58982762ad194f22d1281baaf529c9cbc Mon Sep 17 00:00:00 2001
From: Santosh Shilimkar <santosh.shilimkar@ti.com>
Date: Tue, 3 Aug 2010 12:58:22 +0530
Subject: [PATCH v2] console: flush delayed log messages from cpu-hotplug events

When a secondary CPU is being brought up, it is not uncommon for
printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
case that I witnessed personally was on MIPS:

http://lkml.org/lkml/2010/5/30/4

If (can_use_console() == 0), printk() will spool its output to log_buf
and it will be visible in "dmesg", but that output will NOT be echoed to
the console until somebody calls release_console_sem() from a CPU that
is online.  Therefore, the boot time messages from the new CPU can get
stuck in "limbo" for a long time, and might suddenly appear on the
screen when a completely unrelated event (e.g. "eth0: link is down")
occurs.

This patch modifies the console code so that any pending messages are
automatically flushed out to the console whenever a CPU hotplug
operation completes successfully or aborts.
This is true even when CPU is getting hot-plugged out(offline) so
need to add additional hotplug events.

The issue was seen on 2.6.34.

Signed-off-by: Santosh Shilimkar <santosh.shilimkar@ti.com>
Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
---
 kernel/printk.c |   39 +++++++++++++++++++++++++++++++++++++++
 1 files changed, 39 insertions(+), 0 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 444b770..c145cef 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -37,6 +37,8 @@
 #include <linux/ratelimit.h>
 #include <linux/kmsg_dump.h>
 #include <linux/syslog.h>
+#include <linux/cpu.h>
+#include <linux/notifier.h>
 
 #include <asm/uaccess.h>
 
@@ -985,6 +987,43 @@ void resume_console(void)
 }
 
 /**
+ * console_cpu_notify - print deferred console messages after CPU hotplug
+ * @self: pointer to notfier block
+ * @action: cpu-hotplug events
+ * @hcpu: void poniter to pass any data
+ *
+ * If printk() is called from a CPU that is not online yet, the messages
+ * will be spooled but will not show up on the console.  This function is
+ * called when a new CPU comes online or goes offline and ensures that
+ * any such output gets printed.
+ */
+static int __cpuinit console_cpu_notify(struct notifier_block *self,
+	unsigned long action, void *hcpu)
+{
+	switch (action) {
+	case CPU_ONLINE:
+	case CPU_DEAD:
+	case CPU_DYING:
+	case CPU_DOWN_FAILED:
+	case CPU_UP_CANCELED:
+		if (try_acquire_console_sem() == 0)
+			release_console_sem();
+	}
+	return NOTIFY_OK;
+}
+
+static struct notifier_block __cpuinitdata console_nb = {
+	.notifier_call		= console_cpu_notify,
+};
+
+static int __init console_notifier_init(void)
+{
+	register_cpu_notifier(&console_nb);
+	return 0;
+}
+late_initcall(console_notifier_init);
+
+/**
  * acquire_console_sem - lock the console system for exclusive use.
  *
  * Acquires a semaphore which guarantees that the caller has
-- 
1.6.0.4


[-- Attachment #2: console-flush-delayed-log-messages-from-cpu-hotplug_v2.patch --]
[-- Type: application/octet-stream, Size: 2975 bytes --]

From 127c0ea58982762ad194f22d1281baaf529c9cbc Mon Sep 17 00:00:00 2001
From: Santosh Shilimkar <santosh.shilimkar@ti.com>
Date: Tue, 3 Aug 2010 12:58:22 +0530
Subject: [PATCH v2] console: flush delayed log messages from cpu-hotplug events

When a secondary CPU is being brought up, it is not uncommon for
printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
case that I witnessed personally was on MIPS:

http://lkml.org/lkml/2010/5/30/4

If (can_use_console() == 0), printk() will spool its output to log_buf
and it will be visible in "dmesg", but that output will NOT be echoed to
the console until somebody calls release_console_sem() from a CPU that
is online.  Therefore, the boot time messages from the new CPU can get
stuck in "limbo" for a long time, and might suddenly appear on the
screen when a completely unrelated event (e.g. "eth0: link is down")
occurs.

This patch modifies the console code so that any pending messages are
automatically flushed out to the console whenever a CPU hotplug
operation completes successfully or aborts.
This is true even when CPU is getting hot-plugged out(offline) so
need to add additional hotplug events.

The issue was seen on 2.6.34.

Signed-off-by: Santosh Shilimkar <santosh.shilimkar@ti.com>
Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
---
 kernel/printk.c |   39 +++++++++++++++++++++++++++++++++++++++
 1 files changed, 39 insertions(+), 0 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 444b770..c145cef 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -37,6 +37,8 @@
 #include <linux/ratelimit.h>
 #include <linux/kmsg_dump.h>
 #include <linux/syslog.h>
+#include <linux/cpu.h>
+#include <linux/notifier.h>
 
 #include <asm/uaccess.h>
 
@@ -985,6 +987,43 @@ void resume_console(void)
 }
 
 /**
+ * console_cpu_notify - print deferred console messages after CPU hotplug
+ * @self: pointer to notfier block
+ * @action: cpu-hotplug events
+ * @hcpu: void poniter to pass any data
+ *
+ * If printk() is called from a CPU that is not online yet, the messages
+ * will be spooled but will not show up on the console.  This function is
+ * called when a new CPU comes online or goes offline and ensures that
+ * any such output gets printed.
+ */
+static int __cpuinit console_cpu_notify(struct notifier_block *self,
+	unsigned long action, void *hcpu)
+{
+	switch (action) {
+	case CPU_ONLINE:
+	case CPU_DEAD:
+	case CPU_DYING:
+	case CPU_DOWN_FAILED:
+	case CPU_UP_CANCELED:
+		if (try_acquire_console_sem() == 0)
+			release_console_sem();
+	}
+	return NOTIFY_OK;
+}
+
+static struct notifier_block __cpuinitdata console_nb = {
+	.notifier_call		= console_cpu_notify,
+};
+
+static int __init console_notifier_init(void)
+{
+	register_cpu_notifier(&console_nb);
+	return 0;
+}
+late_initcall(console_notifier_init);
+
+/**
  * acquire_console_sem - lock the console system for exclusive use.
  *
  * Acquires a semaphore which guarantees that the caller has
-- 
1.6.0.4

Re: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Andrew Morton]

On Tue, 3 Aug 2010 13:03:25 +0530
"Shilimkar, Santosh" <santosh.shilimkar@ti.com> wrote:

> > thought that those events simply aren't occurring, and that the patch
> > has no effect.  Confused - please explain further.
> These events can come during the CPU hotplug(offline). Below is the
> complete patch. Also attaching it in case some email format screw
> up.
> 
> -----------------------------------------------
> >From b99271ce43cc82cda28447444004933d0f218ee3 Mon Sep 17 00:00:00 2001
> From: Santosh Shilimkar <santosh.shilimkar@ti.com>
> Date: Tue, 3 Aug 2010 12:58:22 +0530
> Subject: [PATCH] console: flush delayed log messages from cpu-hotplug events
> 
> When a secondary CPU is being brought up, it is not uncommon for
> printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
> case that I witnessed personally was on MIPS:
> 
> http://lkml.org/lkml/2010/5/30/4
> 
> If (can_use_console() == 0), printk() will spool its output to log_buf
> and it will be visible in "dmesg", but that output will NOT be echoed to
> the console until somebody calls release_console_sem() from a CPU that
> is online.  Therefore, the boot time messages from the new CPU can get
> stuck in "limbo" for a long time, and might suddenly appear on the
> screen when a completely unrelated event (e.g. "eth0: link is down")
> occurs.
> 
> This patch modifies the console code so that any pending messages are
> automatically flushed out to the console whenever a CPU hotplug
> operation completes successfully or aborts.
> This is true even when CPU is getting hot-plugged out(offline) so
> need to add additional hotplug events.
> 
> The issue was seen on 2.6.34.
> 
> Signed-off-by: Santosh Shilimkar <santosh.shilimkar@ti.com>
> Signed-off-by: Kevin Cernekee <cernekee@gmail.com>

An older version of this patch is present in linux-next, committed by
Paul Mundt, who wasn't cc'ed here(!).

Paul, please update.  Be aware that the version of the patch to which I
replied is also not the latest.

Re: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Paul Mundt]

On Tue, Aug 03, 2010 at 04:59:26PM -0700, Andrew Morton wrote:
> On Tue, 3 Aug 2010 13:03:25 +0530
> "Shilimkar, Santosh" <santosh.shilimkar@ti.com> wrote:
> 
> > > thought that those events simply aren't occurring, and that the patch
> > > has no effect.  Confused - please explain further.
> > These events can come during the CPU hotplug(offline). Below is the
> > complete patch. Also attaching it in case some email format screw
> > up.
> > 
> > -----------------------------------------------
> > >From b99271ce43cc82cda28447444004933d0f218ee3 Mon Sep 17 00:00:00 2001
> > From: Santosh Shilimkar <santosh.shilimkar@ti.com>
> > Date: Tue, 3 Aug 2010 12:58:22 +0530
> > Subject: [PATCH] console: flush delayed log messages from cpu-hotplug events
> > 
> > When a secondary CPU is being brought up, it is not uncommon for
> > printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
> > case that I witnessed personally was on MIPS:
> > 
> > http://lkml.org/lkml/2010/5/30/4
> > 
> > If (can_use_console() == 0), printk() will spool its output to log_buf
> > and it will be visible in "dmesg", but that output will NOT be echoed to
> > the console until somebody calls release_console_sem() from a CPU that
> > is online.  Therefore, the boot time messages from the new CPU can get
> > stuck in "limbo" for a long time, and might suddenly appear on the
> > screen when a completely unrelated event (e.g. "eth0: link is down")
> > occurs.
> > 
> > This patch modifies the console code so that any pending messages are
> > automatically flushed out to the console whenever a CPU hotplug
> > operation completes successfully or aborts.
> > This is true even when CPU is getting hot-plugged out(offline) so
> > need to add additional hotplug events.
> > 
> > The issue was seen on 2.6.34.
> > 
> > Signed-off-by: Santosh Shilimkar <santosh.shilimkar@ti.com>
> > Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
> 
> An older version of this patch is present in linux-next, committed by
> Paul Mundt, who wasn't cc'ed here(!).
> 
> Paul, please update.  Be aware that the version of the patch to which I
> replied is also not the latest.
> 
I just reviewed it, it went in through the MIPS tree if memory serves
correctly, so Ralf (added to Cc) would have been the one that checked it
in. I'll take a look at the thread though.

Re: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Ralf Baechle]

On Wed, Aug 04, 2010 at 12:30:34PM +0900, Paul Mundt wrote:

> > An older version of this patch is present in linux-next, committed by
> > Paul Mundt, who wasn't cc'ed here(!).
> > 
> > Paul, please update.  Be aware that the version of the patch to which I
> > replied is also not the latest.
> > 
> I just reviewed it, it went in through the MIPS tree if memory serves
> correctly, so Ralf (added to Cc) would have been the one that checked it
> in. I'll take a look at the thread though.

Authored by Kevin Cernekee and committed by me.  No idea where akpm found
Paul's name.

commit 4251bce66898298b03824b7d94ce94c431404b54
Author:     Kevin Cernekee <cernekee@gmail.com>
AuthorDate: Thu Jun 3 22:11:25 2010 -0700
Commit:     Ralf Baechle <ralf@linux-mips.org>
CommitDate: Mon Aug 2 14:00:10 2010 +0100

Will update the patch.

  Ralf

Re: Additional fix : (was [v2]printk: fix delayed messages from CPU hotplug events)

[Ralf Baechle]

Santosh's patch was lacking akpm's cleanup patch.  So I created the
following from all contributions.

  Ralf

>From 040f52ce2a3cab374bfed036ccd8ecf4b1fb7add Mon Sep 17 00:00:00 2001
From: Kevin Cernekee <cernekee@gmail.com>
Date: Thu, 3 Jun 2010 22:11:25 -0700
Subject: [PATCH] printk: fix delayed messages from CPU hotplug events

When a secondary CPU is being brought up, it is not uncommon for
printk() to be invoked when cpu_online(smp_processor_id()) == 0.  The
case that I witnessed personally was on MIPS:

http://lkml.org/lkml/2010/5/30/4

If (can_use_console() == 0), printk() will spool its output to log_buf
and it will be visible in "dmesg", but that output will NOT be echoed to
the console until somebody calls release_console_sem() from a CPU that
is online.  Therefore, the boot time messages from the new CPU can get
stuck in "limbo" for a long time, and might suddenly appear on the
screen when a completely unrelated event (e.g. "eth0: link is down")
occurs.

This patch modifies the console code so that any pending messages are
automatically flushed out to the console whenever a CPU hotplug
operation completes successfully or aborts.

The issue was seen on 2.6.34.

Original patch by Kevin Cernekee with cleanups by akpm and additional fixes
by Santosh Shilimkar.  This patch superseeds
https://patchwork.linux-mips.org/patch/1357/.

Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
To: <mingo@elte.hu>
To: <akpm@linux-foundation.org>
To: <simon.kagstrom@netinsight.net>
To: <David.Woodhouse@intel.com>
To: <lethal@linux-sh.org>
Cc: <linux-kernel@vger.kernel.org>
Cc: <linux-mips@linux-mips.org>
Reviewed-by: Paul Mundt <lethal@linux-sh.org>
Signed-off-by: Kevin Cernekee <cernekee@gmail.com>
Patchwork: https://patchwork.linux-mips.org/patch/1533/
LKML-Reference: <ede63b5a20af951c755736f035d1e787772d7c28@localhost>
LKML-Reference: <EAF47CD23C76F840A9E7FCE10091EFAB02C5DB6D1F@dbde02.ent.ti.com>
Signed-off-by: Ralf Baechle <ralf@linux-mips.org>

diff --git a/kernel/printk.c b/kernel/printk.c
index 444b770..4ab0164 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -37,6 +37,8 @@
 #include <linux/ratelimit.h>
 #include <linux/kmsg_dump.h>
 #include <linux/syslog.h>
+#include <linux/cpu.h>
+#include <linux/notifier.h>
 
 #include <asm/uaccess.h>
 
@@ -985,6 +987,32 @@ void resume_console(void)
 }
 
 /**
+ * console_cpu_notify - print deferred console messages after CPU hotplug
+ * @self: notifier struct
+ * @action: CPU hotplug event
+ * @hcpu: unused
+ *
+ * If printk() is called from a CPU that is not online yet, the messages
+ * will be spooled but will not show up on the console.  This function is
+ * called when a new CPU comes online (or fails to come up), and ensures
+ * that any such output gets printed.
+ */
+static int __cpuinit console_cpu_notify(struct notifier_block *self,
+	unsigned long action, void *hcpu)
+{
+	switch (action) {
+	case CPU_ONLINE:
+	case CPU_DEAD:
+	case CPU_DYING:
+	case CPU_DOWN_FAILED:
+	case CPU_UP_CANCELED:
+		acquire_console_sem();
+		release_console_sem();
+	}
+	return NOTIFY_OK;
+}
+
+/**
  * acquire_console_sem - lock the console system for exclusive use.
  *
  * Acquires a semaphore which guarantees that the caller has
@@ -1371,7 +1399,7 @@ int unregister_console(struct console *console)
 }
 EXPORT_SYMBOL(unregister_console);
 
-static int __init disable_boot_consoles(void)
+static int __init printk_late_init(void)
 {
 	struct console *con;
 
@@ -1382,9 +1410,10 @@ static int __init disable_boot_consoles(void)
 			unregister_console(con);
 		}
 	}
+	hotcpu_notifier(console_cpu_notify, 0);
 	return 0;
 }
-late_initcall(disable_boot_consoles);
+late_initcall(printk_late_init);
 
 #if defined CONFIG_PRINTK