[RFC PATCH net-next] net/sched: introduce pretty printers for Qdiscs

[RFC PATCH net-next] net/sched: introduce pretty printers for Qdiscs

[Vladimir Oltean]

Sometimes when debugging Qdiscs it may be confusing to know exactly what
you're looking at, especially since they're hierarchical. Pretty printing
the handle, parent handle and netdev is a bit cumbersome, so this patch
proposes a set of wrappers around __qdisc_printk() which are heavily
inspired from __net_printk().

It is assumed that these printers will be more useful for untalented
kernel hackers such as myself rather than to the overall quality of the
code, since Qdiscs rarely print stuff to the kernel log by design (and
where they do, maybe that should be reconsidered in the first place).

A single demo conversion has been made, there is room for more if the
idea is appreciated.

Signed-off-by: Vladimir Oltean <vladimir.oltean@nxp.com>
---
 include/net/sch_debug.h | 45 +++++++++++++++++++++
 net/sched/Makefile      |  2 +-
 net/sched/sch_api.c     |  4 +-
 net/sched/sch_debug.c   | 86 +++++++++++++++++++++++++++++++++++++++++
 4 files changed, 134 insertions(+), 3 deletions(-)
 create mode 100644 include/net/sch_debug.h
 create mode 100644 net/sched/sch_debug.c

diff --git a/include/net/sch_debug.h b/include/net/sch_debug.h
new file mode 100644
index 000000000000..032de4710671
--- /dev/null
+++ b/include/net/sch_debug.h
@@ -0,0 +1,45 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#ifndef __NET_SCHED_DEBUG_H
+#define __NET_SCHED_DEBUG_H
+
+#include <linux/bug.h>
+#include <linux/kern_levels.h>
+
+struct Qdisc;
+
+__printf(3, 4) __cold
+void qdisc_printk(const char *level, const struct Qdisc *sch,
+		  const char *format, ...);
+__printf(2, 3) __cold
+void qdisc_emerg(const struct Qdisc *sch, const char *format, ...);
+__printf(2, 3) __cold
+void qdisc_alert(const struct Qdisc *sch, const char *format, ...);
+__printf(2, 3) __cold
+void qdisc_crit(const struct Qdisc *sch, const char *format, ...);
+__printf(2, 3) __cold
+void qdisc_err(const struct Qdisc *sch, const char *format, ...);
+__printf(2, 3) __cold
+void qdisc_warn(const struct Qdisc *sch, const char *format, ...);
+__printf(2, 3) __cold
+void qdisc_notice(const struct Qdisc *sch, const char *format, ...);
+__printf(2, 3) __cold
+void qdisc_info(const struct Qdisc *sch, const char *format, ...);
+
+#if defined(CONFIG_DYNAMIC_DEBUG) || \
+	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
+#define qdisc_dbg(__sch, format, args...)			\
+do {								\
+	dynamic_qdisc_dbg(__sch, format, ##args);		\
+} while (0)
+#elif defined(DEBUG)
+#define qdisc_dbg(__sch, format, args...)			\
+	qdisc_printk(KERN_DEBUG, __sch, format, ##args)
+#else
+#define qdisc_dbg(__sch, format, args...)			\
+({								\
+	if (0)							\
+		qdisc_printk(KERN_DEBUG, __sch, format, ##args); \
+})
+#endif
+
+#endif
diff --git a/net/sched/Makefile b/net/sched/Makefile
index b5fd49641d91..ab13bf7db283 100644
--- a/net/sched/Makefile
+++ b/net/sched/Makefile
@@ -6,7 +6,7 @@
 obj-y	:= sch_generic.o sch_mq.o
 
 obj-$(CONFIG_INET)		+= sch_frag.o
-obj-$(CONFIG_NET_SCHED)		+= sch_api.o sch_blackhole.o
+obj-$(CONFIG_NET_SCHED)		+= sch_api.o sch_blackhole.o sch_debug.o
 obj-$(CONFIG_NET_CLS)		+= cls_api.o
 obj-$(CONFIG_NET_CLS_ACT)	+= act_api.o
 obj-$(CONFIG_NET_ACT_POLICE)	+= act_police.o
diff --git a/net/sched/sch_api.c b/net/sched/sch_api.c
index fdb8f429333d..a6bfe2e40f89 100644
--- a/net/sched/sch_api.c
+++ b/net/sched/sch_api.c
@@ -31,6 +31,7 @@
 #include <net/netlink.h>
 #include <net/pkt_sched.h>
 #include <net/pkt_cls.h>
+#include <net/sch_debug.h>
 #include <net/tc_wrapper.h>
 
 #include <trace/events/qdisc.h>
@@ -597,8 +598,7 @@ EXPORT_SYMBOL(__qdisc_calculate_pkt_len);
 void qdisc_warn_nonwc(const char *txt, struct Qdisc *qdisc)
 {
 	if (!(qdisc->flags & TCQ_F_WARN_NONWC)) {
-		pr_warn("%s: %s qdisc %X: is non-work-conserving?\n",
-			txt, qdisc->ops->id, qdisc->handle >> 16);
+		qdisc_warn(qdisc, "%s: qdisc is non-work-conserving?\n", txt);
 		qdisc->flags |= TCQ_F_WARN_NONWC;
 	}
 }
diff --git a/net/sched/sch_debug.c b/net/sched/sch_debug.c
new file mode 100644
index 000000000000..1f47dac88c6e
--- /dev/null
+++ b/net/sched/sch_debug.c
@@ -0,0 +1,86 @@
+#include <linux/pkt_sched.h>
+#include <net/sch_generic.h>
+#include <net/sch_debug.h>
+
+static void qdisc_handle_str(u32 handle, char *str)
+{
+	if (handle == TC_H_ROOT) {
+		sprintf(str, "root");
+		return;
+	} else if (handle == TC_H_INGRESS) {
+		sprintf(str, "ingress");
+		return;
+	} else {
+		sprintf(str, "%x:%x", TC_H_MAJ(handle) >> 16, TC_H_MIN(handle));
+		return;
+	}
+}
+
+static void __qdisc_printk(const char *level, const struct Qdisc *sch,
+			   struct va_format *vaf)
+{
+	struct net_device *dev = qdisc_dev(sch);
+	char handle_str[10], parent_str[10];
+
+	qdisc_handle_str(sch->handle, handle_str);
+	qdisc_handle_str(sch->parent, parent_str);
+
+	if (dev && dev->dev.parent) {
+		dev_printk_emit(level[1] - '0',
+				dev->dev.parent,
+				"%s %s %s%s %s %s parent %s: %pV",
+				dev_driver_string(dev->dev.parent),
+				dev_name(dev->dev.parent),
+				netdev_name(dev), netdev_reg_state(dev),
+				sch->ops->id, handle_str, parent_str, vaf);
+	} else if (dev) {
+		printk("%s%s%s %s %s parent %s: %pV",
+		       level, netdev_name(dev), netdev_reg_state(dev),
+		       sch->ops->id, handle_str, parent_str, vaf);
+	} else {
+		printk("%s(NULL net_device) %s %s parent %s: %pV", level,
+		       sch->ops->id, handle_str, parent_str, vaf);
+	}
+}
+
+void qdisc_printk(const char *level, const struct Qdisc *sch,
+		  const char *format, ...)
+{
+	struct va_format vaf;
+	va_list args;
+
+	va_start(args, format);
+
+	vaf.fmt = format;
+	vaf.va = &args;
+
+	__qdisc_printk(level, sch, &vaf);
+
+	va_end(args);
+}
+EXPORT_SYMBOL(qdisc_printk);
+
+#define define_qdisc_printk_level(func, level)			\
+void func(const struct Qdisc *sch, const char *fmt, ...)	\
+{								\
+	struct va_format vaf;					\
+	va_list args;						\
+								\
+	va_start(args, fmt);					\
+								\
+	vaf.fmt = fmt;						\
+	vaf.va = &args;						\
+								\
+	__qdisc_printk(level, sch, &vaf);			\
+								\
+	va_end(args);						\
+}								\
+EXPORT_SYMBOL(func);
+
+define_qdisc_printk_level(qdisc_emerg, KERN_EMERG);
+define_qdisc_printk_level(qdisc_alert, KERN_ALERT);
+define_qdisc_printk_level(qdisc_crit, KERN_CRIT);
+define_qdisc_printk_level(qdisc_err, KERN_ERR);
+define_qdisc_printk_level(qdisc_warn, KERN_WARNING);
+define_qdisc_printk_level(qdisc_notice, KERN_NOTICE);
+define_qdisc_printk_level(qdisc_info, KERN_INFO);
-- 
2.34.1

Re: [RFC PATCH net-next] net/sched: introduce pretty printers for Qdiscs

[Pedro Tammela]

On 02/06/2023 13:29, Vladimir Oltean wrote:
> Sometimes when debugging Qdiscs it may be confusing to know exactly what
> you're looking at, especially since they're hierarchical. Pretty printing
> the handle, parent handle and netdev is a bit cumbersome, so this patch
> proposes a set of wrappers around __qdisc_printk() which are heavily
> inspired from __net_printk().

Probably worth mentioning drgn 
(https://drgn.readthedocs.io/en/latest/user_guide.html)
I've picked it up recently after Peilin mentioned it and it's quite helpful.

> 
> It is assumed that these printers will be more useful for untalented
> kernel hackers such as myself rather than to the overall quality of the
> code, since Qdiscs rarely print stuff to the kernel log by design (and
> where they do, maybe that should be reconsidered in the first place).
> 
> A single demo conversion has been made, there is room for more if the
> idea is appreciated.
> 
> Signed-off-by: Vladimir Oltean <vladimir.oltean@nxp.com>
> ---
>   include/net/sch_debug.h | 45 +++++++++++++++++++++
>   net/sched/Makefile      |  2 +-
>   net/sched/sch_api.c     |  4 +-
>   net/sched/sch_debug.c   | 86 +++++++++++++++++++++++++++++++++++++++++
>   4 files changed, 134 insertions(+), 3 deletions(-)
>   create mode 100644 include/net/sch_debug.h
>   create mode 100644 net/sched/sch_debug.c
> 
> diff --git a/include/net/sch_debug.h b/include/net/sch_debug.h
> new file mode 100644
> index 000000000000..032de4710671
> --- /dev/null
> +++ b/include/net/sch_debug.h
> @@ -0,0 +1,45 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +#ifndef __NET_SCHED_DEBUG_H
> +#define __NET_SCHED_DEBUG_H
> +
> +#include <linux/bug.h>
> +#include <linux/kern_levels.h>
> +
> +struct Qdisc;
> +
> +__printf(3, 4) __cold
> +void qdisc_printk(const char *level, const struct Qdisc *sch,
> +		  const char *format, ...);
> +__printf(2, 3) __cold
> +void qdisc_emerg(const struct Qdisc *sch, const char *format, ...);
> +__printf(2, 3) __cold
> +void qdisc_alert(const struct Qdisc *sch, const char *format, ...);
> +__printf(2, 3) __cold
> +void qdisc_crit(const struct Qdisc *sch, const char *format, ...);
> +__printf(2, 3) __cold
> +void qdisc_err(const struct Qdisc *sch, const char *format, ...);
> +__printf(2, 3) __cold
> +void qdisc_warn(const struct Qdisc *sch, const char *format, ...);
> +__printf(2, 3) __cold
> +void qdisc_notice(const struct Qdisc *sch, const char *format, ...);
> +__printf(2, 3) __cold
> +void qdisc_info(const struct Qdisc *sch, const char *format, ...);
> +
> +#if defined(CONFIG_DYNAMIC_DEBUG) || \
> +	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
> +#define qdisc_dbg(__sch, format, args...)			\
> +do {								\
> +	dynamic_qdisc_dbg(__sch, format, ##args);		\
> +} while (0)
> +#elif defined(DEBUG)
> +#define qdisc_dbg(__sch, format, args...)			\
> +	qdisc_printk(KERN_DEBUG, __sch, format, ##args)
> +#else
> +#define qdisc_dbg(__sch, format, args...)			\
> +({								\
> +	if (0)							\
> +		qdisc_printk(KERN_DEBUG, __sch, format, ##args); \
> +})
> +#endif
> +
> +#endif
> diff --git a/net/sched/Makefile b/net/sched/Makefile
> index b5fd49641d91..ab13bf7db283 100644
> --- a/net/sched/Makefile
> +++ b/net/sched/Makefile
> @@ -6,7 +6,7 @@
>   obj-y	:= sch_generic.o sch_mq.o
>   
>   obj-$(CONFIG_INET)		+= sch_frag.o
> -obj-$(CONFIG_NET_SCHED)		+= sch_api.o sch_blackhole.o
> +obj-$(CONFIG_NET_SCHED)		+= sch_api.o sch_blackhole.o sch_debug.o
>   obj-$(CONFIG_NET_CLS)		+= cls_api.o
>   obj-$(CONFIG_NET_CLS_ACT)	+= act_api.o
>   obj-$(CONFIG_NET_ACT_POLICE)	+= act_police.o
> diff --git a/net/sched/sch_api.c b/net/sched/sch_api.c
> index fdb8f429333d..a6bfe2e40f89 100644
> --- a/net/sched/sch_api.c
> +++ b/net/sched/sch_api.c
> @@ -31,6 +31,7 @@
>   #include <net/netlink.h>
>   #include <net/pkt_sched.h>
>   #include <net/pkt_cls.h>
> +#include <net/sch_debug.h>
>   #include <net/tc_wrapper.h>
>   
>   #include <trace/events/qdisc.h>
> @@ -597,8 +598,7 @@ EXPORT_SYMBOL(__qdisc_calculate_pkt_len);
>   void qdisc_warn_nonwc(const char *txt, struct Qdisc *qdisc)
>   {
>   	if (!(qdisc->flags & TCQ_F_WARN_NONWC)) {
> -		pr_warn("%s: %s qdisc %X: is non-work-conserving?\n",
> -			txt, qdisc->ops->id, qdisc->handle >> 16);
> +		qdisc_warn(qdisc, "%s: qdisc is non-work-conserving?\n", txt);

Looks much better

>   		qdisc->flags |= TCQ_F_WARN_NONWC;
>   	}
>   }
> diff --git a/net/sched/sch_debug.c b/net/sched/sch_debug.c
> new file mode 100644
> index 000000000000..1f47dac88c6e
> --- /dev/null
> +++ b/net/sched/sch_debug.c
> @@ -0,0 +1,86 @@ > +#include <linux/pkt_sched.h>
> +#include <net/sch_generic.h>
> +#include <net/sch_debug.h>
> +
> +static void qdisc_handle_str(u32 handle, char *str)
> +{
> +	if (handle == TC_H_ROOT) {
> +		sprintf(str, "root");
> +		return;
> +	} else if (handle == TC_H_INGRESS) {
> +		sprintf(str, "ingress");
> +		return;
> +	} else {
> +		sprintf(str, "%x:%x", TC_H_MAJ(handle) >> 16, TC_H_MIN(handle));
> +		return;
> +	}

nit: Did you consider a switch?

> +}
> +
> +static void __qdisc_printk(const char *level, const struct Qdisc *sch,
> +			   struct va_format *vaf)
> +{
> +	struct net_device *dev = qdisc_dev(sch);
> +	char handle_str[10], parent_str[10];
> +
> +	qdisc_handle_str(sch->handle, handle_str);
> +	qdisc_handle_str(sch->parent, parent_str);
> +
> +	if (dev && dev->dev.parent) {
> +		dev_printk_emit(level[1] - '0',
> +				dev->dev.parent,
> +				"%s %s %s%s %s %s parent %s: %pV",
> +				dev_driver_string(dev->dev.parent),
> +				dev_name(dev->dev.parent),
> +				netdev_name(dev), netdev_reg_state(dev),
> +				sch->ops->id, handle_str, parent_str, vaf);
> +	} else if (dev) {
> +		printk("%s%s%s %s %s parent %s: %pV",
> +		       level, netdev_name(dev), netdev_reg_state(dev),
> +		       sch->ops->id, handle_str, parent_str, vaf);
> +	} else {
> +		printk("%s(NULL net_device) %s %s parent %s: %pV", level,
> +		       sch->ops->id, handle_str, parent_str, vaf);
> +	}
> +}
> +
> +void qdisc_printk(const char *level, const struct Qdisc *sch,
> +		  const char *format, ...)
> +{
> +	struct va_format vaf;
> +	va_list args;
> +
> +	va_start(args, format);
> +
> +	vaf.fmt = format;
> +	vaf.va = &args;
> +
> +	__qdisc_printk(level, sch, &vaf);
> +
> +	va_end(args);
> +}
> +EXPORT_SYMBOL(qdisc_printk);
> +
> +#define define_qdisc_printk_level(func, level)			\
> +void func(const struct Qdisc *sch, const char *fmt, ...)	\
> +{								\
> +	struct va_format vaf;					\
> +	va_list args;						\
> +								\
> +	va_start(args, fmt);					\
> +								\
> +	vaf.fmt = fmt;						\
> +	vaf.va = &args;						\
> +								\
> +	__qdisc_printk(level, sch, &vaf);			\
> +								\
> +	va_end(args);						\
> +}								\
> +EXPORT_SYMBOL(func);
> +
> +define_qdisc_printk_level(qdisc_emerg, KERN_EMERG);
> +define_qdisc_printk_level(qdisc_alert, KERN_ALERT);
> +define_qdisc_printk_level(qdisc_crit, KERN_CRIT);
> +define_qdisc_printk_level(qdisc_err, KERN_ERR);
> +define_qdisc_printk_level(qdisc_warn, KERN_WARNING);
> +define_qdisc_printk_level(qdisc_notice, KERN_NOTICE);
> +define_qdisc_printk_level(qdisc_info, KERN_INFO);