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
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.
Signed-off-by: Chris Down <[email protected]>
Cc: Petr Mladek <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Rasmus Villemoes <[email protected]>
---
drivers/base/core.c | 6 ++--
include/linux/dev_printk.h | 63 ++++++++++++++++++++++++++++----------
2 files changed, 49 insertions(+), 20 deletions(-)
diff --git a/drivers/base/core.c b/drivers/base/core.c
index 60c5f5ea0268..78b8297e7f2b 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -4547,8 +4547,8 @@ static void __dev_printk(const char *level, const struct device *dev,
printk("%s(NULL device *): %pV", level, vaf);
}
-void dev_printk(const char *level, const struct device *dev,
- const char *fmt, ...)
+void _dev_printk(const char *level, const struct device *dev,
+ const char *fmt, ...)
{
struct va_format vaf;
va_list args;
@@ -4562,7 +4562,7 @@ void dev_printk(const char *level, const struct device *dev,
va_end(args);
}
-EXPORT_SYMBOL(dev_printk);
+EXPORT_SYMBOL(_dev_printk);
#define define_dev_printk_level(func, kern_level) \
void func(const struct device *dev, const char *fmt, ...) \
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
@@ -38,8 +38,8 @@ __printf(3, 4) __cold
int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...);
__printf(3, 4) __cold
-void dev_printk(const char *level, const struct device *dev,
- const char *fmt, ...);
+void _dev_printk(const char *level, const struct device *dev,
+ const char *fmt, ...);
__printf(2, 3) __cold
void _dev_emerg(const struct device *dev, const char *fmt, ...);
__printf(2, 3) __cold
@@ -69,7 +69,7 @@ static inline void __dev_printk(const char *level, const struct device *dev,
struct va_format *vaf)
{}
static inline __printf(3, 4)
-void dev_printk(const char *level, const struct device *dev,
+void _dev_printk(const char *level, const struct device *dev,
const char *fmt, ...)
{}
@@ -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); \
+ _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__); \
+})
+#define dev_err(dev, fmt, ...) ({ \
+ dev_printk_index_emit(KERN_ERR, dev_fmt(fmt)); \
+ _dev_err(dev, dev_fmt(fmt), ##__VA_ARGS__); \
+})
+#define dev_warn(dev, fmt, ...) ({ \
+ dev_printk_index_emit(KERN_WARNING, dev_fmt(fmt)); \
+ _dev_warn(dev, dev_fmt(fmt), ##__VA_ARGS__); \
+})
+#define dev_notice(dev, fmt, ...) ({ \
+ dev_printk_index_emit(KERN_NOTICE, dev_fmt(fmt)); \
+ _dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__); \
+})
+#define dev_info(dev, fmt, ...) ({ \
+ dev_printk_index_emit(KERN_INFO, dev_fmt(fmt)); \
+ _dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__); \
+})
#if defined(CONFIG_DYNAMIC_DEBUG) || \
(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
--
2.31.1
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