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

[Jason Baron]

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 <hkallweit1@xxxxxxxxx>
>>>>> ---
>>>>>  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
>