diff mbox series

[4/5] log: convert pr_*() to logging

Message ID 20210104070256.260002-5-xypron.glpk@gmx.de
State Accepted
Commit e86ad666d08599e2bb163260d63ab670cf82aa4a
Delegated to: Tom Rini
Headers show
Series None | expand

Commit Message

Heinrich Schuchardt Jan. 4, 2021, 7:02 a.m. UTC
In drivers we use a family of printing functions including pr_err() and
pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
via printf().

Our logging functions allow finer grained control of output. So replace
printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
remains unchanged.

Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
---
 include/linux/bitops.h |  4 ++-
 include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
 2 files changed, 48 insertions(+), 38 deletions(-)

--
2.29.2

Comments

Simon Glass Jan. 7, 2021, 12:36 p.m. UTC | #1
Hi Heinrich,

On Mon, 4 Jan 2021 at 00:03, Heinrich Schuchardt <xypron.glpk@gmx.de> wrote:
>
> In drivers we use a family of printing functions including pr_err() and
> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
> via printf().
>
> Our logging functions allow finer grained control of output. So replace
> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
> remains unchanged.
>
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> ---
>  include/linux/bitops.h |  4 ++-
>  include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>  2 files changed, 48 insertions(+), 38 deletions(-)
>
> diff --git a/include/linux/bitops.h b/include/linux/bitops.h
> index 16f28993f5..d2e5ca026e 100644
> --- a/include/linux/bitops.h
> +++ b/include/linux/bitops.h
> @@ -6,7 +6,6 @@
>  #include <asm/types.h>
>  #include <asm-generic/bitsperlong.h>
>  #include <linux/compiler.h>
> -#include <linux/kernel.h>
>
>  #ifdef __KERNEL__
>  #define BIT(nr)                        (1UL << (nr))
> @@ -19,6 +18,9 @@
>  #define BITS_TO_LONGS(nr)      DIV_ROUND_UP(nr, BITS_PER_BYTE * sizeof(long))
>  #endif
>
> +/* kernel.h includes log.h which include bitops.h */
> +#include <linux/kernel.h>
> +
>  /*
>   * Create a contiguous bitmask starting at bit position @l and ending at
>   * position @h. For example
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 088513ad29..5e85513853 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -1,6 +1,7 @@
>  #ifndef __KERNEL_PRINTK__
>  #define __KERNEL_PRINTK__
>
> +#include <log.h>
>  #include <stdio.h>
>  #include <linux/compiler.h>
>
> @@ -28,49 +29,56 @@
>         0;                                              \
>  })
>
> -#define __printk(level, fmt, ...)                                      \
> -({                                                                     \
> -       level < CONFIG_LOGLEVEL ? printk(fmt, ##__VA_ARGS__) : 0;       \
> -})
> -
>  #ifndef pr_fmt
>  #define pr_fmt(fmt) fmt
>  #endif
>
> -#define pr_emerg(fmt, ...) \
> -       __printk(0, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_alert(fmt, ...) \
> -       __printk(1, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_crit(fmt, ...) \
> -       __printk(2, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_err(fmt, ...) \
> -       __printk(3, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_warning(fmt, ...) \
> -       __printk(4, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_warn pr_warning
> -#define pr_notice(fmt, ...) \
> -       __printk(5, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_info(fmt, ...) \
> -       __printk(6, pr_fmt(fmt), ##__VA_ARGS__)
> -
> -#define pr_cont(fmt, ...) \
> -       printk(fmt, ##__VA_ARGS__)
> -
> -/* pr_devel() should produce zero code unless DEBUG is defined */
> -#ifdef DEBUG
> -#define pr_devel(fmt, ...) \
> -       __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
> -#else
> -#define pr_devel(fmt, ...) \
> -       no_printk(pr_fmt(fmt), ##__VA_ARGS__)
> -#endif
> +#define pr_emerg(fmt, ...)                                             \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 0 ? log_emerg(fmt, ##__VA_ARGS__) : 0;        \

Should this use CONFIG_VAL(LOGLEVEL) ?

Also I don't suppose there is a way to implement this in the __printk() macro?

> +})
> +#define pr_alert(fmt, ...)                                             \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 1 ? log_alert(fmt, ##__VA_ARGS__) : 0;        \
> +})
> +#define pr_crit(fmt, ...)                                              \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 2 ? log_crit(fmt, ##__VA_ARGS__) : 0;         \
> +})
> +#define pr_err(fmt, ...)                                               \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 3 ? log_err(fmt, ##__VA_ARGS__) : 0;          \
> +})
> +#define pr_warn(fmt, ...)                                              \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 4 ? log_warning(fmt, ##__VA_ARGS__) : 0;      \
> +})
> +#define pr_notice(fmt, ...)                                            \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 5 ? log_notice(fmt, ##__VA_ARGS__) : 0;       \
> +})
> +#define pr_info(fmt, ...)                                              \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 6 ? log_info(fmt, ##__VA_ARGS__) : 0;         \
> +})
> +#define pr_debug(fmt, ...)                                             \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;        \
> +})
> +#define pr_devel(fmt, ...)                                             \
> +({                                                                     \
> +       CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;        \
> +})
>
> -#ifdef DEBUG
> -#define pr_debug(fmt, ...) \
> -       __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
> +#ifdef CONFIG_LOG
> +#define pr_cont(fmt, ...)                                              \
> +({                                                                     \
> +       gd->logl_prev < CONFIG_LOGLEVEL ?                               \
> +               log_cont(fmt, ##__VA_ARGS__) : 0;                       \
> +})
>  #else
> -#define pr_debug(fmt, ...) \
> -       no_printk(pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_cont(fmt, ...)                                              \
> +       printk(fmt, ##__VA_ARGS__)
>  #endif
>
>  #define printk_once(fmt, ...) \
> --
> 2.29.2
>

Regards,
Simon
Tom Rini Jan. 17, 2021, 12:16 a.m. UTC | #2
On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:

> In drivers we use a family of printing functions including pr_err() and
> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
> via printf().
> 
> Our logging functions allow finer grained control of output. So replace
> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
> remains unchanged.
> 
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> ---
>  include/linux/bitops.h |  4 ++-
>  include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>  2 files changed, 48 insertions(+), 38 deletions(-)

This causes some fairly massive growth in various subsystems such as ubi
and we might want to look at what, if anything, we can do, before
growing some platforms by 15KiB (xilinx_zynqmp_virt) due to strings.
Thanks.
Sean Anderson Jan. 17, 2021, 12:37 a.m. UTC | #3
On 1/4/21 2:02 AM, Heinrich Schuchardt wrote:
> In drivers we use a family of printing functions including pr_err() and
> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
> via printf().
> 
> Our logging functions allow finer grained control of output. So replace
> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
> remains unchanged.
> 
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> ---
>   include/linux/bitops.h |  4 ++-
>   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>   2 files changed, 48 insertions(+), 38 deletions(-)
> 
> diff --git a/include/linux/bitops.h b/include/linux/bitops.h
> index 16f28993f5..d2e5ca026e 100644
> --- a/include/linux/bitops.h
> +++ b/include/linux/bitops.h
> @@ -6,7 +6,6 @@
>   #include <asm/types.h>
>   #include <asm-generic/bitsperlong.h>
>   #include <linux/compiler.h>
> -#include <linux/kernel.h>
> 
>   #ifdef	__KERNEL__
>   #define BIT(nr)			(1UL << (nr))
> @@ -19,6 +18,9 @@
>   #define BITS_TO_LONGS(nr)	DIV_ROUND_UP(nr, BITS_PER_BYTE * sizeof(long))
>   #endif
> 
> +/* kernel.h includes log.h which include bitops.h */
> +#include <linux/kernel.h>
> +
>   /*
>    * Create a contiguous bitmask starting at bit position @l and ending at
>    * position @h. For example
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 088513ad29..5e85513853 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -1,6 +1,7 @@
>   #ifndef __KERNEL_PRINTK__
>   #define __KERNEL_PRINTK__
> 
> +#include <log.h>
>   #include <stdio.h>
>   #include <linux/compiler.h>
> 
> @@ -28,49 +29,56 @@
>   	0;						\
>   })
> 
> -#define __printk(level, fmt, ...)					\
> -({									\
> -	level < CONFIG_LOGLEVEL ? printk(fmt, ##__VA_ARGS__) : 0;	\

Couldn't we just do

#define __printk(level, fmt, ...) log(LOG_CATEGORY, level, fmt, ##__VA_ARGS__)

> -})
> -
>   #ifndef pr_fmt
>   #define pr_fmt(fmt) fmt
>   #endif
> 
> -#define pr_emerg(fmt, ...) \
> -	__printk(0, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_alert(fmt, ...) \
> -	__printk(1, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_crit(fmt, ...) \
> -	__printk(2, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_err(fmt, ...) \
> -	__printk(3, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_warning(fmt, ...) \
> -	__printk(4, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_warn pr_warning
> -#define pr_notice(fmt, ...) \
> -	__printk(5, pr_fmt(fmt), ##__VA_ARGS__)
> -#define pr_info(fmt, ...) \
> -	__printk(6, pr_fmt(fmt), ##__VA_ARGS__)
> -
> -#define pr_cont(fmt, ...) \
> -	printk(fmt, ##__VA_ARGS__)
> -
> -/* pr_devel() should produce zero code unless DEBUG is defined */
> -#ifdef DEBUG
> -#define pr_devel(fmt, ...) \
> -	__printk(7, pr_fmt(fmt), ##__VA_ARGS__)
> -#else
> -#define pr_devel(fmt, ...) \
> -	no_printk(pr_fmt(fmt), ##__VA_ARGS__)
> -#endif
> +#define pr_emerg(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 0 ? log_emerg(fmt, ##__VA_ARGS__) : 0;	\
> +})

There is also an off-by-one mismatch between the numbers here and the
log level constants. E.g. LOGL_INFO is 6, but pr_info only gets emitted
if CONFIG_LOGLEVEL is >= 7.

--Sean

> +#define pr_alert(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 1 ? log_alert(fmt, ##__VA_ARGS__) : 0;	\
> +})
> +#define pr_crit(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 2 ? log_crit(fmt, ##__VA_ARGS__) : 0;		\
> +})
> +#define pr_err(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 3 ? log_err(fmt, ##__VA_ARGS__) : 0;		\
> +})
> +#define pr_warn(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 4 ? log_warning(fmt, ##__VA_ARGS__) : 0;	\
> +})
> +#define pr_notice(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 5 ? log_notice(fmt, ##__VA_ARGS__) : 0;	\
> +})
> +#define pr_info(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 6 ? log_info(fmt, ##__VA_ARGS__) : 0;		\
> +})
> +#define pr_debug(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;	\
> +})
> +#define pr_devel(fmt, ...)						\
> +({									\
> +	CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;	\
> +})
> 
> -#ifdef DEBUG
> -#define pr_debug(fmt, ...) \
> -	__printk(7, pr_fmt(fmt), ##__VA_ARGS__)
> +#ifdef CONFIG_LOG
> +#define pr_cont(fmt, ...)						\
> +({									\
> +	gd->logl_prev < CONFIG_LOGLEVEL ?				\
> +		log_cont(fmt, ##__VA_ARGS__) : 0;			\
> +})
>   #else
> -#define pr_debug(fmt, ...) \
> -	no_printk(pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_cont(fmt, ...)						\
> +	printk(fmt, ##__VA_ARGS__)
>   #endif
> 
>   #define printk_once(fmt, ...) \
> --
> 2.29.2
>
Heinrich Schuchardt Jan. 17, 2021, 7:26 a.m. UTC | #4
On 1/17/21 1:37 AM, Sean Anderson wrote:
> On 1/4/21 2:02 AM, Heinrich Schuchardt wrote:
>> In drivers we use a family of printing functions including pr_err() and
>> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to 
>> output
>> via printf().
>>
>> Our logging functions allow finer grained control of output. So replace
>> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
>> remains unchanged.
>>
>> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
>> ---
>>   include/linux/bitops.h |  4 ++-
>>   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>>   2 files changed, 48 insertions(+), 38 deletions(-)
>>
>> diff --git a/include/linux/bitops.h b/include/linux/bitops.h
>> index 16f28993f5..d2e5ca026e 100644
>> --- a/include/linux/bitops.h
>> +++ b/include/linux/bitops.h
>> @@ -6,7 +6,6 @@
>>   #include <asm/types.h>
>>   #include <asm-generic/bitsperlong.h>
>>   #include <linux/compiler.h>
>> -#include <linux/kernel.h>
>>
>>   #ifdef    __KERNEL__
>>   #define BIT(nr)            (1UL << (nr))
>> @@ -19,6 +18,9 @@
>>   #define BITS_TO_LONGS(nr)    DIV_ROUND_UP(nr, BITS_PER_BYTE * 
>> sizeof(long))
>>   #endif
>>
>> +/* kernel.h includes log.h which include bitops.h */
>> +#include <linux/kernel.h>
>> +
>>   /*
>>    * Create a contiguous bitmask starting at bit position @l and 
>> ending at
>>    * position @h. For example
>> diff --git a/include/linux/printk.h b/include/linux/printk.h
>> index 088513ad29..5e85513853 100644
>> --- a/include/linux/printk.h
>> +++ b/include/linux/printk.h
>> @@ -1,6 +1,7 @@
>>   #ifndef __KERNEL_PRINTK__
>>   #define __KERNEL_PRINTK__
>>
>> +#include <log.h>
>>   #include <stdio.h>
>>   #include <linux/compiler.h>
>>
>> @@ -28,49 +29,56 @@
>>       0;                        \
>>   })
>>
>> -#define __printk(level, fmt, ...)                    \
>> -({                                    \
>> -    level < CONFIG_LOGLEVEL ? printk(fmt, ##__VA_ARGS__) : 0;    \
> 
> Couldn't we just do
> 
> #define __printk(level, fmt, ...) log(LOG_CATEGORY, level, fmt, 
> ##__VA_ARGS__)

Dear Sean,

Thanks for reviewing.

As of today log() does not print anything if CONFIG_LOG is not enabled.

A patch by Simon to change this behavior is pending. If it gets merged, 
we can do the suggested simplification.

log: Convert log values to printf() if not enabled
https://patchwork.ozlabs.org/project/uboot/patch/20210114033051.483560-5-sjg@chromium.org/

> 
>> -})
>> -
>>   #ifndef pr_fmt
>>   #define pr_fmt(fmt) fmt
>>   #endif
>>
>> -#define pr_emerg(fmt, ...) \
>> -    __printk(0, pr_fmt(fmt), ##__VA_ARGS__)
>> -#define pr_alert(fmt, ...) \
>> -    __printk(1, pr_fmt(fmt), ##__VA_ARGS__)
>> -#define pr_crit(fmt, ...) \
>> -    __printk(2, pr_fmt(fmt), ##__VA_ARGS__)
>> -#define pr_err(fmt, ...) \
>> -    __printk(3, pr_fmt(fmt), ##__VA_ARGS__)
>> -#define pr_warning(fmt, ...) \
>> -    __printk(4, pr_fmt(fmt), ##__VA_ARGS__)
>> -#define pr_warn pr_warning
>> -#define pr_notice(fmt, ...) \
>> -    __printk(5, pr_fmt(fmt), ##__VA_ARGS__)
>> -#define pr_info(fmt, ...) \
>> -    __printk(6, pr_fmt(fmt), ##__VA_ARGS__)
>> -
>> -#define pr_cont(fmt, ...) \
>> -    printk(fmt, ##__VA_ARGS__)
>> -
>> -/* pr_devel() should produce zero code unless DEBUG is defined */
>> -#ifdef DEBUG
>> -#define pr_devel(fmt, ...) \
>> -    __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
>> -#else
>> -#define pr_devel(fmt, ...) \
>> -    no_printk(pr_fmt(fmt), ##__VA_ARGS__)
>> -#endif
>> +#define pr_emerg(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 0 ? log_emerg(fmt, ##__VA_ARGS__) : 0;    \
>> +})
> 
> There is also an off-by-one mismatch between the numbers here and the
> log level constants. E.g. LOGL_INFO is 6, but pr_info only gets emitted
> if CONFIG_LOGLEVEL is >= 7.

The Kconfig for CONFIG_LOGLEVEL description reads:

"All Messages with a loglevel *smaller than* the console loglevel will 
be compiled in."

I did not intend to change this definition.

Best regards

Heinrich

> 
> --Sean
> 
>> +#define pr_alert(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 1 ? log_alert(fmt, ##__VA_ARGS__) : 0;    \
>> +})
>> +#define pr_crit(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 2 ? log_crit(fmt, ##__VA_ARGS__) : 0;        \
>> +})
>> +#define pr_err(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 3 ? log_err(fmt, ##__VA_ARGS__) : 0;        \
>> +})
>> +#define pr_warn(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 4 ? log_warning(fmt, ##__VA_ARGS__) : 0;    \
>> +})
>> +#define pr_notice(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 5 ? log_notice(fmt, ##__VA_ARGS__) : 0;    \
>> +})
>> +#define pr_info(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 6 ? log_info(fmt, ##__VA_ARGS__) : 0;        \
>> +})
>> +#define pr_debug(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;    \
>> +})
>> +#define pr_devel(fmt, ...)                        \
>> +({                                    \
>> +    CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;    \
>> +})
>>
>> -#ifdef DEBUG
>> -#define pr_debug(fmt, ...) \
>> -    __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
>> +#ifdef CONFIG_LOG
>> +#define pr_cont(fmt, ...)                        \
>> +({                                    \
>> +    gd->logl_prev < CONFIG_LOGLEVEL ?                \
>> +        log_cont(fmt, ##__VA_ARGS__) : 0;            \
>> +})
>>   #else
>> -#define pr_debug(fmt, ...) \
>> -    no_printk(pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_cont(fmt, ...)                        \
>> +    printk(fmt, ##__VA_ARGS__)
>>   #endif
>>
>>   #define printk_once(fmt, ...) \
>> -- 
>> 2.29.2
>>
>
Heinrich Schuchardt Jan. 17, 2021, 7:37 a.m. UTC | #5
On 1/17/21 1:16 AM, Tom Rini wrote:
> On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:
>
>> In drivers we use a family of printing functions including pr_err() and
>> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
>> via printf().
>>
>> Our logging functions allow finer grained control of output. So replace
>> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
>> remains unchanged.
>>
>> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
>> ---
>>   include/linux/bitops.h |  4 ++-
>>   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>>   2 files changed, 48 insertions(+), 38 deletions(-)
>
> This causes some fairly massive growth in various subsystems such as ubi
> and we might want to look at what, if anything, we can do, before
> growing some platforms by 15KiB (xilinx_zynqmp_virt) due to strings.

xilinx_zynqmp_virt has CONFIG_LOG enabled. Switching from printf() to
log() incurs size growth. Did you observe a size grows on platforms with
CONFIG_LOG=n?

Best regards

Heinrich

> Thanks.
>
Sean Anderson Jan. 17, 2021, 10:27 p.m. UTC | #6
On 1/17/21 2:26 AM, Heinrich Schuchardt wrote:
> On 1/17/21 1:37 AM, Sean Anderson wrote:
>> On 1/4/21 2:02 AM, Heinrich Schuchardt wrote:
>>> In drivers we use a family of printing functions including pr_err() and
>>> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
>>> via printf().
>>>
>>> Our logging functions allow finer grained control of output. So replace
>>> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
>>> remains unchanged.
>>>
>>> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
>>> ---
>>>   include/linux/bitops.h |  4 ++-
>>>   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>>>   2 files changed, 48 insertions(+), 38 deletions(-)
>>>
>>> diff --git a/include/linux/bitops.h b/include/linux/bitops.h
>>> index 16f28993f5..d2e5ca026e 100644
>>> --- a/include/linux/bitops.h
>>> +++ b/include/linux/bitops.h
>>> @@ -6,7 +6,6 @@
>>>   #include <asm/types.h>
>>>   #include <asm-generic/bitsperlong.h>
>>>   #include <linux/compiler.h>
>>> -#include <linux/kernel.h>
>>>
>>>   #ifdef    __KERNEL__
>>>   #define BIT(nr)            (1UL << (nr))
>>> @@ -19,6 +18,9 @@
>>>   #define BITS_TO_LONGS(nr)    DIV_ROUND_UP(nr, BITS_PER_BYTE * sizeof(long))
>>>   #endif
>>>
>>> +/* kernel.h includes log.h which include bitops.h */
>>> +#include <linux/kernel.h>
>>> +
>>>   /*
>>>    * Create a contiguous bitmask starting at bit position @l and ending at
>>>    * position @h. For example
>>> diff --git a/include/linux/printk.h b/include/linux/printk.h
>>> index 088513ad29..5e85513853 100644
>>> --- a/include/linux/printk.h
>>> +++ b/include/linux/printk.h
>>> @@ -1,6 +1,7 @@
>>>   #ifndef __KERNEL_PRINTK__
>>>   #define __KERNEL_PRINTK__
>>>
>>> +#include <log.h>
>>>   #include <stdio.h>
>>>   #include <linux/compiler.h>
>>>
>>> @@ -28,49 +29,56 @@
>>>       0;                        \
>>>   })
>>>
>>> -#define __printk(level, fmt, ...)                    \
>>> -({                                    \
>>> -    level < CONFIG_LOGLEVEL ? printk(fmt, ##__VA_ARGS__) : 0;    \
>>
>> Couldn't we just do
>>
>> #define __printk(level, fmt, ...) log(LOG_CATEGORY, level, fmt, ##__VA_ARGS__)
> 
> Dear Sean,
> 
> Thanks for reviewing.
> 
> As of today log() does not print anything if CONFIG_LOG is not enabled.

> #if CONFIG_IS_ENABLED(LOG)
> #define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL)
> #define log_err(_fmt...)	log(LOG_CATEGORY, LOGL_ERR, ##_fmt)
> #define log_warning(_fmt...)	log(LOG_CATEGORY, LOGL_WARNING, ##_fmt)
> #define log_notice(_fmt...)	log(LOG_CATEGORY, LOGL_NOTICE, ##_fmt)
> #define log_info(_fmt...)	log(LOG_CATEGORY, LOGL_INFO, ##_fmt)
> #define log_debug(_fmt...)	log(LOG_CATEGORY, LOGL_DEBUG, ##_fmt)
> #define log_content(_fmt...)	log(LOG_CATEGORY, LOGL_DEBUG_CONTENT, ##_fmt)
> #define log_io(_fmt...)		log(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt)
> #else
> #define _LOG_MAX_LEVEL LOGL_INFO
> #define log_err(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
> #define log_warning(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
> #define log_notice(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
> #define log_info(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
> #define log_debug(_fmt, ...)	debug(_fmt, ##__VA_ARGS__)
> #define log_content(_fmt...)	log_nop(LOG_CATEGORY, \
> 					LOGL_DEBUG_CONTENT, ##_fmt)
> #define log_io(_fmt...)		log_nop(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt)
> #endif

If CONFIG_LOG is not enabled, then log statements are converted to
debug and printf.

> 
> A patch by Simon to change this behavior is pending. If it gets merged, we can do the suggested simplification.
> 
> log: Convert log values to printf() if not enabled
> https://patchwork.ozlabs.org/project/uboot/patch/20210114033051.483560-5-sjg@chromium.org/
> 
>>
>>> -})
>>> -
>>>   #ifndef pr_fmt
>>>   #define pr_fmt(fmt) fmt
>>>   #endif
>>>
>>> -#define pr_emerg(fmt, ...) \
>>> -    __printk(0, pr_fmt(fmt), ##__VA_ARGS__)
>>> -#define pr_alert(fmt, ...) \
>>> -    __printk(1, pr_fmt(fmt), ##__VA_ARGS__)
>>> -#define pr_crit(fmt, ...) \
>>> -    __printk(2, pr_fmt(fmt), ##__VA_ARGS__)
>>> -#define pr_err(fmt, ...) \
>>> -    __printk(3, pr_fmt(fmt), ##__VA_ARGS__)
>>> -#define pr_warning(fmt, ...) \
>>> -    __printk(4, pr_fmt(fmt), ##__VA_ARGS__)
>>> -#define pr_warn pr_warning
>>> -#define pr_notice(fmt, ...) \
>>> -    __printk(5, pr_fmt(fmt), ##__VA_ARGS__)
>>> -#define pr_info(fmt, ...) \
>>> -    __printk(6, pr_fmt(fmt), ##__VA_ARGS__)
>>> -
>>> -#define pr_cont(fmt, ...) \
>>> -    printk(fmt, ##__VA_ARGS__)
>>> -
>>> -/* pr_devel() should produce zero code unless DEBUG is defined */
>>> -#ifdef DEBUG
>>> -#define pr_devel(fmt, ...) \
>>> -    __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
>>> -#else
>>> -#define pr_devel(fmt, ...) \
>>> -    no_printk(pr_fmt(fmt), ##__VA_ARGS__)
>>> -#endif
>>> +#define pr_emerg(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 0 ? log_emerg(fmt, ##__VA_ARGS__) : 0;    \
>>> +})
>>
>> There is also an off-by-one mismatch between the numbers here and the
>> log level constants. E.g. LOGL_INFO is 6, but pr_info only gets emitted
>> if CONFIG_LOGLEVEL is >= 7.
> 
> The Kconfig for CONFIG_LOGLEVEL description reads:
> 
> "All Messages with a loglevel *smaller than* the console loglevel will be compiled in."

Ok then, perhaps that should be rectified.

--Sean

> 
> I did not intend to change this definition.
> 
> Best regards
> 
> Heinrich
> 
>>
>> --Sean
>>
>>> +#define pr_alert(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 1 ? log_alert(fmt, ##__VA_ARGS__) : 0;    \
>>> +})
>>> +#define pr_crit(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 2 ? log_crit(fmt, ##__VA_ARGS__) : 0;        \
>>> +})
>>> +#define pr_err(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 3 ? log_err(fmt, ##__VA_ARGS__) : 0;        \
>>> +})
>>> +#define pr_warn(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 4 ? log_warning(fmt, ##__VA_ARGS__) : 0;    \
>>> +})
>>> +#define pr_notice(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 5 ? log_notice(fmt, ##__VA_ARGS__) : 0;    \
>>> +})
>>> +#define pr_info(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 6 ? log_info(fmt, ##__VA_ARGS__) : 0;        \
>>> +})
>>> +#define pr_debug(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;    \
>>> +})
>>> +#define pr_devel(fmt, ...)                        \
>>> +({                                    \
>>> +    CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;    \
>>> +})
>>>
>>> -#ifdef DEBUG
>>> -#define pr_debug(fmt, ...) \
>>> -    __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
>>> +#ifdef CONFIG_LOG
>>> +#define pr_cont(fmt, ...)                        \
>>> +({                                    \
>>> +    gd->logl_prev < CONFIG_LOGLEVEL ?                \
>>> +        log_cont(fmt, ##__VA_ARGS__) : 0;            \
>>> +})
>>>   #else
>>> -#define pr_debug(fmt, ...) \
>>> -    no_printk(pr_fmt(fmt), ##__VA_ARGS__)
>>> +#define pr_cont(fmt, ...)                        \
>>> +    printk(fmt, ##__VA_ARGS__)
>>>   #endif
>>>
>>>   #define printk_once(fmt, ...) \
>>> -- 
>>> 2.29.2
>>>
>>
>
Heinrich Schuchardt Jan. 17, 2021, 11:13 p.m. UTC | #7
On 1/17/21 11:27 PM, Sean Anderson wrote:
> On 1/17/21 2:26 AM, Heinrich Schuchardt wrote:
>> On 1/17/21 1:37 AM, Sean Anderson wrote:
>>> On 1/4/21 2:02 AM, Heinrich Schuchardt wrote:
>>>> In drivers we use a family of printing functions including pr_err() and
>>>> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to 
>>>> output
>>>> via printf().
>>>>
>>>> Our logging functions allow finer grained control of output. So replace
>>>> printf() by the matching logging functions. The usage of 
>>>> CONFIG_LOGLEVEL
>>>> remains unchanged.
>>>>
>>>> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
>>>> ---
>>>>   include/linux/bitops.h |  4 ++-
>>>>   include/linux/printk.h | 82 
>>>> +++++++++++++++++++++++-------------------
>>>>   2 files changed, 48 insertions(+), 38 deletions(-)
>>>>
>>>> diff --git a/include/linux/bitops.h b/include/linux/bitops.h
>>>> index 16f28993f5..d2e5ca026e 100644
>>>> --- a/include/linux/bitops.h
>>>> +++ b/include/linux/bitops.h
>>>> @@ -6,7 +6,6 @@
>>>>   #include <asm/types.h>
>>>>   #include <asm-generic/bitsperlong.h>
>>>>   #include <linux/compiler.h>
>>>> -#include <linux/kernel.h>
>>>>
>>>>   #ifdef    __KERNEL__
>>>>   #define BIT(nr)            (1UL << (nr))
>>>> @@ -19,6 +18,9 @@
>>>>   #define BITS_TO_LONGS(nr)    DIV_ROUND_UP(nr, BITS_PER_BYTE * 
>>>> sizeof(long))
>>>>   #endif
>>>>
>>>> +/* kernel.h includes log.h which include bitops.h */
>>>> +#include <linux/kernel.h>
>>>> +
>>>>   /*
>>>>    * Create a contiguous bitmask starting at bit position @l and 
>>>> ending at
>>>>    * position @h. For example
>>>> diff --git a/include/linux/printk.h b/include/linux/printk.h
>>>> index 088513ad29..5e85513853 100644
>>>> --- a/include/linux/printk.h
>>>> +++ b/include/linux/printk.h
>>>> @@ -1,6 +1,7 @@
>>>>   #ifndef __KERNEL_PRINTK__
>>>>   #define __KERNEL_PRINTK__
>>>>
>>>> +#include <log.h>
>>>>   #include <stdio.h>
>>>>   #include <linux/compiler.h>
>>>>
>>>> @@ -28,49 +29,56 @@
>>>>       0;                        \
>>>>   })
>>>>
>>>> -#define __printk(level, fmt, ...)                    \
>>>> -({                                    \
>>>> -    level < CONFIG_LOGLEVEL ? printk(fmt, ##__VA_ARGS__) : 0;    \
>>>
>>> Couldn't we just do
>>>
>>> #define __printk(level, fmt, ...) log(LOG_CATEGORY, level, fmt, 
>>> ##__VA_ARGS__)
>>
>> Dear Sean,
>>
>> Thanks for reviewing.
>>
>> As of today log() does not print anything if CONFIG_LOG is not enabled.
> 
>> #if CONFIG_IS_ENABLED(LOG)
>> #define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL)
>> #define log_err(_fmt...)    log(LOG_CATEGORY, LOGL_ERR, ##_fmt)
>> #define log_warning(_fmt...)    log(LOG_CATEGORY, LOGL_WARNING, ##_fmt)
>> #define log_notice(_fmt...)    log(LOG_CATEGORY, LOGL_NOTICE, ##_fmt)
>> #define log_info(_fmt...)    log(LOG_CATEGORY, LOGL_INFO, ##_fmt)
>> #define log_debug(_fmt...)    log(LOG_CATEGORY, LOGL_DEBUG, ##_fmt)
>> #define log_content(_fmt...)    log(LOG_CATEGORY, LOGL_DEBUG_CONTENT, 
>> ##_fmt)
>> #define log_io(_fmt...)        log(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt)
>> #else
>> #define _LOG_MAX_LEVEL LOGL_INFO
>> #define log_err(_fmt, ...)    printf(_fmt, ##__VA_ARGS__)
>> #define log_warning(_fmt, ...)    printf(_fmt, ##__VA_ARGS__)
>> #define log_notice(_fmt, ...)    printf(_fmt, ##__VA_ARGS__)
>> #define log_info(_fmt, ...)    printf(_fmt, ##__VA_ARGS__)
>> #define log_debug(_fmt, ...)    debug(_fmt, ##__VA_ARGS__)
>> #define log_content(_fmt...)    log_nop(LOG_CATEGORY, \
>>                     LOGL_DEBUG_CONTENT, ##_fmt)
>> #define log_io(_fmt...)        log_nop(LOG_CATEGORY, LOGL_DEBUG_IO, 
>> ##_fmt)
>> #endif
> 
> If CONFIG_LOG is not enabled, then log statements are converted to
> debug and printf.

Only the ones you cited, not the function log() referenced in your proposal.

> 
>>
>> A patch by Simon to change this behavior is pending. If it gets 
>> merged, we can do the suggested simplification.
>>
>> log: Convert log values to printf() if not enabled
>> https://patchwork.ozlabs.org/project/uboot/patch/20210114033051.483560-5-sjg@chromium.org/ 
>>
>>
>>>
>>>> -})
>>>> -
>>>>   #ifndef pr_fmt
>>>>   #define pr_fmt(fmt) fmt
>>>>   #endif
>>>>
>>>> -#define pr_emerg(fmt, ...) \
>>>> -    __printk(0, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#define pr_alert(fmt, ...) \
>>>> -    __printk(1, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#define pr_crit(fmt, ...) \
>>>> -    __printk(2, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#define pr_err(fmt, ...) \
>>>> -    __printk(3, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#define pr_warning(fmt, ...) \
>>>> -    __printk(4, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#define pr_warn pr_warning
>>>> -#define pr_notice(fmt, ...) \
>>>> -    __printk(5, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#define pr_info(fmt, ...) \
>>>> -    __printk(6, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -
>>>> -#define pr_cont(fmt, ...) \
>>>> -    printk(fmt, ##__VA_ARGS__)
>>>> -
>>>> -/* pr_devel() should produce zero code unless DEBUG is defined */
>>>> -#ifdef DEBUG
>>>> -#define pr_devel(fmt, ...) \
>>>> -    __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#else
>>>> -#define pr_devel(fmt, ...) \
>>>> -    no_printk(pr_fmt(fmt), ##__VA_ARGS__)
>>>> -#endif
>>>> +#define pr_emerg(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 0 ? log_emerg(fmt, ##__VA_ARGS__) : 0;    \
>>>> +})
>>>
>>> There is also an off-by-one mismatch between the numbers here and the
>>> log level constants. E.g. LOGL_INFO is 6, but pr_info only gets emitted
>>> if CONFIG_LOGLEVEL is >= 7.
>>
>> The Kconfig for CONFIG_LOGLEVEL description reads:
>>
>> "All Messages with a loglevel *smaller than* the console loglevel will 
>> be compiled in."
> 
> Ok then, perhaps that should be rectified.

The current definition allows to disable log level 0. So you better 
don't change it.

Best regards

Heinrich

> 
> --Sean
> 
>>
>> I did not intend to change this definition.
>>
>> Best regards
>>
>> Heinrich
>>
>>>
>>> --Sean
>>>
>>>> +#define pr_alert(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 1 ? log_alert(fmt, ##__VA_ARGS__) : 0;    \
>>>> +})
>>>> +#define pr_crit(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 2 ? log_crit(fmt, ##__VA_ARGS__) : 0;        \
>>>> +})
>>>> +#define pr_err(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 3 ? log_err(fmt, ##__VA_ARGS__) : 0;        \
>>>> +})
>>>> +#define pr_warn(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 4 ? log_warning(fmt, ##__VA_ARGS__) : 0;    \
>>>> +})
>>>> +#define pr_notice(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 5 ? log_notice(fmt, ##__VA_ARGS__) : 0;    \
>>>> +})
>>>> +#define pr_info(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 6 ? log_info(fmt, ##__VA_ARGS__) : 0;        \
>>>> +})
>>>> +#define pr_debug(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;    \
>>>> +})
>>>> +#define pr_devel(fmt, ...)                        \
>>>> +({                                    \
>>>> +    CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;    \
>>>> +})
>>>>
>>>> -#ifdef DEBUG
>>>> -#define pr_debug(fmt, ...) \
>>>> -    __printk(7, pr_fmt(fmt), ##__VA_ARGS__)
>>>> +#ifdef CONFIG_LOG
>>>> +#define pr_cont(fmt, ...)                        \
>>>> +({                                    \
>>>> +    gd->logl_prev < CONFIG_LOGLEVEL ?                \
>>>> +        log_cont(fmt, ##__VA_ARGS__) : 0;            \
>>>> +})
>>>>   #else
>>>> -#define pr_debug(fmt, ...) \
>>>> -    no_printk(pr_fmt(fmt), ##__VA_ARGS__)
>>>> +#define pr_cont(fmt, ...)                        \
>>>> +    printk(fmt, ##__VA_ARGS__)
>>>>   #endif
>>>>
>>>>   #define printk_once(fmt, ...) \
>>>> -- 
>>>> 2.29.2
>>>>
>>>
>>
>
Tom Rini Jan. 18, 2021, 1:02 p.m. UTC | #8
On Sun, Jan 17, 2021 at 08:37:15AM +0100, Heinrich Schuchardt wrote:
> On 1/17/21 1:16 AM, Tom Rini wrote:
> > On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:
> > 
> > > In drivers we use a family of printing functions including pr_err() and
> > > pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
> > > via printf().
> > > 
> > > Our logging functions allow finer grained control of output. So replace
> > > printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
> > > remains unchanged.
> > > 
> > > Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> > > ---
> > >   include/linux/bitops.h |  4 ++-
> > >   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
> > >   2 files changed, 48 insertions(+), 38 deletions(-)
> > 
> > This causes some fairly massive growth in various subsystems such as ubi
> > and we might want to look at what, if anything, we can do, before
> > growing some platforms by 15KiB (xilinx_zynqmp_virt) due to strings.
> 
> xilinx_zynqmp_virt has CONFIG_LOG enabled. Switching from printf() to
> log() incurs size growth. Did you observe a size grows on platforms with
> CONFIG_LOG=n?

Yes, it has logging enabled, and we're converting a large number of
things that were before compile-time discarded to no longer be so.  This
is, in general, good and what I've asked for.  But when seeing very
large growth in doing so, I think we need to maybe take a step back and
look at the UBI subsystem for example and see if we can't/shouldn't
tweak things more.

So, I'm going to run a size test with just this patch as the change, so
we can have more concrete numbers to look at.
Tom Rini Jan. 18, 2021, 3:30 p.m. UTC | #9
On Mon, Jan 18, 2021 at 08:02:41AM -0500, Tom Rini wrote:
> On Sun, Jan 17, 2021 at 08:37:15AM +0100, Heinrich Schuchardt wrote:
> > On 1/17/21 1:16 AM, Tom Rini wrote:
> > > On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:
> > > 
> > > > In drivers we use a family of printing functions including pr_err() and
> > > > pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
> > > > via printf().
> > > > 
> > > > Our logging functions allow finer grained control of output. So replace
> > > > printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
> > > > remains unchanged.
> > > > 
> > > > Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> > > > ---
> > > >   include/linux/bitops.h |  4 ++-
> > > >   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
> > > >   2 files changed, 48 insertions(+), 38 deletions(-)
> > > 
> > > This causes some fairly massive growth in various subsystems such as ubi
> > > and we might want to look at what, if anything, we can do, before
> > > growing some platforms by 15KiB (xilinx_zynqmp_virt) due to strings.
> > 
> > xilinx_zynqmp_virt has CONFIG_LOG enabled. Switching from printf() to
> > log() incurs size growth. Did you observe a size grows on platforms with
> > CONFIG_LOG=n?
> 
> Yes, it has logging enabled, and we're converting a large number of
> things that were before compile-time discarded to no longer be so.  This
> is, in general, good and what I've asked for.  But when seeing very
> large growth in doing so, I think we need to maybe take a step back and
> look at the UBI subsystem for example and see if we can't/shouldn't
> tweak things more.
> 
> So, I'm going to run a size test with just this patch as the change, so
> we can have more concrete numbers to look at.

OK, so the build is done and interesting output starts at:
https://gist.github.com/trini/53e7da62c6c9d18c189e6baffd01ff00#file-2021-01-18-0800-txt-L239

Most of the time we're well under 1KiB, which is great.  UBI has some
huge growth, but it's a very few platforms, and I've added the
custodians here so they can object, or not, to such size growth.
Heinrich Schuchardt Feb. 18, 2021, 9:16 a.m. UTC | #10
On 18.01.21 16:30, Tom Rini wrote:
> On Mon, Jan 18, 2021 at 08:02:41AM -0500, Tom Rini wrote:
>> On Sun, Jan 17, 2021 at 08:37:15AM +0100, Heinrich Schuchardt wrote:
>>> On 1/17/21 1:16 AM, Tom Rini wrote:
>>>> On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:
>>>>
>>>>> In drivers we use a family of printing functions including pr_err() and
>>>>> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
>>>>> via printf().
>>>>>
>>>>> Our logging functions allow finer grained control of output. So replace
>>>>> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
>>>>> remains unchanged.
>>>>>
>>>>> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
>>>>> ---
>>>>>   include/linux/bitops.h |  4 ++-
>>>>>   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>>>>>   2 files changed, 48 insertions(+), 38 deletions(-)
>>>>
>>>> This causes some fairly massive growth in various subsystems such as ubi
>>>> and we might want to look at what, if anything, we can do, before
>>>> growing some platforms by 15KiB (xilinx_zynqmp_virt) due to strings.
>>>
>>> xilinx_zynqmp_virt has CONFIG_LOG enabled. Switching from printf() to
>>> log() incurs size growth. Did you observe a size grows on platforms with
>>> CONFIG_LOG=n?
>>
>> Yes, it has logging enabled, and we're converting a large number of
>> things that were before compile-time discarded to no longer be so.  This
>> is, in general, good and what I've asked for.  But when seeing very
>> large growth in doing so, I think we need to maybe take a step back and
>> look at the UBI subsystem for example and see if we can't/shouldn't
>> tweak things more.
>>
>> So, I'm going to run a size test with just this patch as the change, so
>> we can have more concrete numbers to look at.
>
> OK, so the build is done and interesting output starts at:
> https://gist.github.com/trini/53e7da62c6c9d18c189e6baffd01ff00#file-2021-01-18-0800-txt-L239
>
> Most of the time we're well under 1KiB, which is great.  UBI has some
> huge growth, but it's a very few platforms, and I've added the
> custodians here so they can object, or not, to such size growth.
>

Hello Tom,

How shall we proceed?

Best regards

Heinrich
Tom Rini Feb. 18, 2021, 1:05 p.m. UTC | #11
On Thu, Feb 18, 2021 at 10:16:58AM +0100, Heinrich Schuchardt wrote:
> On 18.01.21 16:30, Tom Rini wrote:
> > On Mon, Jan 18, 2021 at 08:02:41AM -0500, Tom Rini wrote:
> >> On Sun, Jan 17, 2021 at 08:37:15AM +0100, Heinrich Schuchardt wrote:
> >>> On 1/17/21 1:16 AM, Tom Rini wrote:
> >>>> On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:
> >>>>
> >>>>> In drivers we use a family of printing functions including pr_err() and
> >>>>> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
> >>>>> via printf().
> >>>>>
> >>>>> Our logging functions allow finer grained control of output. So replace
> >>>>> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
> >>>>> remains unchanged.
> >>>>>
> >>>>> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> >>>>> ---
> >>>>>   include/linux/bitops.h |  4 ++-
> >>>>>   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
> >>>>>   2 files changed, 48 insertions(+), 38 deletions(-)
> >>>>
> >>>> This causes some fairly massive growth in various subsystems such as ubi
> >>>> and we might want to look at what, if anything, we can do, before
> >>>> growing some platforms by 15KiB (xilinx_zynqmp_virt) due to strings.
> >>>
> >>> xilinx_zynqmp_virt has CONFIG_LOG enabled. Switching from printf() to
> >>> log() incurs size growth. Did you observe a size grows on platforms with
> >>> CONFIG_LOG=n?
> >>
> >> Yes, it has logging enabled, and we're converting a large number of
> >> things that were before compile-time discarded to no longer be so.  This
> >> is, in general, good and what I've asked for.  But when seeing very
> >> large growth in doing so, I think we need to maybe take a step back and
> >> look at the UBI subsystem for example and see if we can't/shouldn't
> >> tweak things more.
> >>
> >> So, I'm going to run a size test with just this patch as the change, so
> >> we can have more concrete numbers to look at.
> >
> > OK, so the build is done and interesting output starts at:
> > https://gist.github.com/trini/53e7da62c6c9d18c189e6baffd01ff00#file-2021-01-18-0800-txt-L239
> >
> > Most of the time we're well under 1KiB, which is great.  UBI has some
> > huge growth, but it's a very few platforms, and I've added the
> > custodians here so they can object, or not, to such size growth.
> >
> 
> Hello Tom,
> 
> How shall we proceed?

Michal? Patrice or Patrick?  Since this patch causes noticeable growth
on your platforms I'm waiting for your input here, to be clear.  Thanks!
Patrice CHOTARD Feb. 18, 2021, 3:04 p.m. UTC | #12
Hi Tom

On 2/18/21 2:05 PM, Tom Rini wrote:
> On Thu, Feb 18, 2021 at 10:16:58AM +0100, Heinrich Schuchardt wrote:
>> On 18.01.21 16:30, Tom Rini wrote:
>>> On Mon, Jan 18, 2021 at 08:02:41AM -0500, Tom Rini wrote:
>>>> On Sun, Jan 17, 2021 at 08:37:15AM +0100, Heinrich Schuchardt wrote:
>>>>> On 1/17/21 1:16 AM, Tom Rini wrote:
>>>>>> On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:
>>>>>>
>>>>>>> In drivers we use a family of printing functions including pr_err() and
>>>>>>> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
>>>>>>> via printf().
>>>>>>>
>>>>>>> Our logging functions allow finer grained control of output. So replace
>>>>>>> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
>>>>>>> remains unchanged.
>>>>>>>
>>>>>>> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
>>>>>>> ---
>>>>>>>   include/linux/bitops.h |  4 ++-
>>>>>>>   include/linux/printk.h | 82 +++++++++++++++++++++++-------------------
>>>>>>>   2 files changed, 48 insertions(+), 38 deletions(-)
>>>>>>
>>>>>> This causes some fairly massive growth in various subsystems such as ubi
>>>>>> and we might want to look at what, if anything, we can do, before
>>>>>> growing some platforms by 15KiB (xilinx_zynqmp_virt) due to strings.
>>>>>
>>>>> xilinx_zynqmp_virt has CONFIG_LOG enabled. Switching from printf() to
>>>>> log() incurs size growth. Did you observe a size grows on platforms with
>>>>> CONFIG_LOG=n?
>>>>
>>>> Yes, it has logging enabled, and we're converting a large number of
>>>> things that were before compile-time discarded to no longer be so.  This
>>>> is, in general, good and what I've asked for.  But when seeing very
>>>> large growth in doing so, I think we need to maybe take a step back and
>>>> look at the UBI subsystem for example and see if we can't/shouldn't
>>>> tweak things more.
>>>>
>>>> So, I'm going to run a size test with just this patch as the change, so
>>>> we can have more concrete numbers to look at.
>>>
>>> OK, so the build is done and interesting output starts at:
>>> https://gist.github.com/trini/53e7da62c6c9d18c189e6baffd01ff00#file-2021-01-18-0800-txt-L239
>>>
>>> Most of the time we're well under 1KiB, which is great.  UBI has some
>>> huge growth, but it's a very few platforms, and I've added the
>>> custodians here so they can object, or not, to such size growth.
>>>
>>
>> Hello Tom,
>>
>> How shall we proceed?
> 
> Michal? Patrice or Patrick?  Since this patch causes noticeable growth
> on your platforms I'm waiting for your input here, to be clear.  Thanks!
> 

No objection for stm32 platforms, ok for us ;-)

Patrice
Tom Rini March 2, 2021, 3:47 a.m. UTC | #13
On Mon, Jan 04, 2021 at 08:02:55AM +0100, Heinrich Schuchardt wrote:

> In drivers we use a family of printing functions including pr_err() and
> pr_cont(). CONFIG_LOGLEVEL is used to control which of these lead to output
> via printf().
> 
> Our logging functions allow finer grained control of output. So replace
> printf() by the matching logging functions. The usage of CONFIG_LOGLEVEL
> remains unchanged.
> 
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>

Applied to u-boot/master, thanks!
diff mbox series

Patch

diff --git a/include/linux/bitops.h b/include/linux/bitops.h
index 16f28993f5..d2e5ca026e 100644
--- a/include/linux/bitops.h
+++ b/include/linux/bitops.h
@@ -6,7 +6,6 @@ 
 #include <asm/types.h>
 #include <asm-generic/bitsperlong.h>
 #include <linux/compiler.h>
-#include <linux/kernel.h>

 #ifdef	__KERNEL__
 #define BIT(nr)			(1UL << (nr))
@@ -19,6 +18,9 @@ 
 #define BITS_TO_LONGS(nr)	DIV_ROUND_UP(nr, BITS_PER_BYTE * sizeof(long))
 #endif

+/* kernel.h includes log.h which include bitops.h */
+#include <linux/kernel.h>
+
 /*
  * Create a contiguous bitmask starting at bit position @l and ending at
  * position @h. For example
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 088513ad29..5e85513853 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -1,6 +1,7 @@ 
 #ifndef __KERNEL_PRINTK__
 #define __KERNEL_PRINTK__

+#include <log.h>
 #include <stdio.h>
 #include <linux/compiler.h>

@@ -28,49 +29,56 @@ 
 	0;						\
 })

-#define __printk(level, fmt, ...)					\
-({									\
-	level < CONFIG_LOGLEVEL ? printk(fmt, ##__VA_ARGS__) : 0;	\
-})
-
 #ifndef pr_fmt
 #define pr_fmt(fmt) fmt
 #endif

-#define pr_emerg(fmt, ...) \
-	__printk(0, pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_alert(fmt, ...) \
-	__printk(1, pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_crit(fmt, ...) \
-	__printk(2, pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_err(fmt, ...) \
-	__printk(3, pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_warning(fmt, ...) \
-	__printk(4, pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_warn pr_warning
-#define pr_notice(fmt, ...) \
-	__printk(5, pr_fmt(fmt), ##__VA_ARGS__)
-#define pr_info(fmt, ...) \
-	__printk(6, pr_fmt(fmt), ##__VA_ARGS__)
-
-#define pr_cont(fmt, ...) \
-	printk(fmt, ##__VA_ARGS__)
-
-/* pr_devel() should produce zero code unless DEBUG is defined */
-#ifdef DEBUG
-#define pr_devel(fmt, ...) \
-	__printk(7, pr_fmt(fmt), ##__VA_ARGS__)
-#else
-#define pr_devel(fmt, ...) \
-	no_printk(pr_fmt(fmt), ##__VA_ARGS__)
-#endif
+#define pr_emerg(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 0 ? log_emerg(fmt, ##__VA_ARGS__) : 0;	\
+})
+#define pr_alert(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 1 ? log_alert(fmt, ##__VA_ARGS__) : 0;	\
+})
+#define pr_crit(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 2 ? log_crit(fmt, ##__VA_ARGS__) : 0;		\
+})
+#define pr_err(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 3 ? log_err(fmt, ##__VA_ARGS__) : 0;		\
+})
+#define pr_warn(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 4 ? log_warning(fmt, ##__VA_ARGS__) : 0;	\
+})
+#define pr_notice(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 5 ? log_notice(fmt, ##__VA_ARGS__) : 0;	\
+})
+#define pr_info(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 6 ? log_info(fmt, ##__VA_ARGS__) : 0;		\
+})
+#define pr_debug(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;	\
+})
+#define pr_devel(fmt, ...)						\
+({									\
+	CONFIG_LOGLEVEL > 7 ? log_debug(fmt, ##__VA_ARGS__) : 0;	\
+})

-#ifdef DEBUG
-#define pr_debug(fmt, ...) \
-	__printk(7, pr_fmt(fmt), ##__VA_ARGS__)
+#ifdef CONFIG_LOG
+#define pr_cont(fmt, ...)						\
+({									\
+	gd->logl_prev < CONFIG_LOGLEVEL ?				\
+		log_cont(fmt, ##__VA_ARGS__) : 0;			\
+})
 #else
-#define pr_debug(fmt, ...) \
-	no_printk(pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_cont(fmt, ...)						\
+	printk(fmt, ##__VA_ARGS__)
 #endif

 #define printk_once(fmt, ...) \