Maintain timer value across sysjumps and clean up init debug output

This helps us keep track of how long vboot is taking on the EC.

Signed-off-by: Randall Spangler <rspangler@chromium.org>

BUG=chrome-os-partner:9651
TEST=reboot system and look at debug log.  time shouldn't start over after it jumps to image A.

Change-Id: Iad86e90d42dabf1c67b2c2be80dda1151cf9a288

7 files changed, 74 insertions, 31 deletions

diff --git a/chip/lm4/hwtimer.c b/chip/lm4/hwtimer.c
index 41e737b10d..b3c8498294 100644
--- a/chip/lm4/hwtimer.c
+++ b/chip/lm4/hwtimer.c
@@ -69,7 +69,7 @@ static int update_prescaler(void)
 DECLARE_HOOK(HOOK_FREQ_CHANGE, update_prescaler, HOOK_PRIO_DEFAULT);
 
 
-int __hw_clock_source_init(void)
+int __hw_clock_source_init(uint32_t start_t)
 {
 	volatile uint32_t scratch __attribute__((unused));
 
@@ -93,10 +93,13 @@ int __hw_clock_source_init(void)
 
 	/* Periodic mode, counting down */
 	LM4_TIMER_TAMR(6) = 0x22;
-	/* use the full 32-bits of the timer */
+	/* Use the full 32-bits of the timer */
 	LM4_TIMER_TAILR(6) = 0xffffffff;
 	/* Starts counting in timer A */
 	LM4_TIMER_CTL(6) |= 0x1;
+	/* Override the count with the start value now that counting has
+	 * started. */
+	LM4_TIMER_TAV(6) = 0xffffffff - start_t;
 
 	/* Enable interrupt */
 	task_enable_irq(LM4_IRQ_TIMERW0A);
diff --git a/chip/stm32/hwtimer.c b/chip/stm32/hwtimer.c
index 9576a6fb46..0d0417274f 100644
--- a/chip/stm32/hwtimer.c
+++ b/chip/stm32/hwtimer.c
@@ -90,7 +90,7 @@ static void __hw_clock_source_irq(void)
 DECLARE_IRQ(STM32_IRQ_TIM2, __hw_clock_source_irq, 1);
 DECLARE_IRQ(STM32_IRQ_TIM3, __hw_clock_source_irq, 1);
 
-int __hw_clock_source_init(void)
+int __hw_clock_source_init(uint32_t start_t)
 {
 	/*
 	 * we use 2 chained 16-bit counters to emulate a 32-bit one :
@@ -134,6 +134,11 @@ int __hw_clock_source_init(void)
 	STM32_TIM_CR1(2) |= 1;
 	STM32_TIM_CR1(3) |= 1;
 
+	/* Override the count with the start value now that counting has
+	 * started. */
+	STM32_TIM_CNT(2) = start_t >> 16;
+	STM32_TIM_CNT(3) = start_t & 0xffff;
+
 	/* Enable timer interrupts */
 	task_enable_irq(STM32_IRQ_TIM2);
 	task_enable_irq(STM32_IRQ_TIM3);
diff --git a/common/main.c b/common/main.c
index 62f6cc8501..6b4dfb704c 100644
--- a/common/main.c
+++ b/common/main.c
@@ -68,6 +68,17 @@ int main(void)
 
 	/* Initialize UART.  uart_printf(), etc. may now be used. */
 	uart_init();
+	if (system_jumped_to_this_image())
+		uart_printf("[%T UART initialized after sysjump]\n");
+	else {
+		uart_puts("\n\n--- UART initialized after reboot ---\n");
+		uart_printf("[Reset cause: %s]\n",
+			    system_get_reset_cause_string());
+	}
+	uart_printf("[Image: %s, %s]\n",
+		    system_get_image_copy_string(),
+		    system_get_build_info());
+
 
 #ifdef CONFIG_TASK_WATCHDOG
 	/* Intialize watchdog timer.  All lengthy operations between now and
@@ -110,15 +121,10 @@ int main(void)
 	/* Reduce core clock now that init is done */
 	clock_enable_pll(0);
 #endif
-	/* Print the init time and reset cause.  Init time isn't completely
-	 * accurate because it can't take into account the time for the first
-	 * few module inits, but it'll at least catch the majority of them. */
-	uart_printf("\n\n--- Chrome EC initialized in %ld us ---\n",
-		    get_time().val);
-	uart_printf("build: %s\n", system_get_build_info());
-	uart_printf("(image: %s, last reset: %s)\n",
-		    system_get_image_copy_string(),
-		    system_get_reset_cause_string());
+	/* Print the init time.  Not completely accurate because it can't take
+	 * into account the time for the first few module inits, but it'll at
+	 * least catch the majority of them. */
+	uart_printf("[%T Inits done]\n");
 
 	/* Launch task scheduling (never returns) */
 	return task_start();
diff --git a/common/system_common.c b/common/system_common.c
index 17fd18d7f4..4fe6204af2 100644
--- a/common/system_common.c
+++ b/common/system_common.c
@@ -277,7 +277,7 @@ int system_run_image_copy(enum system_image_copy_t copy,
 	if (init_addr < base || init_addr >= base + CONFIG_FW_IMAGE_SIZE)
 		return EC_ERROR_UNKNOWN;
 
-	CPRINTF("Rebooting to image %s\n", image_names[copy]);
+	CPRINTF("[%T Jumping to image %s]\n", image_names[copy]);
 
 	jump_to_image(init_addr, recovery_required);
 
diff --git a/common/vboot.c b/common/vboot.c
index 31baad9d82..ea7840753a 100644
--- a/common/vboot.c
+++ b/common/vboot.c
@@ -141,12 +141,12 @@ int vboot_init(void)
 	enum howgood r;
 	timestamp_t ts1, ts2;
 
-	CPRINTF("\n[--- %s() ---]\n", __func__);
+	CPRINTF("[%T Vboot init]\n");
 
 	if (!maybe_jump_to_other_image())
 		return EC_SUCCESS;
 
-	CPRINTF("[Check image A...]\n");
+	CPRINTF("[%T Vboot check image A...]\n");
 
 	ts1 = get_time();
 	r = good_image((uint8_t *)CONFIG_VBOOT_ROOTKEY_OFF,
@@ -154,16 +154,17 @@ int vboot_init(void)
 		       (uint8_t *)CONFIG_FW_A_OFF, CONFIG_FW_A_SIZE);
 	ts2 = get_time();
 
-	CPRINTF("[result=%d, elapsed time=%ld]\n", r, ts2.val - ts1.val);
+	CPRINTF("[%T Vboot result=%d, elapsed time=%ld us]\n",
+		r, ts2.val - ts1.val);
 
 	switch (r) {
 	case IMAGE_IS_GOOD:
-		CPRINTF("[Image A verified at %T]\n");
+		CPRINTF("[Image A verified]\n");
 		system_run_image_copy(SYSTEM_IMAGE_RW_A, 0);
 		CPRINTF("[ERROR: Unable to jump to image A]\n");
 		goto bad;
 	case IMAGE_IS_GOOD_BUT_USE_RO_ANYWAY:
-		CPRINTF("[Image A verified at %T]\n");
+		CPRINTF("[Image A verified]\n");
 		CPRINTF("[Staying in RO mode]\n");
 		return EC_SUCCESS;
 	default:
@@ -171,9 +172,9 @@ int vboot_init(void)
 	}
 
 #ifdef CONFIG_NO_RW_B
-	CPRINTF("[No image B to check]\n");
+	CPRINTF("[Vboot no image B to check]\n");
 #else
-	CPRINTF("[Check image B...]\n");
+	CPRINTF("[%T Vboot check image B...]\n");
 
 	ts1 = get_time();
 	r = good_image((uint8_t *)CONFIG_VBOOT_ROOTKEY_OFF,
@@ -181,16 +182,17 @@ int vboot_init(void)
 		       (uint8_t *)CONFIG_FW_B_OFF, CONFIG_FW_B_SIZE);
 	ts2 = get_time();
 
-	CPRINTF("[result=%d, elapsed time=%ld]\n", r, ts2.val - ts1.val);
+	CPRINTF("[%T Vboot result=%d, elapsed time=%ld us]\n",
+		r, ts2.val - ts1.val);
 
 	switch (r) {
 	case IMAGE_IS_GOOD:
-		CPRINTF("[Image B verified at %T]\n");
+		CPRINTF("[Image B verified]\n");
 		system_run_image_copy(SYSTEM_IMAGE_RW_B, 0);
 		CPRINTF("[ERROR: Unable to jump to image B]\n");
 		goto bad;
 	case IMAGE_IS_GOOD_BUT_USE_RO_ANYWAY:
-		CPRINTF("[Image B verified at %T]\n");
+		CPRINTF("[Image B verified]\n");
 		CPRINTF("[Staying in RO mode]\n");
 		return EC_SUCCESS;
 	default:
diff --git a/core/cortex-m/timer.c b/core/cortex-m/timer.c
index 0078936f5a..10c83c8921 100644
--- a/core/cortex-m/timer.c
+++ b/core/cortex-m/timer.c
@@ -5,15 +5,15 @@
 
 /* Timer module for Chrome EC operating system */
 
-#include <stdint.h>
-
-#include "task.h"
-#include "timer.h"
-#include "hwtimer.h"
 #include "atomic.h"
 #include "console.h"
+#include "hooks.h"
+#include "hwtimer.h"
+#include "system.h"
 #include "uart.h"
 #include "util.h"
+#include "task.h"
+#include "timer.h"
 
 /* high word of the 64-bit timestamp counter  */
 static volatile uint32_t clksrc_high;
@@ -212,11 +212,37 @@ int command_timer_info(int argc, char **argv)
 DECLARE_CONSOLE_COMMAND(timerinfo, command_timer_info);
 
 
+#define TIMER_SYSJUMP_TAG 0x4d54  /* "TM" */
+
+
+/* Preserve time across a sysjump */
+static int timer_sysjump(void)
+{
+	timestamp_t ts = get_time();
+	system_add_jump_tag(TIMER_SYSJUMP_TAG, 1, sizeof(ts), &ts);
+
+	return EC_SUCCESS;
+}
+DECLARE_HOOK(HOOK_SYSJUMP, timer_sysjump, HOOK_PRIO_DEFAULT);
+
+
 int timer_init(void)
 {
+	const timestamp_t *ts;
+	int size, version;
+
 	BUILD_ASSERT(TASK_ID_COUNT < sizeof(timer_running) * 8);
 
-	timer_irq = __hw_clock_source_init();
+	/* Restore time from before sysjump */
+	ts = (const timestamp_t *)system_get_jump_tag(TIMER_SYSJUMP_TAG,
+						      &version, &size);
+	if (ts && version == 1 && size == sizeof(timestamp_t)) {
+		clksrc_high = ts->le.hi;
+		timer_irq = __hw_clock_source_init(ts->le.lo);
+	} else {
+		clksrc_high = 0;
+		timer_irq = __hw_clock_source_init(0);
+	}
 
 	return EC_SUCCESS;
 }
diff --git a/include/hwtimer.h b/include/hwtimer.h
index ae0c634163..4ebc254fa5 100644
--- a/include/hwtimer.h
+++ b/include/hwtimer.h
@@ -24,11 +24,12 @@ void __hw_clock_event_clear(void);
 uint32_t __hw_clock_source_read(void);
 
 /**
- * Initializes the hardware timer used to provide clock services.
+ * Initializes the hardware timer used to provide clock services, using the
+ * specified start timer value.
  *
  * It returns the IRQ number of the timer routine.
  */
-int __hw_clock_source_init(void);
+int __hw_clock_source_init(uint32_t start_t);
 
 /**
  * Searches the next deadline and program it in the timer hardware.