Clean up debug console output

Also prints the current timer value when inits are done, and when the
watchdog task first gets to run (after all higher priority tasks sleep
at least once).

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

BUG=none
TEST=none

Change-Id: I342f86ad087fd18ab064a10a5bcdd0b69ee373d0

5 files changed, 35 insertions, 28 deletions

diff --git a/chip/lm4/keyboard_scan.c b/chip/lm4/keyboard_scan.c
index 3729a304f5..2966713768 100644
--- a/chip/lm4/keyboard_scan.c
+++ b/chip/lm4/keyboard_scan.c
@@ -160,7 +160,7 @@ static uint32_t clear_matrix_interrupt_status(void) {
 
 static void wait_for_interrupt(void)
 {
-	uart_printf("[kbscan %s()]\n", __func__);
+	uart_puts("[KB wait]\n");
 
 	/* Assert all outputs would trigger un-wanted interrupts.
 	 * Clear them before enable interrupt. */
@@ -175,7 +175,7 @@ static void wait_for_interrupt(void)
 
 static void enter_polling_mode(void)
 {
-	uart_printf("[kbscan %s()]\n", __func__);
+	uart_puts("[KB poll]\n");
 	LM4_GPIO_IM(KB_SCAN_ROW_GPIO) = 0;  /* 0: disable interrupt */
 	select_column(COLUMN_TRI_STATE_ALL);
 }
@@ -210,7 +210,7 @@ static void print_raw_state(const char *msg)
 {
 	int c;
 
-	uart_printf("[%s:", msg);
+	uart_printf("[KB %s:", msg);
 	for (c = 0; c < KB_COLS; c++) {
 		if (raw_state[c])
 			uart_printf(" %02x", raw_state[c]);
@@ -279,7 +279,7 @@ static int check_keys_changed(void)
 	}
 
 	if (change)
-		print_raw_state("KB raw state");
+		print_raw_state("raw state");
 
 out:
 	/* Count number of key pressed */
@@ -370,7 +370,7 @@ void keyboard_scan_task(void)
 {
 	int key_press_timer = 0;
 
-	print_raw_state("KB init state");
+	print_raw_state("init state");
 	if (recovery_key_pressed)
 		uart_puts("[KB recovery key pressed at init!]\n");
 
diff --git a/chip/lm4/watchdog.c b/chip/lm4/watchdog.c
index ccc6e63b72..5a3080dcdb 100644
--- a/chip/lm4/watchdog.c
+++ b/chip/lm4/watchdog.c
@@ -141,6 +141,11 @@ int watchdog_init(int period_ms)
 /* Low priority task to reload the watchdog */
 void watchdog_task(void)
 {
+	/* Print when the watchdog task starts.  This is the lowest priority
+	 * task, so this only starts once all other tasks have gotten a chance
+	 * to do their task inits and have gone to sleep. */
+	uart_printf("[watchdog task started at %d us]\n", get_time().le.lo);
+
 	while (1) {
 #ifdef BOARD_bds
 		gpio_set_level(GPIO_DEBUG_LED, 1);
diff --git a/chip/stm32l/watchdog.c b/chip/stm32l/watchdog.c
index 4a1cd7f6d2..9d66ea75b7 100644
--- a/chip/stm32l/watchdog.c
+++ b/chip/stm32l/watchdog.c
@@ -58,6 +58,11 @@ int watchdog_init(int period_ms)
 /* Low priority task to reload the watchdog */
 void watchdog_task(void)
 {
+	/* Print when the watchdog task starts.  This is the lowest priority
+	 * task, so this only starts once all other tasks have gotten a chance
+	 * to do their task inits and have gone to sleep. */
+	uart_printf("[watchdog task started at %d us]\n", get_time().le.lo);
+
 	while (1) {
 #ifdef BOARD_discovery
 		gpio_set_level(GPIO_GREEN_LED, 1);
diff --git a/common/charge_state.c b/common/charge_state.c
index fb2e565025..088f43669f 100644
--- a/common/charge_state.c
+++ b/common/charge_state.c
@@ -308,25 +308,17 @@ static enum power_state state_error(void)
 
 	/* Debug output */
 	if (error_flags != last_error_flags) {
-		uart_printf("errors   : %02x\n", error_flags);
-		uart_printf("previous : %02x\n", last_error_flags);
+		uart_printf("[Charge error flags %02x -> %02x; AC=%d",
+			    last_error_flags, error_flags, ac);
+
+		if (error_flags & (F_CHG_V | F_CHG_I))
+			uart_puts(", charger error");
+
+		uart_printf(", battery V=%d I=%d T=%d Vwant=%d Iwant=%d]\n",
+			    bat_v, bat_i, (bat_temp - 2731) / 10,
+			    desired_v, desired_i);
+
 		last_error_flags = error_flags;
-		uart_printf("ac       : %d\n", ac);
-		uart_puts("charger\n");
-		if (ac)
-			if (error_flags & (F_CHG_V | F_CHG_I))
-				uart_puts("  error\n");
-			else
-				uart_puts("  ok\n");
-		else
-			uart_puts("  offline\n");
-
-		uart_puts("battery\n");
-		uart_printf("  voltage: %5d\n", bat_v);
-		uart_printf("  current: %5d\n", bat_i);
-		uart_printf("  temp   : %5d\n", (bat_temp - 2731) / 10);
-		uart_printf("  des_vol: %5d\n", desired_v);
-		uart_printf("  des_cur: %5d\n", desired_i);
 	}
 
 	*memmap_batt_flags = batt_flags;
@@ -392,7 +384,7 @@ void charge_state_machine_task(void)
 		}
 
 		if (new_state)
-			uart_printf("CHARGE: %s --> %s\n",
+			uart_printf("[Charge state %s -> %s]\n",
 				_state_name[current_state],
 				_state_name[new_state]);
 
diff --git a/common/main.c b/common/main.c
index 887312f6e5..50c5b6d63d 100644
--- a/common/main.c
+++ b/common/main.c
@@ -45,8 +45,11 @@ int main(void)
 	 * source we need to calibrate the internal oscillator. */
 	system_pre_init();
 
-	/* Set the CPU clocks / PLLs */
+	/* Set the CPU clocks / PLLs and timer */
 	clock_init();
+	timer_init();
+	/* The timer used by get_time() is now started, so everything after
+	 * this can be benchmarked. */
 
 	/* Do system, gpio, and vboot pre-initialization so we can jump to
 	 * another image if necessary.  This must be done as early as
@@ -60,7 +63,6 @@ int main(void)
 #ifdef CONFIG_TASK_WATCHDOG
 	watchdog_init(1100);
 #endif
-	timer_init();
 	uart_init();
 	system_init();
 #ifdef CONFIG_TASK_KEYSCAN
@@ -94,8 +96,11 @@ int main(void)
 	peci_init();
 #endif
 
-	/* Print the reset cause */
-	uart_printf("\n\n--- Chrome EC initialized! ---\n");
+	/* 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 %d us ---\n",
+		    get_time().le.lo);
 	uart_printf("build: %s\n", system_get_build_info());
 	uart_printf("(image: %s, last reset: %s)\n",
 		    system_get_image_copy_string(),