Can you please try running with the attached patch and share the
warnings it produces? Should give slightly more information.
>From b6f360d9b1fdc418105fcc41b41f1206ca04334d Mon Sep 17 00:00:00 2001
From: Taylor R Campbell <[email protected]>
Date: Wed, 26 Jul 2023 01:36:28 +0000
Subject: [PATCH] WIP: attribution for l_stime updates
---
sys/kern/init_main.c | 4 +++-
sys/kern/kern_idle.c | 4 +++-
sys/kern/kern_softint.c | 4 +++-
sys/kern/kern_synch.c | 53 ++++++++++++++++++++++++++++++++++++++++-
4 files changed, 61 insertions(+), 4 deletions(-)
diff --git a/sys/kern/init_main.c b/sys/kern/init_main.c
index 1d2dbd742fed..bc43f7dd18e9 100644
--- a/sys/kern/init_main.c
+++ b/sys/kern/init_main.c
@@ -254,6 +254,8 @@ static void configure2(void);
static void configure3(void);
void main(void);
+void updatestime(struct lwp *, const struct bintime *); /* XXX */
+
/*
* System startup; initialize the world, create process 0, mount root
* filesystem, and fork to create init and pagedaemon. Most of the
@@ -728,7 +730,7 @@ main(void)
mutex_exit(p->p_lock);
}
mutex_exit(&proc_lock);
- binuptime(&curlwp->l_stime);
+ updatestime(curlwp, NULL);
for (CPU_INFO_FOREACH(cii, ci)) {
ci->ci_schedstate.spc_lastmod = time_second;
diff --git a/sys/kern/kern_idle.c b/sys/kern/kern_idle.c
index dc1fc194f491..b5c6f7a4d90e 100644
--- a/sys/kern/kern_idle.c
+++ b/sys/kern/kern_idle.c
@@ -41,6 +41,8 @@ __KERNEL_RCSID(0, "$NetBSD: kern_idle.c,v 1.34 2020/09/05
16:30:12 riastradh Exp
#include <uvm/uvm.h> /* uvm_idle */
+void updatestime(struct lwp *, const struct bintime *); /* XXX */
+
void
idle_loop(void *dummy)
{
@@ -53,7 +55,7 @@ idle_loop(void *dummy)
KASSERT(lwp_locked(l, spc->spc_lwplock));
kcpuset_atomic_set(kcpuset_running, cpu_index(ci));
/* Update start time for this thread. */
- binuptime(&l->l_stime);
+ updatestime(l, NULL);
spc->spc_flags |= SPCF_RUNNING;
KASSERT((l->l_pflag & LP_RUNNING) != 0);
l->l_stat = LSIDL;
diff --git a/sys/kern/kern_softint.c b/sys/kern/kern_softint.c
index 5aa4c786037c..370d22bb94ca 100644
--- a/sys/kern/kern_softint.c
+++ b/sys/kern/kern_softint.c
@@ -793,6 +793,8 @@ softint_thread(void *cookie)
panic("softint_thread");
}
+void updatestime(struct lwp *, const struct bintime *); /* XXX */
+
/*
* softint_dispatch:
*
@@ -841,7 +843,7 @@ softint_dispatch(lwp_t *pinned, int s)
* for it.
*/
if (timing) {
- binuptime(&l->l_stime);
+ updatestime(l, NULL);
membar_producer(); /* for calcru */
l->l_pflag |= LP_TIMEINTR;
}
diff --git a/sys/kern/kern_synch.c b/sys/kern/kern_synch.c
index 6695205ac900..13862681c9fb 100644
--- a/sys/kern/kern_synch.c
+++ b/sys/kern/kern_synch.c
@@ -545,6 +545,57 @@ updatertime(lwp_t *l, const struct bintime *now)
bintime_sub(&l->l_rtime, &l->l_stime);
}
+void updatestime(struct lwp *, const struct bintime *); /* XXX */
+void
+updatestime(struct lwp *l, const struct bintime *now)
+{
+ static bool backwards = false;
+ struct bintime bt;
+ void *hereaddr = __builtin_return_address(0);
+ unsigned herecpu = curcpu()->ci_index;
+
+ if (now == NULL) {
+ binuptime(&bt);
+ now = &bt;
+ }
+
+ if (__predict_false(bintimecmp(now, &l->l_stime, <)) && !backwards) {
+ char heresym[128], theresym[128];
+ void *thereaddr = l->l_sched.info; /* XXX */
+ unsigned therecpu = l->l___rsvd1;
+
+#ifdef DDB
+ db_symstr(heresym, sizeof(heresym),
+ (db_expr_t)(intptr_t)hereaddr, DB_STGY_PROC);
+ db_symstr(theresym, sizeof(theresym),
+ (db_expr_t)(intptr_t)thereaddr, DB_STGY_PROC);
+#else
+ snprintf(heresym, sizeof(heresym), "%p", hereaddr);
+ snprintf(theresym, sizeof(theresym), "%p", thereaddr);
+#endif
+ backwards = true;
+ printf("WARNING: lwp %ld (%s%s%s) flags 0x%x:"
+ " timecounter went backwards"
+ " from (%jd + 0x%016"PRIx64"/2^64) sec"
+ " at %s on cpu%u"
+ " to (%jd + 0x%016"PRIx64"/2^64) sec"
+ " at %s on cpu%u\n",
+ (long)l->l_lid,
+ l->l_proc->p_comm,
+ l->l_name ? " " : "",
+ l->l_name ? l->l_name : "",
+ l->l_pflag,
+ (intmax_t)l->l_stime.sec, l->l_stime.frac,
+ theresym, therecpu,
+ (intmax_t)now->sec, now->frac,
+ heresym, herecpu);
+ }
+
+ l->l_stime = *now;
+ l->l_sched.info = hereaddr;
+ l->l___rsvd1 = herecpu;
+}
+
/*
* Select next LWP from the current CPU to run..
*/
@@ -695,7 +746,7 @@ mi_switch(lwp_t *l)
updatertime(l, &bt);
/* Update the new LWP's start time. */
- newl->l_stime = bt;
+ updatestime(newl, &bt);
/*
* ci_curlwp changes when a fast soft interrupt occurs.
