ec: Support logging system boot time info

This CL add support logging system boot time and hostcommand to get
boot time info.
EC logs elapsed time (in micro second) info since boot for different
signal events,that can be used to calculate system boot time in cold
boot and warm boot scenarios.

Below are the events when EC logs time info

 ARAIL		EC turns on A-RAIL
 RSMRST		EC releases RSMRST#
 ESPIRST	ESPIRST received
 PLTRST_LOW	PLTRST# asserted
 PLTRST_HIGH	PLTRST# deasserted
 EC_CUR_TIME	EC current time
 cnt		increments on every warm reboot and reset to 0 on
 		cold reboot

BUG=b:249163956
BRANCH=none
TEST='ectool boottime' AP console command is used to fetch data
     'reboot' on AP console to trigger warm reboot
     'apshutdown' on EC console to trigger cold reboot

Signed-off-by: Rajesh Kumar <rajesh3.kumar@intel.com>
Change-Id: I15fedbde252e0452270ef0e3fd4391bf624169f1
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/3794612
Reviewed-by: Boris Mittelberg <bmbm@google.com>
Code-Coverage: Zoss <zoss-cl-coverage@prod.google.com>

20 files changed, 227 insertions, 3 deletions

diff --git a/chip/it83xx/espi.c b/chip/it83xx/espi.c
index bf52b87404..f59f3728bf 100644
--- a/chip/it83xx/espi.c
+++ b/chip/it83xx/espi.c
@@ -13,6 +13,7 @@
 #include "power.h"
 #include "registers.h"
 #include "system.h"
+#include "system_boot_time.h"
 #include "task.h"
 #include "uart.h"
 #include "util.h"
@@ -273,6 +274,7 @@ static void espi_vw_idx7_isr(uint8_t flag_changed, uint8_t vw_evt)
 static void espi_chipset_reset(void)
 {
 	hook_notify(HOOK_CHIPSET_RESET);
+	update_ap_boot_time(ESPIRST);
 }
 DECLARE_DEFERRED(espi_chipset_reset);
 #endif
@@ -284,12 +286,14 @@ static void espi_vw_idx3_isr(uint8_t flag_changed, uint8_t vw_evt)
 
 		if (pltrst) {
 			espi_vw_host_startup();
+			update_ap_boot_time(PLTRST_HIGH);
 		} else {
 #ifdef CONFIG_CHIPSET_RESET_HOOK
 			hook_call_deferred(&espi_chipset_reset_data, MSEC);
 #endif
 			/* Store port 80 reset event */
 			port_80_write(PORT_80_EVENT_RESET);
+			update_ap_boot_time(PLTRST_LOW);
 		}
 
 		CPRINTS("VW PLTRST_L %sasserted", pltrst ? "de" : "");
diff --git a/chip/mchp/espi.c b/chip/mchp/espi.c
index 53d17e90b2..dce81448d7 100644
--- a/chip/mchp/espi.c
+++ b/chip/mchp/espi.c
@@ -20,6 +20,7 @@
 #include "power.h"
 #include "registers.h"
 #include "system.h"
+#include "system_boot_time.h"
 #include "task.h"
 #include "tfdp_chip.h"
 #include "timer.h"
@@ -833,6 +834,7 @@ int espi_vw_disable_wire_int(enum espi_vw_signal signal)
 static void espi_chipset_reset(void)
 {
 	hook_notify(HOOK_CHIPSET_RESET);
+	update_ap_boot_time(ESPIRST);
 }
 DECLARE_DEFERRED(espi_chipset_reset);
 #endif
@@ -867,12 +869,15 @@ void espi_vw_evt_pltrst_n(uint32_t wire_state, uint32_t bpos)
 {
 	CPRINTS("VW PLTRST#: %d", wire_state);
 
-	if (wire_state) /* Platform Reset de-assertion */
+	if (wire_state) { /* Platform Reset de-assertion */
 		espi_host_init();
-	else /* assertion */
+		update_ap_boot_time(PLTRST_HIGH);
+	} else { /* assertion */
 #ifdef CONFIG_CHIPSET_RESET_HOOK
 		hook_call_deferred(&espi_chipset_reset_data, MSEC);
 #endif
+		update_ap_boot_time(PLTRST_LOW);
+	}
 }
 
 /* OOB Reset Warn event handler */
diff --git a/chip/npcx/espi.c b/chip/npcx/espi.c
index e73d04e988..3bed4f4564 100644
--- a/chip/npcx/espi.c
+++ b/chip/npcx/espi.c
@@ -13,6 +13,7 @@
 #include "power.h"
 #include "registers.h"
 #include "system.h"
+#include "system_boot_time.h"
 #include "task.h"
 #include "timer.h"
 #include "uart.h"
@@ -459,11 +460,14 @@ void espi_vw_evt_pltrst(void)
 		/* Enable eSPI peripheral channel */
 		SET_BIT(NPCX_ESPICFG, NPCX_ESPICFG_PCHANEN);
 #endif
+		update_ap_boot_time(PLTRST_HIGH);
+
 	} else {
 		/* PLTRST# asserted */
 #ifdef CONFIG_CHIPSET_RESET_HOOK
 		hook_call_deferred(&espi_chipset_reset_data, MSEC);
 #endif
+		update_ap_boot_time(PLTRST_LOW);
 	}
 }
 
@@ -524,6 +528,8 @@ void espi_espirst_handler(void)
 	/* Clear pending bit of WUI */
 	SET_BIT(NPCX_WKPCL(MIWU_TABLE_0, MIWU_GROUP_5), 5);
 
+	update_ap_boot_time(ESPIRST);
+
 	CPRINTS("eSPI RST issued!");
 }
 
diff --git a/common/build.mk b/common/build.mk
index c9b2630de5..9ad87fdc27 100644
--- a/common/build.mk
+++ b/common/build.mk
@@ -76,7 +76,8 @@ common-$(CONFIG_CMD_I2CWEDGE)+=i2c_wedge.o
 common-$(CONFIG_COMMON_GPIO)+=gpio.o gpio_commands.o
 common-$(CONFIG_IO_EXPANDER)+=ioexpander.o ioexpander_commands.o
 common-$(CONFIG_COMMON_PANIC_OUTPUT)+=panic_output.o
-common-$(CONFIG_COMMON_RUNTIME)+=hooks.o main.o system.o peripheral.o
+common-$(CONFIG_COMMON_RUNTIME)+=hooks.o main.o system.o peripheral.o \
+	system_boot_time.o
 common-$(CONFIG_COMMON_TIMER)+=timer.o
 common-$(CONFIG_CRC8)+= crc8.o
 common-$(CONFIG_CURVE25519)+=curve25519.o
diff --git a/common/system.c b/common/system.c
index e10712259c..6123b2b1f9 100644
--- a/common/system.c
+++ b/common/system.c
@@ -31,6 +31,7 @@
 #include "panic.h"
 #include "sysjump.h"
 #include "system.h"
+#include "system_boot_time.h"
 #include "task.h"
 #include "timer.h"
 #include "uart.h"
@@ -1116,6 +1117,9 @@ static void system_common_shutdown(void)
 	if (reboot_at_shutdown)
 		CPRINTF("Reboot at shutdown: %d\n", reboot_at_shutdown);
 	handle_pending_reboot(reboot_at_shutdown);
+
+	/* Reset cnt on cold boot */
+	update_ap_boot_time(RESET_CNT);
 }
 DECLARE_HOOK(HOOK_CHIPSET_SHUTDOWN_COMPLETE, system_common_shutdown,
 	     HOOK_PRIO_DEFAULT);
diff --git a/common/system_boot_time.c b/common/system_boot_time.c
new file mode 100644
index 0000000000..7b93be6de1
--- /dev/null
+++ b/common/system_boot_time.c
@@ -0,0 +1,68 @@
+/* Copyright 2022 The ChromiumOS Authors
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#include "common.h"
+#include "console.h"
+#include "host_command.h"
+#include "system.h"
+#include "util.h"
+
+#ifdef CONFIG_SYSTEM_BOOT_TIME_LOGGING
+/* Content of ap_boot_time will be lost on sysjump */
+static struct ap_boot_time_data ap_boot_time;
+#endif
+
+/* This function updates timestamp for ap boot time params */
+void update_ap_boot_time(enum boot_time_param param)
+{
+#ifdef CONFIG_SYSTEM_BOOT_TIME_LOGGING
+	if (param > RESET_CNT) {
+		ccprintf("invalid boot_time_param: %d\n", param);
+		return;
+	}
+	if (param < RESET_CNT) {
+		ap_boot_time.timestamp[param] = get_time().val;
+		ccprintf("Boot Time: %d, %lld\n", param,
+			 ap_boot_time.timestamp[param]);
+	}
+
+	switch (param) {
+	case PLTRST_LOW:
+		ap_boot_time.cnt++;
+		break;
+	case RESET_CNT:
+		ap_boot_time.cnt = 0;
+		break;
+	default:
+		break;
+	}
+#endif
+}
+
+#ifdef CONFIG_SYSTEM_BOOT_TIME_LOGGING
+/* Returns system boot time data */
+static enum ec_status
+host_command_get_boot_time(struct host_cmd_handler_args *args)
+{
+	struct ap_boot_time_data *boot_time = args->response;
+
+	if (args->response_max < sizeof(*boot_time)) {
+		return EC_RES_RESPONSE_TOO_BIG;
+	}
+
+	/* update current time */
+	update_ap_boot_time(EC_CUR_TIME);
+
+	/* copy data from ap_boot_time struct */
+	memcpy(boot_time, &ap_boot_time, sizeof(*boot_time));
+
+	args->response_size = sizeof(*boot_time);
+
+	return EC_RES_SUCCESS;
+}
+
+DECLARE_HOST_COMMAND(EC_CMD_GET_BOOT_TIME, host_command_get_boot_time,
+		     EC_VER_MASK(0));
+#endif
diff --git a/include/config.h b/include/config.h
index 544fe7c333..3ddd0506d2 100644
--- a/include/config.h
+++ b/include/config.h
@@ -5778,6 +5778,9 @@
  */
 #undef CONFIG_ASSERT_CCD_MODE_ON_DTS_CONNECT
 
+/* Define this to enable system boot time logging */
+#undef CONFIG_SYSTEM_BOOT_TIME_LOGGING
+
 /*
  * The USB port used for CCD. Defaults to 0/C0.
  */
diff --git a/include/ec_commands.h b/include/ec_commands.h
index 6c30528d44..77bb285a0b 100644
--- a/include/ec_commands.h
+++ b/include/ec_commands.h
@@ -7766,6 +7766,24 @@ struct ec_params_usb_pd_mux_ack {
 	uint8_t port; /* USB-C port number */
 } __ec_align1;
 
+/* Get boot time */
+#define EC_CMD_GET_BOOT_TIME 0x0604
+
+enum boot_time_param {
+	ARAIL = 0,
+	RSMRST,
+	ESPIRST,
+	PLTRST_LOW,
+	PLTRST_HIGH,
+	EC_CUR_TIME,
+	RESET_CNT,
+};
+
+struct ap_boot_time_data {
+	uint64_t timestamp[RESET_CNT];
+	uint16_t cnt;
+} __ec_align4;
+
 /*****************************************************************************/
 /*
  * Reserve a range of host commands for board-specific, experimental, or
diff --git a/include/system_boot_time.h b/include/system_boot_time.h
new file mode 100644
index 0000000000..e57d73d2d7
--- /dev/null
+++ b/include/system_boot_time.h
@@ -0,0 +1,18 @@
+/* Copyright 2022 The ChromiumOS Authors
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#ifndef __CROS_EC_SYSTEM_BOOT_TIME_H
+#define __CROS_EC_SYSTEM_BOOT_TIME_H
+
+#include "ec_commands.h"
+
+/**
+ * Updates ap boot time data.
+ *
+ * @param boot time param needs to be updated
+ */
+void update_ap_boot_time(enum boot_time_param param);
+
+#endif /* __CROS_EC_SYSTEM_BOOT_TIME_H */
diff --git a/power/alderlake_slg4bd44540.c b/power/alderlake_slg4bd44540.c
index ccc260c289..09ba6f01e6 100644
--- a/power/alderlake_slg4bd44540.c
+++ b/power/alderlake_slg4bd44540.c
@@ -16,6 +16,7 @@
 #include "power.h"
 #include "power/alderlake_slg4bd44540.h"
 #include "power/intel_x86.h"
+#include "system_boot_time.h"
 #include "timer.h"
 
 /*
@@ -256,6 +257,8 @@ enum power_state power_handle_state(enum power_state state)
 	case POWER_G3S5:
 		GPIO_SET_LEVEL(GPIO_EN_S5_RAILS, 1);
 
+		update_ap_boot_time(ARAIL);
+
 		if (power_wait_signals(IN_PGOOD_ALL_CORE))
 			break;
 
diff --git a/power/icelake.c b/power/icelake.c
index e81a6f6942..7d60e26f40 100644
--- a/power/icelake.c
+++ b/power/icelake.c
@@ -13,6 +13,7 @@
 #include "power.h"
 #include "power/intel_x86.h"
 #include "power_button.h"
+#include "system_boot_time.h"
 #include "task.h"
 #include "timer.h"
 
@@ -280,6 +281,9 @@ enum power_state power_handle_state(enum power_state state)
 		 */
 		/* Turn on the PP3300_DSW rail. */
 		GPIO_SET_LEVEL(GPIO_EN_PP3300_A, 1);
+
+		update_ap_boot_time(ARAIL);
+
 		if (power_wait_signals(IN_PGOOD_ALL_CORE))
 			break;
 
diff --git a/power/intel_x86.c b/power/intel_x86.c
index 4fa3aa3c8e..223942f897 100644
--- a/power/intel_x86.c
+++ b/power/intel_x86.c
@@ -17,6 +17,7 @@
 #include "power/intel_x86.h"
 #include "power_button.h"
 #include "system.h"
+#include "system_boot_time.h"
 #include "task.h"
 #include "util.h"
 #include "vboot.h"
@@ -583,6 +584,8 @@ void common_intel_x86_handle_rsmrst(enum power_state state)
 
 	gpio_set_level(GPIO_PCH_RSMRST_L, rsmrst_in);
 
+	update_ap_boot_time(RSMRST);
+
 	CPRINTS("Pass through GPIO_PG_EC_RSMRST_ODL: %d", rsmrst_in);
 
 	board_after_rsmrst(rsmrst_in);
diff --git a/util/ectool.cc b/util/ectool.cc
index fd27105d1f..30184f1f63 100644
--- a/util/ectool.cc
+++ b/util/ectool.cc
@@ -8305,6 +8305,26 @@ int cmd_board_version(int argc, char *argv[])
 	return rv;
 }
 
+int cmd_boottime(int argc, char *argv[])
+{
+	struct ap_boot_time_data response;
+	int rv;
+
+	rv = ec_command(EC_CMD_GET_BOOT_TIME, 0, NULL, 0, &response,
+			sizeof(response));
+	if (rv < 0)
+		return rv;
+
+	printf("arail: %ld\n", response.timestamp[ARAIL]);
+	printf("rsmrst: %ld\n", response.timestamp[RSMRST]);
+	printf("espirst: %ld\n", response.timestamp[ESPIRST]);
+	printf("pltrst_low: %ld\n", response.timestamp[PLTRST_LOW]);
+	printf("pltrst_high: %ld\n", response.timestamp[PLTRST_HIGH]);
+	printf("cnt: %d\n", response.cnt);
+	printf("ec_cur_time: %ld\n", response.timestamp[EC_CUR_TIME]);
+	return rv;
+}
+
 static void cmd_cbi_help(char *cmd)
 {
 	fprintf(stderr,
@@ -10935,6 +10955,7 @@ const struct command commands[] = {
 	{ "batterycutoff", cmd_battery_cut_off },
 	{ "batteryparam", cmd_battery_vendor_param },
 	{ "boardversion", cmd_board_version },
+	{ "boottime", cmd_boottime },
 	{ "button", cmd_button },
 	{ "cbi", cmd_cbi },
 	{ "chargecurrentlimit", cmd_charge_current_limit },
diff --git a/zephyr/CMakeLists.txt b/zephyr/CMakeLists.txt
index 0b36bcc24e..65070c8fba 100644
--- a/zephyr/CMakeLists.txt
+++ b/zephyr/CMakeLists.txt
@@ -146,6 +146,7 @@ zephyr_library_sources_ifdef(CONFIG_PLATFORM_EC
                                                 "${PLATFORM_EC}/common/queue.c"
                                                 "${PLATFORM_EC}/common/shared_mem.c"
                                                 "${PLATFORM_EC}/common/system.c"
+                                                "${PLATFORM_EC}/common/system_boot_time.c"
                                                 "${PLATFORM_EC}/common/uart_printf.c"
                                                 "${PLATFORM_EC}/common/util.c"
                                                 "${PLATFORM_EC}/common/version.c")
diff --git a/zephyr/Kconfig b/zephyr/Kconfig
index d80548ca39..4943a73676 100644
--- a/zephyr/Kconfig
+++ b/zephyr/Kconfig
@@ -800,4 +800,10 @@ config PLATFORM_EC_GPIO_ID
 	  devicetree node using the known nodelabels gpio_id_sku and
 	  gpio_id_board.
 
+config SYSTEM_BOOT_TIME_LOGGING
+	bool "boot time logging"
+	help
+	  This config enables boot time logging functionality in EC which
+	  is used for calculating system boot time.
+
 endif # PLATFORM_EC
diff --git a/zephyr/program/intelrvp/mtlrvp/src/board_power.c b/zephyr/program/intelrvp/mtlrvp/src/board_power.c
index e35450b8b5..c5b2ccc658 100644
--- a/zephyr/program/intelrvp/mtlrvp/src/board_power.c
+++ b/zephyr/program/intelrvp/mtlrvp/src/board_power.c
@@ -17,6 +17,8 @@
 #include <power_signals.h>
 #include <x86_power_signals.h>
 
+#include "system_boot_time.h"
+
 LOG_MODULE_DECLARE(ap_pwrseq, LOG_LEVEL_INF);
 
 #if CONFIG_X86_NON_DSX_PWRSEQ_MTL
@@ -47,6 +49,7 @@ void board_ap_power_action_g3_s5(void)
 	/* Turn on the PP3300_PRIM rail. */
 	power_signal_set(PWR_EN_PP3300_A, 1);
 
+	update_ap_boot_time(ARAIL);
 	if (!power_wait_signals_timeout(
 		    IN_PGOOD_ALL_CORE,
 		    AP_PWRSEQ_DT_VALUE(wait_signal_timeout))) {
diff --git a/zephyr/program/nissa/src/board_power.c b/zephyr/program/nissa/src/board_power.c
index 858076686b..bdd571e4ca 100644
--- a/zephyr/program/nissa/src/board_power.c
+++ b/zephyr/program/nissa/src/board_power.c
@@ -17,6 +17,8 @@
 #include <power_signals.h>
 #include <x86_power_signals.h>
 
+#include "system_boot_time.h"
+
 LOG_MODULE_DECLARE(ap_pwrseq, LOG_LEVEL_INF);
 
 #define X86_NON_DSX_ADLP_NONPWRSEQ_FORCE_SHUTDOWN_TO_MS 5
@@ -87,6 +89,7 @@ void board_ap_power_action_g3_s5(void)
 	power_signal_set(PWR_EN_PP5000_A, 1);
 	power_signal_set(PWR_EN_PP3300_A, 1);
 
+	update_ap_boot_time(ARAIL);
 	power_wait_signals_timeout(IN_PGOOD_ALL_CORE,
 				   AP_PWRSEQ_DT_VALUE(wait_signal_timeout));
 
diff --git a/zephyr/shim/src/espi.c b/zephyr/shim/src/espi.c
index 9cc5de8f0b..5f053908db 100644
--- a/zephyr/shim/src/espi.c
+++ b/zephyr/shim/src/espi.c
@@ -16,6 +16,7 @@
 #include "task.h"
 #include "timer.h"
 #include "zephyr_espi_shim.h"
+#include "system_boot_time.h"
 
 #include <stdint.h>
 
@@ -162,6 +163,8 @@ static void espi_chipset_reset(void)
 	} else {
 		hook_notify(HOOK_CHIPSET_RESET);
 	}
+
+	update_ap_boot_time(ESPIRST);
 }
 DECLARE_DEFERRED(espi_chipset_reset);
 #endif /* CONFIG_PLATFORM_EC_CHIPSET_RESET_HOOK */
@@ -189,6 +192,10 @@ static void espi_vwire_handler(const struct device *dev,
 	if (event.evt_details == ESPI_VWIRE_SIGNAL_PLTRST &&
 	    event.evt_data == 0) {
 		hook_call_deferred(&espi_chipset_reset_data, MSEC);
+		update_ap_boot_time(PLTRST_LOW);
+	} else if (event.evt_details == ESPI_VWIRE_SIGNAL_PLTRST &&
+		   event.evt_data == 1) {
+		update_ap_boot_time(PLTRST_HIGH);
 	}
 #endif
 }
diff --git a/zephyr/test/system_common/prj.conf b/zephyr/test/system_common/prj.conf
index 67dc659eed..dafd50345b 100644
--- a/zephyr/test/system_common/prj.conf
+++ b/zephyr/test/system_common/prj.conf
@@ -14,3 +14,4 @@ CONFIG_PLATFORM_EC_LID_SWITCH=n
 CONFIG_PLATFORM_EC_PANIC=n
 CONFIG_PLATFORM_EC_SWITCH=n
 CONFIG_PLATFORM_EC_VBOOT_HASH=n
+CONFIG_SYSTEM_BOOT_TIME_LOGGING=y
diff --git a/zephyr/test/system_common/src/get_boot_time.c b/zephyr/test/system_common/src/get_boot_time.c
new file mode 100644
index 0000000000..9bf5f12406
--- /dev/null
+++ b/zephyr/test/system_common/src/get_boot_time.c
@@ -0,0 +1,45 @@
+/* Copyright 2022 The ChromiumOS Authors
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#include "host_command.h"
+#include "hooks.h"
+#include "system.h"
+#include "system_boot_time.h"
+
+#include <zephyr/device.h>
+#include <zephyr/fff.h>
+#include <zephyr/ztest_assert.h>
+#include <zephyr/ztest_test_new.h>
+
+ZTEST_SUITE(host_cmd_get_boot_time, NULL, NULL, NULL, NULL, NULL);
+
+ZTEST(host_cmd_get_boot_time, test_get_boot_time)
+{
+	int ret;
+	struct ap_boot_time_data r;
+	struct host_cmd_handler_args args =
+		BUILD_HOST_COMMAND_RESPONSE(EC_CMD_GET_BOOT_TIME, 0, r);
+
+	update_ap_boot_time(ARAIL);
+	update_ap_boot_time(RSMRST);
+	update_ap_boot_time(ESPIRST);
+	update_ap_boot_time(PLTRST_LOW);
+	update_ap_boot_time(PLTRST_HIGH);
+	update_ap_boot_time(EC_CUR_TIME);
+	/* trigger update_ap_boot_time(RESET_CNT) */
+	hook_notify(HOOK_CHIPSET_SHUTDOWN_COMPLETE);
+
+	ret = host_command_process(&args);
+
+	zassert_equal(ret, EC_SUCCESS, "Unexpected return value: %d", ret);
+
+	ccprintf("arail: %llu\n", r.timestamp[ARAIL]);
+	ccprintf("rsmrst: %llu\n", r.timestamp[RSMRST]);
+	ccprintf("espirst: %llu\n", r.timestamp[ESPIRST]);
+	ccprintf("pltrst_low: %llu\n", r.timestamp[PLTRST_LOW]);
+	ccprintf("pltrst_high: %llu\n", r.timestamp[PLTRST_HIGH]);
+	ccprintf("cnt: %d\n", r.cnt);
+	ccprintf("ec_cur_time: %llu\n", r.timestamp[EC_CUR_TIME]);
+}