Re: NetBSD-current Time issues on RPI3

[Ryo Shimizu <ryo%nerv.org@localhost>]

>Well, I got FreeBSD running and I've been building ports for a few
>hours now and not seen any issues. Looks like not a hardware bug but
>a NetBSD one. I can help with debugging if anyone can give ideas on
>where to look.


I don't know the cause yet, but when I put in a quick hack like below,
I found that the cntvct value was rolled back.
When cntvct rolls back, the clockhandler stops because the cntv_cval is
still there and will not occur until the next timer interrupt is much later.

The association is unknown, but it seems to be more likely to occur under
high load.

It has never happened with a pinebook.



Index: gtmr.c
===================================================================
RCS file: /src/cvs/cvsroot-netbsd/src/sys/arch/arm/cortex/gtmr.c,v
retrieving revision 1.39
diff -a -u -p -r1.39 gtmr.c
--- gtmr.c	30 Jan 2019 02:01:58 -0000	1.39
+++ gtmr.c	30 Jan 2019 20:45:23 -0000
@@ -322,6 +322,34 @@ gtmr_intr(void *arg)
 	return 1;
 }
 
+void gtmr_fixup(void);
+
+void
+gtmr_fixup(void)
+{
+	struct gtmr_softc * const sc = &gtmr_sc;
+	uint64_t now;
+	int s;
+
+	if (sc->sc_autoinc == 0)
+		return;
+
+	s = splclock();
+
+	now = gtmr_read_cntvct(sc);
+	if (now < curcpu()->ci_lastintr) {
+		printf("cpu%d: detect cntvc was rollbacked: "
+		    "0x%"PRIx64" -> 0x%"PRIx64" (%+"PRId64"). fixup\n",
+		    curcpu()->ci_index,
+		    curcpu()->ci_lastintr, now, now - curcpu()->ci_lastintr);
+
+		curcpu()->ci_lastintr = now;
+		gtmr_cntv_tval_write(sc->sc_autoinc);
+	}
+
+	splx(s);
+}
+
 void
 setstatclockrate(int newhz)
 {
@@ -332,5 +360,6 @@ gtmr_get_timecount(struct timecounter *t
 {
 	struct gtmr_softc * const sc = tc->tc_priv;
 	arm_isb();	// we want the time NOW, not some instructions later.
+	gtmr_fixup();
 	return (u_int) gtmr_read_cntvct(sc);
 }


% grep rollbacked /var/log/messages
Apr  6 17:08:04 rpi3 /netbsd: [ 63180.6866292] cpu1: detect cntvc was rollbacked: 0x40ef47c06 -> 0x1000000bf (-13135805255). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 63180.6866292] cpu2: detect cntvc was rollbacked: 0x40ef47c71 -> 0x10000e80e (-13135746147). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 63180.6866292] cpu0: detect cntvc was rollbacked: 0x40ef47b2f -> 0x100002d6b (-13135793604). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 63180.6866292] cpu3: detect cntvc was rollbacked: 0x40ef47c36 -> 0x10000052b (-13135804171). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 63180.6866292] cpu2: detect cntvc was rollbacked: 0x10000e80e -> 0x100007d75 (-27289). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 71410.1380696] cpu1: detect cntvc was rollbacked: 0x293f05c4c5 -> 0x800000543 (-142791262082). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 71410.1380696] cpu0: detect cntvc was rollbacked: 0x293f03ce29 -> 0x80002ab8a (-142790959775). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 71411.0787579] cpu3: detect cntvc was rollbacked: 0x293f05b78e -> 0x8005a5701 (-142785339533). fixup
Apr  6 17:08:04 rpi3 /netbsd: [ 71419.0599171] cpu2: detect cntvc was rollbacked: 0x293f05ba08 -> 0x8097c9ca8 (-142632099168). fixup

Apr  8 19:08:59 rpi3 /netbsd: [ 5520.0160081] cpu0: detect cntvc was rollbacked: 0x190003ab62 -> 0x100000014 (-103079455566). fixup
Apr  8 19:08:59 rpi3 /netbsd: [ 5520.0160081] cpu3: detect cntvc was rollbacked: 0x190003bbf3 -> 0x1000277ea (-103079298057). fixup
Apr  8 19:08:59 rpi3 /netbsd: [ 5520.0217974] cpu1: detect cntvc was rollbacked: 0x190003bc6b -> 0x100079933 (-103078961976). fixup
Apr  8 19:08:59 rpi3 /netbsd: [ 5520.0318095] cpu2: detect cntvc was rollbacked: 0x190003bc92 -> 0x10008ff3b (-103078870359). fixup
Apr  9 04:52:37 rpi3 /netbsd: [ 34343.6114058] cpu2: detect cntvc was rollbacked: 0x9c6f80e503 -> 0x80001b2eb (-637525766680). fixup
Apr  9 04:52:37 rpi3 /netbsd: [ 34343.6114058] cpu3: detect cntvc was rollbacked: 0x9c6f80e357 -> 0x8000001ad (-637525877162). fixup
Apr  9 04:52:37 rpi3 /netbsd: [ 34343.6114058] cpu0: detect cntvc was rollbacked: 0x9c6f80dc9a -> 0x80000681f (-637525849211). fixup
Apr  9 04:52:37 rpi3 /netbsd: [ 34343.6114058] cpu2: detect cntvc was rollbacked: 0x8000fe354 -> 0x10001e758 (-30065687548). fixup
Apr  9 04:52:37 rpi3 /netbsd: [ 34343.6114058] cpu3: detect cntvc was rollbacked: 0x8000001ad -> 0x10001e688 (-30064646949). fixup
Apr  9 04:52:37 rpi3 /netbsd: [ 34343.6114058] cpu1: detect cntvc was rollbacked: 0x9c6f80e502 -> 0x80000023c (-637525877446). fixup
Apr  9 04:52:37 rpi3 /netbsd: [ 34343.6114058] cpu0: detect cntvc was rollbacked: 0x80000681f -> 0x10002e56b (-30064607924). fixup


-- 
ryo shimizu