Re: [PATCH v6 4/4] printk: index: Add indexing support to dev_printk

[Petr Mladek]

On Tue 2021-05-18 13:00:48, Chris Down wrote:
> While for most kinds of issues we have counters, tracepoints, or metrics
> with a stable interface which can reliably be used to indicate issues,
> in order to react to production issues quickly we sometimes need to work
> with the interface which most kernel developers naturally use when
> developing: printk, and printk-esques like dev_printk.
> 
> dev_printk is by far the most likely custom subsystem printk to benefit
> from the printk indexing infrastructure, since niche device issues
> brought about by production changes, firmware upgrades, and the like are
> one of the most common things that we need printk infrastructure's
> assistance to monitor.
> 
> Often these errors were never expected to practically manifest in
> reality, and exhibit in code without extensive (or any) metrics present.
> As such, there are typically very few options for issue detection
> available to those with large fleets at the time the incident happens,
> and we thus benefit strongly from monitoring netconsole in these
> instances.
> 
> As such, add the infrastructure for dev_printk to be indexed in the
> printk index. Even on a minimal kernel config, the coverage of the base
> kernel's printk index is significantly improved:
> 
> Before:
> 
>     [root@ktst ~]# wc -l /sys/kernel/debug/printk/index/vmlinux
>     4497 /sys/kernel/debug/printk/index/vmlinux
> 
> After:
> 
>     [root@ktst ~]# wc -l /sys/kernel/debug/printk/index/vmlinux
>     5573 /sys/kernel/debug/printk/index/vmlinux

Cool.

> In terms of implementation, in order to trivially disambiguate them,
> dev_printk is now a macro which wraps _dev_printk. If preferred, it's
> also possible to have the macro and function have the same name.

I prefer to use _dev_printk to disambiguate the macro and function
names. By other words, I prefer the approach used in this patch.

Please, remove the "If preferred..." sentence in the next version.

> diff --git a/include/linux/dev_printk.h b/include/linux/dev_printk.h
> index 6f009559ee54..202c6a9ea7eb 100644
> --- a/include/linux/dev_printk.h
> +++ b/include/linux/dev_printk.h
> @@ -97,25 +97,54 @@ void _dev_info(const struct device *dev, const char *fmt, ...)
>  
>  #endif
>  
> +/*
> + * Some callsites directly call dev_printk rather than going through the
> + * dev_<level> infrastructure, so we need to emit here as well as inside those
> + * level-specific macros. Only one index entry will be produced, either way,
> + * since dev_printk's `fmt` isn't known at compile time if going through the
> + * dev_<level> macros.
> + */
> +#define dev_printk(level, dev, fmt, ...) ({			\
> +	dev_printk_index_emit(level, fmt);			\

Please, define dev_printk_index_emit() macro before it is used
for the first time.

> +	_dev_printk(level, dev, fmt, ##__VA_ARGS__);		\
> +})
> +
>  /*
>   * #defines for all the dev_<level> macros to prefix with whatever
>   * possible use of #define dev_fmt(fmt) ...
>   */
>  
> -#define dev_emerg(dev, fmt, ...)					\
> -	_dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__)
> -#define dev_crit(dev, fmt, ...)						\
> -	_dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__)
> -#define dev_alert(dev, fmt, ...)					\
> -	_dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__)
> -#define dev_err(dev, fmt, ...)						\
> -	_dev_err(dev, dev_fmt(fmt), ##__VA_ARGS__)
> -#define dev_warn(dev, fmt, ...)						\
> -	_dev_warn(dev, dev_fmt(fmt), ##__VA_ARGS__)
> -#define dev_notice(dev, fmt, ...)					\
> -	_dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__)
> -#define dev_info(dev, fmt, ...)						\
> -	_dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__)
> +#define dev_printk_index_emit(level, fmt)				\
> +	printk_index_subsys_emit("%s %s: ", "", level, fmt)
> +
> +#define dev_emerg(dev, fmt, ...) ({					\
> +	dev_printk_index_emit(KERN_EMERG, dev_fmt(fmt));		\
> +	_dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
> +})
> +#define dev_crit(dev, fmt, ...) ({					\
> +	dev_printk_index_emit(KERN_CRIT, dev_fmt(fmt));			\
> +	_dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
> +})
> +#define dev_alert(dev, fmt, ...) ({					\
> +	dev_printk_index_emit(KERN_ALERT, dev_fmt(fmt));		\
> +	_dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
> +})

I would slightly reduce the duplcation the follwing way:

#define dev_printk_index_wrap(_p_func, level, dev, fmt, ...)			\
	({								       \
		printk_index_subsys_emit("%s %s: ", "", level, dev_fmt(fmt));  \
		_p_func(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
	})

#define dev_printk(level, dev, fmt, ...)				\
	dev_printk_index_wrap(_dev_printk, level, dev, ##__VA_ARGS__)

#define dev_crit(dev, fmt, ...)							\
	dev_printk_index_wrap(_dev_crit, KERN_CRIT, dev, ##__VA_ARGS__)
#define dev_alert(dev, fmt, ...)						\
	dev_printk_index_wrap(_dev_alert, KERN_ALERT, dev, ##__VA_ARGS__)


Note that I did not try to complile it, so there might be a mistake.


BTW: I was curious why we actually need _dev_crit() defined as a function.
But it seems to reduce size of the kernel binaries, see
the commit 38a1ec40efa196efbac0253 ("device.h drivers/base/core.c
Convert dev_<level> logging macros to functions"). Sigh.

Best Regards,
Petr