[src/trunk]: src/sys/kern kern: Sprinkle biglock-slippage assertions.

[riastradh <riastradh%NetBSD.org@localhost>]

details:   https://anonhg.NetBSD.org/src/rev/b099167deca3
branches:  trunk
changeset: 364576:b099167deca3
user:      riastradh <riastradh%NetBSD.org@localhost>
date:      Wed Mar 30 10:34:14 2022 +0000

description:
kern: Sprinkle biglock-slippage assertions.

We seem to have a poltergeist that occasionally messes with the
biglock depth, but it's very hard to reproduce and only manifests as
some other CPU spinning out on the kernel lock which is no good for
diagnostics.

diffstat:

 sys/kern/kern_softint.c |  12 ++++++++++--
 sys/kern/kern_timeout.c |  10 +++++++---
 sys/kern/vfs_bio.c      |   9 +++++++--
 3 files changed, 24 insertions(+), 7 deletions(-)

diffs (130 lines):

diff -r dfa91f96b0d4 -r b099167deca3 sys/kern/kern_softint.c
--- a/sys/kern/kern_softint.c   Wed Mar 30 08:26:45 2022 +0000
+++ b/sys/kern/kern_softint.c   Wed Mar 30 10:34:14 2022 +0000
@@ -1,4 +1,4 @@
-/*     $NetBSD: kern_softint.c,v 1.67 2021/12/05 04:56:40 msaitoh Exp $        */
+/*     $NetBSD: kern_softint.c,v 1.68 2022/03/30 10:34:14 riastradh Exp $      */
 
 /*-
  * Copyright (c) 2007, 2008, 2019, 2020 The NetBSD Foundation, Inc.
@@ -170,7 +170,7 @@
  */
 
 #include <sys/cdefs.h>
-__KERNEL_RCSID(0, "$NetBSD: kern_softint.c,v 1.67 2021/12/05 04:56:40 msaitoh Exp $");
+__KERNEL_RCSID(0, "$NetBSD: kern_softint.c,v 1.68 2022/03/30 10:34:14 riastradh Exp $");
 
 #include <sys/param.h>
 #include <sys/proc.h>
@@ -536,6 +536,7 @@
 {
        softint_t *si = l->l_private;
        softhand_t *sh;
+       int locks;
 
        KASSERT(si->si_lwp == curlwp);
        KASSERT(si->si_cpu == curcpu());
@@ -560,6 +561,9 @@
                sh->sh_flags ^= SOFTINT_PENDING;
                splx(s);
 
+               /* Record the kernel lock depth for diagnostics.  */
+               locks = curcpu()->ci_biglock_count;
+
                /* Run the handler. */
                if (__predict_true((sh->sh_flags & SOFTINT_MPSAFE) != 0)) {
                        (*sh->sh_func)(sh->sh_arg);
@@ -576,6 +580,10 @@
                /* Diagnostic: check that psrefs have not leaked. */
                KASSERTMSG(l->l_psrefs == 0, "%s: l_psrefs=%d, sh_func=%p\n",
                    __func__, l->l_psrefs, sh->sh_func);
+               /* Diagnostic: check that biglocks have not leaked. */
+               KASSERTMSG(locks == curcpu()->ci_biglock_count,
+                   "%s: sh_func=%p slipped %d->%d biglocks",
+                   __func__, sh->sh_func, locks, curcpu()->ci_biglock_count);
 
                (void)splhigh();
        }
diff -r dfa91f96b0d4 -r b099167deca3 sys/kern/kern_timeout.c
--- a/sys/kern/kern_timeout.c   Wed Mar 30 08:26:45 2022 +0000
+++ b/sys/kern/kern_timeout.c   Wed Mar 30 10:34:14 2022 +0000
@@ -1,4 +1,4 @@
-/*     $NetBSD: kern_timeout.c,v 1.66 2020/06/27 01:26:32 rin Exp $    */
+/*     $NetBSD: kern_timeout.c,v 1.67 2022/03/30 10:34:14 riastradh Exp $      */
 
 /*-
  * Copyright (c) 2003, 2006, 2007, 2008, 2009, 2019 The NetBSD Foundation, Inc.
@@ -59,7 +59,7 @@
  */
 
 #include <sys/cdefs.h>
-__KERNEL_RCSID(0, "$NetBSD: kern_timeout.c,v 1.66 2020/06/27 01:26:32 rin Exp $");
+__KERNEL_RCSID(0, "$NetBSD: kern_timeout.c,v 1.67 2022/03/30 10:34:14 riastradh Exp $");
 
 /*
  * Timeouts are kept in a hierarchical timing wheel.  The c_time is the
@@ -740,7 +740,7 @@
        struct callout_cpu *cc;
        void (*func)(void *);
        void *arg;
-       int mpsafe, count, ticks, delta;
+       int mpsafe, count, ticks, delta, locks;
        lwp_t *l;
 
        l = curlwp;
@@ -776,6 +776,7 @@
                cc->cc_active = c;
 
                mutex_spin_exit(cc->cc_lock);
+               locks = curcpu()->ci_biglock_count;
                KASSERT(func != NULL);
                if (__predict_false(!mpsafe)) {
                        KERNEL_LOCK(1, NULL);
@@ -783,6 +784,9 @@
                        KERNEL_UNLOCK_ONE(NULL);
                } else
                        (*func)(arg);
+               KASSERTMSG(locks == curcpu()->ci_biglock_count,
+                   "callout %p func %p slipped %d->%d biglocks",
+                   c, func, locks, curcpu()->ci_biglock_count);
                mutex_spin_enter(cc->cc_lock);
 
                /*
diff -r dfa91f96b0d4 -r b099167deca3 sys/kern/vfs_bio.c
--- a/sys/kern/vfs_bio.c        Wed Mar 30 08:26:45 2022 +0000
+++ b/sys/kern/vfs_bio.c        Wed Mar 30 10:34:14 2022 +0000
@@ -1,4 +1,4 @@
-/*     $NetBSD: vfs_bio.c,v 1.301 2021/07/25 06:06:40 simonb Exp $     */
+/*     $NetBSD: vfs_bio.c,v 1.302 2022/03/30 10:34:14 riastradh Exp $  */
 
 /*-
  * Copyright (c) 2007, 2008, 2009, 2019, 2020 The NetBSD Foundation, Inc.
@@ -123,7 +123,7 @@
  */
 
 #include <sys/cdefs.h>
-__KERNEL_RCSID(0, "$NetBSD: vfs_bio.c,v 1.301 2021/07/25 06:06:40 simonb Exp $");
+__KERNEL_RCSID(0, "$NetBSD: vfs_bio.c,v 1.302 2022/03/30 10:34:14 riastradh Exp $");
 
 #ifdef _KERNEL_OPT
 #include "opt_bufcache.h"
@@ -1673,6 +1673,7 @@
 biodone2(buf_t *bp)
 {
        void (*callout)(buf_t *);
+       int locks;
 
        SDT_PROBE1(io, kernel, ,done, bp);
 
@@ -1699,7 +1700,11 @@
                KASSERT(!cv_has_waiters(&bp->b_done));
                bp->b_iodone = NULL;
                mutex_exit(bp->b_objlock);
+               locks = curcpu()->ci_biglock_count;
                (*callout)(bp);
+               KASSERTMSG(locks == curcpu()->ci_biglock_count,
+                   "buf %p b_iodone %p slipped %d->%d biglocks",
+                   bp, callout, locks, curcpu()->ci_biglock_count);
        } else if (ISSET(bp->b_flags, B_ASYNC)) {
                /* If async, release. */
                BIOHIST_LOG(biohist, "async", 0, 0, 0, 0);