[PATCH 4/5] log: convert pr_*() to logging
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 --- 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 #include #include -#include #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 + /* * 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 #include #include @@ -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
Re: [PATCH 4/5] log: convert pr_*() to logging
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 > --- > 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
Re: [PATCH 4/5] log: convert pr_*() to logging
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 > > --- > > 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! -- Tom signature.asc Description: PGP signature
Re: [PATCH 4/5] log: convert pr_*() to logging
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 >>> --- >>> 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
Re: [PATCH 4/5] log: convert pr_*() to logging
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 Applied to u-boot/master, thanks! -- Tom signature.asc Description: PGP signature
Re: [PATCH 4/5] log: convert pr_*() to logging
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 > --- > 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. -- Tom signature.asc Description: PGP signature
Re: [PATCH 4/5] log: convert pr_*() to logging
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 --- 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 #include #include -#include #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 + /* * 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 #include #include @@ -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; \ +}) -#i
Re: [PATCH 4/5] log: convert pr_*() to logging
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 --- 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 #include #include -#include #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 + /* * 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 #include #include @@ -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-...@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(f
Re: [PATCH 4/5] log: convert pr_*() to logging
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 --- 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.
Re: [PATCH 4/5] log: convert pr_*() to logging
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 --- 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 #include #include -#include #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 + /* * 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 #include #include @@ -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-...@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, ...)\
Re: [PATCH 4/5] log: convert pr_*() to logging
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 --- 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 #include #include -#include #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 + /* * 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 #include #include @@ -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-...@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
Re: [PATCH 4/5] log: convert pr_*() to logging
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 > > > --- > > > 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 signature.asc Description: PGP signature
Re: [PATCH 4/5] log: convert pr_*() to logging
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 > > > > --- > > > > 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. -- Tom signature.asc Description: PGP signature
Re: [PATCH 4/5] log: convert pr_*() to logging
Hi Heinrich, On Mon, 4 Jan 2021 at 00:03, 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 > --- > 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 > #include > #include > -#include > > #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 > + > /* > * 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 > #include > #include > > @@ -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, ...) \ > +({ \ > +