2010-06-04 05:16:06

by Kevin Cernekee

[permalink] [raw]
Subject: [PATCH v3] printk: fix delayed messages from CPU hotplug events

[Changes from v2:

Use hotcpu_notifier - fix will only apply to hotplug events, not
initial SMP boot

Kerneldocify function arguments

Use acquire_console_sem() instead of try_acquire_console_sem()

Reuse the existing disable_boot_consoles() initcall instead of making a
new one]

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.

Signed-off-by: Kevin Cernekee <[email protected]>
---
kernel/printk.c | 34 ++++++++++++++++++++++++++++++++--
1 files changed, 32 insertions(+), 2 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 444b770..1748519 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,33 @@ 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_UP_CANCELED:
+ acquire_console_sem();
+ release_console_sem();
+ }
+ return NOTIFY_OK;
+}
+
+static struct notifier_block __cpuinitdata console_nb = {
+ .notifier_call = console_cpu_notify,
+};
+
+/**
* acquire_console_sem - lock the console system for exclusive use.
*
* Acquires a semaphore which guarantees that the caller has
@@ -1371,7 +1400,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 +1411,10 @@ static int __init disable_boot_consoles(void)
unregister_console(con);
}
}
+ register_hotcpu_notifier(&console_nb);
return 0;
}
-late_initcall(disable_boot_consoles);
+late_initcall(printk_late_init);

#if defined CONFIG_PRINTK

--
1.7.0.4


2010-06-04 05:20:46

by Paul Mundt

[permalink] [raw]
Subject: Re: [PATCH v3] printk: fix delayed messages from CPU hotplug events

On Thu, Jun 03, 2010 at 10:11:25PM -0700, Kevin Cernekee wrote:
> [Changes from v2:
>
> Use hotcpu_notifier - fix will only apply to hotplug events, not
> initial SMP boot
>
With the hotcpu notifier it looks good to me.

Reviewed-by: Paul Mundt <[email protected]>

2010-06-04 05:59:28

by Andrew Morton

[permalink] [raw]
Subject: Re: [PATCH v3] printk: fix delayed messages from CPU hotplug events

On Thu, 3 Jun 2010 22:11:25 -0700 Kevin Cernekee <[email protected]> wrote:

> [Changes from v2:
>
> Use hotcpu_notifier - fix will only apply to hotplug events, not
> initial SMP boot
>
> Kerneldocify function arguments
>
> Use acquire_console_sem() instead of try_acquire_console_sem()
>
> Reuse the existing disable_boot_consoles() initcall instead of making a
> new one]
>
> 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.
>
> ...
>
> +static int __cpuinit console_cpu_notify(struct notifier_block *self,
> + unsigned long action, void *hcpu)
> +{
> + switch (action) {
> + case CPU_ONLINE:
> + case CPU_UP_CANCELED:
> + acquire_console_sem();
> + release_console_sem();
> + }
> + return NOTIFY_OK;
> +}
> +
> +static struct notifier_block __cpuinitdata console_nb = {
> + .notifier_call = console_cpu_notify,
> +};
> +
> +/**
> * acquire_console_sem - lock the console system for exclusive use.
> *
> * Acquires a semaphore which guarantees that the caller has
> @@ -1371,7 +1400,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 +1411,10 @@ static int __init disable_boot_consoles(void)
> unregister_console(con);
> }
> }
> + register_hotcpu_notifier(&console_nb);

gack, we seem to have made these interfaces as hard to use and as documentation-free
as we possibly could :(

This:

--- a/kernel/printk.c~printk-fix-delayed-messages-from-cpu-hotplug-events-fix
+++ a/kernel/printk.c
@@ -1009,10 +1009,6 @@ static int __cpuinit console_cpu_notify(
return NOTIFY_OK;
}

-static struct notifier_block __cpuinitdata console_nb = {
- .notifier_call = console_cpu_notify,
-};
-
/**
* acquire_console_sem - lock the console system for exclusive use.
*
@@ -1411,7 +1407,7 @@ static int __init printk_late_init(void)
unregister_console(con);
}
}
- register_hotcpu_notifier(&console_nb);
+ hotcpu_notifier(console_cpu_notify, 0);
return 0;
}
late_initcall(printk_late_init);


There are numerous other register_hotcpu_notifier() callsites which can
probably be converted.

2010-06-06 01:31:13

by Ralf Baechle

[permalink] [raw]
Subject: Re: [PATCH v3] printk: fix delayed messages from CPU hotplug events

On Thu, Jun 03, 2010 at 10:58:24PM -0700, Andrew Morton wrote:

Assuming everybody is happy now I've merged Andrew's patch into Kevin's
patch and dropped it into the linux-queue tree and my tree for -next.
If nobody objects I intend to send the patch to Linus in about a week
or so.

Andrew, your patch had no Signed-off-by ;-)

Thanks everbody,

Ralf