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 <riastr...@netbsd.org> 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.