Re: What to do about "WARNING: negative runtime; monotonic clock has gone backwards"

[Taylor R Campbell <riastradh%NetBSD.org@localhost>]

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 <riastradh%NetBSD.org@localhost>
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.