dyndbg: add print-once and print-ratelimited features. RFC.

Expand ddebug.flags to 11 bits, and define new flags to support pr_debug_once() and pr_debug_ratelimited() semantics: echo file init/main.c +o > control # init/main runs just once anyway echo module foo +r > control # turn on ratelimiting echo module foo +g > control # turn on group flag Test these conditions in bool is_onced_or_ratelimited(), and call it from __dynamic_pr_debug and others (which are behind the '+p' enablement test). print-once: can be done with just 2 bits in flags; .o _DPRINTK_FLAGS_ONCE enables state test and set .P _DPRINTK_FLAGS_PRINTED state bit Just adding the flags lets the existing code operate on them. We will need new code to enforce constraints on flag combos; '+ro' is nonsense, but this can wait, or can take a new meaning. +oP behavior is testable using module module +o vs +oP > control rate-limiting: .r _DPRINTK_FLAGS_RATELIMITED - track & limit prdbgs callrate We wait until a prdebug is called, and if RATELIMITED is set, THEN lookup a RateLimitState (RL) for it. If found, bump its state and return true/false, otherwise create & initialize one and return false. group-flag: RFC .g _DPRINTK_FLAGS_GROUPED Currently, the hash-key is just the prdebug descriptor, so is unique per prdebug. With the 'g' flag, we could use a different key, for example desc->site.function, to get a shared ratelimit for whole functions. This gets subtly different behavior at the ratelimit transition, but it is predictable for a given function (except perhaps recursive, but thats not done anyway). Note also that any function can have a single group of prdebugs, plus any number of prdbgs without 'g', either with or without 'r'. So grouping should be flexible enough to use advantageously. TLDR: older key thinking That lookup is basically a hash, with 2 part key: . &builtin-vector-base OR &module or the hash(s) could hang off the header struct . ._back OR ._map chosen by _DPRINTK_FLAGS_GROUPED choice dictates per-site OR sharing across function print more debug context for verbose=4 bash-5.1# modprobe test_static_keys [ 407.563410] dyndbg: found ffffffff8313efd0 [ 407.564180] is_onced_or_limited: 8 callbacks suppressed [ 407.564194] dyndbg: RLstate{solo}=1 on module.layout_sections.2438 [ 407.565806] dyndbg: found ffffffff8313efb0 [ 407.566459] is_onced_or_limited: 348 callbacks suppressed [ 407.566464] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.568214] dyndbg: found ffffffff8313efb0 [ 407.568777] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.569727] dyndbg: found ffffffff8313efb0 [ 407.570355] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.571226] dyndbg: found ffffffff8313efb0 [ 407.571797] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.572686] dyndbg: found ffffffff8313efb0 [ 407.573284] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.574214] dyndbg: found ffffffff8313efb0 [ 407.574791] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.575749] dyndbg: found ffffffff8313efb0 [ 407.576409] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.577415] dyndbg: found ffffffff8313efb0 [ 407.578221] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.579622] dyndbg: found ffffffff8313efb0 [ 407.580391] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.581553] dyndbg: found ffffffff8313efb0 [ 407.582273] dyndbg: RLstate{solo}=1 on module.layout_sections.2450 [ 407.583174] dyndbg: found ffffffff8313efb0 [ 407.583745] dyndbg: RLstate{solo}=0 on module.layout_sections.2450 [ 407.584722] dyndbg: found ffffffff8313efb0 [ 407.585310] dyndbg: RLstate{solo}=0 on module.layout_sections.2450 [ 407.586228] dyndbg: found ffffffff8313efb0 [ 407.586880] dyndbg: RLstate{solo}=0 on module.layout_sections.2450 [ 407.587870] dyndbg: found ffffffff8313efb0 [ 407.588559] dyndbg: RLstate{solo}=0 on module.layout_sections.2450 [ 407.589515] dyndbg: found ffffffff8313efb0 [ 407.590254] dyndbg: RLstate{solo}=0 on module.layout_sections.2450 [ 407.591200] dyndbg: found ffffffff8313efb0 [ 407.591845] dyndbg: RLstate{solo}=0 on module.layout_sections.2450 [ 407.592957] dyndbg: found ffffffff8313ef90 [ 407.593755] is_onced_or_limited: 8 callbacks suppressed [ 407.593765] dyndbg: RLstate{solo}=1 on module.layout_sections.2471 [ 407.595770] dyndbg: found ffffffff8313ef70 [ 407.596536] is_onced_or_limited: 34 callbacks suppressed [ 407.596542] dyndbg: RLstate{solo}=1 on module.layout_symtab.2484 [ 407.598350] dyndbg: found ffffffff8313ef70 [ 407.598932] dyndbg: RLstate{solo}=1 on module.layout_symtab.2484 [ 407.599849] dyndbg: found ffffffff8313ef50 [ 407.600559] is_onced_or_limited: 8 callbacks suppressed [ 407.600563] dyndbg: RLstate{solo}=1 on module.layout_symtab.2703 [ 407.602366] dyndbg: found ffffffff8313ef30 [ 407.603074] is_onced_or_limited: 8 callbacks suppressed [ 407.603079] dyndbg: RLstate{solo}=1 on module.move_module.2730 [ 407.604776] dyndbg: found ffffffff8313ef10 [ 407.605455] is_onced_or_limited: 8 callbacks suppressed [ 407.605461] dyndbg: RLstate{solo}=1 on module.move_module.3390 [ 407.607497] dyndbg: found ffffffff8313eef0 [ 407.608206] is_onced_or_limited: 428 callbacks suppressed [ 407.608211] dyndbg: RLstate{solo}=1 on module.__do_sys_init_module.3408 [ 407.610280] dyndbg: found ffffffff8313eef0 [ 407.610935] dyndbg: RLstate{solo}=1 on module.__do_sys_init_module.3408 [ 407.612012] dyndbg: found ffffffff8313eef0 [ 407.612641] dyndbg: RLstate{solo}=1 on module.__do_sys_init_module.3408
jimc · Jul 10, 2021 · 5729928be52f1ce26a82e6263185f7f2f891d68e · 5729928
1 parent a3e1acc
commit 5729928be52f1ce26a82e6263185f7f2f891d68e
Show file tree

Hide file tree

Showing 2 changed files with 128 additions and 4 deletions.
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
@@ -64,18 +64,22 @@ struct _ddebug {
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
 #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
-#define _DPRINTK_FLAGS_DELETE_SITE	(1<<7) /* drop site info to save ram */
-
 #define _DPRINTK_FLAGS_INCL_ANY		\
 	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
 	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
 
+#define _DPRINTK_FLAGS_ONCE		(1<<5) /* print once flag */
+#define _DPRINTK_FLAGS_PRINTED		(1<<6) /* print once state */
+#define _DPRINTK_FLAGS_RATELIMITED	(1<<7)
+#define _DPRINTK_FLAGS_GROUPED		(1<<8) /* manipulate as a group */
+#define _DPRINTK_FLAGS_DELETE_SITE	(1<<9) /* drop site info to save ram */
+
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
 #else
 #define _DPRINTK_FLAGS_DEFAULT 0
 #endif
-	unsigned int flags:8;
+	unsigned int flags:11;
 
 #ifdef CONFIG_JUMP_LABEL
 	union {

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
@@ -86,13 +86,17 @@ static inline const char *trim_prefix(const char *path)
 	return path + skip;
 }
 
-static struct { unsigned flag:8; char opt_char; } opt_array[] = {
+static struct { unsigned flag:11; char opt_char; } opt_array[] = {
 	{ _DPRINTK_FLAGS_PRINT, 'p' },
 	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
 	{ _DPRINTK_FLAGS_INCL_TID, 't' },
 	{ _DPRINTK_FLAGS_NONE, '_' },
+	{ _DPRINTK_FLAGS_ONCE, 'o' },
+	{ _DPRINTK_FLAGS_PRINTED, 'P' },
+	{ _DPRINTK_FLAGS_RATELIMITED, 'r' },
+	{ _DPRINTK_FLAGS_GROUPED, 'g' },
 	{ _DPRINTK_FLAGS_DELETE_SITE, 'D' },
 };
 
@@ -731,6 +735,51 @@ static inline char *dynamic_emit_prefix(struct _ddebug *desc, char *buf)
 	return buf;
 }
 
+struct dd_ratelimit {
+	struct hlist_node hnode;
+	struct ratelimit_state rs;
+	u64 key;
+};
+
+/* test print-once or ratelimited conditions */
+#define is_rated(desc) unlikely(desc->flags & _DPRINTK_FLAGS_RATELIMITED)
+#define is_once(desc) unlikely(desc->flags & _DPRINTK_FLAGS_ONCE)
+#define is_onced(desc)						\
+	unlikely((desc->flags & _DPRINTK_FLAGS_ONCE)		\
+		 && (desc->flags & _DPRINTK_FLAGS_PRINTED))
+
+static struct dd_ratelimit *dd_rl_fetch(struct _ddebug *desc);
+
+static inline bool is_onced_or_limited(struct _ddebug *descriptor)
+{
+	if (unlikely(descriptor->flags & _DPRINTK_FLAGS_ONCE &&
+		     descriptor->flags & _DPRINTK_FLAGS_RATELIMITED))
+		pr_info(" ONCE & RATELIMITED together is nonsense\n");
+
+	if (is_once(descriptor)) {
+		if (is_onced(descriptor)) {
+			v4pr_info("already printed once\n");
+			return true;
+		}
+		descriptor->flags |= _DPRINTK_FLAGS_PRINTED;
+		return false;
+
+	} else if (is_rated(descriptor)) {
+		/* test rate-limits */
+		bool state = __ratelimit(&dd_rl_fetch(descriptor)->rs);
+		struct _ddebug_site *site = ddebug_site_get(descriptor);
+
+		v4pr_info("RLstate{%s}=%d on %s.%s.%d\n",
+			  (descriptor->flags & _DPRINTK_FLAGS_GROUPED
+			   ? "grouped" : "solo"), state,
+			  site->modname, site->function, descriptor->lineno);
+
+		ddebug_site_put(descriptor);
+		return state;
+	}
+	return false;
+}
+
 void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 {
 	va_list args;
@@ -740,6 +789,9 @@ void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -760,6 +812,9 @@ void __dynamic_dev_dbg(struct _ddebug *descriptor,
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -791,6 +846,9 @@ void __dynamic_netdev_dbg(struct _ddebug *descriptor,
 	BUG_ON(!descriptor);
 	BUG_ON(!fmt);
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -827,6 +885,9 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 	struct va_format vaf;
 	va_list args;
 
+	if (is_onced_or_limited(descriptor))
+		return;
+
 	va_start(args, fmt);
 
 	vaf.fmt = fmt;
@@ -1371,3 +1432,62 @@ static int __init dynamic_debug_sites_reclaim(void)
 }
 late_initcall(dynamic_debug_sites_reclaim);
 
+/*
+ * Rate-Limited debug is expected to rarely be needed, so it is
+ * provisioned on-demand when an enabled and rate-limit-flagged
+ * pr_debug is called, by dd_rl_fetch().  For now, key is just
+ * descriptor, so is unique per site.
+
+ * Plan: for 'gr' flagged callsites, choose a key that is same across
+ * all prdebugs in a function, to apply a single rate-limit to the
+ * whole function.  This should give nearly identical behavior at much
+ * lower memory cost.
+ */
+static DEFINE_HASHTABLE(dd_rl_map, 6);
+
+static struct dd_ratelimit *dd_rl_find(u64 key)
+{
+	struct dd_ratelimit *limiter;
+
+	hash_for_each_possible(dd_rl_map, limiter, hnode, key) {
+		if (limiter->key == key)
+			return limiter;
+	}
+	return NULL;
+}
+
+/* Must be called with dd_rl_lock locked. */
+static struct dd_ratelimit *dd_rl_add(u64 key)
+{
+	struct dd_ratelimit *limiter;
+
+	limiter = dd_rl_find(key);
+	if (limiter)
+		return limiter;
+	limiter = kmalloc(sizeof(*limiter), GFP_ATOMIC);
+	if (!limiter)
+		return ERR_PTR(-ENOMEM);
+
+	limiter->key = key;
+	ratelimit_default_init(&limiter->rs);
+	hash_add(dd_rl_map, &limiter->hnode, key);
+
+	v3pr_info("added %llx\n", key);
+	return limiter;
+}
+
+/*
+ * called when enabled callsite has _DPRINTK_FLAGS_RATELIMITED flag
+ * set (echo +pr >control), it hashes on &table-header+index
+ */
+static struct dd_ratelimit *dd_rl_fetch(struct _ddebug *desc)
+{
+	u64 key = (u64)desc;
+	struct dd_ratelimit *dd_rl = dd_rl_find(key);
+
+	if (dd_rl) {
+		v4pr_info("found %llx\n", key);
+		return dd_rl;
+	}
+	return dd_rl_add(key);
+}