2021-05-03 19:39:47

by Heiner Kallweit

[permalink] [raw]
Subject: [PATCH 0/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

e820 emits quite some debug messages to the dmesg log. Let's restrict
this to cases where the debug output is actually requested. Switch to
pr_debug() for this purpose and make sure by checking the return code
that pr_cont() is only called if applicable. This would currently fail
if dynamic debugging is enabled because dynamic_pr_debug() has no
return value. So let's change this first.

Heiner Kallweit (2):
dyndbg: add pr_debug return value if dynamic debugging is enabled
x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

arch/x86/kernel/e820.c | 27 ++++++++++++++++-----------
include/linux/dynamic_debug.h | 14 +++++++++++---
lib/dynamic_debug.c | 7 +++++--
3 files changed, 32 insertions(+), 16 deletions(-)

--
2.31.1


2021-05-03 19:41:45

by Heiner Kallweit

[permalink] [raw]
Subject: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

e820 emits quite some debug messages to the dmesg log. Let's restrict
this to cases where the debug output is actually requested. Switch to
pr_debug() for this purpose and make sure by checking the return code
that pr_cont() is only called if applicable.

Signed-off-by: Heiner Kallweit <[email protected]>
---
arch/x86/kernel/e820.c | 27 ++++++++++++++++-----------
1 file changed, 16 insertions(+), 11 deletions(-)

diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
index bc0657f0d..67ad4d8f0 100644
--- a/arch/x86/kernel/e820.c
+++ b/arch/x86/kernel/e820.c
@@ -465,6 +465,7 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
u64 end;
unsigned int i;
u64 real_updated_size = 0;
+ int printed;

BUG_ON(old_type == new_type);

@@ -472,11 +473,13 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
size = ULLONG_MAX - start;

end = start + size;
- printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
- e820_print_type(old_type);
- pr_cont(" ==> ");
- e820_print_type(new_type);
- pr_cont("\n");
+ printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
+ if (printed > 0) {
+ e820_print_type(old_type);
+ pr_cont(" ==> ");
+ e820_print_type(new_type);
+ pr_cont("\n");
+ }

for (i = 0; i < table->nr_entries; i++) {
struct e820_entry *entry = &table->entries[i];
@@ -540,7 +543,7 @@ static u64 __init e820__range_update_kexec(u64 start, u64 size, enum e820_type o
/* Remove a range of memory from the E820 table: */
u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool check_type)
{
- int i;
+ int printed, i;
u64 end;
u64 real_removed_size = 0;

@@ -548,10 +551,12 @@ u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool
size = ULLONG_MAX - start;

end = start + size;
- printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
- if (check_type)
- e820_print_type(old_type);
- pr_cont("\n");
+ printed = pr_debug("e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
+ if (printed > 0) {
+ if (check_type)
+ e820_print_type(old_type);
+ pr_cont("\n");
+ }

for (i = 0; i < e820_table->nr_entries; i++) {
struct e820_entry *entry = &e820_table->entries[i];
@@ -1230,7 +1235,7 @@ void __init e820__reserve_resources_late(void)
if (start >= end)
continue;

- printk(KERN_DEBUG "e820: reserve RAM buffer [mem %#010llx-%#010llx]\n", start, end);
+ pr_debug("e820: reserve RAM buffer [mem %#010llx-%#010llx]\n", start, end);
reserve_region_with_split(&iomem_resource, start, end, "RAM buffer");
}
}
--
2.31.1


2021-05-03 19:42:10

by Heiner Kallweit

[permalink] [raw]
Subject: [PATCH 1/2] dyndbg: add pr_debug return value if dynamic debugging is enabled

If a pr_cont() follows a pr_debug() then it must not print something if
the the pr_debug() output is suppressed. We can use the pr_debug() return
value as criteria, however this fails in case dynamic debugging is enabled
because dynamic_pr_debug() has no return value. So let's add this missing
feature.

Signed-off-by: Heiner Kallweit <[email protected]>
---
include/linux/dynamic_debug.h | 14 +++++++++++---
lib/dynamic_debug.c | 7 +++++--
2 files changed, 16 insertions(+), 5 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index a57ee7534..1de271d1a 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -57,7 +57,7 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
const char *modname);
extern int ddebug_remove_module(const char *mod_name);
extern __printf(2, 3)
-void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...);
+int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...);

extern int ddebug_dyndbg_module_param_cb(char *param, char *val,
const char *modname);
@@ -123,6 +123,14 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,

#endif /* CONFIG_JUMP_LABEL */

+#define __dynamic_func_call_pr_debug(id, fmt, ...) ({ \
+ DEFINE_DYNAMIC_DEBUG_METADATA(id, fmt); \
+ int ret = 0; \
+ if (DYNAMIC_DEBUG_BRANCH(id)) \
+ ret = __dynamic_pr_debug(&id, __VA_ARGS__); \
+ ret; \
+})
+
#define __dynamic_func_call(id, fmt, func, ...) do { \
DEFINE_DYNAMIC_DEBUG_METADATA(id, fmt); \
if (DYNAMIC_DEBUG_BRANCH(id)) \
@@ -154,8 +162,8 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
__dynamic_func_call_no_desc(__UNIQUE_ID(ddebug), fmt, func, ##__VA_ARGS__)

#define dynamic_pr_debug(fmt, ...) \
- _dynamic_func_call(fmt, __dynamic_pr_debug, \
- pr_fmt(fmt), ##__VA_ARGS__)
+ __dynamic_func_call_pr_debug(__UNIQUE_ID(ddebug), fmt, \
+ pr_fmt(fmt), ##__VA_ARGS__)

#define dynamic_dev_dbg(dev, fmt, ...) \
_dynamic_func_call(fmt,__dynamic_dev_dbg, \
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index c70d6347a..f7a771c06 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -618,11 +618,12 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
return buf;
}

-void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
+int __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
{
va_list args;
struct va_format vaf;
char buf[PREFIX_SIZE];
+ int ret;

BUG_ON(!descriptor);
BUG_ON(!fmt);
@@ -632,9 +633,11 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
vaf.fmt = fmt;
vaf.va = &args;

- printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
+ ret = printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);

va_end(args);
+
+ return ret;
}
EXPORT_SYMBOL(__dynamic_pr_debug);

--
2.31.1


2021-05-05 17:35:59

by Jason Baron

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages



On 5/3/21 3:40 PM, Heiner Kallweit wrote:
> e820 emits quite some debug messages to the dmesg log. Let's restrict
> this to cases where the debug output is actually requested. Switch to
> pr_debug() for this purpose and make sure by checking the return code
> that pr_cont() is only called if applicable.
>
> Signed-off-by: Heiner Kallweit <[email protected]>
> ---
> arch/x86/kernel/e820.c | 27 ++++++++++++++++-----------
> 1 file changed, 16 insertions(+), 11 deletions(-)
>
> diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
> index bc0657f0d..67ad4d8f0 100644
> --- a/arch/x86/kernel/e820.c
> +++ b/arch/x86/kernel/e820.c
> @@ -465,6 +465,7 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
> u64 end;
> unsigned int i;
> u64 real_updated_size = 0;
> + int printed;
>
> BUG_ON(old_type == new_type);
>
> @@ -472,11 +473,13 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
> size = ULLONG_MAX - start;
>
> end = start + size;
> - printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
> - e820_print_type(old_type);
> - pr_cont(" ==> ");
> - e820_print_type(new_type);
> - pr_cont("\n");
> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
> + if (printed > 0) {
> + e820_print_type(old_type);
> + pr_cont(" ==> ");
> + e820_print_type(new_type);
> + pr_cont("\n");
> + }


Hi Heiner,

We've been doing these like:

DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");

.
.
.

if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
e820_print_type(old_type);
pr_cont(" ==> ");
e820_print_type(new_type);
pr_cont("\n");
}


You could then have one DEFINE_DYNAMIC_DEBUG_METADATA statement - such that it enables
it all in one go, or do separate ones that enable it how you see fit.

Would that work here?

Thanks,

-Jason

>
> for (i = 0; i < table->nr_entries; i++) {
> struct e820_entry *entry = &table->entries[i];
> @@ -540,7 +543,7 @@ static u64 __init e820__range_update_kexec(u64 start, u64 size, enum e820_type o
> /* Remove a range of memory from the E820 table: */
> u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool check_type)
> {
> - int i;
> + int printed, i;
> u64 end;
> u64 real_removed_size = 0;
>
> @@ -548,10 +551,12 @@ u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool
> size = ULLONG_MAX - start;
>
> end = start + size;
> - printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
> - if (check_type)
> - e820_print_type(old_type);
> - pr_cont("\n");
> + printed = pr_debug("e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
> + if (printed > 0) {
> + if (check_type)
> + e820_print_type(old_type);
> + pr_cont("\n");
> + }
>
> for (i = 0; i < e820_table->nr_entries; i++) {
> struct e820_entry *entry = &e820_table->entries[i];
> @@ -1230,7 +1235,7 @@ void __init e820__reserve_resources_late(void)
> if (start >= end)
> continue;
>
> - printk(KERN_DEBUG "e820: reserve RAM buffer [mem %#010llx-%#010llx]\n", start, end);
> + pr_debug("e820: reserve RAM buffer [mem %#010llx-%#010llx]\n", start, end);
> reserve_region_with_split(&iomem_resource, start, end, "RAM buffer");
> }
> }
>

2021-05-05 18:43:03

by Heiner Kallweit

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

On 05.05.2021 18:58, Jason Baron wrote:
>
>
> On 5/3/21 3:40 PM, Heiner Kallweit wrote:
>> e820 emits quite some debug messages to the dmesg log. Let's restrict
>> this to cases where the debug output is actually requested. Switch to
>> pr_debug() for this purpose and make sure by checking the return code
>> that pr_cont() is only called if applicable.
>>
>> Signed-off-by: Heiner Kallweit <[email protected]>
>> ---
>> arch/x86/kernel/e820.c | 27 ++++++++++++++++-----------
>> 1 file changed, 16 insertions(+), 11 deletions(-)
>>
>> diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
>> index bc0657f0d..67ad4d8f0 100644
>> --- a/arch/x86/kernel/e820.c
>> +++ b/arch/x86/kernel/e820.c
>> @@ -465,6 +465,7 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>> u64 end;
>> unsigned int i;
>> u64 real_updated_size = 0;
>> + int printed;
>>
>> BUG_ON(old_type == new_type);
>>
>> @@ -472,11 +473,13 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>> size = ULLONG_MAX - start;
>>
>> end = start + size;
>> - printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>> - e820_print_type(old_type);
>> - pr_cont(" ==> ");
>> - e820_print_type(new_type);
>> - pr_cont("\n");
>> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>> + if (printed > 0) {
>> + e820_print_type(old_type);
>> + pr_cont(" ==> ");
>> + e820_print_type(new_type);
>> + pr_cont("\n");
>> + }
>
>
> Hi Heiner,
>
> We've been doing these like:
>
> DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");
>
> .
> .
> .
>
> if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
> printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
> e820_print_type(old_type);
> pr_cont(" ==> ");
> e820_print_type(new_type);
> pr_cont("\n");
> }
>
>
> You could then have one DEFINE_DYNAMIC_DEBUG_METADATA statement - such that it enables
> it all in one go, or do separate ones that enable it how you see fit.
>
> Would that work here?
>

How would we handle the case that CONFIG_DYNAMIC_DEBUG_CORE isn't defined?
Then also DEFINE_DYNAMIC_DEBUG_METADATA isn't defined and we'd need to
duplicate the logic used here:

#if defined(CONFIG_DYNAMIC_DEBUG) || \
(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
#include <linux/dynamic_debug.h>
#define pr_debug(fmt, ...) \
dynamic_pr_debug(fmt, ##__VA_ARGS__)
#elif defined(DEBUG)
#define pr_debug(fmt, ...) \
printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
#define pr_debug(fmt, ...) \
no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#endif

IMO it's better to have the complexity of using DEFINE_DYNAMIC_DEBUG_METADATA
only once in the implementation of dynamic_pr_debug(), and not in every
code that wants to use pr_debug() in combination with pr_cont().

Also I think that to a certain extent pr_debug() is broken currently in case
of dynamic debugging because it has no return value, one drawback of
using not type-safe macros. This doesn't hurt so far because no caller seems to
check the return value or very few people have dynamic debugging enabled.

> Thanks,
>
> -Jason
>

Heiner

>>
>> for (i = 0; i < table->nr_entries; i++) {
>> struct e820_entry *entry = &table->entries[i];
>> @@ -540,7 +543,7 @@ static u64 __init e820__range_update_kexec(u64 start, u64 size, enum e820_type o
>> /* Remove a range of memory from the E820 table: */
>> u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool check_type)
>> {
>> - int i;
>> + int printed, i;
>> u64 end;
>> u64 real_removed_size = 0;
>>
>> @@ -548,10 +551,12 @@ u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool
>> size = ULLONG_MAX - start;
>>
>> end = start + size;
>> - printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
>> - if (check_type)
>> - e820_print_type(old_type);
>> - pr_cont("\n");
>> + printed = pr_debug("e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
>> + if (printed > 0) {
>> + if (check_type)
>> + e820_print_type(old_type);
>> + pr_cont("\n");
>> + }
>>
>> for (i = 0; i < e820_table->nr_entries; i++) {
>> struct e820_entry *entry = &e820_table->entries[i];
>> @@ -1230,7 +1235,7 @@ void __init e820__reserve_resources_late(void)
>> if (start >= end)
>> continue;
>>
>> - printk(KERN_DEBUG "e820: reserve RAM buffer [mem %#010llx-%#010llx]\n", start, end);
>> + pr_debug("e820: reserve RAM buffer [mem %#010llx-%#010llx]\n", start, end);
>> reserve_region_with_split(&iomem_resource, start, end, "RAM buffer");
>> }
>> }
>>

2021-05-11 03:24:19

by Jason Baron

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages



On 5/5/21 2:40 PM, Heiner Kallweit wrote:
> On 05.05.2021 18:58, Jason Baron wrote:
>>
>>
>> On 5/3/21 3:40 PM, Heiner Kallweit wrote:
>>> e820 emits quite some debug messages to the dmesg log. Let's restrict
>>> this to cases where the debug output is actually requested. Switch to
>>> pr_debug() for this purpose and make sure by checking the return code
>>> that pr_cont() is only called if applicable.
>>>
>>> Signed-off-by: Heiner Kallweit <[email protected]>
>>> ---
>>> arch/x86/kernel/e820.c | 27 ++++++++++++++++-----------
>>> 1 file changed, 16 insertions(+), 11 deletions(-)
>>>
>>> diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
>>> index bc0657f0d..67ad4d8f0 100644
>>> --- a/arch/x86/kernel/e820.c
>>> +++ b/arch/x86/kernel/e820.c
>>> @@ -465,6 +465,7 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>>> u64 end;
>>> unsigned int i;
>>> u64 real_updated_size = 0;
>>> + int printed;
>>>
>>> BUG_ON(old_type == new_type);
>>>
>>> @@ -472,11 +473,13 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>>> size = ULLONG_MAX - start;
>>>
>>> end = start + size;
>>> - printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>> - e820_print_type(old_type);
>>> - pr_cont(" ==> ");
>>> - e820_print_type(new_type);
>>> - pr_cont("\n");
>>> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>> + if (printed > 0) {
>>> + e820_print_type(old_type);
>>> + pr_cont(" ==> ");
>>> + e820_print_type(new_type);
>>> + pr_cont("\n");
>>> + }
>>
>>
>> Hi Heiner,
>>
>> We've been doing these like:
>>
>> DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");
>>
>> .
>> .
>> .
>>
>> if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
>> printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>> e820_print_type(old_type);
>> pr_cont(" ==> ");
>> e820_print_type(new_type);
>> pr_cont("\n");
>> }
>>
>>
>> You could then have one DEFINE_DYNAMIC_DEBUG_METADATA statement - such that it enables
>> it all in one go, or do separate ones that enable it how you see fit.
>>
>> Would that work here?
>>
>
> How would we handle the case that CONFIG_DYNAMIC_DEBUG_CORE isn't defined?
> Then also DEFINE_DYNAMIC_DEBUG_METADATA isn't defined and we'd need to
> duplicate the logic used here:
>
> #if defined(CONFIG_DYNAMIC_DEBUG) || \
> (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
> #include <linux/dynamic_debug.h>
> #define pr_debug(fmt, ...) \
> dynamic_pr_debug(fmt, ##__VA_ARGS__)
> #elif defined(DEBUG)
> #define pr_debug(fmt, ...) \
> printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> #else
> #define pr_debug(fmt, ...) \
> no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> #endif
>

I'm not sure we need to duplicate all that I think we just need something
like the following for the !CONFIG_DYNAMIC_DEBUG_CORE case. Would this
help?

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index a57ee75..91ede70 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -182,6 +182,15 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
#include <linux/errno.h>
#include <linux/printk.h>

+#ifdef DEBUG
+#define DYNAMIC_DEBUG_BRANCH(descriptor) true
+#else
+#define DYNAMIC_DEBUG_BRANCH(descriptor) false
+#if
+
+#define DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt)
+
+
static inline int ddebug_add_module(struct _ddebug *tab, unsigned int n,
const char *modname)
{



> IMO it's better to have the complexity of using DEFINE_DYNAMIC_DEBUG_METADATA
> only once in the implementation of dynamic_pr_debug(), and not in every
> code that wants to use pr_debug() in combination with pr_cont().

I think for your use-case it would just require one DEFINE_DYNAMIC_DEBUG_METADATA()
statement?

>
> Also I think that to a certain extent pr_debug() is broken currently in case
> of dynamic debugging because it has no return value, one drawback of
> using not type-safe macros. This doesn't hurt so far because no caller seems to
> check the return value or very few people have dynamic debugging enabled.

The model of:

DEFINE_DYNAMIC_DEBUG_METADATA(foo, "enble_foo");

.
.
.

if (DYNAMIC_DEBUG_BRANCH(foo) {
do debugging stuff;
}

Seems more general since the 'do debugging stuff' doesn't have to be limited
to printk, it can be anything. So if we add another different model for this
use-case, it seems like it might be less general.

Thanks,

-Jason

2021-05-11 20:38:43

by Heiner Kallweit

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

On 11.05.2021 05:21, Jason Baron wrote:
>
>
> On 5/5/21 2:40 PM, Heiner Kallweit wrote:
>> On 05.05.2021 18:58, Jason Baron wrote:
>>>
>>>
>>> On 5/3/21 3:40 PM, Heiner Kallweit wrote:
>>>> e820 emits quite some debug messages to the dmesg log. Let's restrict
>>>> this to cases where the debug output is actually requested. Switch to
>>>> pr_debug() for this purpose and make sure by checking the return code
>>>> that pr_cont() is only called if applicable.
>>>>
>>>> Signed-off-by: Heiner Kallweit <[email protected]>
>>>> ---
>>>> arch/x86/kernel/e820.c | 27 ++++++++++++++++-----------
>>>> 1 file changed, 16 insertions(+), 11 deletions(-)
>>>>
>>>> diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
>>>> index bc0657f0d..67ad4d8f0 100644
>>>> --- a/arch/x86/kernel/e820.c
>>>> +++ b/arch/x86/kernel/e820.c
>>>> @@ -465,6 +465,7 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>>>> u64 end;
>>>> unsigned int i;
>>>> u64 real_updated_size = 0;
>>>> + int printed;
>>>>
>>>> BUG_ON(old_type == new_type);
>>>>
>>>> @@ -472,11 +473,13 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>>>> size = ULLONG_MAX - start;
>>>>
>>>> end = start + size;
>>>> - printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>>> - e820_print_type(old_type);
>>>> - pr_cont(" ==> ");
>>>> - e820_print_type(new_type);
>>>> - pr_cont("\n");
>>>> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>>> + if (printed > 0) {
>>>> + e820_print_type(old_type);
>>>> + pr_cont(" ==> ");
>>>> + e820_print_type(new_type);
>>>> + pr_cont("\n");
>>>> + }
>>>
>>>
>>> Hi Heiner,
>>>
>>> We've been doing these like:
>>>
>>> DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");
>>>
>>> .
>>> .
>>> .
>>>
>>> if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
>>> printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>> e820_print_type(old_type);
>>> pr_cont(" ==> ");
>>> e820_print_type(new_type);
>>> pr_cont("\n");
>>> }
>>>
>>>
>>> You could then have one DEFINE_DYNAMIC_DEBUG_METADATA statement - such that it enables
>>> it all in one go, or do separate ones that enable it how you see fit.
>>>
>>> Would that work here?
>>>
>>
>> How would we handle the case that CONFIG_DYNAMIC_DEBUG_CORE isn't defined?
>> Then also DEFINE_DYNAMIC_DEBUG_METADATA isn't defined and we'd need to
>> duplicate the logic used here:
>>
>> #if defined(CONFIG_DYNAMIC_DEBUG) || \
>> (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
>> #include <linux/dynamic_debug.h>
>> #define pr_debug(fmt, ...) \
>> dynamic_pr_debug(fmt, ##__VA_ARGS__)
>> #elif defined(DEBUG)
>> #define pr_debug(fmt, ...) \
>> printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>> #else
>> #define pr_debug(fmt, ...) \
>> no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>> #endif
>>
>
> I'm not sure we need to duplicate all that I think we just need something
> like the following for the !CONFIG_DYNAMIC_DEBUG_CORE case. Would this
> help?
>
> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
> index a57ee75..91ede70 100644
> --- a/include/linux/dynamic_debug.h
> +++ b/include/linux/dynamic_debug.h
> @@ -182,6 +182,15 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
> #include <linux/errno.h>
> #include <linux/printk.h>
>
> +#ifdef DEBUG
> +#define DYNAMIC_DEBUG_BRANCH(descriptor) true
> +#else
> +#define DYNAMIC_DEBUG_BRANCH(descriptor) false
> +#if
> +
> +#define DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt)
> +
> +
> static inline int ddebug_add_module(struct _ddebug *tab, unsigned int n,
> const char *modname)
> {
>
>
>
>> IMO it's better to have the complexity of using DEFINE_DYNAMIC_DEBUG_METADATA
>> only once in the implementation of dynamic_pr_debug(), and not in every
>> code that wants to use pr_debug() in combination with pr_cont().
>
> I think for your use-case it would just require one DEFINE_DYNAMIC_DEBUG_METADATA()
> statement?
>
The point is that e820 isn't interested in using dynamic debugging. It just
would need to be able to deal with it because pr_debug() uses it. The actual
issue is independent of e820. It boils down to pr_cont() having no way to find
out whether it should print something or not if it follows a pr_debug() and
dynamic debugging is enabled.

>>
>> Also I think that to a certain extent pr_debug() is broken currently in case
>> of dynamic debugging because it has no return value, one drawback of
>> using not type-safe macros. This doesn't hurt so far because no caller seems to
>> check the return value or very few people have dynamic debugging enabled.
>
> The model of:
>
> DEFINE_DYNAMIC_DEBUG_METADATA(foo, "enble_foo");
>
> .
> .
> .
>
> if (DYNAMIC_DEBUG_BRANCH(foo) {
> do debugging stuff;
> }
>
> Seems more general since the 'do debugging stuff' doesn't have to be limited
> to printk, it can be anything. So if we add another different model for this
> use-case, it seems like it might be less general.
>
> Thanks,
>
> -Jason
>
Heiner

2021-05-11 21:32:39

by Jason Baron

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages



On 5/11/21 4:36 PM, Heiner Kallweit wrote:
> On 11.05.2021 05:21, Jason Baron wrote:
>>
>>
>> On 5/5/21 2:40 PM, Heiner Kallweit wrote:
>>> On 05.05.2021 18:58, Jason Baron wrote:
>>>>
>>>>
>>>> On 5/3/21 3:40 PM, Heiner Kallweit wrote:
>>>>> e820 emits quite some debug messages to the dmesg log. Let's restrict
>>>>> this to cases where the debug output is actually requested. Switch to
>>>>> pr_debug() for this purpose and make sure by checking the return code
>>>>> that pr_cont() is only called if applicable.
>>>>>
>>>>> Signed-off-by: Heiner Kallweit <[email protected]>
>>>>> ---
>>>>> arch/x86/kernel/e820.c | 27 ++++++++++++++++-----------
>>>>> 1 file changed, 16 insertions(+), 11 deletions(-)
>>>>>
>>>>> diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
>>>>> index bc0657f0d..67ad4d8f0 100644
>>>>> --- a/arch/x86/kernel/e820.c
>>>>> +++ b/arch/x86/kernel/e820.c
>>>>> @@ -465,6 +465,7 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>>>>> u64 end;
>>>>> unsigned int i;
>>>>> u64 real_updated_size = 0;
>>>>> + int printed;
>>>>>
>>>>> BUG_ON(old_type == new_type);
>>>>>
>>>>> @@ -472,11 +473,13 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>>>>> size = ULLONG_MAX - start;
>>>>>
>>>>> end = start + size;
>>>>> - printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>>>> - e820_print_type(old_type);
>>>>> - pr_cont(" ==> ");
>>>>> - e820_print_type(new_type);
>>>>> - pr_cont("\n");
>>>>> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>>>> + if (printed > 0) {
>>>>> + e820_print_type(old_type);
>>>>> + pr_cont(" ==> ");
>>>>> + e820_print_type(new_type);
>>>>> + pr_cont("\n");
>>>>> + }
>>>>
>>>>
>>>> Hi Heiner,
>>>>
>>>> We've been doing these like:
>>>>
>>>> DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");
>>>>
>>>> .
>>>> .
>>>> .
>>>>
>>>> if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
>>>> printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>>> e820_print_type(old_type);
>>>> pr_cont(" ==> ");
>>>> e820_print_type(new_type);
>>>> pr_cont("\n");
>>>> }
>>>>
>>>>
>>>> You could then have one DEFINE_DYNAMIC_DEBUG_METADATA statement - such that it enables
>>>> it all in one go, or do separate ones that enable it how you see fit.
>>>>
>>>> Would that work here?
>>>>
>>>
>>> How would we handle the case that CONFIG_DYNAMIC_DEBUG_CORE isn't defined?
>>> Then also DEFINE_DYNAMIC_DEBUG_METADATA isn't defined and we'd need to
>>> duplicate the logic used here:
>>>
>>> #if defined(CONFIG_DYNAMIC_DEBUG) || \
>>> (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
>>> #include <linux/dynamic_debug.h>
>>> #define pr_debug(fmt, ...) \
>>> dynamic_pr_debug(fmt, ##__VA_ARGS__)
>>> #elif defined(DEBUG)
>>> #define pr_debug(fmt, ...) \
>>> printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>> #else
>>> #define pr_debug(fmt, ...) \
>>> no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>> #endif
>>>
>>
>> I'm not sure we need to duplicate all that I think we just need something
>> like the following for the !CONFIG_DYNAMIC_DEBUG_CORE case. Would this
>> help?
>>
>> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
>> index a57ee75..91ede70 100644
>> --- a/include/linux/dynamic_debug.h
>> +++ b/include/linux/dynamic_debug.h
>> @@ -182,6 +182,15 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
>> #include <linux/errno.h>
>> #include <linux/printk.h>
>>
>> +#ifdef DEBUG
>> +#define DYNAMIC_DEBUG_BRANCH(descriptor) true
>> +#else
>> +#define DYNAMIC_DEBUG_BRANCH(descriptor) false
>> +#if
>> +
>> +#define DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt)
>> +
>> +
>> static inline int ddebug_add_module(struct _ddebug *tab, unsigned int n,
>> const char *modname)
>> {
>>
>>
>>
>>> IMO it's better to have the complexity of using DEFINE_DYNAMIC_DEBUG_METADATA
>>> only once in the implementation of dynamic_pr_debug(), and not in every
>>> code that wants to use pr_debug() in combination with pr_cont().
>>
>> I think for your use-case it would just require one DEFINE_DYNAMIC_DEBUG_METADATA()
>> statement?
>>
> The point is that e820 isn't interested in using dynamic debugging. It just

I'm a little confused by this statement because in your changelog you say:

"
e820 emits quite some debug messages to the dmesg log. Let's restrict
this to cases where the debug output is actually requested.
"

So doesn't this mean you are intending to use dynamic debug to allow the user
to increase the verbosity if they want?

> would need to be able to deal with it because pr_debug() uses it. The actual
> issue is independent of e820. It boils down to pr_cont() having no way to find
> out whether it should print something or not if it follows a pr_debug() and
> dynamic debugging is enabled.

Ok, well the using the DYNAMIC_DEBUG_BRANCH() will address this b/c the branch
is controlled by dynamic debug.

That said, I do see the value in not having to open code the branch stuff, and
making pr_debug() consistent with printk which does return a value. So that
makes sense to me.

Thanks,

-Jason

>
>>>
>>> Also I think that to a certain extent pr_debug() is broken currently in case
>>> of dynamic debugging because it has no return value, one drawback of
>>> using not type-safe macros. This doesn't hurt so far because no caller seems to
>>> check the return value or very few people have dynamic debugging enabled.
>>
>> The model of:
>>
>> DEFINE_DYNAMIC_DEBUG_METADATA(foo, "enble_foo");
>>
>> .
>> .
>> .
>>
>> if (DYNAMIC_DEBUG_BRANCH(foo) {
>> do debugging stuff;
>> }
>>
>> Seems more general since the 'do debugging stuff' doesn't have to be limited
>> to printk, it can be anything. So if we add another different model for this
>> use-case, it seems like it might be less general.
>>
>> Thanks,
>>
>> -Jason
>>
> Heiner
>

2021-05-14 20:53:24

by Jason Baron

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages



On 5/14/21 4:22 PM, Joe Perches wrote:
> On Fri, 2021-05-14 at 15:56 -0400, Jason Baron wrote:
>>
>> On 5/14/21 1:38 PM, Joe Perches wrote:
>>> On Tue, 2021-05-11 at 17:31 -0400, Jason Baron wrote:
>>>
>>>> That said, I do see the value in not having to open code the branch stuff, and
>>>> making pr_debug() consistent with printk which does return a value. So that
>>>> makes sense to me.
>>>
>>> IMO: printk should not return a value.
>>>
>>
>> Ok, the issue we are trying to resolve is to control whether a 'pr_debug()' statement
>> is enabled and thus use that to control subsequent output. The proposed patch does:
>>
>>
>> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>> + if (printed > 0) {
>> + e820_print_type(old_type);
>> + pr_cont(" ==> ");
>> + e820_print_type(new_type);
>> + pr_cont("\n");
>> + }
>>
>> I do think pr_debug() here is different from printk() b/c it can be explicitly
>> toggled.
>>
>> I also suggested an alternative, which is possible with the current code which
>> is to use DYNAMIC_DEBUG_BRANCH().
>>
>> if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
>>     printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>     e820_print_type(old_type);
>>     pr_cont(" ==> ");
>>     e820_print_type(new_type);
>>     pr_cont("\n");
>> }
>>
>> That however does require one to do something like this first:
>>
>> DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");
>>
>> So I don't feel too strongly either way, but maybe others do?
>
> Why not avoid the problem by using temporaries on the stack
> and not use pr_cont altogether?

Nice. That's fine with me Heiner?

I think though Heiner wants to use pr_debug() below instead of printk
with KERN_DEBUG, at least that was my understanding. But that would
be a simpple s/printk/pr_debug().

Thanks,

-Jason




> ---
> arch/x86/kernel/e820.c | 71 ++++++++++++++++++++++++++++++++------------------
> 1 file changed, 46 insertions(+), 25 deletions(-)
>
> diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
> index bc0657f0deed..a6e7ab4b522b 100644
> --- a/arch/x86/kernel/e820.c
> +++ b/arch/x86/kernel/e820.c
> @@ -184,20 +184,38 @@ void __init e820__range_add(u64 start, u64 size, enum e820_type type)
> __e820__range_add(e820_table, start, size, type);
> }
>
> -static void __init e820_print_type(enum e820_type type)
> +static char * __init e820_fmt_type(enum e820_type type, char *buf, size_t size)
> {
> switch (type) {
> - case E820_TYPE_RAM: /* Fall through: */
> - case E820_TYPE_RESERVED_KERN: pr_cont("usable"); break;
> - case E820_TYPE_RESERVED: pr_cont("reserved"); break;
> - case E820_TYPE_SOFT_RESERVED: pr_cont("soft reserved"); break;
> - case E820_TYPE_ACPI: pr_cont("ACPI data"); break;
> - case E820_TYPE_NVS: pr_cont("ACPI NVS"); break;
> - case E820_TYPE_UNUSABLE: pr_cont("unusable"); break;
> - case E820_TYPE_PMEM: /* Fall through: */
> - case E820_TYPE_PRAM: pr_cont("persistent (type %u)", type); break;
> - default: pr_cont("type %u", type); break;
> + case E820_TYPE_RAM:
> + case E820_TYPE_RESERVED_KERN:
> + strscpy(buf, "usable", size);
> + break;
> + case E820_TYPE_RESERVED:
> + strscpy(buf, "reserved", size);
> + break;
> + case E820_TYPE_SOFT_RESERVED:
> + strscpy(buf, "soft reserved", size);
> + break;
> + case E820_TYPE_ACPI:
> + strscpy(buf, "ACPI data", size);
> + break;
> + case E820_TYPE_NVS:
> + strscpy(buf, "ACPI NVS", size);
> + break;
> + case E820_TYPE_UNUSABLE:
> + strscpy(buf, "unusable", size);
> + break;
> + case E820_TYPE_PMEM:
> + case E820_TYPE_PRAM:
> + scnprintf(buf, size, "persistent (type %u)", type);
> + break;
> + default:
> + scnprintf(buf, size, "type %u", type);
> + break;
> }
> +
> + return buf;
> }
>
> void __init e820__print_table(char *who)
> @@ -205,13 +223,14 @@ void __init e820__print_table(char *who)
> int i;
>
> for (i = 0; i < e820_table->nr_entries; i++) {
> - pr_info("%s: [mem %#018Lx-%#018Lx] ",
> + char type[32];
> +
> + pr_info("%s: [mem %#018Lx-%#018Lx] %s\n",
> who,
> e820_table->entries[i].addr,
> - e820_table->entries[i].addr + e820_table->entries[i].size - 1);
> -
> - e820_print_type(e820_table->entries[i].type);
> - pr_cont("\n");
> + e820_table->entries[i].addr + e820_table->entries[i].size - 1,
> + e820_fmt_type(e820_table->entries[i].type,
> + type, sizeof(type)));
> }
> }
>
> @@ -465,6 +484,8 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
> u64 end;
> unsigned int i;
> u64 real_updated_size = 0;
> + char type1[32];
> + char type2[32];
>
> BUG_ON(old_type == new_type);
>
> @@ -472,11 +493,10 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
> size = ULLONG_MAX - start;
>
> end = start + size;
> - printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
> - e820_print_type(old_type);
> - pr_cont(" ==> ");
> - e820_print_type(new_type);
> - pr_cont("\n");
> + printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] %s ==> %s\n",
> + start, end - 1,
> + e820_fmt_type(old_type, type1, sizeof(type1)),
> + e820_fmt_type(new_type, type2, sizeof(type2)));
>
> for (i = 0; i < table->nr_entries; i++) {
> struct e820_entry *entry = &table->entries[i];
> @@ -543,15 +563,16 @@ u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool
> int i;
> u64 end;
> u64 real_removed_size = 0;
> + char type[32];
>
> if (size > (ULLONG_MAX - start))
> size = ULLONG_MAX - start;
>
> end = start + size;
> - printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
> - if (check_type)
> - e820_print_type(old_type);
> - pr_cont("\n");
> + printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx]%s%s\n",
> + start, end - 1,
> + check_type ? " " : "",
> + check_type ? e820_fmt_type(old_type, type, sizeof(type)) : "");
>
> for (i = 0; i < e820_table->nr_entries; i++) {
> struct e820_entry *entry = &e820_table->entries[i];
>
>

2021-05-15 02:15:59

by Joe Perches

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

On Tue, 2021-05-11 at 17:31 -0400, Jason Baron wrote:

> That said, I do see the value in not having to open code the branch stuff, and
> making pr_debug() consistent with printk which does return a value. So that
> makes sense to me.

IMO: printk should not return a value.


2021-05-15 08:00:11

by Jason Baron

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages



On 5/14/21 1:38 PM, Joe Perches wrote:
> On Tue, 2021-05-11 at 17:31 -0400, Jason Baron wrote:
>
>> That said, I do see the value in not having to open code the branch stuff, and
>> making pr_debug() consistent with printk which does return a value. So that
>> makes sense to me.
>
> IMO: printk should not return a value.
>

Ok, the issue we are trying to resolve is to control whether a 'pr_debug()' statement
is enabled and thus use that to control subsequent output. The proposed patch does:


+ printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
+ if (printed > 0) {
+ e820_print_type(old_type);
+ pr_cont(" ==> ");
+ e820_print_type(new_type);
+ pr_cont("\n");
+ }

I do think pr_debug() here is different from printk() b/c it can be explicitly
toggled.

I also suggested an alternative, which is possible with the current code which
is to use DYNAMIC_DEBUG_BRANCH().

if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
e820_print_type(old_type);
pr_cont(" ==> ");
e820_print_type(new_type);
pr_cont("\n");
}

That however does require one to do something like this first:

DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");

So I don't feel too strongly either way, but maybe others do?

Thanks,

-Jason

2021-05-15 08:28:36

by Joe Perches

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

On Fri, 2021-05-14 at 15:56 -0400, Jason Baron wrote:
>
> On 5/14/21 1:38 PM, Joe Perches wrote:
> > On Tue, 2021-05-11 at 17:31 -0400, Jason Baron wrote:
> >
> > > That said, I do see the value in not having to open code the branch stuff, and
> > > making pr_debug() consistent with printk which does return a value. So that
> > > makes sense to me.
> >
> > IMO: printk should not return a value.
> >
>
> Ok, the issue we are trying to resolve is to control whether a 'pr_debug()' statement
> is enabled and thus use that to control subsequent output. The proposed patch does:
>
>
> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
> + if (printed > 0) {
> + e820_print_type(old_type);
> + pr_cont(" ==> ");
> + e820_print_type(new_type);
> + pr_cont("\n");
> + }
>
> I do think pr_debug() here is different from printk() b/c it can be explicitly
> toggled.
>
> I also suggested an alternative, which is possible with the current code which
> is to use DYNAMIC_DEBUG_BRANCH().
>
> if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
> ????printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
> ????e820_print_type(old_type);
> ????pr_cont(" ==> ");
> ????e820_print_type(new_type);
> ????pr_cont("\n");
> }
>
> That however does require one to do something like this first:
>
> DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");
>
> So I don't feel too strongly either way, but maybe others do?

Why not avoid the problem by using temporaries on the stack
and not use pr_cont altogether?
---
arch/x86/kernel/e820.c | 71 ++++++++++++++++++++++++++++++++------------------
1 file changed, 46 insertions(+), 25 deletions(-)

diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
index bc0657f0deed..a6e7ab4b522b 100644
--- a/arch/x86/kernel/e820.c
+++ b/arch/x86/kernel/e820.c
@@ -184,20 +184,38 @@ void __init e820__range_add(u64 start, u64 size, enum e820_type type)
__e820__range_add(e820_table, start, size, type);
}

-static void __init e820_print_type(enum e820_type type)
+static char * __init e820_fmt_type(enum e820_type type, char *buf, size_t size)
{
switch (type) {
- case E820_TYPE_RAM: /* Fall through: */
- case E820_TYPE_RESERVED_KERN: pr_cont("usable"); break;
- case E820_TYPE_RESERVED: pr_cont("reserved"); break;
- case E820_TYPE_SOFT_RESERVED: pr_cont("soft reserved"); break;
- case E820_TYPE_ACPI: pr_cont("ACPI data"); break;
- case E820_TYPE_NVS: pr_cont("ACPI NVS"); break;
- case E820_TYPE_UNUSABLE: pr_cont("unusable"); break;
- case E820_TYPE_PMEM: /* Fall through: */
- case E820_TYPE_PRAM: pr_cont("persistent (type %u)", type); break;
- default: pr_cont("type %u", type); break;
+ case E820_TYPE_RAM:
+ case E820_TYPE_RESERVED_KERN:
+ strscpy(buf, "usable", size);
+ break;
+ case E820_TYPE_RESERVED:
+ strscpy(buf, "reserved", size);
+ break;
+ case E820_TYPE_SOFT_RESERVED:
+ strscpy(buf, "soft reserved", size);
+ break;
+ case E820_TYPE_ACPI:
+ strscpy(buf, "ACPI data", size);
+ break;
+ case E820_TYPE_NVS:
+ strscpy(buf, "ACPI NVS", size);
+ break;
+ case E820_TYPE_UNUSABLE:
+ strscpy(buf, "unusable", size);
+ break;
+ case E820_TYPE_PMEM:
+ case E820_TYPE_PRAM:
+ scnprintf(buf, size, "persistent (type %u)", type);
+ break;
+ default:
+ scnprintf(buf, size, "type %u", type);
+ break;
}
+
+ return buf;
}

void __init e820__print_table(char *who)
@@ -205,13 +223,14 @@ void __init e820__print_table(char *who)
int i;

for (i = 0; i < e820_table->nr_entries; i++) {
- pr_info("%s: [mem %#018Lx-%#018Lx] ",
+ char type[32];
+
+ pr_info("%s: [mem %#018Lx-%#018Lx] %s\n",
who,
e820_table->entries[i].addr,
- e820_table->entries[i].addr + e820_table->entries[i].size - 1);
-
- e820_print_type(e820_table->entries[i].type);
- pr_cont("\n");
+ e820_table->entries[i].addr + e820_table->entries[i].size - 1,
+ e820_fmt_type(e820_table->entries[i].type,
+ type, sizeof(type)));
}
}

@@ -465,6 +484,8 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
u64 end;
unsigned int i;
u64 real_updated_size = 0;
+ char type1[32];
+ char type2[32];

BUG_ON(old_type == new_type);

@@ -472,11 +493,10 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
size = ULLONG_MAX - start;

end = start + size;
- printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
- e820_print_type(old_type);
- pr_cont(" ==> ");
- e820_print_type(new_type);
- pr_cont("\n");
+ printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] %s ==> %s\n",
+ start, end - 1,
+ e820_fmt_type(old_type, type1, sizeof(type1)),
+ e820_fmt_type(new_type, type2, sizeof(type2)));

for (i = 0; i < table->nr_entries; i++) {
struct e820_entry *entry = &table->entries[i];
@@ -543,15 +563,16 @@ u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool
int i;
u64 end;
u64 real_removed_size = 0;
+ char type[32];

if (size > (ULLONG_MAX - start))
size = ULLONG_MAX - start;

end = start + size;
- printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
- if (check_type)
- e820_print_type(old_type);
- pr_cont("\n");
+ printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx]%s%s\n",
+ start, end - 1,
+ check_type ? " " : "",
+ check_type ? e820_fmt_type(old_type, type, sizeof(type)) : "");

for (i = 0; i < e820_table->nr_entries; i++) {
struct e820_entry *entry = &e820_table->entries[i];



2021-05-15 10:20:52

by Heiner Kallweit

[permalink] [raw]
Subject: Re: [PATCH 2/2] x86/e820: Use pr_debug to avoid spamming dmesg log with debug messages

On 14.05.2021 22:32, Jason Baron wrote:
>
>
> On 5/14/21 4:22 PM, Joe Perches wrote:
>> On Fri, 2021-05-14 at 15:56 -0400, Jason Baron wrote:
>>>
>>> On 5/14/21 1:38 PM, Joe Perches wrote:
>>>> On Tue, 2021-05-11 at 17:31 -0400, Jason Baron wrote:
>>>>
>>>>> That said, I do see the value in not having to open code the branch stuff, and
>>>>> making pr_debug() consistent with printk which does return a value. So that
>>>>> makes sense to me.
>>>>
>>>> IMO: printk should not return a value.
>>>>
>>>
>>> Ok, the issue we are trying to resolve is to control whether a 'pr_debug()' statement
>>> is enabled and thus use that to control subsequent output. The proposed patch does:
>>>
>>>
>>> + printed = pr_debug("e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>> + if (printed > 0) {
>>> + e820_print_type(old_type);
>>> + pr_cont(" ==> ");
>>> + e820_print_type(new_type);
>>> + pr_cont("\n");
>>> + }
>>>
>>> I do think pr_debug() here is different from printk() b/c it can be explicitly
>>> toggled.
>>>
>>> I also suggested an alternative, which is possible with the current code which
>>> is to use DYNAMIC_DEBUG_BRANCH().
>>>
>>> if (DYNAMIC_DEBUG_BRANCH(e820_debg)) {
>>>     printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>>>     e820_print_type(old_type);
>>>     pr_cont(" ==> ");
>>>     e820_print_type(new_type);
>>>     pr_cont("\n");
>>> }
>>>
>>> That however does require one to do something like this first:
>>>
>>> DEFINE_DYNAMIC_DEBUG_METADATA(e820_dbg, "e820 verbose mode");
>>>
>>> So I don't feel too strongly either way, but maybe others do?
>>
>> Why not avoid the problem by using temporaries on the stack
>> and not use pr_cont altogether?
>
> Nice. That's fine with me Heiner?
>
I once tested a similar approach, just using kasprintf() to dynamically
allocate the substrings. Still using pr_cont() looks a little bit
more elegant to me, but it has its drawbacks. Having said that:
Yes, fine with me (with pr_debug).

> I think though Heiner wants to use pr_debug() below instead of printk
> with KERN_DEBUG, at least that was my understanding. But that would
> be a simpple s/printk/pr_debug().
>
> Thanks,
>
> -Jason
>

Heiner

>
>
>
>> ---
>> arch/x86/kernel/e820.c | 71 ++++++++++++++++++++++++++++++++------------------
>> 1 file changed, 46 insertions(+), 25 deletions(-)
>>
>> diff --git a/arch/x86/kernel/e820.c b/arch/x86/kernel/e820.c
>> index bc0657f0deed..a6e7ab4b522b 100644
>> --- a/arch/x86/kernel/e820.c
>> +++ b/arch/x86/kernel/e820.c
>> @@ -184,20 +184,38 @@ void __init e820__range_add(u64 start, u64 size, enum e820_type type)
>> __e820__range_add(e820_table, start, size, type);
>> }
>>
>> -static void __init e820_print_type(enum e820_type type)
>> +static char * __init e820_fmt_type(enum e820_type type, char *buf, size_t size)
>> {
>> switch (type) {
>> - case E820_TYPE_RAM: /* Fall through: */
>> - case E820_TYPE_RESERVED_KERN: pr_cont("usable"); break;
>> - case E820_TYPE_RESERVED: pr_cont("reserved"); break;
>> - case E820_TYPE_SOFT_RESERVED: pr_cont("soft reserved"); break;
>> - case E820_TYPE_ACPI: pr_cont("ACPI data"); break;
>> - case E820_TYPE_NVS: pr_cont("ACPI NVS"); break;
>> - case E820_TYPE_UNUSABLE: pr_cont("unusable"); break;
>> - case E820_TYPE_PMEM: /* Fall through: */
>> - case E820_TYPE_PRAM: pr_cont("persistent (type %u)", type); break;
>> - default: pr_cont("type %u", type); break;
>> + case E820_TYPE_RAM:
>> + case E820_TYPE_RESERVED_KERN:
>> + strscpy(buf, "usable", size);
>> + break;
>> + case E820_TYPE_RESERVED:
>> + strscpy(buf, "reserved", size);
>> + break;
>> + case E820_TYPE_SOFT_RESERVED:
>> + strscpy(buf, "soft reserved", size);
>> + break;
>> + case E820_TYPE_ACPI:
>> + strscpy(buf, "ACPI data", size);
>> + break;
>> + case E820_TYPE_NVS:
>> + strscpy(buf, "ACPI NVS", size);
>> + break;
>> + case E820_TYPE_UNUSABLE:
>> + strscpy(buf, "unusable", size);
>> + break;
>> + case E820_TYPE_PMEM:
>> + case E820_TYPE_PRAM:
>> + scnprintf(buf, size, "persistent (type %u)", type);
>> + break;
>> + default:
>> + scnprintf(buf, size, "type %u", type);
>> + break;
>> }
>> +
>> + return buf;
>> }
>>
>> void __init e820__print_table(char *who)
>> @@ -205,13 +223,14 @@ void __init e820__print_table(char *who)
>> int i;
>>
>> for (i = 0; i < e820_table->nr_entries; i++) {
>> - pr_info("%s: [mem %#018Lx-%#018Lx] ",
>> + char type[32];
>> +
>> + pr_info("%s: [mem %#018Lx-%#018Lx] %s\n",
>> who,
>> e820_table->entries[i].addr,
>> - e820_table->entries[i].addr + e820_table->entries[i].size - 1);
>> -
>> - e820_print_type(e820_table->entries[i].type);
>> - pr_cont("\n");
>> + e820_table->entries[i].addr + e820_table->entries[i].size - 1,
>> + e820_fmt_type(e820_table->entries[i].type,
>> + type, sizeof(type)));
>> }
>> }
>>
>> @@ -465,6 +484,8 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>> u64 end;
>> unsigned int i;
>> u64 real_updated_size = 0;
>> + char type1[32];
>> + char type2[32];
>>
>> BUG_ON(old_type == new_type);
>>
>> @@ -472,11 +493,10 @@ __e820__range_update(struct e820_table *table, u64 start, u64 size, enum e820_ty
>> size = ULLONG_MAX - start;
>>
>> end = start + size;
>> - printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] ", start, end - 1);
>> - e820_print_type(old_type);
>> - pr_cont(" ==> ");
>> - e820_print_type(new_type);
>> - pr_cont("\n");
>> + printk(KERN_DEBUG "e820: update [mem %#010Lx-%#010Lx] %s ==> %s\n",
>> + start, end - 1,
>> + e820_fmt_type(old_type, type1, sizeof(type1)),
>> + e820_fmt_type(new_type, type2, sizeof(type2)));
>>
>> for (i = 0; i < table->nr_entries; i++) {
>> struct e820_entry *entry = &table->entries[i];
>> @@ -543,15 +563,16 @@ u64 __init e820__range_remove(u64 start, u64 size, enum e820_type old_type, bool
>> int i;
>> u64 end;
>> u64 real_removed_size = 0;
>> + char type[32];
>>
>> if (size > (ULLONG_MAX - start))
>> size = ULLONG_MAX - start;
>>
>> end = start + size;
>> - printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx] ", start, end - 1);
>> - if (check_type)
>> - e820_print_type(old_type);
>> - pr_cont("\n");
>> + printk(KERN_DEBUG "e820: remove [mem %#010Lx-%#010Lx]%s%s\n",
>> + start, end - 1,
>> + check_type ? " " : "",
>> + check_type ? e820_fmt_type(old_type, type, sizeof(type)) : "");
>>
>> for (i = 0; i < e820_table->nr_entries; i++) {
>> struct e820_entry *entry = &e820_table->entries[i];
>>
>>