linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH 1/7] dyndbg: move struct _ddebug's display fields to new _ddebug_callsite
       [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
@ 2020-11-25 19:36 ` Jim Cromie
  2020-11-25 19:36 ` [PATCH 2/7] dyndbg: count repetition in __dyndbg_callsite fields Jim Cromie
                   ` (5 subsequent siblings)
  6 siblings, 0 replies; 10+ messages in thread
From: Jim Cromie @ 2020-11-25 19:36 UTC (permalink / raw)
  To: linux-mm
  Cc: gregkh, linux, Jim Cromie, Arnd Bergmann, Jason Baron,
	linux-arch, linux-kernel

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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* [PATCH 2/7] dyndbg: count repetition in __dyndbg_callsite fields.
       [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
  2020-11-25 19:36 ` [PATCH 1/7] dyndbg: move struct _ddebug's display fields to new _ddebug_callsite Jim Cromie
@ 2020-11-25 19:36 ` Jim Cromie
  2020-11-25 19:36 ` [PATCH 3/7] dyndbg: add some code to see alignments of linkage data Jim Cromie
                   ` (4 subsequent siblings)
  6 siblings, 0 replies; 10+ messages in thread
From: Jim Cromie @ 2020-11-25 19:36 UTC (permalink / raw)
  To: linux-mm; +Cc: gregkh, linux, Jim Cromie, Jason Baron, linux-kernel

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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* [PATCH 3/7] dyndbg: add some code to see alignments of linkage data
       [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
  2020-11-25 19:36 ` [PATCH 1/7] dyndbg: move struct _ddebug's display fields to new _ddebug_callsite Jim Cromie
  2020-11-25 19:36 ` [PATCH 2/7] dyndbg: count repetition in __dyndbg_callsite fields Jim Cromie
@ 2020-11-25 19:36 ` Jim Cromie
  2020-11-25 19:36 ` [PATCH 4/7] dyndbg: select ZPOOL,ZS_MALLOC in Kconfig.debug DYNAMIC_DEBUG_CORE Jim Cromie
                   ` (3 subsequent siblings)
  6 siblings, 0 replies; 10+ messages in thread
From: Jim Cromie @ 2020-11-25 19:36 UTC (permalink / raw)
  To: linux-mm; +Cc: gregkh, linux, Jim Cromie, Jason Baron, linux-kernel

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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* [PATCH 4/7] dyndbg: select ZPOOL,ZS_MALLOC in Kconfig.debug DYNAMIC_DEBUG_CORE
       [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
                   ` (2 preceding siblings ...)
  2020-11-25 19:36 ` [PATCH 3/7] dyndbg: add some code to see alignments of linkage data Jim Cromie
@ 2020-11-25 19:36 ` Jim Cromie
  2020-11-25 19:36 ` [PATCH 5/7] dyndbg: replace __dyndbg_callsite section with a zs-pool copy Jim Cromie
                   ` (2 subsequent siblings)
  6 siblings, 0 replies; 10+ messages in thread
From: Jim Cromie @ 2020-11-25 19:36 UTC (permalink / raw)
  To: linux-mm
  Cc: gregkh, linux, Jim Cromie, kernel test robot, Andrew Morton,
	Randy Dunlap, Changbin Du, Masahiro Yamada, peterz,
	Peter Enderborg, Krzysztof Kozlowski, linux-kernel

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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* [PATCH 5/7] dyndbg: replace __dyndbg_callsite section with a zs-pool copy.
       [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
                   ` (3 preceding siblings ...)
  2020-11-25 19:36 ` [PATCH 4/7] dyndbg: select ZPOOL,ZS_MALLOC in Kconfig.debug DYNAMIC_DEBUG_CORE Jim Cromie
@ 2020-11-25 19:36 ` Jim Cromie
  2020-11-25 19:36 ` [PATCH 6/7] dyndbg: add locking around zpool-add loop in zpool-init Jim Cromie
  2020-11-25 19:36 ` [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites Jim Cromie
  6 siblings, 0 replies; 10+ messages in thread
From: Jim Cromie @ 2020-11-25 19:36 UTC (permalink / raw)
  To: linux-mm; +Cc: gregkh, linux, Jim Cromie, Jason Baron, linux-kernel

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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* [PATCH 6/7] dyndbg: add locking around zpool-add loop in zpool-init
       [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
                   ` (4 preceding siblings ...)
  2020-11-25 19:36 ` [PATCH 5/7] dyndbg: replace __dyndbg_callsite section with a zs-pool copy Jim Cromie
@ 2020-11-25 19:36 ` Jim Cromie
  2020-11-25 19:36 ` [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites Jim Cromie
  6 siblings, 0 replies; 10+ messages in thread
From: Jim Cromie @ 2020-11-25 19:36 UTC (permalink / raw)
  To: linux-mm; +Cc: gregkh, linux, Jim Cromie, Jason Baron, linux-kernel

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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites
       [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
                   ` (5 preceding siblings ...)
  2020-11-25 19:36 ` [PATCH 6/7] dyndbg: add locking around zpool-add loop in zpool-init Jim Cromie
@ 2020-11-25 19:36 ` Jim Cromie
  2020-11-25 20:54   ` Jason Baron
  6 siblings, 1 reply; 10+ messages in thread
From: Jim Cromie @ 2020-11-25 19:36 UTC (permalink / raw)
  To: linux-mm; +Cc: gregkh, linux, Jim Cromie, Jason Baron, linux-kernel

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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* Re: [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites
  2020-11-25 19:36 ` [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites Jim Cromie
@ 2020-11-25 20:54   ` Jason Baron
  2020-11-25 21:23     ` jim.cromie
  0 siblings, 1 reply; 10+ messages in thread
From: Jason Baron @ 2020-11-25 20:54 UTC (permalink / raw)
  To: Jim Cromie, linux-mm; +Cc: gregkh, linux, linux-kernel



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;
>  }
> 

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites
  2020-11-25 20:54   ` Jason Baron
@ 2020-11-25 21:23     ` jim.cromie
  0 siblings, 0 replies; 10+ messages in thread
From: jim.cromie @ 2020-11-25 21:23 UTC (permalink / raw)
  To: Jason Baron; +Cc: linux-mm, Greg KH, Rasmus Villemoes, LKML

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;
> >  }
> >

^ permalink raw reply	[flat|nested] 10+ messages in thread

* [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites
  2020-08-07 20:09 [PATCH 0/7] dyndbg: WIP diet plan Jim Cromie
@ 2020-08-07 20:09 ` Jim Cromie
  0 siblings, 0 replies; 10+ messages in thread
From: Jim Cromie @ 2020-08-07 20:09 UTC (permalink / raw)
  To: jbaron, linux-kernel
  Cc: Jim Cromie, Sumit Semwal, linux-media, dri-devel, linaro-mm-sig

in ddebug_zpool_put() dont zs_unmap the callsite, if it is enabled for
printing.  This will eliminate possibly repeated un-maps then re-maps
of enabled and invoked pr-debug callsites, and will promptly retire
all other uses.

But this causes kernel to BUG
[    1.364303] BUG: sleeping function called from invalid context at mm/slab.h:567

[jimc@frodo build-v2]$ krun -a main.dyndbg=+pmf -q=-s -q=-S
./.virtme_mods/lib/modules/0.0.0
/usr/bin/qemu-system-x86_64 -fsdev local,id=virtfs1,path=/,security_model=none,readonly,multidevs=remap -device virtio-9p-pci,fsdev=virtfs1,mount_tag=/dev/root -fsdev local,id=virtfs5,path=/usr/local/lib/python3.8/site-packages/virtme-0.1.1-py3.8.egg/virtme/guest,security_model=none,readonly,multidevs=remap -device virtio-9p-pci,fsdev=virtfs5,mount_tag=virtme.guesttools -machine accel=kvm:tcg -watchdog i6300esb -cpu host -parallel none -net none -echr 1 -serial none -chardev stdio,id=console,signal=off,mux=on -serial chardev:console -mon chardev=console -vga none -display none -kernel ./arch/x86/boot/bzImage -append 'virtme_link_mods=/home/jimc/projects/lx/linux.git/build-v2/.virtme_mods/lib/modules/0.0.0 earlyprintk=serial,ttyS0,115200 console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 25 cols 102 iutf8" TERM=xterm-256color rootfstype=9p rootflags=version=9p2000.L,trans=virtio,access=any raid=noautodetect ro nokaslr dynamic_debug.verbose=3 module.dyndbg=+pm main.dyndbg=+pmf init=/bin/sh -- -c "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"' -s -S
Wrong EFI loader signature.
early console in extract_kernel
input_data: 0x00000000033373a8
input_len: 0x0000000000aba748
output: 0x0000000001000000
output_len: 0x00000000025f9e28
kernel_total_size: 0x0000000002e2c000
needed_size: 0x0000000003000000
trampoline_32bit: 0x000000000009d000

KASLR disabled: 'nokaslr' on cmdline.

Decompressing Linux... Parsing ELF... No relocation needed... done.
Booting the kernel.
[    0.000000] Linux version 5.8.0-00025-g4e76f4427bf8 (jimc@frodo) (gcc (GCC) 10.2.1 20200723 (Red Hat 10.2.1-1), GNU ld version 2.34-4.fc32) #30 SMP Thu Aug 6 16:39:03 MDT 2020
[    0.000000] Command line: virtme_link_mods=/home/jimc/projects/lx/linux.git/build-v2/.virtme_mods/lib/modules/0.0.0 earlyprintk=serial,ttyS0,115200 console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 25 cols 102 iutf8" TERM=xterm-256color rootfstype=9p rootflags=version=9p2000.L,trans=virtio,access=any raid=noautodetect ro nokaslr dynamic_debug.verbose=3 module.dyndbg=+pm main.dyndbg=+pmf init=/bin/sh -- -c "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"
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x008: 'MPX bounds registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x010: 'MPX CSR'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: xstate_offset[3]:  832, xstate_sizes[3]:   64
[    0.000000] x86/fpu: xstate_offset[4]:  896, xstate_sizes[4]:   64
[    0.000000] x86/fpu: Enabled xstate features 0x1f, context size is 960 bytes, using 'compacted' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x0000000007fdffff] usable
[    0.000000] BIOS-e820: [mem 0x0000000007fe0000-0x0000000007ffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    0.000000] printk: bootconsole [earlyser0] enabled
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.8 present.
[    0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-2.fc32 04/01/2014
[    0.000000] Hypervisor detected: KVM
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 3141001, primary cpu clock
[    0.000000] kvm-clock: using sched offset of 218135524 cycles
[    0.000900] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.003580] tsc: Detected 2591.998 MHz processor
[    0.004611] last_pfn = 0x7fe0 max_arch_pfn = 0x400000000
[    0.005518] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT
[    0.013334] found SMP MP-table at [mem 0x000f5c30-0x000f5c3f]
[    0.014404] check: Scanning 1 areas for low memory corruption
[    0.015327] Using GB pages for direct mapping
[    0.016207] ACPI: Early table checksum verification disabled
[    0.017097] ACPI: RSDP 0x00000000000F5A70 000014 (v00 BOCHS )
[    0.018015] ACPI: RSDT 0x0000000007FE157B 000030 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
[    0.019607] ACPI: FACP 0x0000000007FE1457 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
[    0.021045] ACPI: DSDT 0x0000000007FE0040 001417 (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
[    0.022479] ACPI: FACS 0x0000000007FE0000 000040
[    0.023399] ACPI: APIC 0x0000000007FE14CB 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
[    0.024818] ACPI: HPET 0x0000000007FE1543 000038 (v01 BOCHS  BXPCHPET 00000001 BXPC 00000001)
[    0.026390] No NUMA configuration found
[    0.026962] Faking a node at [mem 0x0000000000000000-0x0000000007fdffff]
[    0.027986] NODE_DATA(0) allocated [mem 0x07fdc000-0x07fdffff]
[    0.028978] Zone ranges:
[    0.029398]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.030489]   DMA32    [mem 0x0000000001000000-0x0000000007fdffff]
[    0.031567]   Normal   empty
[    0.031954] Movable zone start for each node
[    0.032662] Early memory node ranges
[    0.033219]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.034078]   node   0: [mem 0x0000000000100000-0x0000000007fdffff]
[    0.035334] Zeroed struct page in unavailable ranges: 130 pages
[    0.035336] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007fdffff]
[    0.038090] ACPI: PM-Timer IO Port: 0x608
[    0.038770] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.039730] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.040855] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.041956] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.043186] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.044213] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.045280] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.046277] Using ACPI (MADT) for SMP configuration information
[    0.047208] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.048083] TSC deadline timer available
[    0.048763] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
[    0.049527] KVM setup pv remote TLB flush
[    0.050297] KVM setup pv sched yield
[    0.050864] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.052112] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.053290] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff]
[    0.054468] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[    0.055881] [mem 0x08000000-0xfeffbfff] available for PCI devices
[    0.056952] Booting paravirtualized kernel on KVM
[    0.057938] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.059627] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:1 nr_node_ids:1
[    0.061318] percpu: Embedded 502 pages/cpu s2015896 r8192 d32104 u2097152
[    0.062483] KVM setup async PF for cpu 0
[    0.063242] kvm-stealtime: cpu 0, msr 7a17cc0
[    0.063989] Built 1 zonelists, mobility grouping on.  Total pages: 32105
[    0.065255] Policy zone: DMA32
[    0.065776] Kernel command line: virtme_link_mods=/home/jimc/projects/lx/linux.git/build-v2/.virtme_mods/lib/modules/0.0.0 earlyprintk=serial,ttyS0,115200 console=ttyS0 psmouse.proto=exps "virtme_stty_con=rows 25 cols 102 iutf8" TERM=xterm-256color rootfstype=9p rootflags=version=9p2000.L,trans=virtio,access=any raid=noautodetect ro nokaslr dynamic_debug.verbose=3 module.dyndbg=+pm main.dyndbg=+pmf init=/bin/sh -- -c "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"
[    0.075229] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    0.076569] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.077888] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.079127] Memory: 79000K/130552K available (16390K kernel code, 2056K rwdata, 8476K rodata, 3008K init, 13184K bss, 51552K reserved, 0K cma-reserved)
[    0.081449] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.082840] Kernel/User page tables isolation: enabled
[    0.088889] Running RCU self tests
[    0.089529] rcu: Hierarchical RCU implementation.
[    0.090444] rcu: 	RCU event tracing is enabled.
[    0.091347] rcu: 	RCU lockdep checking is enabled.
[    0.092084] rcu: 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=1.
[    0.093238] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
[    0.094467] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[    0.096052] NR_IRQS: 4352, nr_irqs: 256, preallocated irqs: 16
[    0.097804] random: get_random_bytes called from start_kernel+0x36b/0x544 with crng_init=0
[    0.097951] Console: colour *CGA 80x25
[    0.100066] printk: console [ttyS0] enabled
[    0.100066] printk: console [ttyS0] enabled
[    0.101286] printk: bootconsole [earlyser0] disabled
[    0.101286] printk: bootconsole [earlyser0] disabled
[    0.102875] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.104018] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.104714] ... MAX_LOCK_DEPTH:          48
[    0.105600] ... MAX_LOCKDEP_KEYS:        8192
[    0.106572] ... CLASSHASH_SIZE:          4096
[    0.107509] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.108265] ... MAX_LOCKDEP_CHAINS:      65536
[    0.108892] ... CHAINHASH_SIZE:          32768
[    0.109598]  memory used by lock dependency info: 6813 kB
[    0.110461]  memory used for stack traces: 4224 kB
[    0.111274]  per task-struct memory footprint: 2688 bytes
[    0.112067] ------------------------
[    0.112669] | Locking API testsuite:
[    0.113368] ----------------------------------------------------------------------------
[    0.114770]                                  | spin |wlock |rlock |mutex | wsem | rsem |
[    0.116032]   --------------------------------------------------------------------------
[    0.117269]                      A-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.121931]                  A-B-B-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.126875]              A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.131594]              A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.136460]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.141138]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.146236]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.151113]                     double unlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.155610]                   initialize held:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.159968]   --------------------------------------------------------------------------
[    0.161246]               recursive read-lock:             |  ok  |             |  ok  |
[    0.163424]            recursive read-lock #2:             |  ok  |             |  ok  |
[    0.165567]             mixed read-write-lock:             |  ok  |             |  ok  |
[    0.167698]             mixed write-read-lock:             |  ok  |             |  ok  |
[    0.170041]   mixed read-lock/lock-write ABBA:             |  ok  |             |  ok  |
[    0.170927]    mixed read-lock/lock-read ABBA:             |FAILED|             |  ok  |
[    0.173043]  mixed write-lock/lock-write ABBA:             |  ok  |             |  ok  |
[    0.175456]   --------------------------------------------------------------------------
[    0.178055]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.180435]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.182596]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.184786]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.187120]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[    0.189291]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[    0.191487]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.193918]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.196176]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.198335]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.200556]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.203119]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.205467]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.208201]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.210585]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.213147]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.215550]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.217926]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.220455]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.222807]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.225246]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.227480]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.229886]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.232121]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.234488]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.237863]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.241987]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.244188]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.246434]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.248782]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.250969]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.253578]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.256138]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.258583]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.261091]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.263609]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.266030]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.268224]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.270522]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.272741]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.274977]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.277139]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.279390]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.281880]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.284206]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.286949]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.289404]       hard-irq read-recursion/123:  ok  |
[    0.290832]       soft-irq read-recursion/123:  ok  |
[    0.292139]       hard-irq read-recursion/132:  ok  |
[    0.293402]       soft-irq read-recursion/132:  ok  |
[    0.294707]       hard-irq read-recursion/213:  ok  |
[    0.296035]       soft-irq read-recursion/213:  ok  |
[    0.297515]       hard-irq read-recursion/231:  ok  |
[    0.298786]       soft-irq read-recursion/231:  ok  |
[    0.300243]       hard-irq read-recursion/312:  ok  |
[    0.301589]       soft-irq read-recursion/312:  ok  |
[    0.302907]       hard-irq read-recursion/321:  ok  |
[    0.304080]       soft-irq read-recursion/321:  ok  |
[    0.305288]   --------------------------------------------------------------------------
[    0.306410]   | Wound/wait tests |
[    0.306883]   ---------------------
[    0.307421]                   ww api failures:  ok  |  ok  |  ok  |
[    0.309949]                ww contexts mixing:  ok  |  ok  |
[    0.311666]              finishing ww context:  ok  |  ok  |  ok  |  ok  |
[    0.314669]                locking mismatches:  ok  |  ok  |  ok  |
[    0.317124]                  EDEADLK handling:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.323525]            spinlock nest unlocked:  ok  |
[    0.324643]   -----------------------------------------------------
[    0.325504]                                  |block | try  |context|
[    0.326631]   -----------------------------------------------------
[    0.327505]                           context:  ok  |  ok  |  ok  |
[    0.329832]                               try:  ok  |  ok  |  ok  |
[    0.331964]                             block:  ok  |  ok  |  ok  |
[    0.334585]                          spinlock:  ok  |  ok  |  ok  |
[    0.337766] -------------------------------------------------------
[    0.338756] Good, all 261 testcases passed! |
[    0.339394] ---------------------------------
[    0.340334] ACPI: Core revision 20200528
[    0.341167] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    0.342557] APIC: Switch to symmetric I/O mode setup
[    0.343248] KVM setup pv IPIs
[    0.345126] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.345981] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x255cb518234, max_idle_ns: 440795279333 ns
[    0.347449] Calibrating delay loop (skipped) preset value.. 5183.99 BogoMIPS (lpj=2591998)
[    0.348446] pid_max: default: 32768 minimum: 301
[    0.349095] LSM: Security Framework initializing
[    0.349460] SELinux:  Initializing.
[    0.349964] Mount-cache hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.350446] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes, linear)
Poking KASLR using RDRAND RDTSC...
[    0.353011] x86/cpu: User Mode Instruction Prevention (UMIP) activated
[    0.353541] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.354445] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    0.355453] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.356449] Spectre V2 : Mitigation: Full generic retpoline
[    0.357446] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.358444] Spectre V2 : Enabling Restricted Speculation for firmware calls
[    0.359450] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
[    0.360447] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.361458] TAA: Mitigation: Clear CPU buffers
[    0.362446] SRBDS: Unknown: Dependent on hypervisor status
[    0.363444] MDS: Mitigation: Clear CPU buffers
[    0.374194] Freeing SMP alternatives memory: 40K
[    0.375553] smpboot: CPU0: Intel(R) Core(TM) i7-6700HQ CPU @ 2.60GHz (family: 0x6, model: 0x5e, stepping: 0x3)
[    0.376791] Performance Events: Skylake events, full-width counters, Intel PMU driver.
[    0.377456] ... version:                2
[    0.378089] ... bit width:              48
[    0.378447] ... generic registers:      4
[    0.379067] ... value mask:             0000ffffffffffff
[    0.379446] ... max period:             00007fffffffffff
[    0.380291] ... fixed-purpose events:   3
[    0.380453] ... event mask:             000000070000000f
[    0.381618] rcu: Hierarchical SRCU implementation.
[    0.382784] dyndbg:   6 debug prints in module main
[    0.383485] dyndbg:   1 debug prints in module initramfs
[    0.384338] dyndbg:   3 debug prints in module ibs
[    0.384448] dyndbg:   2 debug prints in module pt
[    0.385176] dyndbg:  11 debug prints in module kvm
[    0.385448] dyndbg:  15 debug prints in module kvm_intel
[    0.386231] dyndbg:   1 debug prints in module kvm_amd
[    0.386471] dyndbg:   1 debug prints in module common
[    0.387311] dyndbg:   1 debug prints in module amd
[    0.387466] dyndbg:   1 debug prints in module hygon
[    0.388234] dyndbg:   1 debug prints in module therm_throt
[    0.388447] dyndbg:   2 debug prints in module mtrr
[    0.389158] dyndbg:   7 debug prints in module generic
[    0.389447] dyndbg:   6 debug prints in module cleanup
[    0.390213] dyndbg:  19 debug prints in module microcode
[    0.390447] dyndbg:   1 debug prints in module mshyperv
[    0.391193] dyndbg:   5 debug prints in module boot
[    0.391447] dyndbg:  21 debug prints in module smpboot
[    0.392372] dyndbg:   1 debug prints in module tsc_sync
[    0.392448] dyndbg:   2 debug prints in module setup_percpu
[    0.393274] dyndbg:  30 debug prints in module vector
[    0.393447] dyndbg:   2 debug prints in module hpet
[    0.394139] dyndbg:   2 debug prints in module init
[    0.394447] dyndbg:   4 debug prints in module init_64
[    0.395237] dyndbg:   1 debug prints in module numa
[    0.395447] dyndbg:   1 debug prints in module pti
[    0.396142] dyndbg:   2 debug prints in module iosf_mbi
[    0.396447] dyndbg:   4 debug prints in module params
[    0.397197] dyndbg:   4 debug prints in module async
[    0.397447] dyndbg:   4 debug prints in module snapshot
[    0.398219] dyndbg:   6 debug prints in module swap
[    0.398447] dyndbg:   1 debug prints in module manage
[    0.399198] dyndbg:  14 debug prints in module irqdomain
[    0.399447] dyndbg:   1 debug prints in module cpuhotplug
[    0.400254] dyndbg:   2 debug prints in module msi
[    0.400448] dyndbg:   2 debug prints in module freezer
[    0.401248] dyndbg:  18 debug prints in module module
[    0.401454] dyndbg:   1 debug prints in module cgroup
[    0.402235] dyndbg:   1 debug prints in module util
[    0.402466] dyndbg:   1 debug prints in module swapfile
[    0.403376] dyndbg:   5 debug prints in module zswap
[    0.403448] dyndbg:   6 debug prints in module mempolicy
[    0.404214] dyndbg:   1 debug prints in module sparse
[    0.404454] dyndbg:   1 debug prints in module sparse_vmemmap
[    0.405374] dyndbg:   3 debug prints in module zpool
[    0.405448] dyndbg:   1 debug prints in module fsnotify
[    0.406112] dyndbg:   2 debug prints in module notification
[    0.406447] dyndbg:   1 debug prints in module inotify_fsnotify
[    0.407234] dyndbg:   5 debug prints in module inotify_user
[    0.407448] dyndbg:  22 debug prints in module aio
[    0.408221] dyndbg:  14 debug prints in module binfmt_misc
[    0.408447] dyndbg:   2 debug prints in module mount
[    0.409127] dyndbg:   1 debug prints in module dir
[    0.409447] dyndbg:  32 debug prints in module autofs4
[    0.410141] dyndbg:   1 debug prints in module debugfs
[    0.410447] dyndbg:   1 debug prints in module tracefs
[    0.411080] dyndbg:  11 debug prints in module selinux
[    0.411447] dyndbg:   6 debug prints in module asymmetric_keys
[    0.412295] dyndbg:  13 debug prints in module x509_key_parser
[    0.412448] dyndbg:  21 debug prints in module pkcs7_message
[    0.413252] dyndbg:  14 debug prints in module efi
[    0.413447] dyndbg:   2 debug prints in module bsg
[    0.414439] dyndbg:   1 debug prints in module percpu_refcount
[    0.414448] dyndbg:  11 debug prints in module asn1_decoder
[    0.415325] dyndbg:   1 debug prints in module decompress
[    0.415447] dyndbg:  10 debug prints in module kobject
[    0.416268] dyndbg:   6 debug prints in module kobject_uevent
[    0.416447] dyndbg:   6 debug prints in module probe
[    0.417267] dyndbg:   9 debug prints in module pci
[    0.417447] dyndbg:   3 debug prints in module pci_driver
[    0.418258] dyndbg:   2 debug prints in module setup_bus
[    0.418447] dyndbg:   2 debug prints in module setup_irq
[    0.419314] dyndbg:   4 debug prints in module pcieportdrv
[    0.419448] dyndbg:   3 debug prints in module slot
[    0.420182] dyndbg:   2 debug prints in module pci_acpi
[    0.420448] dyndbg:   2 debug prints in module quirks
[    0.421285] dyndbg:   1 debug prints in module pci_hotplug
[    0.421447] dyndbg:   3 debug prints in module backlight
[    0.422213] dyndbg:   1 debug prints in module fb
[    0.422447] dyndbg:   7 debug prints in module tables
[    0.423239] dyndbg:  89 debug prints in module acpi
[    0.423465] dyndbg:   1 debug prints in module button
[    0.424291] dyndbg:   3 debug prints in module fan
[    0.424448] dyndbg:   1 debug prints in module video
[    0.425451] dyndbg:   8 debug prints in module processor
[    0.426405] dyndbg:   4 debug prints in module srat
[    0.426449] dyndbg:  24 debug prints in module cppc_acpi
[    0.427295] dyndbg:   7 debug prints in module pnp
[    0.427447] dyndbg:   6 debug prints in module clk
[    0.428223] dyndbg:   9 debug prints in module dmaengine
[    0.428447] dyndbg:   2 debug prints in module virt_dma
[    0.429254] dyndbg:   3 debug prints in module acpi_dma
[    0.429447] dyndbg:   5 debug prints in module dw_dmac_core
[    0.430364] dyndbg:  10 debug prints in module virtio_ring
[    0.430447] dyndbg:   5 debug prints in module tty_io
[    0.431225] dyndbg:   1 debug prints in module tty_jobctrl
[    0.431447] dyndbg:   1 debug prints in module vt_ioctl
[    0.432268] dyndbg:   4 debug prints in module serial_core
[    0.432447] dyndbg:   4 debug prints in module 8250
[    0.433246] dyndbg:   5 debug prints in module 8250_base
[    0.433447] dyndbg:   8 debug prints in module 8250_pci
[    0.434452] dyndbg:   1 debug prints in module 8250_exar
[    0.435254] dyndbg:   2 debug prints in module virtio_console
[    0.435447] dyndbg:   6 debug prints in module iommu
[    0.436400] dyndbg:   2 debug prints in module dmar
[    0.436447] dyndbg:   3 debug prints in module iommu
[    0.437241] dyndbg:   1 debug prints in module drm
[    0.437447] dyndbg:  19 debug prints in module vgaarb
[    0.438350] dyndbg:   7 debug prints in module component
[    0.438449] dyndbg:  16 debug prints in module core
[    0.439245] dyndbg:   7 debug prints in module bus
[    0.439450] dyndbg:  20 debug prints in module dd
[    0.440184] dyndbg:   1 debug prints in module syscore
[    0.440447] dyndbg:   5 debug prints in module class
[    0.441198] dyndbg:   4 debug prints in module platform
[    0.441447] dyndbg:   6 debug prints in module main
[    0.442203] dyndbg:   1 debug prints in module wakeup
[    0.442447] dyndbg:   6 debug prints in module clock_ops
[    0.443391] dyndbg:  15 debug prints in module firmware_class
[    0.443447] dyndbg:   1 debug prints in module regmap
[    0.444227] dyndbg:   7 debug prints in module regcache
[    0.444448] dyndbg:   1 debug prints in module regmap_debugfs
[    0.445248] dyndbg:   1 debug prints in module dma_buf
[    0.445448] dyndbg:   5 debug prints in module scsi_mod
[    0.446454] dyndbg:   2 debug prints in module virtio_scsi
[    0.447451] dyndbg:  98 debug prints in module cdrom
[    0.448250] dyndbg:  14 debug prints in module pcmcia_core
[    0.448449] dyndbg:  79 debug prints in module pcmcia
[    0.449353] dyndbg:   2 debug prints in module pcmcia_rsrc
[    0.449447] dyndbg:  13 debug prints in module yenta_socket
[    0.450320] dyndbg: 153 debug prints in module usbcore
[    0.450448] dyndbg:  10 debug prints in module pci_quirks
[    0.451268] dyndbg:  53 debug prints in module ehci_hcd
[    0.451447] dyndbg:   2 debug prints in module ehci_pci
[    0.452336] dyndbg:  46 debug prints in module ohci_hcd
[    0.452447] dyndbg:  11 debug prints in module uhci_hcd
[    0.453253] dyndbg:  10 debug prints in module usb_storage
[    0.453463] dyndbg:   6 debug prints in module libps2
[    0.454370] dyndbg:   6 debug prints in module input_core
[    0.454448] dyndbg:  11 debug prints in module ff_memless
[    0.455385] dyndbg:   3 debug prints in module input_polldev
[    0.455461] dyndbg:   5 debug prints in module atkbd
[    0.456294] dyndbg:  27 debug prints in module psmouse
[    0.456453] dyndbg:  11 debug prints in module rtc_core
[    0.457263] dyndbg:   5 debug prints in module rtc_cmos
[    0.457447] dyndbg:   1 debug prints in module i2c_boardinfo
[    0.458203] dyndbg:  24 debug prints in module i2c_core
[    0.458447] dyndbg:   2 debug prints in module i2c_smbus
[    0.459317] dyndbg:  11 debug prints in module i2c_i801
[    0.459450] dyndbg:  17 debug prints in module pps_core
[    0.460334] dyndbg:   8 debug prints in module power_supply
[    0.460452] dyndbg:   1 debug prints in module hwmon
[    0.461361] dyndbg:   8 debug prints in module thermal_sys
[    0.461448] dyndbg:  48 debug prints in module md_mod
[    0.462303] dyndbg:   5 debug prints in module dm_mod
[    0.462448] dyndbg:  43 debug prints in module cpufreq
[    0.463268] dyndbg:   9 debug prints in module freq_table
[    0.463448] dyndbg:   1 debug prints in module cpufreq_performance
[    0.464447] dyndbg:   4 debug prints in module cpufreq_userspace
[    0.465448] dyndbg:  23 debug prints in module acpi_cpufreq
[    0.466434] dyndbg:  17 debug prints in module intel_pstate
[    0.466449] dyndbg:   1 debug prints in module sysfs
[    0.467364] dyndbg:   1 debug prints in module led_class
[    0.467451] dyndbg:   2 debug prints in module dmi_scan
[    0.468364] dyndbg:   4 debug prints in module esrt
[    0.468451] dyndbg:   1 debug prints in module hid
[    0.469273] dyndbg:   4 debug prints in module hid_pl
[    0.469447] dyndbg:   1 debug prints in module hid_sony
[    0.470307] dyndbg:  32 debug prints in module usbhid
[    0.470447] dyndbg:   2 debug prints in module mailbox
[    0.471297] dyndbg:   6 debug prints in module pcc
[    0.471463] dyndbg:   1 debug prints in module nvmem_core
[    0.472349] dyndbg:   3 debug prints in module snd
[    0.472447] dyndbg:   1 debug prints in module snd_timer
[    0.473406] dyndbg:   5 debug prints in module snd_pcm
[    0.473449] dyndbg:  11 debug prints in module snd_seq
[    0.474315] dyndbg:  19 debug prints in module snd_hda_codec
[    0.474448] dyndbg:  12 debug prints in module snd_hda_intel
[    0.475448] dyndbg:  16 debug prints in module snd_hda_core
[    0.476447] dyndbg:   1 debug prints in module sock
[    0.477309] dyndbg:  17 debug prints in module dev
[    0.477447] dyndbg:   2 debug prints in module sch_api
[    0.478271] dyndbg:   1 debug prints in module netfilter
[    0.478450] dyndbg:  43 debug prints in module nf_conntrack
[    0.479432] dyndbg:   1 debug prints in module nf_conntrack_netlink
[    0.479451] dyndbg:  19 debug prints in module nf_conntrack_ftp
[    0.480441] dyndbg:   4 debug prints in module nf_conntrack_irc
[    0.480469] dyndbg:   2 debug prints in module nf_conntrack_sip
[    0.481419] dyndbg:   4 debug prints in module nf_nat
[    0.481447] dyndbg:   2 debug prints in module nf_nat_ftp
[    0.482299] dyndbg:   1 debug prints in module nf_nat_irc
[    0.482447] dyndbg:   2 debug prints in module x_tables
[    0.483288] dyndbg:   4 debug prints in module xt_tcpudp
[    0.483447] dyndbg:   3 debug prints in module route
[    0.484234] dyndbg:   1 debug prints in module ip_fragment
[    0.484447] dyndbg:   1 debug prints in module ip_output
[    0.485346] dyndbg:   1 debug prints in module tcp
[    0.485447] dyndbg:   6 debug prints in module tcp_input
[    0.486335] dyndbg:   2 debug prints in module tcp_output
[    0.486448] dyndbg:   3 debug prints in module tcp_timer
[    0.487264] dyndbg:   1 debug prints in module tcp_ipv4
[    0.487447] dyndbg:   1 debug prints in module tcp_cong
[    0.488281] dyndbg:   1 debug prints in module tcp_rate
[    0.488447] dyndbg:   1 debug prints in module tcp_recovery
[    0.489337] dyndbg:   8 debug prints in module udp
[    0.489448] dyndbg:   1 debug prints in module arp
[    0.490308] dyndbg:   2 debug prints in module icmp
[    0.490447] dyndbg:   1 debug prints in module devinet
[    0.491223] dyndbg:   8 debug prints in module fib_trie
[    0.491447] dyndbg:  27 debug prints in module ping
[    0.492225] dyndbg:   1 debug prints in module sysctl_net_ipv4
[    0.492447] dyndbg:  11 debug prints in module ipconfig
[    0.493233] dyndbg:   1 debug prints in module tcp_cubic
[    0.493449] dyndbg:  39 debug prints in module ipv6
[    0.494276] dyndbg:   1 debug prints in module ah6
[    0.494447] dyndbg:   1 debug prints in module esp6
[    0.495152] dyndbg:  12 debug prints in module nf_defrag_ipv6
[    0.495447] dyndbg:   6 debug prints in module nf_reject_ipv6
[    0.496372] dyndbg:   2 debug prints in module sit
[    0.496448] dyndbg:   2 debug prints in module ip6_checksum
[    0.497306] dyndbg:  35 debug prints in module cfg80211
[    0.497452] dyndbg:   6 debug prints in module mac80211
[    0.498213] dyndbg:   2 debug prints in module i386
[    0.498456] dyndbg:   2 debug prints in module fixup
[    0.499187] dyndbg:   7 debug prints in module irq
[    0.499448] dyndbg: 224 modules, 1994 entries and 8960 bytes in ddebug tables, 79760 bytes in __dyndbg section, 79760 bytes in __dyndbg_callsites section
[    0.500447] dyndbg: 1994 entries. repeated entries: 1769 module 1646 file 799 func
[    0.501449] dyndbg: virtme_link_mods="/home/jimc/projects/lx/linux.git/build-v2/.virtme_mods/lib/modules/0.0.0"
[    0.502447] dyndbg: earlyprintk="serial,ttyS0,115200"
[    0.503340] dyndbg: console="ttyS0"
[    0.503448] dyndbg: psmouse.proto="exps"
[    0.504154] dyndbg: virtme_stty_con="rows 25 cols 102 iutf8"
[    0.504452] dyndbg: TERM="xterm-256color"
[    0.505396] dyndbg: rootfstype="9p"
[    0.505449] dyndbg: rootflags="version=9p2000.L,trans=virtio,access=any"
[    0.506450] dyndbg: raid="noautodetect"
[    0.507166] dyndbg: ro="(null)"
[    0.507447] dyndbg: nokaslr="(null)"
[    0.507995] dyndbg: dynamic_debug.verbose="3"
[    0.508446] dyndbg: module.dyndbg="+pm"
[    0.509067] dyndbg: query 0: "+pm"
[    0.509446] dyndbg: split into words: "+pm"
[    0.510144] dyndbg: op='+'
[    0.510446] dyndbg: flags=0x3
[    0.510898] dyndbg: *flagsp=0x3 *maskp=0xffffffff
[    0.511447] dyndbg: parsed: func="" file="" module="module" format="" lineno=0-0
[    0.512473] dyndbg: changed kernel/module.c:4001 [module]__do_sys_finit_module =pm
[    0.513453] dyndbg: changed kernel/module.c:3980 [module]__do_sys_init_module =pm
[    0.514452] dyndbg: changed kernel/module.c:3302 [module]move_module =pm
[    0.515467] dyndbg: changed kernel/module.c:3284 [module]move_module =pm
[    0.516419] dyndbg: changed kernel/module.c:2707 [module]layout_symtab =pm
[    0.516452] dyndbg: changed kernel/module.c:2680 [module]layout_symtab =pm
[    0.517410] dyndbg: changed kernel/module.c:2461 [module]layout_sections =pm
[    0.517457] dyndbg: changed kernel/module.c:2448 [module]layout_sections =pm
[    0.518471] dyndbg: changed kernel/module.c:2427 [module]layout_sections =pm
[    0.519456] dyndbg: changed kernel/module.c:2415 [module]layout_sections =pm
[    0.520458] dyndbg: changed kernel/module.c:2300 [module]simplify_symbols =pm
[    0.521452] dyndbg: changed kernel/module.c:2292 [module]simplify_symbols =pm
[    0.522452] dyndbg: changed kernel/module.c:1007 [module]__do_sys_delete_module =pm
[    0.523454] dyndbg: changed kernel/module.c:901 [module]module_unload_free =pm
[    0.524452] dyndbg: changed kernel/module.c:859 [module]add_module_usage =pm
[    0.525452] dyndbg: changed kernel/module.c:844 [module]already_uses =pm
[    0.526452] dyndbg: changed kernel/module.c:840 [module]already_uses =pm
[    0.527451] dyndbg: changed kernel/module.c:608 [module]find_symbol =pm
[    0.528449] dyndbg: applied: func="" file="" module="module" format="" lineno=0-0
[    0.529461] dyndbg: processed 1 queries, with 18 matches, 0 errs
[    0.530361] dyndbg: main.dyndbg="+pmf"
[    0.530447] dyndbg: query 0: "+pmf"
[    0.531105] dyndbg: split into words: "+pmf"
[    0.531446] dyndbg: op='+'
[    0.531876] dyndbg: flags=0x7
[    0.532440] dyndbg: *flagsp=0x7 *maskp=0xffffffff
[    0.532447] dyndbg: parsed: func="" file="" module="main" format="" lineno=0-0
[    0.533416] dyndbg: changed drivers/base/power/main.c:445 [main]pm_dev_dbg =pmf
[    0.533455] dyndbg: changed drivers/base/power/main.c:202 [main]device_pm_move_last =pmf
[    0.534452] dyndbg: changed drivers/base/power/main.c:189 [main]device_pm_move_after =pmf
[    0.535452] dyndbg: changed drivers/base/power/main.c:175 [main]device_pm_move_before =pmf
[    0.536453] dyndbg: changed drivers/base/power/main.c:156 [main]device_pm_remove =pmf
[    0.537452] dyndbg: changed drivers/base/power/main.c:135 [main]device_pm_add =pmf
[    0.538449] dyndbg: changed init/main.c:1331 [main]run_init_process =pmf
[    0.539386] dyndbg: changed init/main.c:1329 [main]run_init_process =pmf
[    0.539447] dyndbg: changed init/main.c:1328 [main]run_init_process =pmf
[    0.540435] dyndbg: changed init/main.c:1326 [main]run_init_process =pmf
[    0.540448] dyndbg: changed init/main.c:1115 [main]initcall_blacklisted =pmf
[    0.541447] dyndbg: changed init/main.c:1076 [main]initcall_blacklist =pmf
[    0.542339] dyndbg: applied: func="" file="" module="main" format="" lineno=0-0
[    0.542450] dyndbg: processed 1 queries, with 12 matches, 0 errs
[    0.543451] dyndbg: init="/bin/sh"
[    0.544127] smp: Bringing up secondary CPUs ...
[    0.544449] smp: Brought up 1 node, 1 CPU
[    0.545130] smpboot: Max logical packages: 1
[    0.545449] smpboot: Total of 1 processors activated (5183.99 BogoMIPS)
[    0.546839] devtmpfs: initialized
[    0.548202] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.548452] futex hash table entries: 256 (order: 3, 32768 bytes, linear)
[    0.549664] PM: RTC time: 00:46:43, date: 2020-08-07
[    0.550466] thermal_sys: Registered thermal governor 'step_wise'
[    0.550467] thermal_sys: Registered thermal governor 'user_space'
[    0.551644] NET: Registered protocol family 16
[    0.552713] audit: initializing netlink subsys (disabled)
[    0.553532] audit: type=2000 audit(1596761203.662:1): state=initialized audit_enabled=0 res=1
[    0.554971] cpuidle: using governor menu
[    0.555555] ACPI: bus type PCI registered
[    0.556412] PCI: Using configuration type 1 for base access
[    0.568724] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.569690] cryptomgr_test (19) used greatest stack depth: 14840 bytes left
[    0.572805] ACPI: Added _OSI(Module Device)
[    0.573456] ACPI: Added _OSI(Processor Device)
[    0.574110] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.574447] ACPI: Added _OSI(Processor Aggregator Device)
[    0.575295] ACPI: Added _OSI(Linux-Dell-Video)
[    0.575506] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.576314] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    0.578310] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.580046] ACPI: Interpreter enabled
[    0.580532] ACPI: (supports S0 S3 S4 S5)
[    0.581240] ACPI: Using IOAPIC for interrupt routing
[    0.581491] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.582716] ACPI: Enabled 2 GPEs in block 00 to 0F
[    0.592022] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.592457] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3]
[    0.593500] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[    0.594647] PCI host bridge to bus 0000:00
[    0.595302] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.595457] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.596413] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.596448] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
[    0.597447] pci_bus 0000:00: root bus resource [mem 0x100000000-0x17fffffff window]
[    0.598449] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.599388] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[    0.600305] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[    0.601408] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180
[    0.603406] pci 0000:00:01.1: reg 0x20: [io  0xc080-0xc08f]
[    0.604297] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
[    0.604449] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
[    0.605447] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
[    0.606447] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
[    0.607866] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
[    0.609461] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
[    0.610491] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
[    0.612002] pci 0000:00:02.0: [1af4:1009] type 00 class 0x000200
[    0.613238] pci 0000:00:02.0: reg 0x10: [io  0xc000-0xc03f]
[    0.614084] pci 0000:00:02.0: reg 0x14: [mem 0xfebfd000-0xfebfdfff]
[    0.617136] pci 0000:00:02.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref]
[    0.619337] pci 0000:00:03.0: [1af4:1009] type 00 class 0x000200
[    0.620450] pci 0000:00:03.0: reg 0x10: [io  0xc040-0xc07f]
[    0.622041] pci 0000:00:03.0: reg 0x14: [mem 0xfebfe000-0xfebfefff]
[    0.625400] pci 0000:00:03.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref]
[    0.626990] pci 0000:00:04.0: [8086:25ab] type 00 class 0x088000
[    0.627717] pci 0000:00:04.0: reg 0x10: [mem 0xfebff000-0xfebff00f]
[    0.631736] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[    0.632626] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    0.633664] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    0.634766] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[    0.635551] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[    0.636710] iommu: Default domain type: Translated
[    0.637656] vgaarb: loaded
[    0.638518] SCSI subsystem initialized
[    0.639275] ACPI: bus type USB registered
[    0.639530] usbcore: registered new interface driver usbfs
[    0.640305] usbcore: registered new interface driver hub
[    0.640482] usbcore: registered new device driver usb
[    0.641460] pps_core: LinuxPPS API ver. 1 registered
[    0.642264] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.642464] PTP clock support registered
[    0.643299] Advanced Linux Sound Architecture Driver Initialized.
[    0.644011] NetLabel: Initializing
[    0.644447] NetLabel:  domain hash size = 128
[    0.645113] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.645484] NetLabel:  unlabeled traffic allowed by default
[    0.646506] PCI: Using ACPI for IRQ routing
[    0.647581] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.648448] hpet0: 3 comparators, 64-bit 100.000000 MHz counter
[    0.652478] clocksource: Switched to clocksource kvm-clock
[    0.810605] VFS: Disk quotas dquot_6.6.0
[    0.811509] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.812869] pnp: PnP ACPI init
[    0.814458] pnp: PnP ACPI: found 5 devices
[    0.824953] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    0.826824] NET: Registered protocol family 2
[    0.828000] tcp_listen_portaddr_hash hash table entries: 64 (order: 0, 5632 bytes, linear)
[    0.829351] TCP established hash table entries: 1024 (order: 1, 8192 bytes, linear)
[    0.830688] TCP bind hash table entries: 1024 (order: 4, 81920 bytes, linear)
[    0.831938] TCP: Hash tables configured (established 1024 bind 1024)
[    0.833143] UDP hash table entries: 256 (order: 3, 49152 bytes, linear)
[    0.834457] UDP-Lite hash table entries: 256 (order: 3, 49152 bytes, linear)
[    0.835774] NET: Registered protocol family 1
[    0.836796] RPC: Registered named UNIX socket transport module.
[    0.837784] RPC: Registered udp transport module.
[    0.838506] RPC: Registered tcp transport module.
[    0.839492] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.841142] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    0.842085] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    0.842919] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    0.843899] pci_bus 0000:00: resource 7 [mem 0x08000000-0xfebfffff window]
[    0.845022] pci_bus 0000:00: resource 8 [mem 0x100000000-0x17fffffff window]
[    0.846622] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[    0.847617] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.848722] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    0.849796] PCI: CLS 0 bytes, default 64
[    0.850789] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer
[    0.852897] kvm: already loaded the other module
[    0.853839] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x255cb518234, max_idle_ns: 440795279333 ns
[    0.855861] check: Scanning for low memory corruption every 60 seconds
[    0.858222] Initialise system trusted keyrings
[    0.859187] workingset: timestamp_bits=56 max_order=15 bucket_order=0
[    0.868673] zbud: loaded
[    0.871222] NFS: Registering the id_resolver key type
[    0.872176] Key type id_resolver registered
[    0.872878] Key type id_legacy registered
[    0.873688] 9p: Installing v9fs 9p2000 file system support
[    0.882923] Key type asymmetric registered
[    0.883786] Asymmetric key parser 'x509' registered
[    0.884535] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.885639] io scheduler mq-deadline registered
[    0.886292] io scheduler kyber registered
[    0.887591] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    0.889220] ACPI: Power Button [PWRF]
[    1.019699] PCI Interrupt Link [LNKB] enabled at IRQ 10
[    1.148365] PCI Interrupt Link [LNKC] enabled at IRQ 11
[    1.150685] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    1.152160] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    1.154491] Non-volatile memory driver v1.3
[    1.155330] Linux agpgart interface v0.103
[    1.173865] loop: module loaded
[    1.176134] scsi host0: ata_piix
[    1.177034] scsi host1: ata_piix
[    1.177651] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc080 irq 14
[    1.178648] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc088 irq 15
[    1.180343] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.181262] ehci-pci: EHCI PCI platform driver
[    1.181910] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.183041] uhci_hcd: USB Universal Host Controller Interface driver
[    1.184018] usbcore: registered new interface driver usb-storage
[    1.184906] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    1.186830] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.187574] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.189138] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[    1.191348] rtc_cmos 00:00: RTC can wake from S4
[    1.193774] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input3
[    1.196269] rtc_cmos 00:00: registered as rtc0
[    1.197262] rtc_cmos 00:00: setting system clock to 2020-08-07T00:46:44 UTC (1596761204)
[    1.198746] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram, hpet irqs
[    1.200734] i6300ESB timer 0000:00:04.0: initialized. heartbeat=30 sec (nowayout=0)
[    1.202299] device-mapper: ioctl: 4.42.0-ioctl (2020-02-27) initialised: dm-devel@redhat.com
[    1.203681] intel_pstate: CPU model not supported
[    1.204836] hid: raw HID events driver (C) Jiri Kosina
[    1.206965] usbcore: registered new interface driver usbhid
[    1.208054] usbhid: USB HID core driver
[    1.210148] Initializing XFRM netlink socket
[    1.211744] NET: Registered protocol family 10
[    1.215494] Segment Routing with IPv6
[    1.216481] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    1.217919] NET: Registered protocol family 17
[    1.218669] 9pnet: Installing 9P2000 support
[    1.220942] Key type dns_resolver registered
[    1.221784] IPI shorthand broadcast: enabled
[    1.222360] sched_clock: Marking stable (974790714, 246701357)->(1352607600, -131115529)
[    1.223874] registered taskstats version 1
[    1.224404] Loading compiled-in X.509 certificates
[    1.225739] zswap: loaded using pool zstd/zsmalloc
[    1.271317] dyndbg: total pages: 24 compaction: 0
[    1.350122] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
[    1.357252] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5
[    1.364303] BUG: sleeping function called from invalid context at mm/slab.h:567
[    1.368292] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 7, name: kworker/u2:0
[    1.371245] 4 locks held by kworker/u2:0/7:
[    1.372739]  #0: ffff888007412948 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x1f5/0x5c0
[    1.375712]  #1: ffffc90000043e58 ((work_completion)(&entry->work)){+.+.}-{0:0}, at: process_one_work+0x1f5/0x5c0
[    1.378357]  #2: ffff8880061500f0 (&shost->scan_mutex){+.+.}-{4:4}, at: __scsi_add_device+0x7d/0x120
[    1.380376]  #3: ffff8880063b40b0 (&zspage->lock){.+.+}-{3:3}, at: zs_map_object+0x7b/0x2b0
[    1.382161] CPU: 0 PID: 7 Comm: kworker/u2:0 Not tainted 5.8.0-00025-g4e76f4427bf8 #30
[    1.383739] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-2.fc32 04/01/2014
[    1.385230] Workqueue: events_unbound async_run_entry_fn
[    1.386137] Call Trace:
[    1.386587]  dump_stack+0x81/0xba
[    1.387183]  ___might_sleep.cold+0xa6/0xb7
[    1.387887]  __might_sleep+0x46/0x80
[    1.388511]  __kmalloc_track_caller+0x177/0x200
[    1.389183]  kstrdup_const+0x45/0x70
[    1.389713]  __kernfs_new_node+0x4b/0x280
[    1.390331]  ? dynamic_emit_prefix+0x1da/0x1f0
[    1.391004]  ? __dynamic_pr_debug+0x8a/0xb0
[    1.391697]  kernfs_create_dir_ns+0x44/0xc0
[    1.392366]  sysfs_create_dir_ns+0x6c/0xd0
[    1.392971]  kobject_add_internal+0x102/0x300
[    1.393627]  kobject_add+0x7e/0xb0
[    1.394112]  ? device_links_flush_sync_list+0xf0/0xf0
[    1.394805]  ? get_device+0x20/0x20
[    1.395334]  device_add+0x123/0x810
[    1.395843]  ? scsi_attach_vpd+0xfb/0x110
[    1.396412]  scsi_sysfs_add_sdev+0x160/0x290
[    1.396997]  scsi_probe_and_add_lun+0x83f/0xbe0
[    1.397659]  __scsi_add_device+0x10a/0x120
[    1.398268]  ata_scsi_scan_host+0x98/0x1d0
[    1.398811]  ? wait_woken+0xb0/0xb0
[    1.399284]  async_port_probe+0x56/0x70
[    1.399799]  async_run_entry_fn+0x37/0x150
[    1.400372]  process_one_work+0x273/0x5c0
[    1.400891]  worker_thread+0x50/0x400
[    1.401412]  kthread+0x14c/0x170
[    1.401830]  ? process_one_work+0x5c0/0x5c0
[    1.402411]  ? kthread_create_worker_on_cpu+0x60/0x60
[    1.403185]  ret_from_fork+0x22/0x30
[    1.403779]
[    1.403983] =============================
[    1.404536] [ BUG: Invalid wait context ]
[    1.405132] 5.8.0-00025-g4e76f4427bf8 #30 Tainted: G        W
[    1.406196] -----------------------------
[    1.406847] kworker/u2:0/7 is trying to lock:
[    1.407513] ffffffff82cb6b70 (iattr_mutex){+.+.}-{4:4}, at: kernfs_xattr_get+0x25/0x60
[    1.408997] other info that might help us debug this:
[    1.409780] context-{5:5}
[    1.410276] 4 locks held by kworker/u2:0/7:
[    1.410924]  #0: ffff888007412948 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x1f5/0x5c0
[    1.412649]  #1: ffffc90000043e58 ((work_completion)(&entry->work)){+.+.}-{0:0}, at: process_one_work+0x1f5/0x5c0
[    1.414238]  #2: ffff8880061500f0 (&shost->scan_mutex){+.+.}-{4:4}, at: __scsi_add_device+0x7d/0x120
[    1.415713]  #3: ffff8880063b40b0 (&zspage->lock){.+.+}-{3:3}, at: zs_map_object+0x7b/0x2b0
[    1.417024] stack backtrace:
[    1.417468] CPU: 0 PID: 7 Comm: kworker/u2:0 Tainted: G        W         5.8.0-00025-g4e76f4427bf8 #30
[    1.419019] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-2.fc32 04/01/2014
[    1.420344] Workqueue: events_unbound async_run_entry_fn
[    1.421154] Call Trace:
[    1.421578]  dump_stack+0x81/0xba
[    1.422123]  __lock_acquire.cold+0xc8/0x2d0
[    1.422709]  ? noop_count+0x10/0x10
[    1.423207]  ? __bfs+0xf4/0x210
[    1.423713]  lock_acquire+0xa2/0x3e0
[    1.424358]  ? kernfs_xattr_get+0x25/0x60
[    1.425109]  ? ___might_sleep+0x15c/0x190
[    1.425777]  __mutex_lock+0x8e/0x930
[    1.426362]  ? kernfs_xattr_get+0x25/0x60
[    1.426948]  ? __lock_acquire+0x1285/0x20e0
[    1.427623]  ? kernfs_xattr_get+0x25/0x60
[    1.428183]  mutex_lock_nested+0x16/0x20
[    1.429053]  kernfs_xattr_get+0x25/0x60
[    1.429695]  selinux_kernfs_init_security+0x5c/0x210
[    1.430475]  ? sched_clock+0x9/0x10
[    1.431012]  ? sched_clock_cpu+0x11/0xc0
[    1.432023]  security_kernfs_init_security+0x2a/0x40
[    1.432866]  __kernfs_new_node+0x1b7/0x280
[    1.433500]  ? dynamic_emit_prefix+0x1da/0x1f0
[    1.434231]  ? __dynamic_pr_debug+0x8a/0xb0
[    1.434852]  kernfs_create_dir_ns+0x44/0xc0
[    1.435586]  sysfs_create_dir_ns+0x6c/0xd0
[    1.436254]  kobject_add_internal+0x102/0x300
[    1.436970]  kobject_add+0x7e/0xb0
[    1.437515]  ? device_links_flush_sync_list+0xf0/0xf0
[    1.438445]  ? get_device+0x20/0x20
[    1.438965]  device_add+0x123/0x810
[    1.439573]  ? scsi_attach_vpd+0xfb/0x110
[    1.440377]  scsi_sysfs_add_sdev+0x160/0x290
[    1.441038]  scsi_probe_and_add_lun+0x83f/0xbe0
[    1.441981]  __scsi_add_device+0x10a/0x120
[    1.442519]  ata_scsi_scan_host+0x98/0x1d0
[    1.443125]  ? wait_woken+0xb0/0xb0
[    1.443630]  async_port_probe+0x56/0x70
[    1.444163]  async_run_entry_fn+0x37/0x150
[    1.444687]  process_one_work+0x273/0x5c0
[    1.445242]  worker_thread+0x50/0x400
[    1.445739]  kthread+0x14c/0x170
[    1.446207]  ? process_one_work+0x5c0/0x5c0
[    1.446745]  ? kthread_create_worker_on_cpu+0x60/0x60
[    1.447494]  ret_from_fork+0x22/0x30
[    1.448107] main:device_pm_add: PM: Adding info for scsi:target1:0:0
[    1.449033] kobject: 'target1:0:0' (00000000e397c75d): kobject_uevent_env
[    1.449990] kobject: 'target1:0:0' (00000000e397c75d): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0'
[    1.451753] kobject: '1:0:0:0' (00000000a54577f2): kobject_add_internal: parent: 'target1:0:0', set: 'devices'
[    1.453131] main:device_pm_add: PM: Adding info for scsi:1:0:0:0
[    1.453999] kobject: '1:0:0:0' (00000000a54577f2): kobject_uevent_env
[    1.454998] kobject: '1:0:0:0' (00000000a54577f2): fill_kobj_path: path = '/devices/pci0000:00/0000:00:01.1/ata2/host1/target1:0:0/1:0:0:0'
[    1.456836] BUG: scheduling while atomic: kworker/u2:0/7/0x00000011
[    1.457715] INFO: lockdep is turned off.
[    1.458651] Modules linked in:
[    1.459134] CPU: 0 PID: 7 Comm: kworker/u2:0 Tainted: G        W         5.8.0-00025-g4e76f4427bf8 #30
[    1.460629] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-2.fc32 04/01/2014
[    1.462015] Workqueue: events_unbound async_run_entry_fn
[    1.463068] Call Trace:
[    1.463470]  dump_stack+0x81/0xba
[    1.464030]  __schedule_bug.cold+0x5f/0x70
[    1.464812]  __schedule+0x80b/0x9a0
[    1.465477]  ? wait_for_completion_io+0x7e/0x110
[    1.466188]  schedule+0x69/0xe0
[    1.466888]  schedule_timeout+0xe0/0x120
[    1.467514]  ? __blk_mq_delay_run_hw_queue+0x16d/0x180
[    1.468363]  ? _raw_spin_unlock_irq+0x23/0x40
[    1.469057]  ? trace_hardirqs_on+0x2b/0xf0
[    1.469709]  io_schedule_timeout+0x4b/0x80
[    1.470405]  wait_for_completion_io+0xa9/0x110
[    1.471149]  blk_execute_rq+0x7f/0xb0
[    1.471748]  __scsi_execute+0x109/0x260
[    1.472426]  scsi_test_unit_ready+0x5b/0xe0
[    1.473097]  sr_probe+0x23b/0x600
[    1.473608]  ? kernfs_create_link+0x63/0xa0
[    1.474256]  really_probe+0x27b/0x410
[    1.474866]  driver_probe_device+0xe4/0x150
[    1.475633]  __device_attach_driver+0x6c/0xd0
[    1.476351]  ? driver_allows_async_probing+0x50/0x50
[    1.477091]  bus_for_each_drv+0x82/0xd0
[    1.477686]  __device_attach+0x111/0x1b0
[    1.478352]  device_initial_probe+0xe/0x10
[    1.478976]  bus_probe_device+0x9b/0xb0
[    1.479601]  device_add+0x3a8/0x810
[    1.480197]  scsi_sysfs_add_sdev+0x91/0x290
[    1.480856]  scsi_probe_and_add_lun+0x83f/0xbe0
[    1.481630]  __scsi_add_device+0x10a/0x120
[    1.482328]  ata_scsi_scan_host+0x98/0x1d0
[    1.482955]  ? wait_woken+0xb0/0xb0
[    1.483459]  async_port_probe+0x56/0x70
[    1.484023]  async_run_entry_fn+0x37/0x150
[    1.484796]  process_one_work+0x273/0x5c0
[    1.485604]  worker_thread+0x50/0x400
[    1.486303]  kthread+0x14c/0x170
[    1.486858]  ? process_one_work+0x5c0/0x5c0
[    1.487708]  ? kthread_create_worker_on_cpu+0x60/0x60
[    1.488631]  ret_from_fork+0x22/0x30
QEMU 4.2.1 monitor - type 'help' for more information

(qemu) dump-guest-memory -p dump.p
(qemu) q

[jimc@frodo build-v2]$ gdb vmlinux dump.p
GNU gdb (GDB) Fedora 9.1-5.fc32
...
Reading symbols from vmlinux...
[New LWP 1]
1271		for (fn = initcall_levels[level]; fn < initcall_levels[level+1]; fn++)
(gdb) bt

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 701d3d1fb7e7..38f7107699e9 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -172,7 +172,9 @@ static void ddebug_callsite_put(struct _ddebug *dp)
 		/* no site to unmap, or no means to restore */
 		return;
 
-	/* always unmap for now. if !pr-debug was too hard */
+	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.26.2


^ permalink raw reply related	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2020-11-25 21:23 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
     [not found] <20201125193626.2266995-1-jim.cromie@gmail.com>
2020-11-25 19:36 ` [PATCH 1/7] dyndbg: move struct _ddebug's display fields to new _ddebug_callsite Jim Cromie
2020-11-25 19:36 ` [PATCH 2/7] dyndbg: count repetition in __dyndbg_callsite fields Jim Cromie
2020-11-25 19:36 ` [PATCH 3/7] dyndbg: add some code to see alignments of linkage data Jim Cromie
2020-11-25 19:36 ` [PATCH 4/7] dyndbg: select ZPOOL,ZS_MALLOC in Kconfig.debug DYNAMIC_DEBUG_CORE Jim Cromie
2020-11-25 19:36 ` [PATCH 5/7] dyndbg: replace __dyndbg_callsite section with a zs-pool copy Jim Cromie
2020-11-25 19:36 ` [PATCH 6/7] dyndbg: add locking around zpool-add loop in zpool-init Jim Cromie
2020-11-25 19:36 ` [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites Jim Cromie
2020-11-25 20:54   ` Jason Baron
2020-11-25 21:23     ` jim.cromie
2020-08-07 20:09 [PATCH 0/7] dyndbg: WIP diet plan Jim Cromie
2020-08-07 20:09 ` [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites Jim Cromie

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).