* Re: [PATCH] arm64: Demote boot and shutdown messages to pr_debug
2019-05-01 10:47 ` Mark Rutland
@ 2019-05-01 11:01 ` Marc Zyngier
2019-05-01 11:02 ` Robin Murphy
2019-05-01 16:07 ` Florian Fainelli
2 siblings, 0 replies; 6+ messages in thread
From: Marc Zyngier @ 2019-05-01 11:01 UTC (permalink / raw)
To: Mark Rutland, Florian Fainelli
Cc: linux-arm-kernel, rmk+kernel, Catalin Marinas, Will Deacon,
Ard Biesheuvel, Julien Thierry, Suzuki K Poulose, Sudeep Holla,
Rob Herring, Steve Capper, Lorenzo Pieralisi, Daniel Thompson,
open list
On 01/05/2019 11:47, Mark Rutland wrote:
> On Tue, Apr 30, 2019 at 03:38:31PM -0700, Florian Fainelli wrote:
>> Similar to commits c68b0274fb3cf ("ARM: reduce "Booted secondary
>> processor" message to debug level") and 035e787543de7 ("ARM: 8644/1: Reduce "CPU:
>> shutdown" message to debug level"), demote the secondary_start_kernel()
>> and __cpu_die() messages from info, respectively notice to debug. While
>> we are at it, also do this for cpu_psci_cpu_kill() which is redundant
>> with __cpu_die().
>>
>> This helps improve the amount of possible hotplug cycles by around +50%
>> on ARCH_BRCMSTB.
>
> Could you elaborate on why that matters?
>
> e.g. is this just for testing, or does this matter in some shutdown or
> hibernate scenario?
>
>> Signed-off-by: Florian Fainelli <f.fainelli@gmail.com>
>> ---
>> arch/arm64/kernel/psci.c | 2 +-
>> arch/arm64/kernel/smp.c | 4 ++--
>> 2 files changed, 3 insertions(+), 3 deletions(-)
>>
>> diff --git a/arch/arm64/kernel/psci.c b/arch/arm64/kernel/psci.c
>> index 8cdaf25e99cd..a78581046c80 100644
>> --- a/arch/arm64/kernel/psci.c
>> +++ b/arch/arm64/kernel/psci.c
>> @@ -96,7 +96,7 @@ static int cpu_psci_cpu_kill(unsigned int cpu)
>> for (i = 0; i < 10; i++) {
>> err = psci_ops.affinity_info(cpu_logical_map(cpu), 0);
>> if (err == PSCI_0_2_AFFINITY_LEVEL_OFF) {
>> - pr_info("CPU%d killed.\n", cpu);
>> + pr_debug("CPU%d killed.\n", cpu);
>> return 0;
>> }
>>
>> diff --git a/arch/arm64/kernel/smp.c b/arch/arm64/kernel/smp.c
>> index 824de7038967..71fd2b5a3f0e 100644
>> --- a/arch/arm64/kernel/smp.c
>> +++ b/arch/arm64/kernel/smp.c
>> @@ -259,7 +259,7 @@ asmlinkage notrace void secondary_start_kernel(void)
>> * the CPU migration code to notice that the CPU is online
>> * before we continue.
>> */
>> - pr_info("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>> + pr_debug("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>> cpu, (unsigned long)mpidr,
>> read_cpuid_id());
>
> I generally agree that we don't need to be verbose, and demoting these
> to debug is fine, but it's a shame that these won't be accessible in
> defconfig.
>
> I wonder if we should enable DYNAMIC_DEBUG so that we can turn these on
> from the kernel command line, or if we should have something like a
> verbose_hotplug option specifically for these messages.
I really wonder what kind of workload is hotplug-happy enough that these
two messages become a bottleneck. Why isn't turning down the loglevel
enough?
Thanks,
M.
--
Jazz is not dead. It just smells funny...
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH] arm64: Demote boot and shutdown messages to pr_debug
2019-05-01 10:47 ` Mark Rutland
2019-05-01 11:01 ` Marc Zyngier
@ 2019-05-01 11:02 ` Robin Murphy
2019-05-01 16:43 ` Florian Fainelli
2019-05-01 16:07 ` Florian Fainelli
2 siblings, 1 reply; 6+ messages in thread
From: Robin Murphy @ 2019-05-01 11:02 UTC (permalink / raw)
To: Mark Rutland, Florian Fainelli
Cc: Rob Herring, Daniel Thompson, Lorenzo Pieralisi, Ard Biesheuvel,
Marc Zyngier, Catalin Marinas, Julien Thierry, Will Deacon,
open list, rmk+kernel, Sudeep Holla, Suzuki K Poulose,
linux-arm-kernel, Steve Capper
On 01/05/2019 11:47, Mark Rutland wrote:
> On Tue, Apr 30, 2019 at 03:38:31PM -0700, Florian Fainelli wrote:
>> Similar to commits c68b0274fb3cf ("ARM: reduce "Booted secondary
>> processor" message to debug level") and 035e787543de7 ("ARM: 8644/1: Reduce "CPU:
>> shutdown" message to debug level"), demote the secondary_start_kernel()
>> and __cpu_die() messages from info, respectively notice to debug. While
>> we are at it, also do this for cpu_psci_cpu_kill() which is redundant
>> with __cpu_die().
>>
>> This helps improve the amount of possible hotplug cycles by around +50%
>> on ARCH_BRCMSTB.
>
> Could you elaborate on why that matters?
Yeah, in general if you have a slow serial console then removing all the
prints from the kernel makes lots of things much faster, but that's not
necessarily a good argument for doing so. If that's a problem that
really concerns users then I'd have to ask why they aren't using a
stricter loglevel or a different console to begin with.
> e.g. is this just for testing, or does this matter in some shutdown or
> hibernate scenario?
>
>> Signed-off-by: Florian Fainelli <f.fainelli@gmail.com>
>> ---
>> arch/arm64/kernel/psci.c | 2 +-
>> arch/arm64/kernel/smp.c | 4 ++--
>> 2 files changed, 3 insertions(+), 3 deletions(-)
>>
>> diff --git a/arch/arm64/kernel/psci.c b/arch/arm64/kernel/psci.c
>> index 8cdaf25e99cd..a78581046c80 100644
>> --- a/arch/arm64/kernel/psci.c
>> +++ b/arch/arm64/kernel/psci.c
>> @@ -96,7 +96,7 @@ static int cpu_psci_cpu_kill(unsigned int cpu)
>> for (i = 0; i < 10; i++) {
>> err = psci_ops.affinity_info(cpu_logical_map(cpu), 0);
>> if (err == PSCI_0_2_AFFINITY_LEVEL_OFF) {
>> - pr_info("CPU%d killed.\n", cpu);
>> + pr_debug("CPU%d killed.\n", cpu);
>> return 0;
>> }
>>
>> diff --git a/arch/arm64/kernel/smp.c b/arch/arm64/kernel/smp.c
>> index 824de7038967..71fd2b5a3f0e 100644
>> --- a/arch/arm64/kernel/smp.c
>> +++ b/arch/arm64/kernel/smp.c
>> @@ -259,7 +259,7 @@ asmlinkage notrace void secondary_start_kernel(void)
>> * the CPU migration code to notice that the CPU is online
>> * before we continue.
>> */
>> - pr_info("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>> + pr_debug("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>> cpu, (unsigned long)mpidr,
>> read_cpuid_id());
>
> I generally agree that we don't need to be verbose, and demoting these
> to debug is fine, but it's a shame that these won't be accessible in
> defconfig.
>
> I wonder if we should enable DYNAMIC_DEBUG so that we can turn these on
> from the kernel command line, or if we should have something like a
> verbose_hotplug option specifically for these messages.
We've had DYNAMIC_DEBUG=y in defconfig for a while already :/
Robin.
>
> Thanks,
> Mark.
>
>> update_cpu_boot_status(CPU_BOOT_SUCCESS);
>> @@ -348,7 +348,7 @@ void __cpu_die(unsigned int cpu)
>> pr_crit("CPU%u: cpu didn't die\n", cpu);
>> return;
>> }
>> - pr_notice("CPU%u: shutdown\n", cpu);
>> + pr_debug("CPU%u: shutdown\n", cpu);
>>
>> /*
>> * Now that the dying CPU is beyond the point of no return w.r.t.
>> --
>> 2.17.1
>>
>
> _______________________________________________
> linux-arm-kernel mailing list
> linux-arm-kernel@lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/linux-arm-kernel
>
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH] arm64: Demote boot and shutdown messages to pr_debug
2019-05-01 11:02 ` Robin Murphy
@ 2019-05-01 16:43 ` Florian Fainelli
0 siblings, 0 replies; 6+ messages in thread
From: Florian Fainelli @ 2019-05-01 16:43 UTC (permalink / raw)
To: Robin Murphy, Mark Rutland
Cc: Rob Herring, Daniel Thompson, Lorenzo Pieralisi, Ard Biesheuvel,
Marc Zyngier, Catalin Marinas, Julien Thierry, Will Deacon,
open list, rmk+kernel, Sudeep Holla, Suzuki K Poulose,
linux-arm-kernel, Steve Capper
On 5/1/19 4:02 AM, Robin Murphy wrote:
> On 01/05/2019 11:47, Mark Rutland wrote:
>> On Tue, Apr 30, 2019 at 03:38:31PM -0700, Florian Fainelli wrote:
>>> Similar to commits c68b0274fb3cf ("ARM: reduce "Booted secondary
>>> processor" message to debug level") and 035e787543de7 ("ARM: 8644/1:
>>> Reduce "CPU:
>>> shutdown" message to debug level"), demote the secondary_start_kernel()
>>> and __cpu_die() messages from info, respectively notice to debug. While
>>> we are at it, also do this for cpu_psci_cpu_kill() which is redundant
>>> with __cpu_die().
>>>
>>> This helps improve the amount of possible hotplug cycles by around +50%
>>> on ARCH_BRCMSTB.
>>
>> Could you elaborate on why that matters?
>
> Yeah, in general if you have a slow serial console then removing all the
> prints from the kernel makes lots of things much faster, but that's not
> necessarily a good argument for doing so. If that's a problem that
> really concerns users then I'd have to ask why they aren't using a
> stricter loglevel or a different console to begin with.
See my response to Mark for specific use cases. Teaching users about
changing their default print levels is certainly an option, although
they will likely start wondering why other messages are now gone as
well. There is not unfortunately a choice of a faster console on those
platforms.
The print levels are not necessarily consistent (info vs. notice) and we
have plenty of messages for when the CPU does not come online so telling
us when it does is completely superfluous and does not bring much value
and just gets in the way of being able to do that more often.
>
>> e.g. is this just for testing, or does this matter in some shutdown or
>> hibernate scenario?
>>
>>> Signed-off-by: Florian Fainelli <f.fainelli@gmail.com>
>>> ---
>>> arch/arm64/kernel/psci.c | 2 +-
>>> arch/arm64/kernel/smp.c | 4 ++--
>>> 2 files changed, 3 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/arch/arm64/kernel/psci.c b/arch/arm64/kernel/psci.c
>>> index 8cdaf25e99cd..a78581046c80 100644
>>> --- a/arch/arm64/kernel/psci.c
>>> +++ b/arch/arm64/kernel/psci.c
>>> @@ -96,7 +96,7 @@ static int cpu_psci_cpu_kill(unsigned int cpu)
>>> for (i = 0; i < 10; i++) {
>>> err = psci_ops.affinity_info(cpu_logical_map(cpu), 0);
>>> if (err == PSCI_0_2_AFFINITY_LEVEL_OFF) {
>>> - pr_info("CPU%d killed.\n", cpu);
>>> + pr_debug("CPU%d killed.\n", cpu);
>>> return 0;
>>> }
>>> diff --git a/arch/arm64/kernel/smp.c b/arch/arm64/kernel/smp.c
>>> index 824de7038967..71fd2b5a3f0e 100644
>>> --- a/arch/arm64/kernel/smp.c
>>> +++ b/arch/arm64/kernel/smp.c
>>> @@ -259,7 +259,7 @@ asmlinkage notrace void secondary_start_kernel(void)
>>> * the CPU migration code to notice that the CPU is online
>>> * before we continue.
>>> */
>>> - pr_info("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>>> + pr_debug("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>>> cpu, (unsigned long)mpidr,
>>> read_cpuid_id());
>>
>> I generally agree that we don't need to be verbose, and demoting these
>> to debug is fine, but it's a shame that these won't be accessible in
>> defconfig.
>>
>> I wonder if we should enable DYNAMIC_DEBUG so that we can turn these on
>> from the kernel command line, or if we should have something like a
>> verbose_hotplug option specifically for these messages.
>
> We've had DYNAMIC_DEBUG=y in defconfig for a while already :/
>
> Robin.
>
>>
>> Thanks,
>> Mark.
>>
>>> update_cpu_boot_status(CPU_BOOT_SUCCESS);
>>> @@ -348,7 +348,7 @@ void __cpu_die(unsigned int cpu)
>>> pr_crit("CPU%u: cpu didn't die\n", cpu);
>>> return;
>>> }
>>> - pr_notice("CPU%u: shutdown\n", cpu);
>>> + pr_debug("CPU%u: shutdown\n", cpu);
>>> /*
>>> * Now that the dying CPU is beyond the point of no return w.r.t.
>>> --
>>> 2.17.1
>>>
>>
>> _______________________________________________
>> linux-arm-kernel mailing list
>> linux-arm-kernel@lists.infradead.org
>> http://lists.infradead.org/mailman/listinfo/linux-arm-kernel
>>
--
Florian
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH] arm64: Demote boot and shutdown messages to pr_debug
2019-05-01 10:47 ` Mark Rutland
2019-05-01 11:01 ` Marc Zyngier
2019-05-01 11:02 ` Robin Murphy
@ 2019-05-01 16:07 ` Florian Fainelli
2 siblings, 0 replies; 6+ messages in thread
From: Florian Fainelli @ 2019-05-01 16:07 UTC (permalink / raw)
To: Mark Rutland
Cc: linux-arm-kernel, rmk+kernel, Catalin Marinas, Will Deacon,
Ard Biesheuvel, Marc Zyngier, Julien Thierry, Suzuki K Poulose,
Sudeep Holla, Rob Herring, Steve Capper, Lorenzo Pieralisi,
Daniel Thompson, open list
On 5/1/19 3:47 AM, Mark Rutland wrote:
> On Tue, Apr 30, 2019 at 03:38:31PM -0700, Florian Fainelli wrote:
>> Similar to commits c68b0274fb3cf ("ARM: reduce "Booted secondary
>> processor" message to debug level") and 035e787543de7 ("ARM: 8644/1: Reduce "CPU:
>> shutdown" message to debug level"), demote the secondary_start_kernel()
>> and __cpu_die() messages from info, respectively notice to debug. While
>> we are at it, also do this for cpu_psci_cpu_kill() which is redundant
>> with __cpu_die().
>>
>> This helps improve the amount of possible hotplug cycles by around +50%
>> on ARCH_BRCMSTB.
>
> Could you elaborate on why that matters?
>
> e.g. is this just for testing, or does this matter in some shutdown or
> hibernate scenario?
It matters to both testing, e.g.: how many hotplug cycles you can go
through within a given time frame to help assess system stsability, and
during opportunistic suspend that e.g.: Android does.
>
>> Signed-off-by: Florian Fainelli <f.fainelli@gmail.com>
>> ---
>> arch/arm64/kernel/psci.c | 2 +-
>> arch/arm64/kernel/smp.c | 4 ++--
>> 2 files changed, 3 insertions(+), 3 deletions(-)
>>
>> diff --git a/arch/arm64/kernel/psci.c b/arch/arm64/kernel/psci.c
>> index 8cdaf25e99cd..a78581046c80 100644
>> --- a/arch/arm64/kernel/psci.c
>> +++ b/arch/arm64/kernel/psci.c
>> @@ -96,7 +96,7 @@ static int cpu_psci_cpu_kill(unsigned int cpu)
>> for (i = 0; i < 10; i++) {
>> err = psci_ops.affinity_info(cpu_logical_map(cpu), 0);
>> if (err == PSCI_0_2_AFFINITY_LEVEL_OFF) {
>> - pr_info("CPU%d killed.\n", cpu);
>> + pr_debug("CPU%d killed.\n", cpu);
>> return 0;
>> }
>>
>> diff --git a/arch/arm64/kernel/smp.c b/arch/arm64/kernel/smp.c
>> index 824de7038967..71fd2b5a3f0e 100644
>> --- a/arch/arm64/kernel/smp.c
>> +++ b/arch/arm64/kernel/smp.c
>> @@ -259,7 +259,7 @@ asmlinkage notrace void secondary_start_kernel(void)
>> * the CPU migration code to notice that the CPU is online
>> * before we continue.
>> */
>> - pr_info("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>> + pr_debug("CPU%u: Booted secondary processor 0x%010lx [0x%08x]\n",
>> cpu, (unsigned long)mpidr,
>> read_cpuid_id());
>
> I generally agree that we don't need to be verbose, and demoting these
> to debug is fine, but it's a shame that these won't be accessible in
> defconfig.
>
> I wonder if we should enable DYNAMIC_DEBUG so that we can turn these on
> from the kernel command line, or if we should have something like a
> verbose_hotplug option specifically for these messages.
Based on Robin's answer (CONFIG_DYNAMIC_DEBUG already enabled in the
default configuration), would you prefer this to become a dynamic debug
message instead?
--
Florian
^ permalink raw reply [flat|nested] 6+ messages in thread