[PATCH 1/7] dyndbg: move struct _ddebug's display fields to new _ddebug_callsite

[PATCH 1/7] dyndbg: move struct _ddebug's display fields to new _ddebug_callsite

[Jim Cromie]

struct _ddebug has 5 fields used to display and select pr_debug
callsites, move these to a new struct _ddebug_callsite, and add ptr to
link 1st to 2nd.  While this increases memory footprint by 1 ptr per
pr_debug, the indirection gives several advantages:

- we can allocate storage only for enabled callsites.  Since pr_debugs
  are 99% disabled, we should see savings.

- the display fields are inherently hierarchical, and the linker
  section is ordered; so (module, file, function) have redundant
  values (90%, 85%, 45%).  This is readily compressible, even with a
  simple field-wise run length encoding.  Because theyre placed in a
  separate linker section, theyre in a contiguous block of memory,
  which should simplify that compression.

Looking forward, there are several approaches to get the advantages.

A - copy each callsite to zram, save to new .zhandle member, and
update site pointers.  Must later retire __dyndbg_callsite section
afterwards to actually recover memory.

I did this (next patches), and get 3:1 zs_page:page compression.  It
works when sites are zs_mapped in just for the print.  But if I leave
them mapped in cuz the pr_debug is enabled, locking conflicts & panic
ensue.  Patches follow.

B - compress __dyndbg_callsite linker section, using some format which
is good at random-index decompression.

I did objcopy --dump-sections .. vmlinux.o, got mostly empty data,
like Im getting values before the final link.  Im missing some
understanding.

C - field-wise RLE.  This is feeling increasingly suitable.

Whats actually done here:

dynamic_debug.h:

I cut struct _ddebug in half, renamed top-half (body), kept __align(8)
on both head & body, added a forward decl for a unified comment for
both head & body.  And added head.site to point at body.

DECLARE_DYNAMIC_DEBUG_METADATA does the core of the work; it declares
and initializes both static struct vars together, and refs one to the
other.

And since Im rejiggering the structs:

- I moved static_key key to front of struct _ddebug; its the biggest
  member, and most alignment sensitive, so moving it to front may
  improve ambient pahole conditions.

- reorder display fields to match the hierarchy.  This should help
  improve compressability, particularly for field-wise RLE.  With
  this, consecutive records are tail-different.

Also
- reserved a flag bit for zram mapping (no use yet)
- I shrunk lineno member from 18 to 16 bits, and made it const.
  No source file is near 64k-lines, I doubt any could get added.

dynamic_debug.c:

dynamic_debug_init() mem-usage now counts callsites.

The 3 funcs which use _ddebug* pointers (ddebug_change,
dynamic_emit_prefix, ddebug_proc_show) each get an auto-var, inited
with ->site, and s/dp/dc/ as needed.  These once-per-func dp->site
derefs are also a setup for the next commit.

vmlinux.lds.h:

add __ddebug_callsites section, with the same align(8) and KEEP as
used in the __ddebug section.

TBD:

_align(8) may be unnecessary on struct _ddebug_callsite, I think its
there for the static_key member.  I do wonder if its arch dependent, 8
seems big for i686 at least.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 include/asm-generic/vmlinux.lds.h |  4 +++
 include/linux/dynamic_debug.h     | 41 +++++++++++++++---------
 lib/dynamic_debug.c               | 52 +++++++++++++++++--------------
 3 files changed, 58 insertions(+), 39 deletions(-)

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index b2b3d81b1535..1ef1efc73d20 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -340,6 +340,10 @@
 	*(__tracepoints)						\
 	/* implement dynamic printk debug */				\
 	. = ALIGN(8);							\
+	__start___dyndbg_callsites = .;					\
+	KEEP(*(__dyndbg_callsites))					\
+	__stop___dyndbg_callsites = .;					\
+	. = ALIGN(8);							\
 	__start___dyndbg = .;						\
 	KEEP(*(__dyndbg))						\
 	__stop___dyndbg = .;						\
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index a57ee75342cf..0bf7036bcdb2 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -7,11 +7,14 @@
 #endif
 
 /*
- * An instance of this structure is created in a special
- * ELF section at every dynamic debug callsite.  At runtime,
- * the special section is treated as an array of these.
+ * a pair of these structs are created in 2 special ELF sections
+ * (__dyndbg, __dyndbg_callsites) for every dynamic debug callsite.
+ * During init, __dyndbg_callsites is copied to zram, and links to
+ * them in _ddebug are updated.  At runtime, the __dyndbg section is
+ * treated as an array of struct _ddebugs.
  */
-struct _ddebug {
+struct _ddebug;
+struct _ddebug_callsite {
 	/*
 	 * These fields are used to drive the user interface
 	 * for selecting and displaying debug callsites.
@@ -20,7 +23,17 @@ struct _ddebug {
 	const char *function;
 	const char *filename;
 	const char *format;
-	unsigned int lineno:18;
+	const unsigned int lineno:16;
+} __aligned(8);
+
+struct _ddebug {
+#ifdef CONFIG_JUMP_LABEL
+	union {
+		struct static_key_true dd_key_true;
+		struct static_key_false dd_key_false;
+	} key;
+#endif
+	struct _ddebug_callsite *site;
 	/*
 	 * The flags field controls the behaviour at the callsite.
 	 * The bits here are changed dynamically when the user
@@ -32,20 +45,14 @@ 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_MAPPED		(1<<7) /* reserved */
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
 #else
 #define _DPRINTK_FLAGS_DEFAULT 0
 #endif
 	unsigned int flags:8;
-#ifdef CONFIG_JUMP_LABEL
-	union {
-		struct static_key_true dd_key_true;
-		struct static_key_false dd_key_false;
-	} key;
-#endif
-} __attribute__((aligned(8)));
-
+} __aligned(8);
 
 
 #if defined(CONFIG_DYNAMIC_DEBUG_CORE)
@@ -83,13 +90,17 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 			 const char *fmt, ...);
 
 #define DEFINE_DYNAMIC_DEBUG_METADATA(name, fmt)		\
-	static struct _ddebug  __aligned(8)			\
-	__section("__dyndbg") name = {				\
+	static struct _ddebug_callsite  __aligned(8)		\
+	__section("__dyndbg_callsites") name##_site = {		\
 		.modname = KBUILD_MODNAME,			\
 		.function = __func__,				\
 		.filename = __FILE__,				\
 		.format = (fmt),				\
 		.lineno = __LINE__,				\
+	};							\
+	static struct _ddebug  __aligned(8)			\
+	__section("__dyndbg") name = {				\
+		.site = &name##_site,				\
 		.flags = _DPRINTK_FLAGS_DEFAULT,		\
 		_DPRINTK_KEY_INIT				\
 	}
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 711a9def8c83..2e4a39c349a5 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -165,19 +165,20 @@ static int ddebug_change(const struct ddebug_query *query,
 
 		for (i = 0; i < dt->num_ddebugs; i++) {
 			struct _ddebug *dp = &dt->ddebugs[i];
+			struct _ddebug_callsite *dc = dp->site;
 
 			/* match against the source filename */
 			if (query->filename &&
-			    !match_wildcard(query->filename, dp->filename) &&
+			    !match_wildcard(query->filename, dc->filename) &&
 			    !match_wildcard(query->filename,
-					   kbasename(dp->filename)) &&
+					   kbasename(dc->filename)) &&
 			    !match_wildcard(query->filename,
-					   trim_prefix(dp->filename)))
+					   trim_prefix(dc->filename)))
 				continue;
 
 			/* match against the function */
 			if (query->function &&
-			    !match_wildcard(query->function, dp->function))
+			    !match_wildcard(query->function, dc->function))
 				continue;
 
 			/* match against the format */
@@ -185,19 +186,19 @@ static int ddebug_change(const struct ddebug_query *query,
 				if (*query->format == '^') {
 					char *p;
 					/* anchored search. match must be at beginning */
-					p = strstr(dp->format, query->format+1);
-					if (p != dp->format)
+					p = strstr(dc->format, query->format+1);
+					if (p != dc->format)
 						continue;
-				} else if (!strstr(dp->format, query->format))
+				} else if (!strstr(dc->format, query->format))
 					continue;
 			}
 
 			/* match against the line number range */
 			if (query->first_lineno &&
-			    dp->lineno < query->first_lineno)
+			    dc->lineno < query->first_lineno)
 				continue;
 			if (query->last_lineno &&
-			    dp->lineno > query->last_lineno)
+			    dc->lineno > query->last_lineno)
 				continue;
 
 			nfound++;
@@ -214,8 +215,8 @@ static int ddebug_change(const struct ddebug_query *query,
 #endif
 			dp->flags = newflags;
 			v2pr_info("changed %s:%d [%s]%s =%s\n",
-				 trim_prefix(dp->filename), dp->lineno,
-				 dt->mod_name, dp->function,
+				 trim_prefix(dc->filename), dc->lineno,
+				 dt->mod_name, dc->function,
 				 ddebug_describe_flags(dp->flags, &fbuf));
 		}
 	}
@@ -587,14 +588,15 @@ static int remaining(int wrote)
 	return 0;
 }
 
-static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
+static char *dynamic_emit_prefix(const struct _ddebug *dp, char *buf)
 {
 	int pos_after_tid;
 	int pos = 0;
+	const struct _ddebug_callsite *desc = dp->site;
 
 	*buf = '\0';
 
-	if (desc->flags & _DPRINTK_FLAGS_INCL_TID) {
+	if (dp->flags & _DPRINTK_FLAGS_INCL_TID) {
 		if (in_interrupt())
 			pos += snprintf(buf + pos, remaining(pos), "<intr> ");
 		else
@@ -602,13 +604,13 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 					task_pid_vnr(current));
 	}
 	pos_after_tid = pos;
-	if (desc->flags & _DPRINTK_FLAGS_INCL_MODNAME)
+	if (dp->flags & _DPRINTK_FLAGS_INCL_MODNAME)
 		pos += snprintf(buf + pos, remaining(pos), "%s:",
 				desc->modname);
-	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
+	if (dp->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
 		pos += snprintf(buf + pos, remaining(pos), "%s:",
 				desc->function);
-	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
+	if (dp->flags & _DPRINTK_FLAGS_INCL_LINENO)
 		pos += snprintf(buf + pos, remaining(pos), "%d:",
 				desc->lineno);
 	if (pos - pos_after_tid)
@@ -880,6 +882,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 {
 	struct ddebug_iter *iter = m->private;
 	struct _ddebug *dp = p;
+	struct _ddebug_callsite *dc = dp->site;
 	struct flagsbuf flags;
 
 	if (p == SEQ_START_TOKEN) {
@@ -889,10 +892,10 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 	}
 
 	seq_printf(m, "%s:%u [%s]%s =%s \"",
-		   trim_prefix(dp->filename), dp->lineno,
-		   iter->table->mod_name, dp->function,
+		   trim_prefix(dc->filename), dc->lineno,
+		   iter->table->mod_name, dc->function,
 		   ddebug_describe_flags(dp->flags, &flags));
-	seq_escape(m, dp->format, "\t\r\n\"");
+	seq_escape(m, dc->format, "\t\r\n\"");
 	seq_puts(m, "\"\n");
 
 	return 0;
@@ -1094,17 +1097,17 @@ static int __init dynamic_debug_init(void)
 		return 0;
 	}
 	iter = __start___dyndbg;
-	modname = iter->modname;
+	modname = iter->site->modname;
 	iter_start = iter;
 	for (; iter < __stop___dyndbg; iter++) {
 		entries++;
-		if (strcmp(modname, iter->modname)) {
+		if (strcmp(modname, iter->site->modname)) {
 			modct++;
 			ret = ddebug_add_module(iter_start, n, modname);
 			if (ret)
 				goto out_err;
 			n = 0;
-			modname = iter->modname;
+			modname = iter->site->modname;
 			iter_start = iter;
 		}
 		n++;
@@ -1114,9 +1117,10 @@ static int __init dynamic_debug_init(void)
 		goto out_err;
 
 	ddebug_init_success = 1;
-	vpr_info("%d modules, %d entries and %d bytes in ddebug tables, %d bytes in __dyndbg section\n",
+	vpr_info("%d modules, %d entries and %d bytes in ddebug tables, %d bytes in __dyndbg section, %d bytes in __dyndbg_callsites section\n",
 		 modct, entries, (int)(modct * sizeof(struct ddebug_table)),
-		 (int)(entries * sizeof(struct _ddebug)));
+		 (int)(entries * sizeof(struct _ddebug)),
+		 (int)(entries * sizeof(struct _ddebug_callsite)));
 
 	/* apply ddebug_query boot param, dont unload tables on err */
 	if (ddebug_setup_string[0] != '\0') {
-- 
2.28.0

[PATCH 2/7] dyndbg: count repetition in __dyndbg_callsite fields.

[Jim Cromie]

The __dyndbg_callsite section is basically a flat db-table, an array
of struct _ddebug_callsite[]s.  Its data is inherently hierarchical
and sorted, so a field-wise run-length encoding would compress well.

Add counters and code to test 3 fields of consecutive callsites for
repeated values.  The results inform a compression estimate.

 dyndbg: 2605 entries. repeated entries: 2369 module 2231 file 1147 func

Thats (91%, 86%, 44%) repeated values in those pointers/columns, on my
i7 laptop build.  With a zero-overhead markup, like LSB-stealing, we
could mark the differing tails of consecutive records, and get 11/24
compression on init/main pr_debugs.

For a slightly apples-to-oranges comparison (text vs pointers),
`gzip /proc/dynamic_debug/control` achieves 6/1 compression.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 2e4a39c349a5..5980d44ff2f8 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1081,11 +1081,12 @@ static int __init dynamic_debug_init_control(void)
 
 static int __init dynamic_debug_init(void)
 {
-	struct _ddebug *iter, *iter_start;
+	struct _ddebug *iter, *iter_start, *prev = NULL;
 	const char *modname = NULL;
 	char *cmdline;
 	int ret = 0;
 	int n = 0, entries = 0, modct = 0;
+	int modreps = 0, funcreps = 0, filereps = 0;
 
 	if (&__start___dyndbg == &__stop___dyndbg) {
 		if (IS_ENABLED(CONFIG_DYNAMIC_DEBUG)) {
@@ -1099,7 +1100,16 @@ static int __init dynamic_debug_init(void)
 	iter = __start___dyndbg;
 	modname = iter->site->modname;
 	iter_start = iter;
-	for (; iter < __stop___dyndbg; iter++) {
+	for (prev = iter; iter < __stop___dyndbg; iter++) {
+		if (entries) {
+			if (prev->site->modname == iter->site->modname)
+				modreps++;
+			if (prev->site->function == iter->site->function)
+				funcreps++;
+			if (prev->site->filename == iter->site->filename)
+				filereps++;
+			prev++; /* one behind iter */
+		}
 		entries++;
 		if (strcmp(modname, iter->site->modname)) {
 			modct++;
@@ -1122,6 +1132,9 @@ static int __init dynamic_debug_init(void)
 		 (int)(entries * sizeof(struct _ddebug)),
 		 (int)(entries * sizeof(struct _ddebug_callsite)));
 
+	vpr_info("%d entries. repeated entries: %d module %d file %d func\n",
+		 entries, modreps, filereps, funcreps);
+
 	/* apply ddebug_query boot param, dont unload tables on err */
 	if (ddebug_setup_string[0] != '\0') {
 		pr_warn("ddebug_query param name is deprecated, change it to dyndbg\n");
-- 
2.28.0

[PATCH 3/7] dyndbg: add some code to see alignments of linkage data

[Jim Cromie]

To be able to use LSB-stealing (lsb as flag, mask b4 addressing), we
need to know that the alignments of existing data is never odd.  So
add code to check the alignment of pointers in _dyndbg_callsites
section.

It turns out that all these fields point to a variety of odd
alignments in the deeper linkage data.  We will need ALIGN(2) to allow
use of LSB to signal the EOT of differing-tail records.

[    0.587654] dyndbg: 2014 entries. \
     	       repeated entries: 1789 module 1667 file 809 func
[    0.588653] dyndbg: mod aligns:
[    0.589130] dyndbg:   align 0 0: 107
[    0.589653] dyndbg:   align 0 1: 210
[    0.590271] dyndbg:   align 0 2: 234
[    0.590652] dyndbg:   align 0 3: 179
[    0.591224] dyndbg:   align 0 4: 358
[    0.591652] dyndbg:   align 0 5: 374
[    0.592283] dyndbg:   align 0 6: 231
[    0.592653] dyndbg:   align 0 7: 321
[    0.593203] dyndbg:  mod align totals: 2014
[    0.593652] dyndbg: file aligns:
[    0.594168] dyndbg:   align 1 0: 569
[    0.594652] dyndbg:   align 1 1: 172
[    0.595179] dyndbg:   align 1 2: 263
[    0.595652] dyndbg:   align 1 3: 252
[    0.596368] dyndbg:   align 1 4: 200
[    0.596652] dyndbg:   align 1 5: 126
[    0.597327] dyndbg:   align 1 6: 177
[    0.597669] dyndbg:   align 1 7: 255
[    0.598316] dyndbg:  file align totals: 2014
[    0.598652] dyndbg: func aligns:
[    0.599214] dyndbg:   align 2 0: 2006
[    0.599652] dyndbg:   align 2 1: 7
[    0.600168] dyndbg:   align 2 2: 0
[    0.600648] dyndbg:   align 2 3: 0
[    0.600652] dyndbg:   align 2 4: 0
[    0.601105] dyndbg:   align 2 5: 0
[    0.601652] dyndbg:   align 2 6: 0
[    0.602203] dyndbg:   align 2 7: 1
[    0.602654] dyndbg:  func align totals: 2014
[    0.603431] dyndbg: format aligns:
[    0.603658] dyndbg:   align 3 0: 1053
[    0.604429] dyndbg:   align 3 1: 134
[    0.604653] dyndbg:   align 3 2: 161
[    0.605181] dyndbg:   align 3 3: 142
[    0.605652] dyndbg:   align 3 4: 137
[    0.606250] dyndbg:   align 3 5: 117
[    0.606652] dyndbg:   align 3 6: 124
[    0.607183] dyndbg:   align 3 7: 146
[    0.608669] dyndbg: earlyprintk="serial,ttyS0,115200"

This means low order bits are unavailable for encoding extra info, as
is done in struct static_key.

Consider the last lines of /proc/dynamic_debug/control, here with
matching fields replaced by '^'.  The pattern here is common head(s)
& differing tail(s).

init/main.c main run_init_process "    %s\012" 1339
^ ^ ^ "  with environment:\012" 1337
^ ^ ^ "    %s\012" 1336
^ ^ ^ "  with arguments:\012" 1334
^ ^ initcall_blacklisted "initcall %s blacklisted\012" 1123
^ ^ initcall_blacklist "blacklisting initcall %s\012" 1084

struct ddebug_callsite fields [mod, file, func, format] are 4-tuples;
each element points at different kinds/sources of linkage data
(&module->name, __FILE__, __FUNC__, format-strings).

callsite-tails are 4,3,2,1-tuples, with matching heads removed.

If we can force ALIGN(2) on all those linkage data sources, then we
can use +1 to mark the Beginning-Of-Tuple (or EOT), and so distinguish
amongst the N-tuples, and reconstruct each record by copying and
changing the previous record.  Each new module block starts with a
4-tuple; the init/main example block above is a 4,1,1,1,2,2-tuple
sequence, using 11/24 of the space.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 27 ++++++++++++++++++++++++++-
 1 file changed, 26 insertions(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 5980d44ff2f8..c84efb4e036b 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1079,6 +1079,13 @@ static int __init dynamic_debug_init_control(void)
 	return 0;
 }
 
+
+static __initdata int alignments[4][8];
+static void bump_ct(int i, const char *p)
+{
+	alignments[i][ (long)p & 7 ]++;
+}
+
 static int __init dynamic_debug_init(void)
 {
 	struct _ddebug *iter, *iter_start, *prev = NULL;
@@ -1087,7 +1094,9 @@ static int __init dynamic_debug_init(void)
 	int ret = 0;
 	int n = 0, entries = 0, modct = 0;
 	int modreps = 0, funcreps = 0, filereps = 0;
-
+	int i,k;
+	char *kind[] = { "mod","file","func","format" };
+	
 	if (&__start___dyndbg == &__stop___dyndbg) {
 		if (IS_ENABLED(CONFIG_DYNAMIC_DEBUG)) {
 			pr_warn("_ddebug table is empty in a CONFIG_DYNAMIC_DEBUG build\n");
@@ -1111,6 +1120,12 @@ static int __init dynamic_debug_init(void)
 			prev++; /* one behind iter */
 		}
 		entries++;
+
+		bump_ct(0, iter->site->modname);
+		bump_ct(1, iter->site->filename);
+		bump_ct(2, iter->site->function);
+		bump_ct(3, iter->site->format);
+
 		if (strcmp(modname, iter->site->modname)) {
 			modct++;
 			ret = ddebug_add_module(iter_start, n, modname);
@@ -1135,6 +1150,16 @@ static int __init dynamic_debug_init(void)
 	vpr_info("%d entries. repeated entries: %d module %d file %d func\n",
 		 entries, modreps, filereps, funcreps);
 
+	/* display alignment info on fields */
+	for (i=0; i<4; i++) {
+		k = 0;
+		vpr_info("%s aligns:\n", kind[i]);
+		for (n=0; n<8; n++) {
+			vpr_info("  align %d %d: %d\n", i, n, alignments[i][n]);
+			k += alignments[i][n];
+		}
+		vpr_info(" %s align totals: %d\n", kind[i], k);
+	}
 	/* apply ddebug_query boot param, dont unload tables on err */
 	if (ddebug_setup_string[0] != '\0') {
 		pr_warn("ddebug_query param name is deprecated, change it to dyndbg\n");
-- 
2.28.0

[PATCH 4/7] dyndbg: select ZPOOL,ZS_MALLOC in Kconfig.debug DYNAMIC_DEBUG_CORE

[Jim Cromie]

dyndbg will next need zs_malloc and friends, so add config reqs now,
to maybe avoid churny remakes later.

ZPOOL,ZSMALLOC are now required for DYNAMIC_DEBUG_CORE, as theyre
needed to get value (mem use reduction) from the upcoming
dyndbg/callsite split.

---

ZS_MALLOC is done with "depends on" instead of "select" to break a
recursive dependency.  I think this doesnt quite sort things out for
other config permutations, TBD.

-v2 fixup -> _CORE
Reported-by: kernel test robot <lkp@intel.com>

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/Kconfig.debug | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index c789b39ed527..7eb7b43037d9 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -170,6 +170,8 @@ config DYNAMIC_DEBUG_CORE
 	bool "Enable core function of dynamic debug support"
 	depends on PRINTK
 	depends on (DEBUG_FS || PROC_FS)
+	select ZPOOL
+	depends on ZSMALLOC
 	help
 	  Enable core functional support of dynamic debug. It is useful
 	  when you want to tie dynamic debug to your kernel modules with
-- 
2.28.0

[PATCH 5/7] dyndbg: replace __dyndbg_callsite section with a zs-pool copy.

[Jim Cromie]

A previous commit split struct _ddebugs into heads & bodies, linked
across 2 ELF sections.  Lets now copy the bodies into a zs_pool, and
relink the head to the new body.  This should allow recycling the
__dyndbg_callsite section soon.

The goal is to let a compression algo handle the repetition, and map
individual records in when needed.  I have seen 3:1 page/zspage
compression (in /sys/kernel/debug/zsmalloc/callsites)

Since dynamic_debug is nice to have but rarely used, paying more for
active logging to save in-kernel memory might be a worthwhile tradeoff.

This is how:

New ddebug_zpool_init(), at late_initcall time, creates the zpool.
Per dmesg, this is shortly after zswap is ready.

ddebug_add_module() now also calls new ddebug_zpool_add(1) foreach
callsite in the module. (1) copies the _ddebug_callsite record into
the zpool, once the zpool is ready.  For builtin modules, added in
early-boot, that zpool was not ready yet.  So ddebug_zpool_init() also
calls ddebug_zpool_add() for all those builtin modules already added
by ddebug_add_module().

New ddebug_zpool_add() does, foreach _ddebug:
 - zs_mallocs a zrec, saves handle to .zhandle,
 - zs_maps and copies callsite to it
 - zs_unmaps it, triggering write to zram
 - .site=0, detaching __dyndbg_callsites[item]
   which later triggers zs_map (.zhandle)

So we leave late-init with a full zram copy of __dyndbg_callsites
section, which is thus ready to reclaim.

ddebug_zpool_remove() undoes ddebug_zpool_add().
We call it from ddebug_remove_module().

The 3 existing users of struct _ddebug get the site ref entirely via 2
helpers, which manage the zs-mapping;

- ddebug_getsite() returns .site 1st, or maps zrec to it
  and returns it.

- ddebug_putsite() always unmaps, minimizing online ram.
  (see 1 below)

Those 3 users each take ddebug_lock around the get/puts, either
directly, or via ddebug_proc_(start|end).

ddebug_change() also gets s/continue/goto skipsite/g to cleanly unmap
the record at the bottom of the loop.

Im seeing 3:1 pages_per_zspage:

 # cut -c1-12,40-77,85-90 $SKD/zsmalloc/dyndbg_callsites/classes | head -n3
 class  sizebj_allocated   obj_used pages_used pagzspage
     0    32           0          0          0         1
     1    48        2816       2605         33         3

This much works.

Next steps:

1. dont always unmap in _put(), leave enabled pr_debugs mapped.

this is sticking point atm.

This would make the set of zs_mapped recs work like a cache, reducing
zs_mappings to a trickle, and only for <>control.

2. move key from struct _ddebug into _ddebug_callsite

key doesnt exactly fit semantically (and its not RO), but its use is
super rare, and is never needed without also needing all the other
callsite data.  Getting it out of head would save on-line ram.

But it broke in HEAD~1 when I tried it, with asm goto errors.
`grep arch_static_branch` suggests my argument to it was uniquely
complicated and dereferencing.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 include/linux/dynamic_debug.h |   1 +
 lib/dynamic_debug.c           | 148 +++++++++++++++++++++++++++++++---
 2 files changed, 137 insertions(+), 12 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 0bf7036bcdb2..a8336b9cc011 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -34,6 +34,7 @@ struct _ddebug {
 	} key;
 #endif
 	struct _ddebug_callsite *site;
+	long unsigned int zhandle;
 	/*
 	 * The flags field controls the behaviour at the callsite.
 	 * The bits here are changed dynamically when the user
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index c84efb4e036b..473406b069a7 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -36,6 +36,7 @@
 #include <linux/sched.h>
 #include <linux/device.h>
 #include <linux/netdevice.h>
+#include <linux/zsmalloc.h>
 
 #include <rdma/ib_verbs.h>
 
@@ -72,6 +73,8 @@ static LIST_HEAD(ddebug_tables);
 static int verbose;
 module_param(verbose, int, 0644);
 
+static struct zs_pool *dd_callsite_zpool;
+
 /* Return the path relative to source root */
 static inline const char *trim_prefix(const char *path)
 {
@@ -139,6 +142,34 @@ static void vpr_info_dq(const struct ddebug_query *query, const char *msg)
 		 query->first_lineno, query->last_lineno);
 }
 
+/*
+ * ddebug_getsite - returns site, or maps it then returns it.
+ */
+static struct _ddebug_callsite* ddebug_getsite(struct _ddebug *dp)
+{
+	if (dp->site)
+		return dp->site;
+
+	dp->site = (struct _ddebug_callsite*)
+		zs_map_object(dd_callsite_zpool, dp->zhandle, ZS_MM_RO);
+
+	return dp->site;
+}
+
+/*
+ * ddebug_putsite - unmaps site, implements policy choice
+ */
+static void ddebug_putsite(struct _ddebug *dp)
+{
+	if (!dp->zhandle)
+		/* need to keep site until zmap backing exists */
+		return;
+
+	/* always unmap for now. if !pr-debug has locking issues */
+	zs_unmap_object(dd_callsite_zpool, dp->zhandle);
+	dp->site = NULL;
+}
+
 /*
  * Search the tables for _ddebug's which match the given `query' and
  * apply the `flags' and `mask' to them.  Returns number of matching
@@ -165,7 +196,8 @@ static int ddebug_change(const struct ddebug_query *query,
 
 		for (i = 0; i < dt->num_ddebugs; i++) {
 			struct _ddebug *dp = &dt->ddebugs[i];
-			struct _ddebug_callsite *dc = dp->site;
+			struct _ddebug_callsite *dc;
+			dc = ddebug_getsite(dp);
 
 			/* match against the source filename */
 			if (query->filename &&
@@ -174,12 +206,12 @@ static int ddebug_change(const struct ddebug_query *query,
 					   kbasename(dc->filename)) &&
 			    !match_wildcard(query->filename,
 					   trim_prefix(dc->filename)))
-				continue;
+				goto skipsite;
 
 			/* match against the function */
 			if (query->function &&
 			    !match_wildcard(query->function, dc->function))
-				continue;
+				goto skipsite;
 
 			/* match against the format */
 			if (query->format) {
@@ -188,24 +220,24 @@ static int ddebug_change(const struct ddebug_query *query,
 					/* anchored search. match must be at beginning */
 					p = strstr(dc->format, query->format+1);
 					if (p != dc->format)
-						continue;
+						goto skipsite;
 				} else if (!strstr(dc->format, query->format))
-					continue;
+					goto skipsite;
 			}
 
 			/* match against the line number range */
 			if (query->first_lineno &&
 			    dc->lineno < query->first_lineno)
-				continue;
+				goto skipsite;
 			if (query->last_lineno &&
 			    dc->lineno > query->last_lineno)
-				continue;
+				goto skipsite;
 
 			nfound++;
 
 			newflags = (dp->flags & modifiers->mask) | modifiers->flags;
 			if (newflags == dp->flags)
-				continue;
+				goto skipsite;
 #ifdef CONFIG_JUMP_LABEL
 			if (dp->flags & _DPRINTK_FLAGS_PRINT) {
 				if (!(modifiers->flags & _DPRINTK_FLAGS_PRINT))
@@ -218,6 +250,9 @@ static int ddebug_change(const struct ddebug_query *query,
 				 trim_prefix(dc->filename), dc->lineno,
 				 dt->mod_name, dc->function,
 				 ddebug_describe_flags(dp->flags, &fbuf));
+
+		skipsite:
+			ddebug_putsite(dp);
 		}
 	}
 	mutex_unlock(&ddebug_lock);
@@ -588,14 +623,16 @@ static int remaining(int wrote)
 	return 0;
 }
 
-static char *dynamic_emit_prefix(const struct _ddebug *dp, char *buf)
+static char *dynamic_emit_prefix(struct _ddebug *dp, char *buf)
 {
 	int pos_after_tid;
 	int pos = 0;
-	const struct _ddebug_callsite *desc = dp->site;
+	const struct _ddebug_callsite *desc;
 
 	*buf = '\0';
 
+	desc = ddebug_getsite(dp);
+
 	if (dp->flags & _DPRINTK_FLAGS_INCL_TID) {
 		if (in_interrupt())
 			pos += snprintf(buf + pos, remaining(pos), "<intr> ");
@@ -618,6 +655,8 @@ static char *dynamic_emit_prefix(const struct _ddebug *dp, char *buf)
 	if (pos >= PREFIX_SIZE)
 		buf[PREFIX_SIZE - 1] = '\0';
 
+	ddebug_putsite(dp);
+
 	return buf;
 }
 
@@ -882,7 +921,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 {
 	struct ddebug_iter *iter = m->private;
 	struct _ddebug *dp = p;
-	struct _ddebug_callsite *dc = dp->site;
+	struct _ddebug_callsite *dc;
 	struct flagsbuf flags;
 
 	if (p == SEQ_START_TOKEN) {
@@ -891,6 +930,8 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 		return 0;
 	}
 
+	dc = ddebug_getsite(dp);
+
 	seq_printf(m, "%s:%u [%s]%s =%s \"",
 		   trim_prefix(dc->filename), dc->lineno,
 		   iter->table->mod_name, dc->function,
@@ -898,6 +939,8 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 	seq_escape(m, dc->format, "\t\r\n\"");
 	seq_puts(m, "\"\n");
 
+	ddebug_putsite(dp);
+
 	return 0;
 }
 
@@ -941,6 +984,50 @@ static const struct proc_ops proc_fops = {
 	.proc_write = ddebug_proc_write
 };
 
+/*
+ * ddebug_zpool_add() copies the callsite into zram, saves ref in
+ * .zhandle, and forgets .site, allowing recycling of the
+ * __dyndbg_callsite[] section.
+ */
+static void ddebug_zpool_add(struct _ddebug *dp)
+{
+	unsigned long handle;
+	struct _ddebug_callsite *site;
+
+	handle = zs_malloc(dd_callsite_zpool, sizeof(struct _ddebug_callsite),
+			   GFP_KERNEL);
+	if (!handle) {
+		pr_err("pool malloc failed on %s\n", dp->site->function);
+		return;
+	}
+	dp->zhandle = handle;
+
+	site = (struct _ddebug_callsite *)
+		zs_map_object(dd_callsite_zpool, handle, ZS_MM_WO);
+
+	if (!site) {
+		pr_err("zs-map failed\n");
+		return;
+	}
+	memcpy(site, dp->site, sizeof(struct _ddebug_callsite));
+
+	/* forget __dyndbg_callsites[] so we can reclaim it */
+	dp->site = NULL;
+	zs_unmap_object(dd_callsite_zpool, handle);
+}
+
+static void ddebug_zpool_remove(struct _ddebug *dp)
+{
+	if (dp->site) {
+		pr_warn("zhandle shouldnt be mapped now\n");
+		zs_unmap_object(dd_callsite_zpool, dp->zhandle);
+	}
+	if (!dp->zhandle)
+		pr_err("zhandle already cleared !\n");
+	else
+		zs_free(dd_callsite_zpool, dp->zhandle);
+}
+
 /*
  * Allocate a new ddebug_table for the given module
  * and add it to the global list.
@@ -966,10 +1053,15 @@ int ddebug_add_module(struct _ddebug *tab, unsigned int n,
 	dt->ddebugs = tab;
 
 	mutex_lock(&ddebug_lock);
+	if (dd_callsite_zpool)
+		/* zpool is ready for filling late */
+		for (; n; n--, tab++)
+			ddebug_zpool_add(tab);
+
 	list_add(&dt->link, &ddebug_tables);
 	mutex_unlock(&ddebug_lock);
 
-	v2pr_info("%3u debug prints in module %s\n", n, dt->mod_name);
+	v2pr_info("%3u debug prints in module %s\n", dt->num_ddebugs, dt->mod_name);
 	return 0;
 }
 
@@ -1033,6 +1125,13 @@ int ddebug_remove_module(const char *mod_name)
 	mutex_lock(&ddebug_lock);
 	list_for_each_entry_safe(dt, nextdt, &ddebug_tables, link) {
 		if (dt->mod_name == mod_name) {
+
+			unsigned int n = dt->num_ddebugs;
+			struct _ddebug *dp = dt->ddebugs;
+
+			for (; n; n--, dp++)
+				ddebug_zpool_remove(dp);
+
 			ddebug_table_free(dt);
 			ret = 0;
 			break;
@@ -1079,6 +1178,31 @@ static int __init dynamic_debug_init_control(void)
 	return 0;
 }
 
+/*
+ * at lateinit, initialize the zpool, and fill it with copies of
+ * struct _ddebug_callsite records, in __dyndbg_callsites linker
+ * section, for the builtin modules.
+ */
+static void __init ddebug_zpool_init(void)
+{
+	struct _ddebug *iter;
+
+	/* tbd- no corresponding destroy */
+	dd_callsite_zpool = zs_create_pool("dyndbg_callsites");
+	if (!dd_callsite_zpool) {
+		pr_err("create pool failed\n");
+		return;
+	}
+
+	/* add-module normally does this, but not in time for builtins */
+	for (iter = __start___dyndbg; iter < __stop___dyndbg; iter++)
+		ddebug_zpool_add(iter);
+
+	v2pr_info("total pages: %lu compaction: %lu\n",
+		  zs_get_total_pages(dd_callsite_zpool),
+		  zs_compact(dd_callsite_zpool));
+}
+late_initcall(ddebug_zpool_init);
 
 static __initdata int alignments[4][8];
 static void bump_ct(int i, const char *p)
-- 
2.28.0

[PATCH 6/7] dyndbg: add locking around zpool-add loop in zpool-init

[Jim Cromie]

This commit doesnt improve things, last commit was working, next one
still breaks, despite this "fix".  I keep it separate to isolate it
and the reasoning for review, which now stated, will be refuted as
needed. ;-)

Locking review:

ddebug_zpool_init(), like other ddebug_*_init() routines, does no
locking itself.  Unlike them, it runs later, at late_init.  This patch
doesnt fix the kernel panic that HEAD+1 does.

ddebug_callsite_get/put() are called as a pair under mutex-lock for
all 3 callsite users.

2 of them; ddebug_change() and dynamic_emit_prefix(), do their own
ABBA-ish LGPU (Lock-Get-Put-Unlock).

ddebug_proc_show() does the GP part, and is wrapped by
ddebug_proc_start|stop() with LU.

ddebug_add_module() does LU to protect list_add(), HEAD~1 added
ddebug_zpool_add() loop inside that protection.

This commit adds locking to ddebug_zpool_init(), around the loop of
ddebug_zpool_add(), to match the locking in ddebug_add_module().

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 473406b069a7..534d73e45844 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1195,8 +1195,10 @@ static void __init ddebug_zpool_init(void)
 	}
 
 	/* add-module normally does this, but not in time for builtins */
+	mutex_lock(&ddebug_lock);
 	for (iter = __start___dyndbg; iter < __stop___dyndbg; iter++)
 		ddebug_zpool_add(iter);
+	mutex_unlock(&ddebug_lock);
 
 	v2pr_info("total pages: %lu compaction: %lu\n",
 		  zs_get_total_pages(dd_callsite_zpool),
-- 
2.28.0

[PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites

[Jim Cromie]

In ddebug_putsite(), dont zs_unmap the callsite if it is enabled for
printing.  This means that the next time this pr_debug callsite is
executed, the _getsite() will succeed quickly without remapping the
zrec.

Once the callsite is disabled via >control, a following _putsite()
will see the flag cleared, and zs_unmap it.

This changes the lifetime of our zs_mappings from brief (only for the
single printk) to as long as uptime (if a prdebug is enabled til
poweroff).  This appears to be triggering the ensuing mayhem.

I am able to get through init, to root console, by disabling all
dynamic-debugs, including the ones that are enabled at compile.

$ kruna --kopt \*.dyndbg=-p --kopt debug_locks_proceed=1

but enabling any pr-debug crashes.
Plain old boot also panics, as pasted below.

$ kruna --kopt debug_locks_proceed=1

[    0.443926] -----------------------------------------------------------------
[    0.445085] BUG:  14 unexpected failures (out of 350) - debugging proceeding anyway! |
[    0.446498] -----------------------------------------------------------------
...
[    0.617347] dyndbg: 224 modules, 2014 entries and 8960 bytes in ddebug tables, 80560 bytes in __dyndbg section, 80560 bytes in __dyndbg_callsites section
[    0.617537] dyndbg: 2014 entries. repeated entries: 1789 module 1667 file 809 func
...
[    1.456548] zswap: loaded using pool zstd/zsmalloc
[    1.462802] dyndbg: total pages: 24 compaction: 0
[    1.463965] PM:   Magic number: 12:980:889
[    1.464860] BUG: sleeping function called from invalid context at mm/slab.h:506
[    1.466150] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 1, name: swapper/0
[    1.467282] 3 locks held by swapper/0/1:
[    1.467936]  #0: ffffffff82875460 (cpu_hotplug_lock){++++}-{0:0}, at: cpufreq_register_driver+0xb5/0x2f0
[    1.469622]  #1: ffff888003cfbd28 (subsys mutex#5){+.+.}-{4:4}, at: subsys_interface_register+0x5f/0x130
[    1.471448]  #2: ffff8880057f00b0 (&zspage->lock){.+.+}-{3:3}, at: zs_map_object+0x7b/0x2b0
[    1.472666] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.474007] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.475314] Call Trace:
[    1.475682]  dump_stack+0x7d/0x9f
[    1.476162]  ___might_sleep.cold+0xa6/0xb7
[    1.476745]  __might_sleep+0x46/0x80
[    1.477266]  __kmalloc_track_caller+0x1dd/0x2d0
[    1.477895]  kstrdup_const+0x45/0x70
[    1.478678]  __kernfs_new_node+0x4b/0x280
[    1.479280]  ? dynamic_emit_prefix+0x1dd/0x1f0
[    1.479907]  ? __dynamic_pr_debug+0x8a/0xb0
[    1.480496]  kernfs_create_dir_ns+0x44/0xc0
[    1.481188]  sysfs_create_dir_ns+0x6c/0xd0
[    1.481820]  kobject_add_internal+0x102/0x300
[    1.482505]  kobject_init_and_add+0x71/0xa0
[    1.483194]  ? kmem_cache_alloc_trace+0x21d/0x270
[    1.483993]  ? cpufreq_online+0x62/0x960
[    1.484628]  cpufreq_online+0xa5/0x960
[    1.485325]  ? system_root_device_release+0x10/0x10
[    1.486223]  cpufreq_add_dev+0x79/0x90
[    1.486868]  subsys_interface_register+0x11e/0x130
[    1.487787]  cpufreq_register_driver+0x171/0x2f0
[    1.488679]  acpi_cpufreq_init+0x266/0x294
[    1.489508]  ? CPU_FREQ_GOV_ONDEMAND_init+0x12/0x12
[    1.490350]  do_one_initcall+0x5a/0x2c0
[    1.491037]  ? rcu_read_lock_sched_held+0x41/0x80
[    1.491820]  kernel_init_freeable+0x23b/0x287
[    1.492561]  ? rest_init+0x24d/0x24d
[    1.493180]  kernel_init+0x9/0x103
[    1.493825]  ret_from_fork+0x22/0x30
[    1.494557]
[    1.494804] =============================
[    1.495503] [ BUG: Invalid wait context ]
[    1.496134] 5.10.0-rc3-00304-g7a4ad0dc5042 #75 Tainted: G        W
[    1.497346] -----------------------------
[    1.497986] swapper/0/1 is trying to lock:
[    1.498668] ffffffff8299ad90 (iattr_mutex){+.+.}-{4:4}, at: kernfs_xattr_get+0x25/0x60
[    1.499855] other info that might help us debug this:
[    1.500655] context-{5:5}
[    1.501118] 3 locks held by swapper/0/1:
[    1.501732]  #0: ffffffff82875460 (cpu_hotplug_lock){++++}-{0:0}, at: cpufreq_register_driver+0xb5/0x2f0
[    1.503384]  #1: ffff888003cfbd28 (subsys mutex#5){+.+.}-{4:4}, at: subsys_interface_register+0x5f/0x130
[    1.505289]  #2: ffff8880057f00b0 (&zspage->lock){.+.+}-{3:3}, at: zs_map_object+0x7b/0x2b0
[    1.506743] stack backtrace:
[    1.507228] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.509060] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.510505] Call Trace:
[    1.510887]  dump_stack+0x7d/0x9f
[    1.511456]  __lock_acquire.cold+0xb9/0x2cd
[    1.512389]  ? usage_match+0x20/0x20
[    1.512960]  ? __bfs+0xf3/0x220
[    1.513442]  lock_acquire+0x137/0x3e0
[    1.514069]  ? kernfs_xattr_get+0x25/0x60
[    1.514724]  ? ___might_sleep+0x15c/0x190
[    1.515369]  __mutex_lock+0x8e/0x940
[    1.515866]  ? kernfs_xattr_get+0x25/0x60
[    1.516515]  ? asm_sysvec_apic_timer_interrupt+0x12/0x20
[    1.517343]  ? kernfs_xattr_get+0x25/0x60
[    1.517884]  mutex_lock_nested+0x16/0x20
[    1.518577]  kernfs_xattr_get+0x25/0x60
[    1.519151]  selinux_kernfs_init_security+0x5c/0x210
[    1.519822]  ? sched_clock+0x9/0x10
[    1.520513]  ? sched_clock_cpu+0x11/0xc0
[    1.521172]  security_kernfs_init_security+0x2a/0x40
[    1.522164]  __kernfs_new_node+0x1b7/0x280
[    1.522842]  ? dynamic_emit_prefix+0x1dd/0x1f0
[    1.523610]  ? __dynamic_pr_debug+0x8a/0xb0
[    1.524350]  kernfs_create_dir_ns+0x44/0xc0
[    1.525033]  sysfs_create_dir_ns+0x6c/0xd0
[    1.525682]  kobject_add_internal+0x102/0x300
[    1.526384]  kobject_init_and_add+0x71/0xa0
[    1.527138]  ? kmem_cache_alloc_trace+0x21d/0x270
[    1.527869]  ? cpufreq_online+0x62/0x960
[    1.528566]  cpufreq_online+0xa5/0x960
[    1.529461]  ? system_root_device_release+0x10/0x10
[    1.530273]  cpufreq_add_dev+0x79/0x90
[    1.530886]  subsys_interface_register+0x11e/0x130
[    1.531591]  cpufreq_register_driver+0x171/0x2f0
[    1.532251]  acpi_cpufreq_init+0x266/0x294
[    1.532803]  ? CPU_FREQ_GOV_ONDEMAND_init+0x12/0x12
[    1.533524]  do_one_initcall+0x5a/0x2c0
[    1.534196]  ? rcu_read_lock_sched_held+0x41/0x80
[    1.535008]  kernel_init_freeable+0x23b/0x287
[    1.535706]  ? rest_init+0x24d/0x24d
[    1.536314]  kernel_init+0x9/0x103
[    1.536903]  ret_from_fork+0x22/0x30
[    1.537555] kobject: 'policy0' (0000000099a22e3a): kobject_cleanup, parent 000000008a313735
[    1.538996] kobject: 'policy0' (0000000099a22e3a): auto cleanup kobject_del
[    1.540082] kobject: 'policy0' (0000000099a22e3a): calling ktype release
[    1.541143] kobject: 'policy0': free name
[    1.541750] ------------[ cut here ]------------
[    1.542630] initcall acpi_cpufreq_init+0x0/0x294 returned with preemption imbalance
[    1.544046] WARNING: CPU: 0 PID: 1 at init/main.c:1230 do_one_initcall+0x220/0x2c0
[    1.545335] Modules linked in:
[    1.545846] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.547549] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.549121] RIP: 0010:do_one_initcall+0x220/0x2c0
[    1.549983] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
[    1.553209] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
[    1.554326] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
[    1.555682] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
[    1.556869] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
[    1.558111] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d5550a
[    1.559357] R13: 00000000ffffffed R14: ffffffff82e0a940 R15: ffff888003d313e0
[    1.560577] FS:  0000000000000000(0000) GS:ffff888007a00000(0000) knlGS:0000000000000000
[    1.562159] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    1.563285] CR2: 0000000000000000 CR3: 0000000002824001 CR4: 0000000000370ef0
[    1.564578] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[    1.565924] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[    1.567224] Call Trace:
[    1.567665]  ? rcu_read_lock_sched_held+0x41/0x80
[    1.568565]  kernel_init_freeable+0x23b/0x287
[    1.569420]  ? rest_init+0x24d/0x24d
[    1.570103]  kernel_init+0x9/0x103
[    1.570736]  ret_from_fork+0x22/0x30
[    1.571750] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.573387] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.575132] Call Trace:
[    1.575538]  dump_stack+0x7d/0x9f
[    1.576085]  ? do_one_initcall+0x220/0x2c0
[    1.576744]  __warn.cold+0x24/0x85
[    1.577522]  ? do_one_initcall+0x220/0x2c0
[    1.578287]  report_bug+0xa1/0xc0
[    1.578812]  handle_bug+0x45/0x90
[    1.579376]  exc_invalid_op+0x19/0x70
[    1.579994]  asm_exc_invalid_op+0x12/0x20
[    1.580649] RIP: 0010:do_one_initcall+0x220/0x2c0
[    1.581497] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
[    1.584556] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
[    1.585491] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
[    1.586739] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
[    1.588054] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
[    1.589347] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d5550a
[    1.590800] R13: 00000000ffffffed R14: ffffffff82e0a940 R15: ffff888003d313e0
[    1.592131]  ? CPU_FREQ_GOV_ONDEMAND_init+0x12/0x12
[    1.593085]  ? console_unlock+0x37d/0x5c0
[    1.593785]  ? console_unlock+0x4d6/0x5c0
[    1.594484]  ? rcu_read_lock_sched_held+0x41/0x80
[    1.595303]  kernel_init_freeable+0x23b/0x287
[    1.596049]  ? rest_init+0x24d/0x24d
[    1.596650]  kernel_init+0x9/0x103
[    1.597232]  ret_from_fork+0x22/0x30
[    1.597872] irq event stamp: 1862449
[    1.598517] hardirqs last  enabled at (1862449): [<ffffffff81d80a15>] irqentry_exit+0x35/0x80
[    1.600046] hardirqs last disabled at (1862448): [<ffffffff81d7f350>] sysvec_apic_timer_interrupt+0x10/0xb0
[    1.601801] softirqs last  enabled at (1862354): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
[    1.603419] softirqs last disabled at (1862345): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
[    1.605203] ---[ end trace ecd8f90d8b1f2ab8 ]---
[    1.606532] ata2.01: NODEV after polling detection
[    1.607776] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
[    1.609726] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5
[    1.611649] kobject: 'target1:0:0' (0000000025bf58b2): kobject_add_internal: parent: 'host1', set: 'devices'
[    1.613564] main:device_pm_add: PM: Adding info for scsi:target1:0:0
[    1.614679] kobject: 'target1:0:0' (0000000025bf58b2): kobject_uevent_env
[    1.615975] kobject: 'target1:0:0' (0000000025bf58b2): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0'
[    1.618095] kobject: '1:0:0:0' (00000000429180e9): kobject_add_internal: parent: 'target1:0:0', set: 'devices'
[    1.619807] main:device_pm_add: PM: Adding info for scsi:1:0:0:0
[    1.621053] kobject: '1:0:0:0' (00000000429180e9): kobject_uevent_env
[    1.622564] kobject: '1:0:0:0' (00000000429180e9): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0'
[    1.624691] BUG: scheduling while atomic: kworker/u2:0/7/0x0000000d
[    1.625799] INFO: lockdep is turned off.
[    1.626446] Modules linked in:
[    1.626908] CPU: 0 PID: 7 Comm: kworker/u2:0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.628455] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.629774] Workqueue: events_unbound async_run_entry_fn
[    1.630649] Call Trace:
[    1.631053]  dump_stack+0x7d/0x9f
[    1.631617]  __schedule_bug.cold+0x5f/0x70
[    1.632263]  __schedule+0x823/0x9c0
[    1.632806]  ? lock_release+0x1e1/0x3f0
[    1.633382]  ? hctx_unlock+0x1a/0xb0
[    1.633975]  ? wait_for_completion_io+0x7e/0x110
[    1.634749]  schedule+0x63/0xe0
[    1.635311]  schedule_timeout+0x175/0x1e0
[    1.636004]  ? __blk_mq_delay_run_hw_queue+0x16d/0x180
[    1.636847]  ? lock_acquired+0x1ef/0x380
[    1.637630]  ? lock_release+0x1e1/0x3f0
[    1.638484]  ? wait_for_completion_io+0xa1/0x110
[    1.639208]  ? _raw_spin_unlock_irq+0x23/0x40
[    1.639877]  io_schedule_timeout+0x4b/0x80
[    1.640614]  wait_for_completion_io+0xa9/0x110
[    1.641355]  blk_execute_rq+0x7f/0xb0
[    1.641905]  __scsi_execute+0x109/0x260
[    1.642545]  scsi_test_unit_ready+0x5b/0xe0
[    1.643275]  sr_probe+0x23b/0x610
[    1.643782]  really_probe+0x3ad/0x460
[    1.644400]  driver_probe_device+0xe4/0x150
[    1.645112]  __device_attach_driver+0x6c/0xd0
[    1.645837]  ? driver_allows_async_probing+0x50/0x50
[    1.646679]  bus_for_each_drv+0x82/0xd0
[    1.647285]  __device_attach+0xde/0x1e0
[    1.647886]  device_initial_probe+0xe/0x10
[    1.648525]  bus_probe_device+0x9b/0xb0
[    1.649077]  device_add+0x3b8/0x840
[    1.649674]  scsi_sysfs_add_sdev+0x91/0x290
[    1.650393]  scsi_probe_and_add_lun+0x83f/0xbe0
[    1.651325]  __scsi_add_device+0x10a/0x120
[    1.652020]  ata_scsi_scan_host+0x98/0x1d0
[    1.652598]  ? wait_woken+0xb0/0xb0
[    1.653146]  async_port_probe+0x56/0x70
[    1.653679]  async_run_entry_fn+0x37/0x150
[    1.654395]  process_one_work+0x277/0x590
[    1.655278]  worker_thread+0x50/0x400
[    1.655802]  kthread+0x14c/0x170
[    1.656322]  ? process_one_work+0x590/0x590
[    1.656890]  ? __kthread_bind_mask+0x70/0x70
[    1.657659]  ret_from_fork+0x22/0x30
[    1.658512] kobject: 'memmap' (000000007533e45a): kobject_add_internal: parent: 'firmware', set: '<NULL>'
[    1.660202] kobject: 'memmap' (000000007533e45a): kobject_uevent_env
[    1.661228] kobject: 'memmap' (000000007533e45a): kobject_uevent_env: attempted to send uevent without kset!
[    1.662681] kobject: '0' (00000000ba522565): kobject_add_internal: parent: 'memmap', set: 'memmap'
[    1.664100] kobject: '1' (00000000387ad507): kobject_add_internal: parent: 'memmap', set: 'memmap'
[    1.665482] kobject: '2' (00000000c4547872): kobject_add_internal: parent: 'memmap', set: 'memmap'
[    1.666863] kobject: '3' (00000000d3a84794): kobject_add_internal: parent: 'memmap', set: 'memmap'
[    1.668227] kobject: '4' (0000000059225206): kobject_add_internal: parent: 'memmap', set: 'memmap'
[    1.669573] kobject: '5' (000000009bfaeef6): kobject_add_internal: parent: 'memmap', set: 'memmap'
[    1.671050] kobject: '6' (00000000fdded59a): kobject_add_internal: parent: 'memmap', set: 'memmap'
[    1.672667] ------------[ cut here ]------------
[    1.673345] initcall firmware_memmap_init+0x0/0x33 returned with preemption imbalance
[    1.674447] WARNING: CPU: 0 PID: 1 at init/main.c:1230 do_one_initcall+0x220/0x2c0
[    1.675557] Modules linked in:
[    1.676071] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.677657] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.678872] RIP: 0010:do_one_initcall+0x220/0x2c0
[    1.679730] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
[    1.682846] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
[    1.683829] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
[    1.684931] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
[    1.686030] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
[    1.687084] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d573c1
[    1.688257] R13: 0000000000000000 R14: ffffffff82e0a944 R15: ffff888003d313e0
[    1.689795] FS:  0000000000000000(0000) GS:ffff888007a00000(0000) knlGS:0000000000000000
[    1.691023] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    1.692094] CR2: 0000000000000000 CR3: 0000000002824001 CR4: 0000000000370ef0
[    1.693237] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[    1.694366] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[    1.695536] Call Trace:
[    1.695877]  ? rcu_read_lock_sched_held+0x41/0x80
[    1.696667]  kernel_init_freeable+0x23b/0x287
[    1.697404]  ? rest_init+0x24d/0x24d
[    1.697968]  kernel_init+0x9/0x103
[    1.698487]  ret_from_fork+0x22/0x30
[    1.699071] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.700595] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.702034] Call Trace:
[    1.702383]  dump_stack+0x7d/0x9f
[    1.702967]  ? do_one_initcall+0x220/0x2c0
[    1.703649]  __warn.cold+0x24/0x85
[    1.704217]  ? do_one_initcall+0x220/0x2c0
[    1.705099]  report_bug+0xa1/0xc0
[    1.705575]  handle_bug+0x45/0x90
[    1.706066]  exc_invalid_op+0x19/0x70
[    1.706547]  asm_exc_invalid_op+0x12/0x20
[    1.707180] RIP: 0010:do_one_initcall+0x220/0x2c0
[    1.707855] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
[    1.710508] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
[    1.711470] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
[    1.712933] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
[    1.714146] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
[    1.715350] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d573c1
[    1.716701] R13: 0000000000000000 R14: ffffffff82e0a944 R15: ffff888003d313e0
[    1.717854]  ? dmi_id_init+0x386/0x386
[    1.718486]  ? console_unlock+0x37d/0x5c0
[    1.719158]  ? console_unlock+0x4d6/0x5c0
[    1.719772]  ? rcu_read_lock_sched_held+0x41/0x80
[    1.720641]  kernel_init_freeable+0x23b/0x287
[    1.721566]  ? rest_init+0x24d/0x24d
[    1.722230]  kernel_init+0x9/0x103
[    1.722680]  ret_from_fork+0x22/0x30
[    1.723276] irq event stamp: 1862449
[    1.723894] hardirqs last  enabled at (1862449): [<ffffffff81d80a15>] irqentry_exit+0x35/0x80
[    1.725695] hardirqs last disabled at (1862448): [<ffffffff81d7f350>] sysvec_apic_timer_interrupt+0x10/0xb0
[    1.727307] softirqs last  enabled at (1862354): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
[    1.728795] softirqs last disabled at (1862345): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
[    1.730347] ---[ end trace ecd8f90d8b1f2ab9 ]---
[    1.731171] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    1.732579] kworker/u2:1 (62) used greatest stack depth: 14536 bytes left
[    1.734275] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
[    1.735368] cdrom: Uniform CD-ROM driver Revision: 3.20
[    1.736684] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    1.737871] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[    1.739479] ALSA device list:
[    1.739928] cfg80211: failed to load regulatory.db
[    1.740784]   No soundcards found.
[    1.741597] kobject: 'regulatory.0' (00000000ab092cdd): kobject_uevent_env
[    1.742766] kobject: 'regulatory.0' (00000000ab092cdd): fill_kobj_path: path = '/devices/platform/regulatory.0'
[    1.750002] kobject: '11:0' (0000000035d88d42): kobject_add_internal: parent: 'bdi', set: 'devices'
[    1.751742] main:device_pm_add: PM: Adding info for No Bus:11:0
[    1.752660] kobject: '11:0' (0000000035d88d42): kobject_uevent_env
[    1.753722] kobject: '11:0' (0000000035d88d42): fill_kobj_path: path = '/devices/virtual/bdi/11:0'
[    1.755338] kobject: 'block' (00000000da37173c): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
[    1.757024] kobject: 'sr0' (000000000b128df7): kobject_add_internal: parent: 'block', set: 'devices'
[    1.758667] main:device_pm_add: PM: Adding info for No Bus:sr0
[    1.759667] kobject: 'sr0' (000000000b128df7): kobject_uevent_env
[    1.760836] kobject: 'sr0' (000000000b128df7): kobject_uevent_env: uevent_suppress caused the event to drop!
[    1.762452] kobject: 'holders' (00000000e28bd786): kobject_add_internal: parent: 'sr0', set: '<NULL>'
[    1.763972] kobject: 'slaves' (00000000b2ff8eb3): kobject_add_internal: parent: 'sr0', set: '<NULL>'
[    1.765611] kobject: 'sr0' (000000000b128df7): kobject_uevent_env
[    1.766705] kobject: 'sr0' (000000000b128df7): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/block/sr0'
[    1.769006] kobject: 'queue' (00000000fbf3c544): kobject_add_internal: parent: 'sr0', set: '<NULL>'
[    1.770551] kobject: 'mq' (0000000001f3c10f): kobject_add_internal: parent: 'sr0', set: '<NULL>'
[    1.772069] kobject: 'mq' (0000000001f3c10f): kobject_uevent_env
[    1.773222] kobject: 'mq' (0000000001f3c10f): kobject_uevent_env: filter function caused the event to drop!
[    1.775037] kobject: '0' (0000000078f2eddd): kobject_add_internal: parent: 'mq', set: '<NULL>'
[    1.776604] kobject: 'cpu0' (000000007c3dee23): kobject_add_internal: parent: '0', set: '<NULL>'
[    1.778217] kobject: 'iosched' (000000003e5ac6f7): kobject_add_internal: parent: 'queue', set: '<NULL>'
[    1.779683] kobject: 'queue' (00000000fbf3c544): kobject_uevent_env
[    1.780580] kobject: 'queue' (00000000fbf3c544): kobject_uevent_env: filter function caused the event to drop!
[    1.782265] kobject: 'iosched' (000000003e5ac6f7): kobject_uevent_env
[    1.783231] kobject: 'iosched' (000000003e5ac6f7): kobject_uevent_env: filter function caused the event to drop!
[    1.784761] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    1.785487] kobject: '1:0:0:0' (00000000429180e9): kobject_uevent_env
[    1.786681] kobject: '1:0:0:0' (00000000429180e9): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0'
[    1.788806] kobject: 'scsi_device' (00000000fc009276): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
[    1.790501] kobject: '1:0:0:0' (0000000035d4f17d): kobject_add_internal: parent: 'scsi_device', set: 'devices'
[    1.792243] main:device_pm_add: PM: Adding info for No Bus:1:0:0:0
[    1.793265] kobject: '1:0:0:0' (0000000035d4f17d): kobject_uevent_env
[    1.794301] kobject: '1:0:0:0' (0000000035d4f17d): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/scsi_device/1:0:0:0'
[    1.796564] kobject: 'scsi_generic' (00000000d5199ad9): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
[    1.798157] kobject: 'sg0' (00000000da2b5c82): kobject_add_internal: parent: 'scsi_generic', set: 'devices'
[    1.799695] main:device_pm_add: PM: Adding info for No Bus:sg0
[    1.800732] BUG: scheduling while atomic: kworker/u2:0/7/0x00000009
[    1.801776] INFO: lockdep is turned off.
[    1.802463] Modules linked in:
[    1.802948] CPU: 0 PID: 7 Comm: kworker/u2:0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.804667] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.806213] Workqueue: events_unbound async_run_entry_fn
[    1.807254] Call Trace:
[    1.807659]  dump_stack+0x7d/0x9f
[    1.808232]  __schedule_bug.cold+0x5f/0x70
[    1.808793]  __schedule+0x823/0x9c0
[    1.809602]  ? wait_for_completion+0x7e/0x110
[    1.810402]  schedule+0x63/0xe0
[    1.810994]  schedule_timeout+0x175/0x1e0
[    1.811661]  ? lock_release+0x1e1/0x3f0
[    1.812329]  ? try_to_wake_up+0x1fe/0x740
[    1.813004]  ? lock_acquired+0x1ef/0x380
[    1.813607]  ? lock_release+0x1e1/0x3f0
[    1.814286]  ? wait_for_completion+0xa1/0x110
[    1.814998]  ? _raw_spin_unlock_irq+0x23/0x40
[    1.815669]  ? trace_hardirqs_on+0x2a/0xe0
[    1.816348]  ? wait_for_completion+0x7e/0x110
[    1.817080]  wait_for_completion+0xa9/0x110
[    1.817744]  devtmpfs_submit_req+0x6e/0x80
[    1.818434]  devtmpfs_create_node+0x9e/0xd0
[    1.819138]  device_add+0x729/0x840
[    1.819697]  device_create_groups_vargs+0xcf/0xf0
[    1.820539]  device_create+0x44/0x60
[    1.821159]  ? cdev_add+0x51/0x80
[    1.821671]  sg_add_device+0x292/0x410
[    1.822323]  device_add+0x449/0x840
[    1.822976]  scsi_sysfs_add_sdev+0x1be/0x290
[    1.823605]  scsi_probe_and_add_lun+0x83f/0xbe0
[    1.824332]  __scsi_add_device+0x10a/0x120
[    1.825052]  ata_scsi_scan_host+0x98/0x1d0
[    1.825756]  ? wait_woken+0xb0/0xb0
[    1.826400]  async_port_probe+0x56/0x70
[    1.827026]  async_run_entry_fn+0x37/0x150
[    1.827752]  process_one_work+0x277/0x590
[    1.828530]  worker_thread+0x50/0x400
[    1.829177]  kthread+0x14c/0x170
[    1.829654]  ? process_one_work+0x590/0x590
[    1.830318]  ? __kthread_bind_mask+0x70/0x70
[    1.830901]  ret_from_fork+0x22/0x30
[    1.831718] kobject: 'sr0' (000000000b128df7): kobject_uevent_env
[    1.832675] kobject: 'sr0' (000000000b128df7): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/block/sr0'
[    1.834777] kobject: 'sg0' (00000000da2b5c82): kobject_uevent_env
[    1.835860] kobject: 'sg0' (00000000da2b5c82): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/scsi_generic/sg0'
[    1.838069] sr 1:0:0:0: Attached scsi generic sg0 type 5
[    1.838805] kobject: 'bsg' (000000005c2815cf): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
[    1.840435] kobject: '1:0:0:0' (00000000ad96192e): kobject_add_internal: parent: 'bsg', set: 'devices'
[    1.841929] main:device_pm_add: PM: Adding info for No Bus:1:0:0:0
[    1.842964] kobject: '1:0:0:0' (00000000ad96192e): kobject_uevent_env
[    1.844087] kobject: '1:0:0:0' (00000000ad96192e): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/bsg/1:0:0:0'
[    1.846261] md: Skipping autodetection of RAID arrays. (raid=autodetect will force)
[    1.847813] kobject: '9p-fcall-cache' (00000000acb65d7d): kobject_add_internal: parent: 'slab', set: 'slab'
[    1.849788] kobject: '9p-1' (00000000f8fd831c): kobject_add_internal: parent: 'bdi', set: 'devices'
[    1.851175] main:device_pm_add: PM: Adding info for No Bus:9p-1
[    1.852055] kobject: '9p-1' (00000000f8fd831c): kobject_uevent_env
[    1.852906] kobject: '9p-1' (00000000f8fd831c): fill_kobj_path: path = '/devices/virtual/bdi/9p-1'
[    1.854695] VFS: Mounted root (9p filesystem) readonly on device 0:19.
[    1.856048] devtmpfs: mounted
[    1.857202] Freeing unused kernel image (initmem) memory: 3024K
[    1.858545] Write protecting the kernel read-only data: 24576k
[    1.860621] Freeing unused kernel image (text/rodata gap) memory: 2028K
[    1.862354] Freeing unused kernel image (rodata/data gap) memory: 1008K
[    1.863493] Run /bin/sh as init process
[    1.864131] main:run_init_process:   with arguments:
[    1.864902] main:run_init_process:     /bin/sh
[    1.865869] main:run_init_process:     -c
[    1.866527] main:run_init_process:     mount -t tmpfs run /run;mkdir -p /run/virtme/guesttools;/bin/mount -n -t 9p -o ro,version=9p2000.L,trans=virtio,access=any virtme.guesttools /run/virtme/guesttools;exec /run/virtme/guesttools/virtme-init
[    1.869845] main:run_init_process:   with environment:
[    1.870634] main:run_init_process:     HOME=/
[    1.871304] main:run_init_process:     TERM=xterm-256color
[    1.872359] main:run_init_process:     virtme_link_mods=/home/jimc/projects/lx/linux.git/builds/v2/.virtme_mods/lib/modules/0.0.0
[    1.874369] main:run_init_process:     virtme_stty_con=rows 24 cols 154 iutf8
[    1.875652] main:run_init_process:     multidevs=remap
[    1.876632] BUG: scheduling while atomic: swapper/0/1/0x00000011
[    1.877856] INFO: lockdep is turned off.
[    1.878502] Modules linked in:
[    1.879028] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.880594] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.882022] Call Trace:
[    1.882410]  dump_stack+0x7d/0x9f
[    1.883045]  __schedule_bug.cold+0x5f/0x70
[    1.883766]  __schedule+0x823/0x9c0
[    1.884524]  schedule+0x63/0xe0
[    1.885126]  p9_client_rpc+0x13b/0x6e0
[    1.885723]  ? wait_woken+0xb0/0xb0
[    1.886332]  p9_client_walk+0x80/0x2e0
[    1.887059]  ? d_alloc_parallel+0x3c8/0xa40
[    1.887735]  ? get_page_from_freelist+0x3ce/0x13b0
[    1.888758]  v9fs_vfs_lookup.part.0+0x65/0x1a0
[    1.889570]  v9fs_vfs_lookup+0x1a/0x20
[    1.890345]  __lookup_slow+0x108/0x1e0
[    1.891012]  ? lock_acquire+0x174/0x3e0
[    1.891705]  ? lock_acquire+0x174/0x3e0
[    1.892343]  walk_component+0x13c/0x1b0
[    1.892994]  ? security_inode_permission+0x30/0x50
[    1.893752]  link_path_walk.part.0+0x21a/0x350
[    1.894473]  path_openat+0xb0/0xa40
[    1.895058]  ? _raw_spin_unlock+0x1e/0x30
[    1.895717]  ? follow_page_mask+0x491/0x600
[    1.896625]  do_filp_open+0x87/0x130
[    1.897171]  ? __might_sleep+0x46/0x80
[    1.897795]  ? _cond_resched+0x15/0x50
[    1.898370]  ? __kmalloc+0x1f9/0x2c0
[    1.898875]  ? lock_acquire+0x174/0x3e0
[    1.899420]  ? avc_disable+0x20/0x20
[    1.899930]  do_open_execat+0x66/0x1a0
[    1.900456]  bprm_execve+0x1fe/0x8f0
[    1.901019]  ? ___might_sleep+0x42/0x190
[    1.901692]  kernel_execve+0x132/0x1b0
[    1.902281]  run_init_process+0xc0/0xc5
[    1.902972]  ? rest_init+0x24d/0x24d
[    1.903587]  kernel_init+0x96/0x103
[    1.904160]  ret_from_fork+0x22/0x30
[    1.908649] Kernel panic - not syncing: Requested init /bin/sh failed (error -14).
[    1.910091] CPU: 0 PID: 1 Comm: sh Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
[    1.911517] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[    1.912845] Call Trace:
[    1.913289]  dump_stack+0x7d/0x9f
[    1.913957]  ? rest_init+0x210/0x24d
[    1.914535]  panic+0x10a/0x2de
[    1.915094]  ? kernel_execve+0x145/0x1b0
[    1.915768]  ? rest_init+0x24d/0x24d
[    1.916417]  kernel_init+0xaf/0x103
[    1.917038]  ret_from_fork+0x22/0x30
[    1.917726] Kernel Offset: disabled
[    1.918324] ---[ end Kernel panic - not syncing: Requested init /bin/sh failed (error -14). ]---
QEMU 5.1.0 monitor - type 'help' for more information

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 534d73e45844..0c69aa52395d 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -165,7 +165,9 @@ static void ddebug_putsite(struct _ddebug *dp)
 		/* need to keep site until zmap backing exists */
 		return;
 
-	/* always unmap for now. if !pr-debug has locking issues */
+	if (dp->flags & _DPRINTK_FLAGS_PRINT)
+		return; /* keep maps of enabled pr_debugs */
+
 	zs_unmap_object(dd_callsite_zpool, dp->zhandle);
 	dp->site = NULL;
 }
-- 
2.28.0

Re: [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites

[Jason Baron]

On 11/25/20 2:36 PM, Jim Cromie wrote:
> In ddebug_putsite(), dont zs_unmap the callsite if it is enabled for
> printing.  This means that the next time this pr_debug callsite is
> executed, the _getsite() will succeed quickly without remapping the
> zrec.
> 
> Once the callsite is disabled via >control, a following _putsite()
> will see the flag cleared, and zs_unmap it.
> 
> This changes the lifetime of our zs_mappings from brief (only for the
> single printk) to as long as uptime (if a prdebug is enabled til
> poweroff).  This appears to be triggering the ensuing mayhem.
> 
> I am able to get through init, to root console, by disabling all
> dynamic-debugs, including the ones that are enabled at compile.
> 
> $ kruna --kopt \*.dyndbg=-p --kopt debug_locks_proceed=1
> 
> but enabling any pr-debug crashes.
> Plain old boot also panics, as pasted below.
> 


Hi Jim,

Looks like you've made a lot of progress with this series...but if I
understand correctly there are still some unresolved issues (panic).
So I think this series is more 'RFC' at this point?

I was also expecting to see updates to the actual printing functions
to now use dp->site. But perhaps I missed those bits?

Thanks,

-Jason

> $ kruna --kopt debug_locks_proceed=1
> 
> [    0.443926] -----------------------------------------------------------------
> [    0.445085] BUG:  14 unexpected failures (out of 350) - debugging proceeding anyway! |
> [    0.446498] -----------------------------------------------------------------
> ...
> [    0.617347] dyndbg: 224 modules, 2014 entries and 8960 bytes in ddebug tables, 80560 bytes in __dyndbg section, 80560 bytes in __dyndbg_callsites section
> [    0.617537] dyndbg: 2014 entries. repeated entries: 1789 module 1667 file 809 func
> ...
> [    1.456548] zswap: loaded using pool zstd/zsmalloc
> [    1.462802] dyndbg: total pages: 24 compaction: 0
> [    1.463965] PM:   Magic number: 12:980:889
> [    1.464860] BUG: sleeping function called from invalid context at mm/slab.h:506
> [    1.466150] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 1, name: swapper/0
> [    1.467282] 3 locks held by swapper/0/1:
> [    1.467936]  #0: ffffffff82875460 (cpu_hotplug_lock){++++}-{0:0}, at: cpufreq_register_driver+0xb5/0x2f0
> [    1.469622]  #1: ffff888003cfbd28 (subsys mutex#5){+.+.}-{4:4}, at: subsys_interface_register+0x5f/0x130
> [    1.471448]  #2: ffff8880057f00b0 (&zspage->lock){.+.+}-{3:3}, at: zs_map_object+0x7b/0x2b0
> [    1.472666] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.474007] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.475314] Call Trace:
> [    1.475682]  dump_stack+0x7d/0x9f
> [    1.476162]  ___might_sleep.cold+0xa6/0xb7
> [    1.476745]  __might_sleep+0x46/0x80
> [    1.477266]  __kmalloc_track_caller+0x1dd/0x2d0
> [    1.477895]  kstrdup_const+0x45/0x70
> [    1.478678]  __kernfs_new_node+0x4b/0x280
> [    1.479280]  ? dynamic_emit_prefix+0x1dd/0x1f0
> [    1.479907]  ? __dynamic_pr_debug+0x8a/0xb0
> [    1.480496]  kernfs_create_dir_ns+0x44/0xc0
> [    1.481188]  sysfs_create_dir_ns+0x6c/0xd0
> [    1.481820]  kobject_add_internal+0x102/0x300
> [    1.482505]  kobject_init_and_add+0x71/0xa0
> [    1.483194]  ? kmem_cache_alloc_trace+0x21d/0x270
> [    1.483993]  ? cpufreq_online+0x62/0x960
> [    1.484628]  cpufreq_online+0xa5/0x960
> [    1.485325]  ? system_root_device_release+0x10/0x10
> [    1.486223]  cpufreq_add_dev+0x79/0x90
> [    1.486868]  subsys_interface_register+0x11e/0x130
> [    1.487787]  cpufreq_register_driver+0x171/0x2f0
> [    1.488679]  acpi_cpufreq_init+0x266/0x294
> [    1.489508]  ? CPU_FREQ_GOV_ONDEMAND_init+0x12/0x12
> [    1.490350]  do_one_initcall+0x5a/0x2c0
> [    1.491037]  ? rcu_read_lock_sched_held+0x41/0x80
> [    1.491820]  kernel_init_freeable+0x23b/0x287
> [    1.492561]  ? rest_init+0x24d/0x24d
> [    1.493180]  kernel_init+0x9/0x103
> [    1.493825]  ret_from_fork+0x22/0x30
> [    1.494557]
> [    1.494804] =============================
> [    1.495503] [ BUG: Invalid wait context ]
> [    1.496134] 5.10.0-rc3-00304-g7a4ad0dc5042 #75 Tainted: G        W
> [    1.497346] -----------------------------
> [    1.497986] swapper/0/1 is trying to lock:
> [    1.498668] ffffffff8299ad90 (iattr_mutex){+.+.}-{4:4}, at: kernfs_xattr_get+0x25/0x60
> [    1.499855] other info that might help us debug this:
> [    1.500655] context-{5:5}
> [    1.501118] 3 locks held by swapper/0/1:
> [    1.501732]  #0: ffffffff82875460 (cpu_hotplug_lock){++++}-{0:0}, at: cpufreq_register_driver+0xb5/0x2f0
> [    1.503384]  #1: ffff888003cfbd28 (subsys mutex#5){+.+.}-{4:4}, at: subsys_interface_register+0x5f/0x130
> [    1.505289]  #2: ffff8880057f00b0 (&zspage->lock){.+.+}-{3:3}, at: zs_map_object+0x7b/0x2b0
> [    1.506743] stack backtrace:
> [    1.507228] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.509060] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.510505] Call Trace:
> [    1.510887]  dump_stack+0x7d/0x9f
> [    1.511456]  __lock_acquire.cold+0xb9/0x2cd
> [    1.512389]  ? usage_match+0x20/0x20
> [    1.512960]  ? __bfs+0xf3/0x220
> [    1.513442]  lock_acquire+0x137/0x3e0
> [    1.514069]  ? kernfs_xattr_get+0x25/0x60
> [    1.514724]  ? ___might_sleep+0x15c/0x190
> [    1.515369]  __mutex_lock+0x8e/0x940
> [    1.515866]  ? kernfs_xattr_get+0x25/0x60
> [    1.516515]  ? asm_sysvec_apic_timer_interrupt+0x12/0x20
> [    1.517343]  ? kernfs_xattr_get+0x25/0x60
> [    1.517884]  mutex_lock_nested+0x16/0x20
> [    1.518577]  kernfs_xattr_get+0x25/0x60
> [    1.519151]  selinux_kernfs_init_security+0x5c/0x210
> [    1.519822]  ? sched_clock+0x9/0x10
> [    1.520513]  ? sched_clock_cpu+0x11/0xc0
> [    1.521172]  security_kernfs_init_security+0x2a/0x40
> [    1.522164]  __kernfs_new_node+0x1b7/0x280
> [    1.522842]  ? dynamic_emit_prefix+0x1dd/0x1f0
> [    1.523610]  ? __dynamic_pr_debug+0x8a/0xb0
> [    1.524350]  kernfs_create_dir_ns+0x44/0xc0
> [    1.525033]  sysfs_create_dir_ns+0x6c/0xd0
> [    1.525682]  kobject_add_internal+0x102/0x300
> [    1.526384]  kobject_init_and_add+0x71/0xa0
> [    1.527138]  ? kmem_cache_alloc_trace+0x21d/0x270
> [    1.527869]  ? cpufreq_online+0x62/0x960
> [    1.528566]  cpufreq_online+0xa5/0x960
> [    1.529461]  ? system_root_device_release+0x10/0x10
> [    1.530273]  cpufreq_add_dev+0x79/0x90
> [    1.530886]  subsys_interface_register+0x11e/0x130
> [    1.531591]  cpufreq_register_driver+0x171/0x2f0
> [    1.532251]  acpi_cpufreq_init+0x266/0x294
> [    1.532803]  ? CPU_FREQ_GOV_ONDEMAND_init+0x12/0x12
> [    1.533524]  do_one_initcall+0x5a/0x2c0
> [    1.534196]  ? rcu_read_lock_sched_held+0x41/0x80
> [    1.535008]  kernel_init_freeable+0x23b/0x287
> [    1.535706]  ? rest_init+0x24d/0x24d
> [    1.536314]  kernel_init+0x9/0x103
> [    1.536903]  ret_from_fork+0x22/0x30
> [    1.537555] kobject: 'policy0' (0000000099a22e3a): kobject_cleanup, parent 000000008a313735
> [    1.538996] kobject: 'policy0' (0000000099a22e3a): auto cleanup kobject_del
> [    1.540082] kobject: 'policy0' (0000000099a22e3a): calling ktype release
> [    1.541143] kobject: 'policy0': free name
> [    1.541750] ------------[ cut here ]------------
> [    1.542630] initcall acpi_cpufreq_init+0x0/0x294 returned with preemption imbalance
> [    1.544046] WARNING: CPU: 0 PID: 1 at init/main.c:1230 do_one_initcall+0x220/0x2c0
> [    1.545335] Modules linked in:
> [    1.545846] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.547549] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.549121] RIP: 0010:do_one_initcall+0x220/0x2c0
> [    1.549983] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
> [    1.553209] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
> [    1.554326] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
> [    1.555682] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
> [    1.556869] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
> [    1.558111] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d5550a
> [    1.559357] R13: 00000000ffffffed R14: ffffffff82e0a940 R15: ffff888003d313e0
> [    1.560577] FS:  0000000000000000(0000) GS:ffff888007a00000(0000) knlGS:0000000000000000
> [    1.562159] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [    1.563285] CR2: 0000000000000000 CR3: 0000000002824001 CR4: 0000000000370ef0
> [    1.564578] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [    1.565924] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [    1.567224] Call Trace:
> [    1.567665]  ? rcu_read_lock_sched_held+0x41/0x80
> [    1.568565]  kernel_init_freeable+0x23b/0x287
> [    1.569420]  ? rest_init+0x24d/0x24d
> [    1.570103]  kernel_init+0x9/0x103
> [    1.570736]  ret_from_fork+0x22/0x30
> [    1.571750] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.573387] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.575132] Call Trace:
> [    1.575538]  dump_stack+0x7d/0x9f
> [    1.576085]  ? do_one_initcall+0x220/0x2c0
> [    1.576744]  __warn.cold+0x24/0x85
> [    1.577522]  ? do_one_initcall+0x220/0x2c0
> [    1.578287]  report_bug+0xa1/0xc0
> [    1.578812]  handle_bug+0x45/0x90
> [    1.579376]  exc_invalid_op+0x19/0x70
> [    1.579994]  asm_exc_invalid_op+0x12/0x20
> [    1.580649] RIP: 0010:do_one_initcall+0x220/0x2c0
> [    1.581497] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
> [    1.584556] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
> [    1.585491] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
> [    1.586739] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
> [    1.588054] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
> [    1.589347] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d5550a
> [    1.590800] R13: 00000000ffffffed R14: ffffffff82e0a940 R15: ffff888003d313e0
> [    1.592131]  ? CPU_FREQ_GOV_ONDEMAND_init+0x12/0x12
> [    1.593085]  ? console_unlock+0x37d/0x5c0
> [    1.593785]  ? console_unlock+0x4d6/0x5c0
> [    1.594484]  ? rcu_read_lock_sched_held+0x41/0x80
> [    1.595303]  kernel_init_freeable+0x23b/0x287
> [    1.596049]  ? rest_init+0x24d/0x24d
> [    1.596650]  kernel_init+0x9/0x103
> [    1.597232]  ret_from_fork+0x22/0x30
> [    1.597872] irq event stamp: 1862449
> [    1.598517] hardirqs last  enabled at (1862449): [<ffffffff81d80a15>] irqentry_exit+0x35/0x80
> [    1.600046] hardirqs last disabled at (1862448): [<ffffffff81d7f350>] sysvec_apic_timer_interrupt+0x10/0xb0
> [    1.601801] softirqs last  enabled at (1862354): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
> [    1.603419] softirqs last disabled at (1862345): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
> [    1.605203] ---[ end trace ecd8f90d8b1f2ab8 ]---
> [    1.606532] ata2.01: NODEV after polling detection
> [    1.607776] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
> [    1.609726] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5
> [    1.611649] kobject: 'target1:0:0' (0000000025bf58b2): kobject_add_internal: parent: 'host1', set: 'devices'
> [    1.613564] main:device_pm_add: PM: Adding info for scsi:target1:0:0
> [    1.614679] kobject: 'target1:0:0' (0000000025bf58b2): kobject_uevent_env
> [    1.615975] kobject: 'target1:0:0' (0000000025bf58b2): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0'
> [    1.618095] kobject: '1:0:0:0' (00000000429180e9): kobject_add_internal: parent: 'target1:0:0', set: 'devices'
> [    1.619807] main:device_pm_add: PM: Adding info for scsi:1:0:0:0
> [    1.621053] kobject: '1:0:0:0' (00000000429180e9): kobject_uevent_env
> [    1.622564] kobject: '1:0:0:0' (00000000429180e9): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0'
> [    1.624691] BUG: scheduling while atomic: kworker/u2:0/7/0x0000000d
> [    1.625799] INFO: lockdep is turned off.
> [    1.626446] Modules linked in:
> [    1.626908] CPU: 0 PID: 7 Comm: kworker/u2:0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.628455] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.629774] Workqueue: events_unbound async_run_entry_fn
> [    1.630649] Call Trace:
> [    1.631053]  dump_stack+0x7d/0x9f
> [    1.631617]  __schedule_bug.cold+0x5f/0x70
> [    1.632263]  __schedule+0x823/0x9c0
> [    1.632806]  ? lock_release+0x1e1/0x3f0
> [    1.633382]  ? hctx_unlock+0x1a/0xb0
> [    1.633975]  ? wait_for_completion_io+0x7e/0x110
> [    1.634749]  schedule+0x63/0xe0
> [    1.635311]  schedule_timeout+0x175/0x1e0
> [    1.636004]  ? __blk_mq_delay_run_hw_queue+0x16d/0x180
> [    1.636847]  ? lock_acquired+0x1ef/0x380
> [    1.637630]  ? lock_release+0x1e1/0x3f0
> [    1.638484]  ? wait_for_completion_io+0xa1/0x110
> [    1.639208]  ? _raw_spin_unlock_irq+0x23/0x40
> [    1.639877]  io_schedule_timeout+0x4b/0x80
> [    1.640614]  wait_for_completion_io+0xa9/0x110
> [    1.641355]  blk_execute_rq+0x7f/0xb0
> [    1.641905]  __scsi_execute+0x109/0x260
> [    1.642545]  scsi_test_unit_ready+0x5b/0xe0
> [    1.643275]  sr_probe+0x23b/0x610
> [    1.643782]  really_probe+0x3ad/0x460
> [    1.644400]  driver_probe_device+0xe4/0x150
> [    1.645112]  __device_attach_driver+0x6c/0xd0
> [    1.645837]  ? driver_allows_async_probing+0x50/0x50
> [    1.646679]  bus_for_each_drv+0x82/0xd0
> [    1.647285]  __device_attach+0xde/0x1e0
> [    1.647886]  device_initial_probe+0xe/0x10
> [    1.648525]  bus_probe_device+0x9b/0xb0
> [    1.649077]  device_add+0x3b8/0x840
> [    1.649674]  scsi_sysfs_add_sdev+0x91/0x290
> [    1.650393]  scsi_probe_and_add_lun+0x83f/0xbe0
> [    1.651325]  __scsi_add_device+0x10a/0x120
> [    1.652020]  ata_scsi_scan_host+0x98/0x1d0
> [    1.652598]  ? wait_woken+0xb0/0xb0
> [    1.653146]  async_port_probe+0x56/0x70
> [    1.653679]  async_run_entry_fn+0x37/0x150
> [    1.654395]  process_one_work+0x277/0x590
> [    1.655278]  worker_thread+0x50/0x400
> [    1.655802]  kthread+0x14c/0x170
> [    1.656322]  ? process_one_work+0x590/0x590
> [    1.656890]  ? __kthread_bind_mask+0x70/0x70
> [    1.657659]  ret_from_fork+0x22/0x30
> [    1.658512] kobject: 'memmap' (000000007533e45a): kobject_add_internal: parent: 'firmware', set: '<NULL>'
> [    1.660202] kobject: 'memmap' (000000007533e45a): kobject_uevent_env
> [    1.661228] kobject: 'memmap' (000000007533e45a): kobject_uevent_env: attempted to send uevent without kset!
> [    1.662681] kobject: '0' (00000000ba522565): kobject_add_internal: parent: 'memmap', set: 'memmap'
> [    1.664100] kobject: '1' (00000000387ad507): kobject_add_internal: parent: 'memmap', set: 'memmap'
> [    1.665482] kobject: '2' (00000000c4547872): kobject_add_internal: parent: 'memmap', set: 'memmap'
> [    1.666863] kobject: '3' (00000000d3a84794): kobject_add_internal: parent: 'memmap', set: 'memmap'
> [    1.668227] kobject: '4' (0000000059225206): kobject_add_internal: parent: 'memmap', set: 'memmap'
> [    1.669573] kobject: '5' (000000009bfaeef6): kobject_add_internal: parent: 'memmap', set: 'memmap'
> [    1.671050] kobject: '6' (00000000fdded59a): kobject_add_internal: parent: 'memmap', set: 'memmap'
> [    1.672667] ------------[ cut here ]------------
> [    1.673345] initcall firmware_memmap_init+0x0/0x33 returned with preemption imbalance
> [    1.674447] WARNING: CPU: 0 PID: 1 at init/main.c:1230 do_one_initcall+0x220/0x2c0
> [    1.675557] Modules linked in:
> [    1.676071] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.677657] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.678872] RIP: 0010:do_one_initcall+0x220/0x2c0
> [    1.679730] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
> [    1.682846] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
> [    1.683829] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
> [    1.684931] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
> [    1.686030] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
> [    1.687084] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d573c1
> [    1.688257] R13: 0000000000000000 R14: ffffffff82e0a944 R15: ffff888003d313e0
> [    1.689795] FS:  0000000000000000(0000) GS:ffff888007a00000(0000) knlGS:0000000000000000
> [    1.691023] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [    1.692094] CR2: 0000000000000000 CR3: 0000000002824001 CR4: 0000000000370ef0
> [    1.693237] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [    1.694366] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [    1.695536] Call Trace:
> [    1.695877]  ? rcu_read_lock_sched_held+0x41/0x80
> [    1.696667]  kernel_init_freeable+0x23b/0x287
> [    1.697404]  ? rest_init+0x24d/0x24d
> [    1.697968]  kernel_init+0x9/0x103
> [    1.698487]  ret_from_fork+0x22/0x30
> [    1.699071] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.700595] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.702034] Call Trace:
> [    1.702383]  dump_stack+0x7d/0x9f
> [    1.702967]  ? do_one_initcall+0x220/0x2c0
> [    1.703649]  __warn.cold+0x24/0x85
> [    1.704217]  ? do_one_initcall+0x220/0x2c0
> [    1.705099]  report_bug+0xa1/0xc0
> [    1.705575]  handle_bug+0x45/0x90
> [    1.706066]  exc_invalid_op+0x19/0x70
> [    1.706547]  asm_exc_invalid_op+0x12/0x20
> [    1.707180] RIP: 0010:do_one_initcall+0x220/0x2c0
> [    1.707855] Code: 74 09 80 3d 9a 6a aa 01 00 74 50 65 ff 0d a8 5f 01 7f e9 48 fe ff ff 48 8d 55 a0 4c 89 e6 48 c7 c7 60 fb 55 82 e8 4e e1 d2 00 <0f> 0b e9 c6 fe ff ff e8 b4 de 17 00 85 c0 75 a5 48 c7 c2 38 f9 55
> [    1.710508] RSP: 0000:ffffc90000013ea0 EFLAGS: 00010286
> [    1.711470] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00000000ffffdfff
> [    1.712933] RDX: 00000000ffffdfff RSI: ffffffff8116c1cd RDI: ffffffff8116c326
> [    1.714146] RBP: ffffc90000013f00 R08: 0000000000000000 R09: 0000000000000000
> [    1.715350] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: ffffffff82d573c1
> [    1.716701] R13: 0000000000000000 R14: ffffffff82e0a944 R15: ffff888003d313e0
> [    1.717854]  ? dmi_id_init+0x386/0x386
> [    1.718486]  ? console_unlock+0x37d/0x5c0
> [    1.719158]  ? console_unlock+0x4d6/0x5c0
> [    1.719772]  ? rcu_read_lock_sched_held+0x41/0x80
> [    1.720641]  kernel_init_freeable+0x23b/0x287
> [    1.721566]  ? rest_init+0x24d/0x24d
> [    1.722230]  kernel_init+0x9/0x103
> [    1.722680]  ret_from_fork+0x22/0x30
> [    1.723276] irq event stamp: 1862449
> [    1.723894] hardirqs last  enabled at (1862449): [<ffffffff81d80a15>] irqentry_exit+0x35/0x80
> [    1.725695] hardirqs last disabled at (1862448): [<ffffffff81d7f350>] sysvec_apic_timer_interrupt+0x10/0xb0
> [    1.727307] softirqs last  enabled at (1862354): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
> [    1.728795] softirqs last disabled at (1862345): [<ffffffff81e00fa2>] asm_call_irq_on_stack+0x12/0x20
> [    1.730347] ---[ end trace ecd8f90d8b1f2ab9 ]---
> [    1.731171] cfg80211: Loading compiled-in X.509 certificates for regulatory database
> [    1.732579] kworker/u2:1 (62) used greatest stack depth: 14536 bytes left
> [    1.734275] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
> [    1.735368] cdrom: Uniform CD-ROM driver Revision: 3.20
> [    1.736684] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
> [    1.737871] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
> [    1.739479] ALSA device list:
> [    1.739928] cfg80211: failed to load regulatory.db
> [    1.740784]   No soundcards found.
> [    1.741597] kobject: 'regulatory.0' (00000000ab092cdd): kobject_uevent_env
> [    1.742766] kobject: 'regulatory.0' (00000000ab092cdd): fill_kobj_path: path = '/devices/platform/regulatory.0'
> [    1.750002] kobject: '11:0' (0000000035d88d42): kobject_add_internal: parent: 'bdi', set: 'devices'
> [    1.751742] main:device_pm_add: PM: Adding info for No Bus:11:0
> [    1.752660] kobject: '11:0' (0000000035d88d42): kobject_uevent_env
> [    1.753722] kobject: '11:0' (0000000035d88d42): fill_kobj_path: path = '/devices/virtual/bdi/11:0'
> [    1.755338] kobject: 'block' (00000000da37173c): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
> [    1.757024] kobject: 'sr0' (000000000b128df7): kobject_add_internal: parent: 'block', set: 'devices'
> [    1.758667] main:device_pm_add: PM: Adding info for No Bus:sr0
> [    1.759667] kobject: 'sr0' (000000000b128df7): kobject_uevent_env
> [    1.760836] kobject: 'sr0' (000000000b128df7): kobject_uevent_env: uevent_suppress caused the event to drop!
> [    1.762452] kobject: 'holders' (00000000e28bd786): kobject_add_internal: parent: 'sr0', set: '<NULL>'
> [    1.763972] kobject: 'slaves' (00000000b2ff8eb3): kobject_add_internal: parent: 'sr0', set: '<NULL>'
> [    1.765611] kobject: 'sr0' (000000000b128df7): kobject_uevent_env
> [    1.766705] kobject: 'sr0' (000000000b128df7): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/block/sr0'
> [    1.769006] kobject: 'queue' (00000000fbf3c544): kobject_add_internal: parent: 'sr0', set: '<NULL>'
> [    1.770551] kobject: 'mq' (0000000001f3c10f): kobject_add_internal: parent: 'sr0', set: '<NULL>'
> [    1.772069] kobject: 'mq' (0000000001f3c10f): kobject_uevent_env
> [    1.773222] kobject: 'mq' (0000000001f3c10f): kobject_uevent_env: filter function caused the event to drop!
> [    1.775037] kobject: '0' (0000000078f2eddd): kobject_add_internal: parent: 'mq', set: '<NULL>'
> [    1.776604] kobject: 'cpu0' (000000007c3dee23): kobject_add_internal: parent: '0', set: '<NULL>'
> [    1.778217] kobject: 'iosched' (000000003e5ac6f7): kobject_add_internal: parent: 'queue', set: '<NULL>'
> [    1.779683] kobject: 'queue' (00000000fbf3c544): kobject_uevent_env
> [    1.780580] kobject: 'queue' (00000000fbf3c544): kobject_uevent_env: filter function caused the event to drop!
> [    1.782265] kobject: 'iosched' (000000003e5ac6f7): kobject_uevent_env
> [    1.783231] kobject: 'iosched' (000000003e5ac6f7): kobject_uevent_env: filter function caused the event to drop!
> [    1.784761] sr 1:0:0:0: Attached scsi CD-ROM sr0
> [    1.785487] kobject: '1:0:0:0' (00000000429180e9): kobject_uevent_env
> [    1.786681] kobject: '1:0:0:0' (00000000429180e9): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0'
> [    1.788806] kobject: 'scsi_device' (00000000fc009276): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
> [    1.790501] kobject: '1:0:0:0' (0000000035d4f17d): kobject_add_internal: parent: 'scsi_device', set: 'devices'
> [    1.792243] main:device_pm_add: PM: Adding info for No Bus:1:0:0:0
> [    1.793265] kobject: '1:0:0:0' (0000000035d4f17d): kobject_uevent_env
> [    1.794301] kobject: '1:0:0:0' (0000000035d4f17d): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/scsi_device/1:0:0:0'
> [    1.796564] kobject: 'scsi_generic' (00000000d5199ad9): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
> [    1.798157] kobject: 'sg0' (00000000da2b5c82): kobject_add_internal: parent: 'scsi_generic', set: 'devices'
> [    1.799695] main:device_pm_add: PM: Adding info for No Bus:sg0
> [    1.800732] BUG: scheduling while atomic: kworker/u2:0/7/0x00000009
> [    1.801776] INFO: lockdep is turned off.
> [    1.802463] Modules linked in:
> [    1.802948] CPU: 0 PID: 7 Comm: kworker/u2:0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.804667] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.806213] Workqueue: events_unbound async_run_entry_fn
> [    1.807254] Call Trace:
> [    1.807659]  dump_stack+0x7d/0x9f
> [    1.808232]  __schedule_bug.cold+0x5f/0x70
> [    1.808793]  __schedule+0x823/0x9c0
> [    1.809602]  ? wait_for_completion+0x7e/0x110
> [    1.810402]  schedule+0x63/0xe0
> [    1.810994]  schedule_timeout+0x175/0x1e0
> [    1.811661]  ? lock_release+0x1e1/0x3f0
> [    1.812329]  ? try_to_wake_up+0x1fe/0x740
> [    1.813004]  ? lock_acquired+0x1ef/0x380
> [    1.813607]  ? lock_release+0x1e1/0x3f0
> [    1.814286]  ? wait_for_completion+0xa1/0x110
> [    1.814998]  ? _raw_spin_unlock_irq+0x23/0x40
> [    1.815669]  ? trace_hardirqs_on+0x2a/0xe0
> [    1.816348]  ? wait_for_completion+0x7e/0x110
> [    1.817080]  wait_for_completion+0xa9/0x110
> [    1.817744]  devtmpfs_submit_req+0x6e/0x80
> [    1.818434]  devtmpfs_create_node+0x9e/0xd0
> [    1.819138]  device_add+0x729/0x840
> [    1.819697]  device_create_groups_vargs+0xcf/0xf0
> [    1.820539]  device_create+0x44/0x60
> [    1.821159]  ? cdev_add+0x51/0x80
> [    1.821671]  sg_add_device+0x292/0x410
> [    1.822323]  device_add+0x449/0x840
> [    1.822976]  scsi_sysfs_add_sdev+0x1be/0x290
> [    1.823605]  scsi_probe_and_add_lun+0x83f/0xbe0
> [    1.824332]  __scsi_add_device+0x10a/0x120
> [    1.825052]  ata_scsi_scan_host+0x98/0x1d0
> [    1.825756]  ? wait_woken+0xb0/0xb0
> [    1.826400]  async_port_probe+0x56/0x70
> [    1.827026]  async_run_entry_fn+0x37/0x150
> [    1.827752]  process_one_work+0x277/0x590
> [    1.828530]  worker_thread+0x50/0x400
> [    1.829177]  kthread+0x14c/0x170
> [    1.829654]  ? process_one_work+0x590/0x590
> [    1.830318]  ? __kthread_bind_mask+0x70/0x70
> [    1.830901]  ret_from_fork+0x22/0x30
> [    1.831718] kobject: 'sr0' (000000000b128df7): kobject_uevent_env
> [    1.832675] kobject: 'sr0' (000000000b128df7): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/block/sr0'
> [    1.834777] kobject: 'sg0' (00000000da2b5c82): kobject_uevent_env
> [    1.835860] kobject: 'sg0' (00000000da2b5c82): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/scsi_generic/sg0'
> [    1.838069] sr 1:0:0:0: Attached scsi generic sg0 type 5
> [    1.838805] kobject: 'bsg' (000000005c2815cf): kobject_add_internal: parent: '1:0:0:0', set: '(null)'
> [    1.840435] kobject: '1:0:0:0' (00000000ad96192e): kobject_add_internal: parent: 'bsg', set: 'devices'
> [    1.841929] main:device_pm_add: PM: Adding info for No Bus:1:0:0:0
> [    1.842964] kobject: '1:0:0:0' (00000000ad96192e): kobject_uevent_env
> [    1.844087] kobject: '1:0:0:0' (00000000ad96192e): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0/bsg/1:0:0:0'
> [    1.846261] md: Skipping autodetection of RAID arrays. (raid=autodetect will force)
> [    1.847813] kobject: '9p-fcall-cache' (00000000acb65d7d): kobject_add_internal: parent: 'slab', set: 'slab'
> [    1.849788] kobject: '9p-1' (00000000f8fd831c): kobject_add_internal: parent: 'bdi', set: 'devices'
> [    1.851175] main:device_pm_add: PM: Adding info for No Bus:9p-1
> [    1.852055] kobject: '9p-1' (00000000f8fd831c): kobject_uevent_env
> [    1.852906] kobject: '9p-1' (00000000f8fd831c): fill_kobj_path: path = '/devices/virtual/bdi/9p-1'
> [    1.854695] VFS: Mounted root (9p filesystem) readonly on device 0:19.
> [    1.856048] devtmpfs: mounted
> [    1.857202] Freeing unused kernel image (initmem) memory: 3024K
> [    1.858545] Write protecting the kernel read-only data: 24576k
> [    1.860621] Freeing unused kernel image (text/rodata gap) memory: 2028K
> [    1.862354] Freeing unused kernel image (rodata/data gap) memory: 1008K
> [    1.863493] Run /bin/sh as init process
> [    1.864131] main:run_init_process:   with arguments:
> [    1.864902] main:run_init_process:     /bin/sh
> [    1.865869] main:run_init_process:     -c
> [    1.866527] main:run_init_process:     mount -t tmpfs run /run;mkdir -p /run/virtme/guesttools;/bin/mount -n -t 9p -o ro,version=9p2000.L,trans=virtio,access=any virtme.guesttools /run/virtme/guesttools;exec /run/virtme/guesttools/virtme-init
> [    1.869845] main:run_init_process:   with environment:
> [    1.870634] main:run_init_process:     HOME=/
> [    1.871304] main:run_init_process:     TERM=xterm-256color
> [    1.872359] main:run_init_process:     virtme_link_mods=/home/jimc/projects/lx/linux.git/builds/v2/.virtme_mods/lib/modules/0.0.0
> [    1.874369] main:run_init_process:     virtme_stty_con=rows 24 cols 154 iutf8
> [    1.875652] main:run_init_process:     multidevs=remap
> [    1.876632] BUG: scheduling while atomic: swapper/0/1/0x00000011
> [    1.877856] INFO: lockdep is turned off.
> [    1.878502] Modules linked in:
> [    1.879028] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.880594] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.882022] Call Trace:
> [    1.882410]  dump_stack+0x7d/0x9f
> [    1.883045]  __schedule_bug.cold+0x5f/0x70
> [    1.883766]  __schedule+0x823/0x9c0
> [    1.884524]  schedule+0x63/0xe0
> [    1.885126]  p9_client_rpc+0x13b/0x6e0
> [    1.885723]  ? wait_woken+0xb0/0xb0
> [    1.886332]  p9_client_walk+0x80/0x2e0
> [    1.887059]  ? d_alloc_parallel+0x3c8/0xa40
> [    1.887735]  ? get_page_from_freelist+0x3ce/0x13b0
> [    1.888758]  v9fs_vfs_lookup.part.0+0x65/0x1a0
> [    1.889570]  v9fs_vfs_lookup+0x1a/0x20
> [    1.890345]  __lookup_slow+0x108/0x1e0
> [    1.891012]  ? lock_acquire+0x174/0x3e0
> [    1.891705]  ? lock_acquire+0x174/0x3e0
> [    1.892343]  walk_component+0x13c/0x1b0
> [    1.892994]  ? security_inode_permission+0x30/0x50
> [    1.893752]  link_path_walk.part.0+0x21a/0x350
> [    1.894473]  path_openat+0xb0/0xa40
> [    1.895058]  ? _raw_spin_unlock+0x1e/0x30
> [    1.895717]  ? follow_page_mask+0x491/0x600
> [    1.896625]  do_filp_open+0x87/0x130
> [    1.897171]  ? __might_sleep+0x46/0x80
> [    1.897795]  ? _cond_resched+0x15/0x50
> [    1.898370]  ? __kmalloc+0x1f9/0x2c0
> [    1.898875]  ? lock_acquire+0x174/0x3e0
> [    1.899420]  ? avc_disable+0x20/0x20
> [    1.899930]  do_open_execat+0x66/0x1a0
> [    1.900456]  bprm_execve+0x1fe/0x8f0
> [    1.901019]  ? ___might_sleep+0x42/0x190
> [    1.901692]  kernel_execve+0x132/0x1b0
> [    1.902281]  run_init_process+0xc0/0xc5
> [    1.902972]  ? rest_init+0x24d/0x24d
> [    1.903587]  kernel_init+0x96/0x103
> [    1.904160]  ret_from_fork+0x22/0x30
> [    1.908649] Kernel panic - not syncing: Requested init /bin/sh failed (error -14).
> [    1.910091] CPU: 0 PID: 1 Comm: sh Tainted: G        W         5.10.0-rc3-00304-g7a4ad0dc5042 #75
> [    1.911517] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
> [    1.912845] Call Trace:
> [    1.913289]  dump_stack+0x7d/0x9f
> [    1.913957]  ? rest_init+0x210/0x24d
> [    1.914535]  panic+0x10a/0x2de
> [    1.915094]  ? kernel_execve+0x145/0x1b0
> [    1.915768]  ? rest_init+0x24d/0x24d
> [    1.916417]  kernel_init+0xaf/0x103
> [    1.917038]  ret_from_fork+0x22/0x30
> [    1.917726] Kernel Offset: disabled
> [    1.918324] ---[ end Kernel panic - not syncing: Requested init /bin/sh failed (error -14). ]---
> QEMU 5.1.0 monitor - type 'help' for more information
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> ---
>  lib/dynamic_debug.c | 4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
> 
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> index 534d73e45844..0c69aa52395d 100644
> --- a/lib/dynamic_debug.c
> +++ b/lib/dynamic_debug.c
> @@ -165,7 +165,9 @@ static void ddebug_putsite(struct _ddebug *dp)
>  		/* need to keep site until zmap backing exists */
>  		return;
>  
> -	/* always unmap for now. if !pr-debug has locking issues */
> +	if (dp->flags & _DPRINTK_FLAGS_PRINT)
> +		return; /* keep maps of enabled pr_debugs */
> +
>  	zs_unmap_object(dd_callsite_zpool, dp->zhandle);
>  	dp->site = NULL;
>  }
> 

Re: [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites

[jim.cromie]

On Wed, Nov 25, 2020 at 1:54 PM Jason Baron <jbaron@akamai.com> wrote:
>
>
>
> On 11/25/20 2:36 PM, Jim Cromie wrote:
> > In ddebug_putsite(), dont zs_unmap the callsite if it is enabled for
> > printing.  This means that the next time this pr_debug callsite is
> > executed, the _getsite() will succeed quickly without remapping the
> > zrec.
> >
> > Once the callsite is disabled via >control, a following _putsite()
> > will see the flag cleared, and zs_unmap it.
> >
> > This changes the lifetime of our zs_mappings from brief (only for the
> > single printk) to as long as uptime (if a prdebug is enabled til
> > poweroff).  This appears to be triggering the ensuing mayhem.
> >
> > I am able to get through init, to root console, by disabling all
> > dynamic-debugs, including the ones that are enabled at compile.
> >
> > $ kruna --kopt \*.dyndbg=-p --kopt debug_locks_proceed=1
> >
> > but enabling any pr-debug crashes.
> > Plain old boot also panics, as pasted below.
> >
>
>
> Hi Jim,
>
> Looks like you've made a lot of progress with this series...but if I
> understand correctly there are still some unresolved issues (panic).
> So I think this series is more 'RFC' at this point?
>

yes, RFC.  WIP suggests I know whats needed next.

certainly Ive seen a variety of sleeping while atomic ... BUGs,



> I was also expecting to see updates to the actual printing functions
> to now use dp->site. But perhaps I missed those bits?

those bits were changed in patch 5
basically changes are ~ s/dp/dc/g, and in ddebug_getsite / _putsite

>
> Thanks,
>
> -Jason
>
> > $ kruna --kopt debug_locks_proceed=1
> >




 [    1.915768]  ? rest_init+0x24d/0x24d
> > [    1.916417]  kernel_init+0xaf/0x103
> > [    1.917038]  ret_from_fork+0x22/0x30
> > [    1.917726] Kernel Offset: disabled
> > [    1.918324] ---[ end Kernel panic - not syncing: Requested init /bin/sh failed (error -14). ]---
> > QEMU 5.1.0 monitor - type 'help' for more information
> >
> > Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> > ---
> >  lib/dynamic_debug.c | 4 +++-
> >  1 file changed, 3 insertions(+), 1 deletion(-)
> >
> > diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> > index 534d73e45844..0c69aa52395d 100644
> > --- a/lib/dynamic_debug.c
> > +++ b/lib/dynamic_debug.c
> > @@ -165,7 +165,9 @@ static void ddebug_putsite(struct _ddebug *dp)
> >               /* need to keep site until zmap backing exists */
> >               return;
> >
> > -     /* always unmap for now. if !pr-debug has locking issues */
> > +     if (dp->flags & _DPRINTK_FLAGS_PRINT)
> > +             return; /* keep maps of enabled pr_debugs */
> > +
> >       zs_unmap_object(dd_callsite_zpool, dp->zhandle);
> >       dp->site = NULL;
> >  }
> >