charge_manager: Log charge-related change events

Add the charging events to the PD event log FIFO
and add an ectool to retrieve/decode them.

BUG=chrome-os-partner:33248
TEST=Manual on Samus. Run `ectool --name cros_pd pdlog`, verify that
all log entries are dumped and the content matches expectation.
BRANCH=Samus

Original-Change-Id: I65dd5696cc0487856ab42aff24134bcdfa1a8219
Signed-off-by: Shawn Nematbakhsh <shawnn@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/238093
Commit-Queue: Vincent Palatin <vpalatin@chromium.org>
Trybot-Ready: Vincent Palatin <vpalatin@chromium.org>
Tested-by: Vincent Palatin <vpalatin@chromium.org>
Reviewed-by: Vincent Palatin <vpalatin@chromium.org>
Reviewed-by: Alec Berg <alecaberg@chromium.org>
(cherry picked from commit bd85bc46360e43b74aa1864565c5ad49b719a804)
Reviewed-on: https://chromium-review.googlesource.com/240838
(cherry picked from commit 97fe3555e00d21f2e5691fb3a7f8eb3a1c371b62)
Signed-off-by: Todd Broch <tbroch@chromium.org>

Change-Id: I46544529ba34ec57dee4940fa9bb834448e12875
Reviewed-on: https://chromium-review.googlesource.com/244223
Reviewed-by: Alec Berg <alecaberg@chromium.org>
Tested-by: Todd Broch <tbroch@chromium.org>
Commit-Queue: Todd Broch <tbroch@chromium.org>

2 files changed, 246 insertions, 138 deletions

diff --git a/common/charge_manager.c b/common/charge_manager.c
index 470c20d08c..7fe9028c5c 100644
--- a/common/charge_manager.c
+++ b/common/charge_manager.c
@@ -88,6 +88,134 @@ static int charge_manager_is_seeded(void)
 	return 1;
 }
 
+#ifndef TEST_CHARGE_MANAGER
+/**
+ * Fills passed power_info structure with current info about the passed port.
+ */
+static void charge_manager_fill_power_info(int port,
+	struct ec_response_usb_pd_power_info *r)
+{
+	int sup = CHARGE_SUPPLIER_NONE;
+	int i;
+
+	/* Determine supplier information to show. */
+	if (port == charge_port)
+		sup = charge_supplier;
+	else
+		/* Find highest priority supplier */
+		for (i = 0; i < CHARGE_SUPPLIER_COUNT; ++i)
+			if (available_charge[i][port].current > 0 &&
+			    available_charge[i][port].voltage > 0 &&
+			    (sup == CHARGE_SUPPLIER_NONE ||
+			     supplier_priority[i] <
+			     supplier_priority[sup] ||
+			    (supplier_priority[i] ==
+			     supplier_priority[sup] &&
+			     POWER(available_charge[i][port]) >
+			     POWER(available_charge[sup]
+						   [port]))))
+				sup = i;
+
+	/* Fill in power role */
+	if (charge_port == port)
+		r->role = USB_PD_PORT_POWER_SINK;
+	else if (pd_is_connected(port) && pd_get_role(port) == PD_ROLE_SOURCE)
+		r->role = USB_PD_PORT_POWER_SOURCE;
+	else if (sup != CHARGE_SUPPLIER_NONE)
+		r->role = USB_PD_PORT_POWER_SINK_NOT_CHARGING;
+	else
+		r->role = USB_PD_PORT_POWER_DISCONNECTED;
+
+	/* Is port partner dual-role capable */
+	r->dualrole = pd_get_partner_dualrole_capable(port);
+
+	if (sup == CHARGE_SUPPLIER_NONE ||
+	    r->role == USB_PD_PORT_POWER_SOURCE) {
+		r->type = USB_CHG_TYPE_NONE;
+		r->meas.voltage_max = 0;
+		r->meas.voltage_now = r->role == USB_PD_PORT_POWER_SOURCE ? 5000
+									  : 0;
+		r->meas.current_max = 0;
+		r->max_power = 0;
+	} else {
+		switch (sup) {
+		case CHARGE_SUPPLIER_PD:
+			r->type = USB_CHG_TYPE_PD;
+			break;
+		case CHARGE_SUPPLIER_TYPEC:
+			r->type = USB_CHG_TYPE_C;
+			break;
+		case CHARGE_SUPPLIER_PROPRIETARY:
+			r->type = USB_CHG_TYPE_PROPRIETARY;
+			break;
+		case CHARGE_SUPPLIER_BC12_DCP:
+			r->type = USB_CHG_TYPE_BC12_DCP;
+			break;
+		case CHARGE_SUPPLIER_BC12_CDP:
+			r->type = USB_CHG_TYPE_BC12_CDP;
+			break;
+		case CHARGE_SUPPLIER_BC12_SDP:
+			r->type = USB_CHG_TYPE_BC12_SDP;
+			break;
+		default:
+			r->type = USB_CHG_TYPE_OTHER;
+		}
+		r->meas.voltage_max = available_charge[sup][port].voltage;
+		r->meas.current_max = available_charge[sup][port].current;
+		r->max_power = POWER(available_charge[sup][port]);
+
+		/*
+		 * If we are sourcing power, or sinking but not charging, then
+		 * VBUS must be 5V. If we are charging, then read VBUS ADC.
+		 */
+		if (r->role == USB_PD_PORT_POWER_SINK_NOT_CHARGING)
+			r->meas.voltage_now = 5000;
+		else
+			r->meas.voltage_now = adc_read_channel(ADC_VBUS);
+	}
+}
+#endif /* TEST_CHARGE_MANAGER */
+
+#ifdef CONFIG_USB_PD_LOGGING
+/**
+ * Saves a power state log entry with the current info about the passed port.
+ */
+static void charge_manager_save_log(int port)
+{
+	uint16_t flags = 0;
+	struct ec_response_usb_pd_power_info pinfo;
+	uint16_t voltage_now;
+	static uint16_t last_voltage[PD_PORT_COUNT];
+	static uint16_t last_flags[PD_PORT_COUNT];
+
+	charge_manager_fill_power_info(port, &pinfo);
+
+	/* Flags are stored in the data field */
+	if (port == override_port)
+		flags |= CHARGE_FLAGS_OVERRIDE;
+	if (port == delayed_override_port)
+		flags |= CHARGE_FLAGS_DELAYED_OVERRIDE;
+	flags |= pinfo.role | (pinfo.type << CHARGE_FLAGS_TYPE_SHIFT) |
+		 (pinfo.dualrole ? CHARGE_FLAGS_DUAL_ROLE : 0);
+
+	/*
+	 * Check for a log change, not considering timestamp. Also, ignore
+	 * voltage_now fluctuations of < 500mV.
+	 */
+	voltage_now = pinfo.meas.voltage_now;
+	if (last_flags[port] == flags &&
+	    voltage_now < last_voltage[port] + 500 &&
+	    last_voltage[port] < voltage_now + 500)
+		return;
+	last_voltage[port] = voltage_now;
+	last_flags[port] = flags;
+
+	pd_log_event(PD_EVENT_MCU_CHARGE,
+		     PD_LOG_PORT_SIZE(port, sizeof(pinfo.meas)),
+		     flags, &pinfo.meas);
+}
+#endif /* CONFIG_USB_PD_LOGGING */
+
 /**
  * Perform cleanup operations on an override port, when switching to a
  * different port. This involves switching the port from sink to source,
@@ -276,6 +404,12 @@ static void charge_manager_refresh(void)
 	charge_supplier = new_supplier;
 	charge_port = new_port;
 
+#ifdef CONFIG_USB_PD_LOGGING
+	/* Log possible charge state changes. */
+	for (i = 0; i < PD_PORT_COUNT; ++i)
+		charge_manager_save_log(i);
+#endif
+
 	/* New power requests must be set only after updating the globals. */
 	if (updated_new_port != CHARGE_PORT_NONE)
 		pd_set_new_power_request(updated_new_port);
@@ -436,89 +570,12 @@ static int hc_pd_power_info(struct host_cmd_handler_args *args)
 	const struct ec_params_usb_pd_power_info *p = args->params;
 	struct ec_response_usb_pd_power_info *r = args->response;
 	int port = p->port;
-	int sup = CHARGE_SUPPLIER_NONE;
-	int i;
 
 	/* If host is asking for the charging port, set port appropriately */
 	if (port == PD_POWER_CHARGING_PORT)
 		port = charge_port;
 
-	/* Determine supplier information to show */
-	if (port == charge_port) {
-		sup = charge_supplier;
-	} else {
-		/* Find highest priority supplier */
-		for (i = 0; i < CHARGE_SUPPLIER_COUNT; ++i) {
-			if (available_charge[i][port].current > 0 &&
-			    available_charge[i][port].voltage > 0 &&
-			    (sup == CHARGE_SUPPLIER_NONE ||
-			     supplier_priority[i] <
-			     supplier_priority[sup] ||
-			    (supplier_priority[i] ==
-			     supplier_priority[sup] &&
-			     POWER(available_charge[i][port]) >
-			     POWER(available_charge[sup]
-						   [port]))))
-				sup = i;
-		}
-	}
-
-	/* Fill in power role */
-	if (charge_port == port)
-		r->role = USB_PD_PORT_POWER_SINK;
-	else if (pd_is_connected(port) && pd_get_role(port) == PD_ROLE_SOURCE)
-		r->role = USB_PD_PORT_POWER_SOURCE;
-	else if (sup != CHARGE_SUPPLIER_NONE)
-		r->role = USB_PD_PORT_POWER_SINK_NOT_CHARGING;
-	else
-		r->role = USB_PD_PORT_POWER_DISCONNECTED;
-
-	/* Is port partner dual-role capable */
-	r->dualrole = pd_get_partner_dualrole_capable(port);
-
-	if (sup == CHARGE_SUPPLIER_NONE) {
-		r->type = USB_CHG_TYPE_NONE;
-		r->voltage_max = 0;
-		r->voltage_now = 0;
-		r->current_max = 0;
-		r->max_power = 0;
-	} else {
-		switch (sup) {
-		case CHARGE_SUPPLIER_PD:
-			r->type = USB_CHG_TYPE_PD;
-			break;
-		case CHARGE_SUPPLIER_TYPEC:
-			r->type = USB_CHG_TYPE_C;
-			break;
-		case CHARGE_SUPPLIER_PROPRIETARY:
-			r->type = USB_CHG_TYPE_PROPRIETARY;
-			break;
-		case CHARGE_SUPPLIER_BC12_DCP:
-			r->type = USB_CHG_TYPE_BC12_DCP;
-			break;
-		case CHARGE_SUPPLIER_BC12_CDP:
-			r->type = USB_CHG_TYPE_BC12_CDP;
-			break;
-		case CHARGE_SUPPLIER_BC12_SDP:
-			r->type = USB_CHG_TYPE_BC12_SDP;
-			break;
-		default:
-			r->type = USB_CHG_TYPE_OTHER;
-		}
-		r->voltage_max = available_charge[sup][port].voltage;
-		r->current_max = available_charge[sup][port].current;
-		r->max_power = POWER(available_charge[sup][port]);
-
-		/*
-		 * If we are sourcing power, or sinking but not charging, then
-		 * VBUS must be 5V. If we are charging, then read VBUS ADC.
-		 */
-		if (r->role == USB_PD_PORT_POWER_SOURCE ||
-		    r->role == USB_PD_PORT_POWER_SINK_NOT_CHARGING)
-			r->voltage_now = 5000;
-		else
-			r->voltage_now = adc_read_channel(ADC_VBUS);
-	}
+	charge_manager_fill_power_info(port, r);
 
 	args->response_size = sizeof(*r);
 	return EC_RES_SUCCESS;
diff --git a/util/ectool.c b/util/ectool.c
index 7be3fad5c2..142c248d3f 100644
--- a/util/ectool.c
+++ b/util/ectool.c
@@ -6,6 +6,7 @@
 #include <ctype.h>
 #include <errno.h>
 #include <getopt.h>
+#include <inttypes.h>
 #include <stdint.h>
 #include <stdio.h>
 #include <stdlib.h>
@@ -137,6 +138,8 @@ const char help_str[] =
 	"      Prints saved panic info\n"
 	"  pause_in_s5 [on|off]\n"
 	"      Whether or not the AP should pause in S5 on shutdown\n"
+	"  pdlog\n"
+	"      Prints the PD event log entries\n"
 	"  port80flood\n"
 	"      Rapidly write bytes to port 80\n"
 	"  port80read\n"
@@ -2965,6 +2968,65 @@ int cmd_usb_pd(int argc, char *argv[])
 	return (rv < 0 ? rv : 0);
 }
 
+static void print_pd_power_info(struct ec_response_usb_pd_power_info *r)
+{
+	printf("Power role: ");
+
+	switch (r->role) {
+	case USB_PD_PORT_POWER_DISCONNECTED:
+		printf("Disconnected\n");
+		break;
+	case USB_PD_PORT_POWER_SOURCE:
+		printf("Source\n");
+		break;
+	case USB_PD_PORT_POWER_SINK:
+		printf("Sink\n");
+		break;
+	case USB_PD_PORT_POWER_SINK_NOT_CHARGING:
+		printf("Sink (not charging)\n");
+		break;
+	default:
+		printf("Unknown\n");
+	}
+
+	if (r->role != USB_PD_PORT_POWER_DISCONNECTED) {
+		printf("  %s\n", r->dualrole ?
+		       "Dual-role device" : "Dedicated charger");
+	}
+
+	printf("  Charger type: ");
+	switch (r->type) {
+	case USB_CHG_TYPE_PD:
+		printf("PD\n");
+		break;
+	case USB_CHG_TYPE_C:
+		printf("Type-c\n");
+		break;
+	case USB_CHG_TYPE_PROPRIETARY:
+		printf("Proprietary\n");
+		break;
+	case USB_CHG_TYPE_BC12_DCP:
+		printf("BC1.2 DCP\n");
+		break;
+	case USB_CHG_TYPE_BC12_CDP:
+		printf("BC1.2 CDP\n");
+		break;
+	case USB_CHG_TYPE_BC12_SDP:
+		printf("BC1.2 SDP\n");
+		break;
+	case USB_CHG_TYPE_OTHER:
+		printf("Other\n");
+		break;
+	default:
+		printf("None\n");
+	}
+	printf("  Max charging voltage: %dmV\n", r->meas.voltage_max);
+	printf("  Current charging voltage: %dmV\n", r->meas.voltage_now);
+	printf("  Max input current: %dmA\n", r->meas.current_max);
+	printf("  Max input power: %dmW\n", r->max_power / 1000);
+	printf("\n");
+}
+
 int cmd_usb_pd_power(int argc, char *argv[])
 {
 	struct ec_params_usb_pd_power_info p;
@@ -2986,66 +3048,8 @@ int cmd_usb_pd_power(int argc, char *argv[])
 		if (rv < 0)
 			return rv;
 
-		printf("Port %d:\n  Power role: ", i);
-		switch (r->role) {
-		case USB_PD_PORT_POWER_DISCONNECTED:
-			printf("Disconnected\n");
-			break;
-		case USB_PD_PORT_POWER_SOURCE:
-			printf("Source\n");
-			break;
-		case USB_PD_PORT_POWER_SINK:
-			printf("Sink\n");
-			break;
-		case USB_PD_PORT_POWER_SINK_NOT_CHARGING:
-			printf("Sink (not charging)\n");
-			break;
-		default:
-			printf("Unknown\n");
-		}
-
-		if (r->role != USB_PD_PORT_POWER_DISCONNECTED) {
-			printf("  %s\n", r->dualrole ?
-				"Dual-role device" : "Dedicated charger");
-		}
-
-		printf("  Charger type: ");
-		switch (r->type) {
-		case USB_CHG_TYPE_PD:
-			printf("PD\n");
-			break;
-		case USB_CHG_TYPE_C:
-			printf("Type-c\n");
-			break;
-		case USB_CHG_TYPE_PROPRIETARY:
-			printf("Proprietary\n");
-			break;
-		case USB_CHG_TYPE_BC12_DCP:
-			printf("BC1.2 DCP\n");
-			break;
-		case USB_CHG_TYPE_BC12_CDP:
-			printf("BC1.2 CDP\n");
-			break;
-		case USB_CHG_TYPE_BC12_SDP:
-			printf("BC1.2 SDP\n");
-			break;
-		case USB_CHG_TYPE_OTHER:
-			printf("Other\n");
-			break;
-		default:
-			printf("None\n");
-		}
-
-		printf("  Max charging voltage: %dmV\n",
-			r->voltage_max);
-		printf("  Current charging voltage: %dmV\n",
-			r->voltage_now);
-		printf("  Max input current: %dmA\n",
-			r->current_max);
-		printf("  Max input power: %dmW\n",
-			r->max_power / 1000);
-
-		printf("\n");
+		printf("Port %d:\n", i);
+		print_pd_power_info(r);
 	}
 
 	return 0;
@@ -5232,6 +5236,52 @@ int cmd_charge_port_override(int argc, char *argv[])
 	return 0;
 }
 
+int cmd_pd_log(int argc, char *argv[])
+{
+	union {
+		struct ec_response_pd_log r;
+		uint32_t words[8]; /* space for the payload */
+	} u;
+	struct ec_response_usb_pd_power_info pinfo;
+	int rv;
+
+	while (1) {
+		rv = ec_command(EC_CMD_PD_GET_LOG_ENTRY, 0,
+				NULL, 0, &u, sizeof(u));
+		if (rv < 0)
+			return rv;
+
+		if (u.r.type == PD_EVENT_NO_ENTRY) {
+			printf("--- END OF LOG ---\n");
+			break;
+		}
+
+		printf("Port: %d, %"PRIu64" ms ago : ",
+			PD_LOG_PORT(u.r.size_port),
+			(uint64_t)(u.r.timestamp << PD_LOG_TIMESTAMP_SHIFT)
+				 / 1000);
+		if (u.r.type == PD_EVENT_MCU_CHARGE) {
+			if (u.r.data & CHARGE_FLAGS_OVERRIDE)
+				printf("override ");
+			if (u.r.data & CHARGE_FLAGS_DELAYED_OVERRIDE)
+				printf("pending_override ");
+			printf("\n");
+			memcpy(&pinfo.meas, u.r.payload,
+				sizeof(struct usb_chg_measures));
+			pinfo.dualrole = !!(u.r.data & CHARGE_FLAGS_DUAL_ROLE);
+			pinfo.role = u.r.data & CHARGE_FLAGS_ROLE_MASK;
+			pinfo.type = (u.r.data & CHARGE_FLAGS_TYPE_MASK)
+					>> CHARGE_FLAGS_TYPE_SHIFT;
+			pinfo.max_power = 0;
+			print_pd_power_info(&pinfo);
+		} else { /* Unknown type */
+			printf(" event %02x\n", u.r.type);
+		}
+	}
+
+	return 0;
+}
+
 /* NULL-terminated list of commands */
 const struct command commands[] = {
 	{"extpwrcurrentlimit", cmd_ext_power_current_limit},
@@ -5285,6 +5335,7 @@ const struct command commands[] = {
 	{"panicinfo", cmd_panic_info},
 	{"pause_in_s5", cmd_s5},
 	{"port80read", cmd_port80_read},
+	{"pdlog", cmd_pd_log},
 	{"powerinfo", cmd_power_info},
 	{"protoinfo", cmd_proto_info},
 	{"pstoreinfo", cmd_pstore_info},