From patchwork Wed Nov 25 19:36:20 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Cromie X-Patchwork-Id: 1345262 Return-Path: Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id D8F07C6379D for ; Wed, 25 Nov 2020 19:37:44 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 870A22063A for ; Wed, 25 Nov 2020 19:37:44 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="fN+uRnZ9" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729484AbgKYThd (ORCPT ); Wed, 25 Nov 2020 14:37:33 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:59974 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729366AbgKYTha (ORCPT ); Wed, 25 Nov 2020 14:37:30 -0500 Received: from mail-io1-xd41.google.com (mail-io1-xd41.google.com [IPv6:2607:f8b0:4864:20::d41]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5921CC0617A7; Wed, 25 Nov 2020 11:37:20 -0800 (PST) Received: by mail-io1-xd41.google.com with SMTP id t8so3273284iov.8; Wed, 25 Nov 2020 11:37:20 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=Wea6QiUzhXHIk6esfYL2NcPGJp+vK9+oW+T7p8v+MVM=; b=fN+uRnZ99+vArdZ7qGdLFv2fXyLT97QaDYrm+jZ5HKLfS57NEKy4sD5H++6zBVGUI/ D2DxrGZ/bVZuBhsZ9NnrshtE2YPL2JdWW9Wwb3NJSJVFfVtP2p70FAm/Z4Jz01+qvLcD y5YVI0m92711ZYUVnXOnmN7oJ2LjuFkJfdzq2BKPhslS5A/QNwRliB+T8aidweIXl/9Y p9FXo7s9s/ABMl6W7t7HWVzEUQu1nXStyd7zUtTRQntG3gc1H30CTgAjiFgt4gsvBRkI woyr8EsTE1aXJnd+aaMPoH6mUDR6kzKboBd8NERzJCf42yOYZNkCSWC9Tw7nRg4r0Y0b zsHA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=Wea6QiUzhXHIk6esfYL2NcPGJp+vK9+oW+T7p8v+MVM=; b=jxPhk/qqH1g8Lc79gP+Fh41iJs6UexUFKA6GLfdYpKfdFiTzOqiGqd2iaZfS0jnGEj wt36X+tldaWe58o2CJrW9Mw2MyJuQbBXbNhL/MWnDb4kWryS5NZ7onNri83pAPjryUuv tYdCTREho7ZPrCK4g1NmGicwPXV9rnCU/k6rpuacaZNqvHnx/V+H7VNOtFIWCNuOv3uD 5kehvbrD+HjzR0icT24zKIdoZZp6sKB1bE9iO5bJMuso56Mat3KaSP3IKax/JonIuXkq iEPpZ6DmDv7US7VFm/XGcU8YHQShGn2QczFQLnfSAPmBxPKBiLa6ltDyalzPRe2JDBm0 vEAg== X-Gm-Message-State: AOAM530ZIC95NoORtd+FUuFVe9AJJOpEyxtxPJyF154Dv8V4aWLwKnv+ 0aatbv/sNyh/Y7JV5mu/LmE= X-Google-Smtp-Source: ABdhPJy/fLRTYIcRihiDuFlvRFnWseq05Er1A0QQbGgD++9qfoiAQHZHYX7mL+hj2EJ3K6nnjEtEhg== X-Received: by 2002:a02:3846:: with SMTP id v6mr4986390jae.8.1606333039581; Wed, 25 Nov 2020 11:37:19 -0800 (PST) Received: from frodo.mearth (c-24-9-77-57.hsd1.co.comcast.net. [24.9.77.57]) by smtp.googlemail.com with ESMTPSA id f8sm1435548ioc.24.2020.11.25.11.37.18 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 25 Nov 2020 11:37:19 -0800 (PST) From: Jim Cromie To: linux-mm@kvack.org Cc: gregkh@linuxfoundation.org, linux@rasmusvillemoes.dk, Jim Cromie , Arnd Bergmann , Jason Baron , linux-arch@vger.kernel.org, linux-kernel@vger.kernel.org Subject: [PATCH 1/7] dyndbg: move struct _ddebug's display fields to new _ddebug_callsite Date: Wed, 25 Nov 2020 12:36:20 -0700 Message-Id: <20201125193626.2266995-2-jim.cromie@gmail.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20201125193626.2266995-1-jim.cromie@gmail.com> References: <20201125193626.2266995-1-jim.cromie@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 --- 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), " "); 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') { From patchwork Wed Nov 25 19:36:21 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Cromie X-Patchwork-Id: 1345264 Return-Path: Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 0F5E9C64E7C for ; Wed, 25 Nov 2020 19:37:45 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id C004A2075A for ; Wed, 25 Nov 2020 19:37:44 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="Xf+OemJs" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729511AbgKYThf (ORCPT ); Wed, 25 Nov 2020 14:37:35 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:59980 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729386AbgKYThb (ORCPT ); Wed, 25 Nov 2020 14:37:31 -0500 Received: from mail-io1-xd43.google.com (mail-io1-xd43.google.com [IPv6:2607:f8b0:4864:20::d43]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5CF2FC061A4F for ; Wed, 25 Nov 2020 11:37:21 -0800 (PST) Received: by mail-io1-xd43.google.com with SMTP id m9so3252534iox.10 for ; Wed, 25 Nov 2020 11:37:21 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=hGMS/KmYTKfdKa5mao6KQL50Vv4NG7QbaRbgc4LfYSo=; b=Xf+OemJsMg096pz+jboLsU3wkp8YxQwP58ep5om6NXA3u5h6j2Mp6Beln4U+QUxA/v TKUyjf5VCvuteIL3AANR763snEt48Ae3fki1RkgFeTTKEPJcBb2szvsPZXFlMcAiaXBy a29jJ4NhD+MrtOAP0KdYtx+0dWQJ1E0RV7yDz5rAU1Q0XfDZv05E05v0GukflvK9L8mn tNb3nwUkKaJvtpD1dPBSIK4n5iguCP+fyGAwgqwn7YFqx3DZiZ61TeUI/+u6J7U8J/ii dO/Lv0FKHY8Dty7q43ktHv2n4aXQL8S2+eXvC2WdHPjYTwzXcgaT9+bVNmaubDZh7HH6 rkvw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=hGMS/KmYTKfdKa5mao6KQL50Vv4NG7QbaRbgc4LfYSo=; b=DLoBbzCNsVoHWB8KFimIsrbRU2P5ydiXk+aagpUnclbr+oDDwCYHUk4Zy1vPSOMGJb bUUrnFC36Bh/8xVXrkrTepFjR7om4STPnUoROYGWsz5x//YT+OuswtrMi5c+MQfcIeuW LeBuTtslDAOChKn6U41AMPnyIRS68EQbWxNpKKK8xWgXRj3kNP9iEhhUfEdPjaHvEN+z sVmkTki7Su0nC+a98vEuIXbvOf8GxFyU9iupYeTZLEjPR+s+uiNmRqhorvw0mW+otYZT 4uDGfMFpMeD89HDdkWYtSiGRaeFHkge7HBGxLbtT2KLrbND+AC3UiEE4wt8F6ojNaqpP gahA== X-Gm-Message-State: AOAM531iqnMl5gM0qSv6TLsupC5uR3RIgHiSic80txEgRaphRlGF3DFX +xnrUpzuniMKYibqZv5TRec= X-Google-Smtp-Source: ABdhPJxkqvqKjeWkSVtPjU2cJU82WEDRmYodw7vEJZXpubZ16DbnWzShqB9wm/1daFMLICozbhkP4A== X-Received: by 2002:a6b:c3c5:: with SMTP id t188mr3929469iof.209.1606333040740; Wed, 25 Nov 2020 11:37:20 -0800 (PST) Received: from frodo.mearth (c-24-9-77-57.hsd1.co.comcast.net. [24.9.77.57]) by smtp.googlemail.com with ESMTPSA id f8sm1435548ioc.24.2020.11.25.11.37.19 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 25 Nov 2020 11:37:20 -0800 (PST) From: Jim Cromie To: linux-mm@kvack.org Cc: gregkh@linuxfoundation.org, linux@rasmusvillemoes.dk, Jim Cromie , Jason Baron , linux-kernel@vger.kernel.org Subject: [PATCH 2/7] dyndbg: count repetition in __dyndbg_callsite fields. Date: Wed, 25 Nov 2020 12:36:21 -0700 Message-Id: <20201125193626.2266995-3-jim.cromie@gmail.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20201125193626.2266995-1-jim.cromie@gmail.com> References: <20201125193626.2266995-1-jim.cromie@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 --- 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"); From patchwork Wed Nov 25 19:36:22 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Cromie X-Patchwork-Id: 1345259 Return-Path: Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 775A5C6379D for ; Wed, 25 Nov 2020 19:37:24 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 105122075A for ; Wed, 25 Nov 2020 19:37:24 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="VfNp8/1Q" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729304AbgKYThX (ORCPT ); Wed, 25 Nov 2020 14:37:23 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:59986 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727041AbgKYThW (ORCPT ); Wed, 25 Nov 2020 14:37:22 -0500 Received: from mail-io1-xd33.google.com (mail-io1-xd33.google.com [IPv6:2607:f8b0:4864:20::d33]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 7E07EC061A51 for ; Wed, 25 Nov 2020 11:37:22 -0800 (PST) Received: by mail-io1-xd33.google.com with SMTP id r9so3286139ioo.7 for ; Wed, 25 Nov 2020 11:37:22 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=0KO/M/u0SKyAHiDpRJL18ynfwCIfU26Y/ceTy3bOazY=; b=VfNp8/1QKA/Nsh0aFCVcwN1562EED1Jd2vd71rfujQQeoL5LCoATCM/VgE8sCyaGfg ZtiRD+8DK8eBG2O/8GKjCH7qz63Lw0OGUHNihV+c9AsGOIxTFK7t60TLY5qD61vky1R6 wwjsw2pUiecEeaJmg6tjo3FtR5hP3NtwZO78RQYrlpotqkGtBIMbVz8Pa6kDxxUSM/MF 696JIsVhJHqONalD5rWOqJzskVfW6efhU9soy4C4WpB3ZDlgkTq58nJnSJW6yJR/HGIl 2gw3BZcHGZxgPF9HkhXPbHzYXsA55JU/b/6gZExoATdGPSU/Z9wued0PmZMsQqpXBtWS ZbnQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=0KO/M/u0SKyAHiDpRJL18ynfwCIfU26Y/ceTy3bOazY=; b=lIt+VgTSzsdNUl3jbLvjR2mXaxlYPJ0pcoOFl4nPuQL8g0rv8IRuixkk/4y8qD2SeV XMEcdgJaTIo/CoJ+bNi3mankW8+1i0qsFm4zC0ovB6TmjP73rP3Cu6jvDkp/oRbgnDAU imJl78YKyp3CYUIVozo87YYXFl4A00hgyJjEPSW2X1yNsBo27vE/t+mU7HwrrG/13ejm BrJ/M2T1U7zG49hlB2efWeDBpLPrWHxLBuvIeNu1R+/nD2KoWHO14PWK6rOJEauPHbJb 7ViePSgGgW8Uu3pQwzwkUjBeUDZZftJLUGkiYUjmUVcoefAqqYoHIJ+P+vvCk0yGwtaA vFdg== X-Gm-Message-State: AOAM5325l3NzCKcfzfwk+kSeJDqxKadPd7r6wmkiErcAWUV2J1UN3Scz 8YEkm7MpjexiP4V6rREOeuo= X-Google-Smtp-Source: ABdhPJxerGLSlABi7avZmWHb6tL0Sa17Gu8SHBI7l4xXs/pdWZOr7Zg3dgBc1LVoiYuV/2Z9rUYrIw== X-Received: by 2002:a6b:6418:: with SMTP id t24mr3908358iog.145.1606333041808; Wed, 25 Nov 2020 11:37:21 -0800 (PST) Received: from frodo.mearth (c-24-9-77-57.hsd1.co.comcast.net. [24.9.77.57]) by smtp.googlemail.com with ESMTPSA id f8sm1435548ioc.24.2020.11.25.11.37.20 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 25 Nov 2020 11:37:21 -0800 (PST) From: Jim Cromie To: linux-mm@kvack.org Cc: gregkh@linuxfoundation.org, linux@rasmusvillemoes.dk, Jim Cromie , Jason Baron , linux-kernel@vger.kernel.org Subject: [PATCH 3/7] dyndbg: add some code to see alignments of linkage data Date: Wed, 25 Nov 2020 12:36:22 -0700 Message-Id: <20201125193626.2266995-4-jim.cromie@gmail.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20201125193626.2266995-1-jim.cromie@gmail.com> References: <20201125193626.2266995-1-jim.cromie@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 --- 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"); From patchwork Wed Nov 25 19:36:23 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Cromie X-Patchwork-Id: 1345265 Return-Path: Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 9FC18C64E8A for ; Wed, 25 Nov 2020 19:37:45 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 445E02075A for ; Wed, 25 Nov 2020 19:37:45 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="Kumbp0V4" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729549AbgKYThk (ORCPT ); Wed, 25 Nov 2020 14:37:40 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:59994 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729399AbgKYThb (ORCPT ); Wed, 25 Nov 2020 14:37:31 -0500 Received: from mail-io1-xd42.google.com (mail-io1-xd42.google.com [IPv6:2607:f8b0:4864:20::d42]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id F297AC061A51 for ; Wed, 25 Nov 2020 11:37:24 -0800 (PST) Received: by mail-io1-xd42.google.com with SMTP id m9so3252707iox.10 for ; Wed, 25 Nov 2020 11:37:24 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=kvaPSRJY7Wr+XTGZOilxIQoBZMtArG1tAWxocteVnYY=; b=Kumbp0V4EzoxbFOpFkMzx33Q0lHEl7NAKxIz7UZ9Zpu6hd8NylGG+hsoBDpFjuMYA0 CJ6sXrCJVglW8hD3wC+p7KjSIiMgVKtI7b3Qhxgo2CL2oEM5kGLhDsTeqUkE/mYxtxVF H5LzkuE3obnUYi4yX5YYqknyVPBxzJyxPS9wW6PhRjZBup7qFqg1QLMLUgJVkf2WRoS/ p5fNrwYcz+cvSPoDFHPXzt4YxpEO/xltiX2ICpMOwcahS9XHrv8QOsYJoGrK5DkUB3RI V1LZ136Kby0M7hb4g/xG5+ifqMcjsnDPzvpRwSRPhWwVygYbxFtB6wz7e+8cz5R8XgNq HkBQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=kvaPSRJY7Wr+XTGZOilxIQoBZMtArG1tAWxocteVnYY=; b=Y5124Gf1mxoital2TxR12dZX5T49uDlnRYI6Q6oN0zf8V1DW8euZOwbWheFsouJJi3 RXJwap4GxB9sfRalNbfUFBhTHwr+B3eIC7WhSo2eAc7zd4qwpNqnRLdbIuc0dOUX2iTZ 2hE+KaXoN9ZUyql1pwdfChYNbXjtdcqN1kRRyz+NCJrf5O3k7d8Um8Gsjwa/wX5Yv6xP +wlAFpoTv1AHdZPDAcJpH6hZ2wVD/gx30PYLtMEluwht8tt5qjgUWplAKHnHThWr5fIg zYfYlDSx/9RzAyb8Z/wgTRC7eMS8iwFvQgATgnY8CDaxjaTluWCC3+96t+bLRgGkuT00 chxg== X-Gm-Message-State: AOAM531HVgEY5x7K2kkfxaY/TBBNx/wb/wHmM+lPHMcgFDZg2bmxzH4n qxSSy9czKLly6PVpQS7pzRWD0zxJSUNVVg== X-Google-Smtp-Source: ABdhPJzvhTups6o4RaesshRE+4F+KrQk7RXYpT05c6z88d9eM+S/aWGJQpGrQ5JTCPqf2suE4OVe0Q== X-Received: by 2002:a02:82cb:: with SMTP id u11mr4844619jag.0.1606333044377; Wed, 25 Nov 2020 11:37:24 -0800 (PST) Received: from frodo.mearth (c-24-9-77-57.hsd1.co.comcast.net. [24.9.77.57]) by smtp.googlemail.com with ESMTPSA id f8sm1435548ioc.24.2020.11.25.11.37.23 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 25 Nov 2020 11:37:23 -0800 (PST) From: Jim Cromie To: linux-mm@kvack.org Cc: gregkh@linuxfoundation.org, linux@rasmusvillemoes.dk, Jim Cromie , kernel test robot , Andrew Morton , Randy Dunlap , Changbin Du , Masahiro Yamada , "peterz@infradead.org" , Peter Enderborg , Krzysztof Kozlowski , linux-kernel@vger.kernel.org Subject: [PATCH 4/7] dyndbg: select ZPOOL,ZS_MALLOC in Kconfig.debug DYNAMIC_DEBUG_CORE Date: Wed, 25 Nov 2020 12:36:23 -0700 Message-Id: <20201125193626.2266995-5-jim.cromie@gmail.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20201125193626.2266995-1-jim.cromie@gmail.com> References: <20201125193626.2266995-1-jim.cromie@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 Signed-off-by: Jim Cromie --- 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 From patchwork Wed Nov 25 19:36:24 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Cromie X-Patchwork-Id: 1345261 Return-Path: Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id D63B8C56202 for ; Wed, 25 Nov 2020 19:37:43 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 6D2112063A for ; Wed, 25 Nov 2020 19:37:43 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="Y91cU2Hn" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729331AbgKYTh1 (ORCPT ); Wed, 25 Nov 2020 14:37:27 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:59996 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727041AbgKYTh0 (ORCPT ); Wed, 25 Nov 2020 14:37:26 -0500 Received: from mail-il1-x141.google.com (mail-il1-x141.google.com [IPv6:2607:f8b0:4864:20::141]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5E13AC061A52 for ; Wed, 25 Nov 2020 11:37:26 -0800 (PST) Received: by mail-il1-x141.google.com with SMTP id a19so3202558ilm.3 for ; Wed, 25 Nov 2020 11:37:26 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=O86fXQJwZF3Z+lAQ2ys/l1etmQM9sjCYa656aScxsN0=; b=Y91cU2HnzlV3IyUacvWUcd0DHPYVMQWRzlk1esFdADVkLbaYHZ97fDXOcljKMgVr27 RZxMckKMtiM6tjkKW+0sTfdMca7Tg89NkrBpHM5fniRhO8OH3BJ3e6JMbuFQUz5+sg94 +tP1AStwaiMz1rb5C+n+r9301TE2Xz/7Pjh9iRsyrYE9g8s5oFRgpLCLHpGYKminYEza bxS1XvSDnxcd4hzmqo+qyfNEfXbn2oASIQx9X+8BwZBsAmnCiCXOWWCxybabYdA9euAs Pz8OWVwP77WoDK5QM0nD8fotO3X10VMaUC6u4oY6wFT3BSkUSo9hryJhqnvekRyv9NkC vnTw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=O86fXQJwZF3Z+lAQ2ys/l1etmQM9sjCYa656aScxsN0=; b=Q2vn6a6rGp4v6+DADcymSrEOWKVQqRaGrqNQwUXUC96PZn3aEvrM5AZDJJ+t8doysR RbdBGkyKYReeSUoWQanDR54rTsCOXCWTT4lfylFDXh7q9xp7FFUVyyXRIw6woHwaa7yz izRFloyQvf/PPXYxCCdgTVmv7WHYVy2K7R2zhWw6u9R6A1fhIHrqayCQD70lQHtNOEe/ Up0djZAbzaK1SLpe5gS0lyd4TiZBKWsygQ0py/C2O2c6UUzr4cb9OFEYIVOur2U3TftI FIUsq/yWYoYwXhhr5fAKHdYAiCsMnaqTNSIfGR0b+WYZCm6AHIf6XY5MeipYZmgkEoeM myhg== X-Gm-Message-State: AOAM532bC3HgwdqAHZ5hatjX+1FiULg//R2i7qMGEd31YwQ0f3Sq/5+6 fVdnyFLYGiFDJP9WdsvCTIU= X-Google-Smtp-Source: ABdhPJy9PEplra9k8ZumVveJR4DUeZ/krWOQkRZfKMvo4oJ9kcB2vkUA/M+WbmR42jeixgC5zdJIkw== X-Received: by 2002:a92:d03:: with SMTP id 3mr4568592iln.197.1606333045518; Wed, 25 Nov 2020 11:37:25 -0800 (PST) Received: from frodo.mearth (c-24-9-77-57.hsd1.co.comcast.net. [24.9.77.57]) by smtp.googlemail.com with ESMTPSA id f8sm1435548ioc.24.2020.11.25.11.37.24 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 25 Nov 2020 11:37:25 -0800 (PST) From: Jim Cromie To: linux-mm@kvack.org Cc: gregkh@linuxfoundation.org, linux@rasmusvillemoes.dk, Jim Cromie , Jason Baron , linux-kernel@vger.kernel.org Subject: [PATCH 5/7] dyndbg: replace __dyndbg_callsite section with a zs-pool copy. Date: Wed, 25 Nov 2020 12:36:24 -0700 Message-Id: <20201125193626.2266995-6-jim.cromie@gmail.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20201125193626.2266995-1-jim.cromie@gmail.com> References: <20201125193626.2266995-1-jim.cromie@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 --- 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 #include #include +#include #include @@ -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), " "); @@ -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) From patchwork Wed Nov 25 19:36:25 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Cromie X-Patchwork-Id: 1345260 Return-Path: Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 1AF56C63777 for ; Wed, 25 Nov 2020 19:37:44 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id BAA962075A for ; Wed, 25 Nov 2020 19:37:43 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="b8ECt+Qn" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729361AbgKYTh2 (ORCPT ); Wed, 25 Nov 2020 14:37:28 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:60002 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727041AbgKYTh1 (ORCPT ); Wed, 25 Nov 2020 14:37:27 -0500 Received: from mail-io1-xd41.google.com (mail-io1-xd41.google.com [IPv6:2607:f8b0:4864:20::d41]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 67968C061A52 for ; Wed, 25 Nov 2020 11:37:27 -0800 (PST) Received: by mail-io1-xd41.google.com with SMTP id r9so3286325ioo.7 for ; Wed, 25 Nov 2020 11:37:27 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=ZLPfmI/xJGGGJxd0CmpcCFxQgQrAkx7EEyyWSE1b3PU=; b=b8ECt+QnI1AYyGfspPRuFOAbuoZGbcEGUClKgcZik0b07PscmuryYvVcmnvlblN6SN nl4agS7v1ajmG5Q3oz7je+sHHEW6IpvF3lFp2lqDnnxAaTu8rNitFkoTS/MoCmnzKr3w pJcQiDyuO8x3s3rm3ytST+mcCq6RY2iClincb4SSSCr39ODsH+SroZ47EJD/qRwl8yqk bkZSxZ9CUp8OmFeswwoFRAihxulhF/TWeyglOaJD84ZY7t7Lod4VzRJoNXamsPXpopIM B1hXCDHQXUSFBr36ls2euoBQpt/aV0rqRNpYDf6g7re3WeEo8YjF1ODDvFLkyaW6kzvy nzWw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=ZLPfmI/xJGGGJxd0CmpcCFxQgQrAkx7EEyyWSE1b3PU=; b=iLX+6AJjOtH6DBP/g2s8d3nWMqELy54JNOjYa244g+PRUWHnd+mfkqi4jWCoNANsfd zs3dffH/AD09L1xH0V3wCrtaxmzsp2dbDGy/nz8D+vhHxduBdnwwFNSQgPkQ9XGA4oGo pEjhqOnYrVoxJcHcmw59b9MVSXcvFxD/dgrq9bi1lOl62qF995yCKoNvnn0UEZOLtedF 3uXJ0JzL8L2kZ5c3LKD+OpAnfQWJE0G/IWumATeYC0bb0+7RNVnVcRwdGPMUmaqqm925 dvyNgXkeLvSMbBcz/1JJP/hF2EgK4Leb6owXPxc6TiUag8lDoqhNO5xXXUc3OV7YWTmZ q3Og== X-Gm-Message-State: AOAM533J6sg0Zt1tP/h3uHYqYmdzh4kGoCgyp8r+5BlkwrxsD31Paf8/ Y5tRQZSDwTZy3l1/In9Acy8= X-Google-Smtp-Source: ABdhPJxNEvPVBjizk2xNlBVx4Wnkr/1JCC/ssyZuJ7uPIZjKAM49kAbHuL+BrLgWJvcve7oCItgWEg== X-Received: by 2002:a02:1007:: with SMTP id 7mr3626403jay.73.1606333046791; Wed, 25 Nov 2020 11:37:26 -0800 (PST) Received: from frodo.mearth (c-24-9-77-57.hsd1.co.comcast.net. [24.9.77.57]) by smtp.googlemail.com with ESMTPSA id f8sm1435548ioc.24.2020.11.25.11.37.25 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 25 Nov 2020 11:37:26 -0800 (PST) From: Jim Cromie To: linux-mm@kvack.org Cc: gregkh@linuxfoundation.org, linux@rasmusvillemoes.dk, Jim Cromie , Jason Baron , linux-kernel@vger.kernel.org Subject: [PATCH 6/7] dyndbg: add locking around zpool-add loop in zpool-init Date: Wed, 25 Nov 2020 12:36:25 -0700 Message-Id: <20201125193626.2266995-7-jim.cromie@gmail.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20201125193626.2266995-1-jim.cromie@gmail.com> References: <20201125193626.2266995-1-jim.cromie@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 --- 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), From patchwork Wed Nov 25 19:36:26 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Cromie X-Patchwork-Id: 1345263 Return-Path: Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id A8504C64E7A for ; Wed, 25 Nov 2020 19:37:44 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 3F6152075A for ; Wed, 25 Nov 2020 19:37:44 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="J1GNI6rz" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729454AbgKYThd (ORCPT ); Wed, 25 Nov 2020 14:37:33 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:60010 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729363AbgKYTh3 (ORCPT ); Wed, 25 Nov 2020 14:37:29 -0500 Received: from mail-io1-xd42.google.com (mail-io1-xd42.google.com [IPv6:2607:f8b0:4864:20::d42]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 730E0C061A52 for ; Wed, 25 Nov 2020 11:37:29 -0800 (PST) Received: by mail-io1-xd42.google.com with SMTP id d17so3278278ion.4 for ; Wed, 25 Nov 2020 11:37:29 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=iGy4dxZbAp2a5oP5xFtZlRNlsWuz4p/YAQO24g1CZik=; b=J1GNI6rznOJEgJuQdI4Jgo57A2k6MoPXMSztaG5eGC08v+nzSxB/yV8tyhX/8gBZg0 Xz0vam9QvgejpBjRuZkcmlsUNEQkIEXn+XnXjSjUf79fz43P4L/szRTy165R+pD+Krru Qc52vlEmpyct7QVOu2F1ZUD68RkKIcC3QllmGpkfb3K/ch39HTdFycHTxY24koa+jaXo jDT8sSmOAEfH86K+XXCR/k5b3/UxZ0dzlENKvEeVsbez25Z6sUrs/BukRAiXJCmfwUO6 udg4+Zdp59K3EQ4k/xx2S9ERNeaRW61ASE1jr0w6N6dLTMUOnAjaYxsB8WOph22HnQ+q cZyQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=iGy4dxZbAp2a5oP5xFtZlRNlsWuz4p/YAQO24g1CZik=; b=eNMtYrJvewfYWTL2GmaSIVWF2zu9/7I/riPS7O5tByVsgrRWcL5kMct5DQMVckZ6jc wWh1/La63zHa6IV3gWNPU4asY+mODy4xmXJHciMQ8Mv5HsvcPd8Cs5HdQwciRqiuCKm4 EvBpbAUMfaC861qk3SxikI66sIPzNRRf8kbzAltKbS+38v+AJ8rBy75EosIaHEpOyslP ieqG9eu8crz+7asItN6Hj1Gxf6BLzfTqb4fizwKbOv1tSEG3nEsQWDDhj6i1b29p1tNK eiq3Ensk8mS3vrlBTlsSB83m0XxnvPgnWFvq5uSSCdd9OsU0BezFS4iSuFMcSWbLlDaS wWhQ== X-Gm-Message-State: AOAM531xzoA9feI13gf/+11HnyMPzyxjNGeyZe9sW78wvIHF27ntiKoD r47PFXGXa+QtNz5rsCOUp6+2dTsQFOgQfw== X-Google-Smtp-Source: ABdhPJxMkb65NRt06oEdzVn3OEnlsb98R4a0Hh7iFNLi5At9eRvxaXJY6N8z7gBd9DFnHXfgLLVh4w== X-Received: by 2002:a5e:dc06:: with SMTP id b6mr3816709iok.121.1606333048483; Wed, 25 Nov 2020 11:37:28 -0800 (PST) Received: from frodo.mearth (c-24-9-77-57.hsd1.co.comcast.net. [24.9.77.57]) by smtp.googlemail.com with ESMTPSA id f8sm1435548ioc.24.2020.11.25.11.37.27 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 25 Nov 2020 11:37:27 -0800 (PST) From: Jim Cromie To: linux-mm@kvack.org Cc: gregkh@linuxfoundation.org, linux@rasmusvillemoes.dk, Jim Cromie , Jason Baron , linux-kernel@vger.kernel.org Subject: [PATCH 7/7] dyndbg: enable 'cache' of active pr_debug callsites Date: Wed, 25 Nov 2020 12:36:26 -0700 Message-Id: <20201125193626.2266995-8-jim.cromie@gmail.com> X-Mailer: git-send-email 2.28.0 In-Reply-To: <20201125193626.2266995-1-jim.cromie@gmail.com> References: <20201125193626.2266995-1-jim.cromie@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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): [] irqentry_exit+0x35/0x80 [ 1.600046] hardirqs last disabled at (1862448): [] sysvec_apic_timer_interrupt+0x10/0xb0 [ 1.601801] softirqs last enabled at (1862354): [] asm_call_irq_on_stack+0x12/0x20 [ 1.603419] softirqs last disabled at (1862345): [] 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: '' [ 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): [] irqentry_exit+0x35/0x80 [ 1.725695] hardirqs last disabled at (1862448): [] sysvec_apic_timer_interrupt+0x10/0xb0 [ 1.727307] softirqs last enabled at (1862354): [] asm_call_irq_on_stack+0x12/0x20 [ 1.728795] softirqs last disabled at (1862345): [] 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: '' [ 1.763972] kobject: 'slaves' (00000000b2ff8eb3): kobject_add_internal: parent: 'sr0', set: '' [ 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: '' [ 1.770551] kobject: 'mq' (0000000001f3c10f): kobject_add_internal: parent: 'sr0', set: '' [ 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: '' [ 1.776604] kobject: 'cpu0' (000000007c3dee23): kobject_add_internal: parent: '0', set: '' [ 1.778217] kobject: 'iosched' (000000003e5ac6f7): kobject_add_internal: parent: 'queue', set: '' [ 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 --- 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; }