[PATCH] ARM: smp: Remove CPU: shutdown notice

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Florian Fainelli]

This message is not particularly informative, and is not paired with an
identical message when a CPU is brought online. Finally, it slows the
CPU hotplug path down, thus allowing less CPU hotplug operations per
second. Just remove it.

Signed-off-by: Florian Fainelli <f.fainelli@gmail.com>
---
 arch/arm/kernel/smp.c | 1 -
 1 file changed, 1 deletion(-)

diff --git a/arch/arm/kernel/smp.c b/arch/arm/kernel/smp.c
index 7dd14e8395e6..b3e02751ab64 100644
--- a/arch/arm/kernel/smp.c
+++ b/arch/arm/kernel/smp.c
@@ -251,7 +251,6 @@ void __cpu_die(unsigned int cpu)
 		pr_err("CPU%u: cpu didn't die\n", cpu);
 		return;
 	}
-	pr_notice("CPU%u: shutdown\n", cpu);
 
 	/*
 	 * platform_cpu_kill() is generally expected to do the powering off
-- 
2.9.3

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Russell King - ARM Linux]

On Tue, Jan 17, 2017 at 03:07:12PM -0800, Florian Fainelli wrote:
> This message is not particularly informative, and is not paired with an
> identical message when a CPU is brought online. Finally, it slows the
> CPU hotplug path down, thus allowing less CPU hotplug operations per
> second. Just remove it.

CPU hotplug isn't a fast operation anyway - it's also fairly disruptive
in that it uses stop_machine() to halt activity everywhere while taking
the CPU offline.

If you're worried about a single printk slowing things down, it sounds
like you're doing something wrong here - maybe you should be using
cpuidle for power management rather than trying to make CPU hotplug do
that for you?

A rapidly changing CPU hotplug state has other side effects - such as
reading /proc/interrupts is meaningless, because as soon as you've read
it the CPUs could have changed.  It also makes a farce of spreading
interrupts over the available CPUs.

All in all, I don't think this is a good idea...

-- 
RMK's Patch system: http://www.armlinux.org.uk/developer/patches/
FTTC broadband for 0.8mile line: currently at 9.6Mbps down 400kbps up
according to speedtest.net.

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Florian Fainelli]

On 01/17/2017 03:23 PM, Russell King - ARM Linux wrote:
> On Tue, Jan 17, 2017 at 03:07:12PM -0800, Florian Fainelli wrote:
>> This message is not particularly informative, and is not paired with an
>> identical message when a CPU is brought online. Finally, it slows the
>> CPU hotplug path down, thus allowing less CPU hotplug operations per
>> second. Just remove it.
> 
> CPU hotplug isn't a fast operation anyway - it's also fairly disruptive
> in that it uses stop_machine() to halt activity everywhere while taking
> the CPU offline.

We have a test that consists in shutting down all CPUs as frequently as
we can and do this for about 2 million iterations which takes roughly
24h, and this printk slows thing down by a reasonable amount. Here are
some numbers on 500 hotplug operations:

w/ printk:
real    0m9.997s
user    0m0.725s
sys     0m3.030s
#

w/o printk:
real    0m8.547s
user    0m0.436s
sys     0m1.838s

> 
> If you're worried about a single printk slowing things down, it sounds
> like you're doing something wrong here - maybe you should be using
> cpuidle for power management rather than trying to make CPU hotplug do
> that for you?

No, this is not about power management considerations here, just how
fast we can bang it.

> 
> A rapidly changing CPU hotplug state has other side effects - such as
> reading /proc/interrupts is meaningless, because as soon as you've read
> it the CPUs could have changed.  It also makes a farce of spreading
> interrupts over the available CPUs.
> 
> All in all, I don't think this is a good idea...

Well, for one it's inconsistent, and it also leaves room for subtle
timing/caching issues with some platforms (OK, maybe not so much).
Improving the speed and consistency was the primary motive.
-- 
Florian

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Petr Mladek]

On Tue 2017-01-17 15:39:45, Florian Fainelli wrote:
> On 01/17/2017 03:23 PM, Russell King - ARM Linux wrote:
> > On Tue, Jan 17, 2017 at 03:07:12PM -0800, Florian Fainelli wrote:
> >> This message is not particularly informative, and is not paired with an
> >> identical message when a CPU is brought online. Finally, it slows the
> >> CPU hotplug path down, thus allowing less CPU hotplug operations per
> >> second. Just remove it.
> > 
> > CPU hotplug isn't a fast operation anyway - it's also fairly disruptive
> > in that it uses stop_machine() to halt activity everywhere while taking
> > the CPU offline.
> 
> We have a test that consists in shutting down all CPUs as frequently as
> we can and do this for about 2 million iterations which takes roughly
> 24h, and this printk slows thing down by a reasonable amount. Here are
> some numbers on 500 hotplug operations:
> 
> w/ printk:
> real    0m9.997s
> user    0m0.725s
> sys     0m3.030s
> #
> 
> w/o printk:
> real    0m8.547s
> user    0m0.436s
> sys     0m1.838s

I am curious that a single printk() might make such a big difference.

One reason might be that the messages are pushed to a "slow" console.

Another reason might be that there are many other messages printed
on the system and there is a contention on logbuf_lock or other
console related locks.

There might be also the opposite problem. The messages are also read
by userspace tools that store them into /var/log/messages or systemd
logs. If these are the only messages printed to the log and if there
is no other activity on the system. Then the waken loggers might make
a difference, especially if all CPUs are getting disabled and only
one is available at some point.

Well, I am not sure what other operations are needed to do the
CPU hotplug operation.

I cannot judge how the message is useful and if the speed up
is worth removing it.

Best Regards,
Petr

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Florian Fainelli]

On 01/18/2017 01:55 AM, Petr Mladek wrote:
> On Tue 2017-01-17 15:39:45, Florian Fainelli wrote:
>> On 01/17/2017 03:23 PM, Russell King - ARM Linux wrote:
>>> On Tue, Jan 17, 2017 at 03:07:12PM -0800, Florian Fainelli wrote:
>>>> This message is not particularly informative, and is not paired with an
>>>> identical message when a CPU is brought online. Finally, it slows the
>>>> CPU hotplug path down, thus allowing less CPU hotplug operations per
>>>> second. Just remove it.
>>>
>>> CPU hotplug isn't a fast operation anyway - it's also fairly disruptive
>>> in that it uses stop_machine() to halt activity everywhere while taking
>>> the CPU offline.
>>
>> We have a test that consists in shutting down all CPUs as frequently as
>> we can and do this for about 2 million iterations which takes roughly
>> 24h, and this printk slows thing down by a reasonable amount. Here are
>> some numbers on 500 hotplug operations:
>>
>> w/ printk:
>> real    0m9.997s
>> user    0m0.725s
>> sys     0m3.030s
>> #
>>
>> w/o printk:
>> real    0m8.547s
>> user    0m0.436s
>> sys     0m1.838s
> 
> I am curious that a single printk() might make such a big difference.

It does, because of how printk() is implemented (there is nothing wrong
with it, just slow by nature and how the UART gets written to as well).

> 
> One reason might be that the messages are pushed to a "slow" console.

115200 UART, yes that's slow, but not unusual.

> 
> Another reason might be that there are many other messages printed
> on the system and there is a contention on logbuf_lock or other
> console related locks.

The other messages being printed are those from the hotplug script that
I run which just checkpoints its running every 50 instances, so it does
not occur that often, the console really is not busy, which really
extracts the overhead of printing "CPU: shutdown".

> 
> There might be also the opposite problem. The messages are also read
> by userspace tools that store them into /var/log/messages or systemd
> logs. If these are the only messages printed to the log and if there
> is no other activity on the system. Then the waken loggers might make
> a difference, especially if all CPUs are getting disabled and only
> one is available at some point.

There is none of that, no systemd, no syslog, just minimal userspace
running.

> 
> Well, I am not sure what other operations are needed to do the
> CPU hotplug operation.
> 
> I cannot judge how the message is useful and if the speed up
> is worth removing it.
> 
> Best Regards,
> Petr
> 


-- 
Florian

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Sergey Senozhatsky]

On (01/18/17 11:56), Florian Fainelli wrote:
[..]
> >>> CPU hotplug isn't a fast operation anyway - it's also fairly disruptive
> >>> in that it uses stop_machine() to halt activity everywhere while taking
> >>> the CPU offline.
> >>
> >> We have a test that consists in shutting down all CPUs as frequently as
> >> we can and do this for about 2 million iterations which takes roughly
> >> 24h, and this printk slows thing down by a reasonable amount. Here are
> >> some numbers on 500 hotplug operations:
> >>
> >> w/ printk:
> >> real    0m9.997s
> >> user    0m0.725s
> >> sys     0m3.030s
> >> #
> >>
> >> w/o printk:
> >> real    0m8.547s
> >> user    0m0.436s
> >> sys     0m1.838s
> > 
> > I am curious that a single printk() might make such a big difference.
> 
> It does, because of how printk() is implemented (there is nothing wrong
> with it, just slow by nature and how the UART gets written to as well).
> 
> > 
> > One reason might be that the messages are pushed to a "slow" console.
> 
> 115200 UART, yes that's slow, but not unusual.
> 
> > 
> > Another reason might be that there are many other messages printed
> > on the system and there is a contention on logbuf_lock or other
> > console related locks.
> 
> The other messages being printed are those from the hotplug script that
> I run which just checkpoints its running every 50 instances, so it does
> not occur that often, the console really is not busy, which really
> extracts the overhead of printing "CPU: shutdown".

there is also console_cpu_notify(), which basically serializes all
CPU hotplug events. and that's a sleepable console_lock(), followed
by a potentially long console_unlock(). for hotplug each notification.

static int console_cpu_notify(unsigned int cpu)
{
        if (!cpuhp_tasks_frozen) {
                console_lock();
                console_unlock();
        }
        return 0;
}




out of curiosity, does the change below improve anything in your test?

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7180088cbb23..72e86e06c4e4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2035,8 +2035,9 @@ void resume_console(void)
 static int console_cpu_notify(unsigned int cpu)
 {
        if (!cpuhp_tasks_frozen) {
-               console_lock();
-               console_unlock();
+               /* If trylock fails, someone else is doing the printing */
+               if (console_trylock())
+                       console_unlock();
        }
        return 0;
 }

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Russell King - ARM Linux]

On Tue, Jan 17, 2017 at 03:39:45PM -0800, Florian Fainelli wrote:
> Well, for one it's inconsistent, and it also leaves room for subtle
> timing/caching issues with some platforms (OK, maybe not so much).
> Improving the speed and consistency was the primary motive.

Actually, it's not as inconsistent as you claim.

c68b0274fb3c ("ARM: reduce "Booted secondary processor" message to debug level")
dropped the corresponding pr_info() in the bringup path to debug level,
so to be consistent, this one should be dropped to debug level too.

Removing it arguably makes it more inconsistent!

So, I'd be willing to accept a patch lowering this to a pr_debug()
to make it more consistent with the bringup path, but otherwise the
consistency argument doesn't really stand.

-- 
RMK's Patch system: http://www.armlinux.org.uk/developer/patches/
FTTC broadband for 0.8mile line: currently at 9.6Mbps down 400kbps up
according to speedtest.net.

[PATCH] ARM: smp: Remove CPU: shutdown notice

[Florian Fainelli]

On 01/18/2017 02:39 PM, Russell King - ARM Linux wrote:
> On Tue, Jan 17, 2017 at 03:39:45PM -0800, Florian Fainelli wrote:
>> Well, for one it's inconsistent, and it also leaves room for subtle
>> timing/caching issues with some platforms (OK, maybe not so much).
>> Improving the speed and consistency was the primary motive.
> 
> Actually, it's not as inconsistent as you claim.
> 
> c68b0274fb3c ("ARM: reduce "Booted secondary processor" message to debug level")
> dropped the corresponding pr_info() in the bringup path to debug level,
> so to be consistent, this one should be dropped to debug level too.
> 
> Removing it arguably makes it more inconsistent!

OK, fair point, I missed that one.

> 
> So, I'd be willing to accept a patch lowering this to a pr_debug()
> to make it more consistent with the bringup path, but otherwise the
> consistency argument doesn't really stand.

Sounds good, thanks!
-- 
Florian

[PATCH] ARM: Reduce "CPU: shutdown" message to debug level

[Florian Fainelli]

Similar to c68b0274fb3c ("ARM: reduce "Booted secondary processor"
message to debug level"), demote the "CPU: shutdown" pr_notice() into a
pr_debug().

Signed-off-by: Florian Fainelli <f.fainelli@gmail.com>
---
 arch/arm/kernel/smp.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/arch/arm/kernel/smp.c b/arch/arm/kernel/smp.c
index 7dd14e8395e6..46377c40d056 100644
--- a/arch/arm/kernel/smp.c
+++ b/arch/arm/kernel/smp.c
@@ -251,7 +251,7 @@ void __cpu_die(unsigned int cpu)
 		pr_err("CPU%u: cpu didn't die\n", cpu);
 		return;
 	}
-	pr_notice("CPU%u: shutdown\n", cpu);
+	pr_debug("CPU%u: shutdown\n", cpu);
 
 	/*
 	 * platform_cpu_kill() is generally expected to do the powering off
-- 
2.9.3

[PATCH] ARM: Reduce "CPU: shutdown" message to debug level

[Russell King - ARM Linux]

On Wed, Jan 18, 2017 at 02:53:26PM -0800, Florian Fainelli wrote:
> Similar to c68b0274fb3c ("ARM: reduce "Booted secondary processor"
> message to debug level"), demote the "CPU: shutdown" pr_notice() into a
> pr_debug().

Much better, and thanks for dropping the "performance" argument as well.
CPU hotplug isn't about performance :)

Please put this in the patch system, thanks.

-- 
RMK's Patch system: http://www.armlinux.org.uk/developer/patches/
FTTC broadband for 0.8mile line: currently at 9.6Mbps down 400kbps up
according to speedtest.net.

[PATCH] ARM: Reduce "CPU: shutdown" message to debug level

[Florian Fainelli]

On 01/18/2017 03:20 PM, Russell King - ARM Linux wrote:
> On Wed, Jan 18, 2017 at 02:53:26PM -0800, Florian Fainelli wrote:
>> Similar to c68b0274fb3c ("ARM: reduce "Booted secondary processor"
>> message to debug level"), demote the "CPU: shutdown" pr_notice() into a
>> pr_debug().
> 
> Much better, and thanks for dropping the "performance" argument as well.
> CPU hotplug isn't about performance :)
> 
> Please put this in the patch system, thanks.

Done, #8644, thanks!
-- 
Florian