[Skiboot] [PATCH] console-log: adjust timestamp when resetting TB from TOD

[Nicholas Piggin]

Allow a TB delta to be recorded and applied, to adjust the console
log timetamp with. This doesn't claim to be cycle accurate, but it
avoid the ugly non-monotonic blip in the timestamp when TBs are
synced.

Signed-off-by: Nicholas Piggin <npiggin at gmail.com>
---
 core/console-log.c |  8 +++++++-
 hw/chiptod.c       | 26 +++++++++++++++++++-------
 include/skiboot.h  |  3 +++
 3 files changed, 29 insertions(+), 8 deletions(-)

diff --git a/core/console-log.c b/core/console-log.c
index 642b39ca7..2cf5f9ff8 100644
--- a/core/console-log.c
+++ b/core/console-log.c
@@ -27,12 +27,18 @@
 #include "console.h"
 #include "timebase.h"
 
+static long tb_delta = 0;
+void prlog_tb_adjust(unsigned long tb_before, unsigned long tb_after)
+{
+	tb_delta += (long)(tb_before - tb_after);
+}
+
 static int vprlog(int log_level, const char *fmt, va_list ap)
 {
 	int count;
 	char buffer[320];
 	bool flush_to_drivers = true;
-	unsigned long tb = mftb();
+	unsigned long tb = mftb() + tb_delta;
 
 	/* It's safe to return 0 when we "did" something here
 	 * as only printf cares about how much we wrote, and
diff --git a/hw/chiptod.c b/hw/chiptod.c
index b9e47741b..f6bc2ab61 100644
--- a/hw/chiptod.c
+++ b/hw/chiptod.c
@@ -775,11 +775,11 @@ static void chiptod_reset_tod_errors(void)
 
 static void chiptod_sync_master(void *data)
 {
+	unsigned long tb_before;
 	bool *result = data;
 
-	prlog(PR_DEBUG, "Master sync on CPU PIR 0x%04x...\n",
-	      this_cpu()->pir);
-
+	prlog(PR_INSANE, "Master sync on CPU PIR 0x%04x started, TB=%lx\n",
+			 this_cpu()->pir, mfspr(SPR_TBRL));
 	/* Apply base tfmr */
 	mtspr(SPR_TFMR, base_tfmr);
 
@@ -836,9 +836,12 @@ static void chiptod_sync_master(void *data)
 		goto error;
 	prlog(PR_INSANE, "SYNC MASTER Step 6 TFMR=0x%016lx\n", mfspr(SPR_TFMR));
 
+	tb_before = mftb();
 	/* Move chiptod value to core TB */
 	if (!chiptod_to_tb())
 		goto error;
+	prlog_tb_adjust(tb_before, mftb());
+
 	prlog(PR_INSANE, "SYNC MASTER Step 7 TFMR=0x%016lx\n", mfspr(SPR_TFMR));
 
 	/* Send local chip TOD to all chips TOD */
@@ -853,6 +856,9 @@ static void chiptod_sync_master(void *data)
 
 	prlog(PR_INSANE, "Master sync completed, TB=%lx\n", mfspr(SPR_TBRL));
 
+	prlog(PR_DEBUG, "Master sync on CPU PIR 0x%04x...\n",
+			this_cpu()->pir);
+
 	/*
 	 * A little delay to make sure the remote chips get up to
 	 * speed before we start syncing them.
@@ -865,7 +871,7 @@ static void chiptod_sync_master(void *data)
 	*result = true;
 	return;
  error:
-	prerror("Master sync failed! TFMR=0x%016lx\n", mfspr(SPR_TFMR));
+	prerror("Master sync on CPU PIR 0x%04x failed! TFMR=0x%016lx\n", this_cpu()->pir, mfspr(SPR_TFMR));
 	*result = false;
 }
 
@@ -881,8 +887,8 @@ static void chiptod_sync_slave(void *data)
 		return;
 	}
 
-	prlog(PR_DEBUG, "Slave sync on CPU PIR 0x%04x...\n",
-	      this_cpu()->pir);
+	prlog(PR_INSANE, "Slave sync on CPU PIR 0x%04x started, TB=%lx\n",
+			 this_cpu()->pir, mfspr(SPR_TBRL));
 
 	/* Apply base tfmr */
 	mtspr(SPR_TFMR, base_tfmr);
@@ -919,12 +925,18 @@ static void chiptod_sync_slave(void *data)
 	if (!chiptod_check_tb_running())
 		goto error;
 
+	/* Do the PR_DEBUG print after chiptod_to_tb, so timebase looks right.
+	 * PR_INSANE are not so important.
+	 */
+	prlog(PR_DEBUG, "Slave sync on CPU PIR 0x%04x...\n",
+			this_cpu()->pir);
+
 	prlog(PR_INSANE, "Slave sync completed, TB=%lx\n", mfspr(SPR_TBRL));
 
 	*result = true;
 	return;
  error:
-	prerror("Slave sync failed ! TFMR=0x%016lx\n", mfspr(SPR_TFMR));
+	prerror("Slave sync on CPU PIR 0x%04x failed ! TFMR=0x%016lx\n", this_cpu()->pir, mfspr(SPR_TFMR));
 	*result = false;
 }
 
diff --git a/include/skiboot.h b/include/skiboot.h
index db9132588..085d1b186 100644
--- a/include/skiboot.h
+++ b/include/skiboot.h
@@ -117,6 +117,9 @@ static inline bool opal_booting(void)
 #define pr_fmt(fmt) fmt
 #endif
 
+/* Compensate for a TB change so that logs appear vaguely correct */
+void prlog_tb_adjust(unsigned long tb_before, unsigned long tb_after);
+
 void _prlog(int log_level, const char* fmt, ...) __attribute__((format (printf, 2, 3)));
 #define prlog(l, f, ...) do { _prlog(l, pr_fmt(f), ##__VA_ARGS__); } while(0)
 #define prerror(fmt...)	do { prlog(PR_ERR, fmt); } while(0)
-- 
2.15.0