[PATCH v2 03/10] usb: tcpm: add lightweight PD negotiation tracing

[Peng Fan (OSS)]

From: Peng Fan <peng.fan at nxp.com>

Add a zero-overhead ring buffer trace facility for debugging USB PD
negotiation timing issues. Trace points record timestamp and event
to a RAM buffer without any serial output, avoiding interference
with PD protocol timing constraints.

Trace points cover the critical PD sink negotiation path:
- Source_Capabilities reception
- Request construction and transmission
- TX completion polling
- Accept/PS_RDY reception
- SNK_READY state entry
- Post-ready polling

The trace buffer can be dumped on demand via pd_trace_dump() for
post-mortem analysis of PD negotiation failures.

Signed-off-by: Peng Fan <peng.fan at nxp.com>
---
 drivers/usb/tcpm/tcpm-internal.h | 40 ++++++++++++++++++++++++++++++++++++++++
 drivers/usb/tcpm/tcpm.c          | 17 +++++++++++++++++
 2 files changed, 57 insertions(+)

diff --git a/drivers/usb/tcpm/tcpm-internal.h b/drivers/usb/tcpm/tcpm-internal.h
index 56144209002..138b0dc089e 100644
--- a/drivers/usb/tcpm/tcpm-internal.h
+++ b/drivers/usb/tcpm/tcpm-internal.h
@@ -166,6 +166,46 @@ struct tcpm_port {
 	unsigned long delay_target;
 };
 
+#define PD_TRACE_MAX 32
+
+struct pd_trace_entry {
+	unsigned long ts_us;
+	const char *event;
+	u32 val;
+};
+
+struct pd_trace_buf {
+	struct pd_trace_entry entries[PD_TRACE_MAX];
+	int count;
+};
+
+extern struct pd_trace_buf g_pd_trace;
+
+static inline void pd_trace(const char *event, u32 val)
+{
+	if (g_pd_trace.count < PD_TRACE_MAX) {
+		struct pd_trace_entry *e = &g_pd_trace.entries[g_pd_trace.count++];
+
+		e->ts_us = timer_get_us();
+		e->event = event;
+		e->val = val;
+	}
+}
+
+static inline void pd_trace_dump(void)
+{
+	int i;
+	unsigned long base = g_pd_trace.count > 0 ? g_pd_trace.entries[0].ts_us : 0;
+
+	printf("=== PD TRACE (%d entries) ===\n", g_pd_trace.count);
+	for (i = 0; i < g_pd_trace.count; i++) {
+		struct pd_trace_entry *e = &g_pd_trace.entries[i];
+
+		printf("[+%7luus] %-30s 0x%08x\n",
+		       e->ts_us - base, e->event, e->val);
+	}
+}
+
 extern const char * const tcpm_states[];
 
 int tcpm_post_probe(struct udevice *dev);
diff --git a/drivers/usb/tcpm/tcpm.c b/drivers/usb/tcpm/tcpm.c
index d6af0fae7c1..1ce46118fea 100644
--- a/drivers/usb/tcpm/tcpm.c
+++ b/drivers/usb/tcpm/tcpm.c
@@ -23,6 +23,8 @@ const char * const tcpm_states[] = {
 	FOREACH_TCPM_STATE(GENERATE_TCPM_STRING)
 };
 
+struct pd_trace_buf g_pd_trace;
+
 const char * const typec_pd_rev_name[] = {
 	[PD_REV10]		= "rev1",
 	[PD_REV20]		= "rev2",
@@ -193,7 +195,9 @@ static int tcpm_pd_transmit(struct udevice *dev,
 		dev_dbg(dev, "TCPM: PD TX, type: %#x\n", type);
 
 	port->tx_complete = false;
+	pd_trace("PD_TX_START", type);
 	ret = drvops->pd_transmit(dev, type, msg, port->negotiated_rev);
+	pd_trace("PD_TX_DONE", ret);
 	if (ret < 0)
 		return ret;
 
@@ -213,6 +217,7 @@ static int tcpm_pd_transmit(struct udevice *dev,
 		return ret;
 	}
 
+	pd_trace("TX_POLL_DONE", port->tx_status);
 	switch (port->tx_status) {
 	case TCPC_TX_SUCCESS:
 		port->message_id = (port->message_id + 1) & PD_HEADER_ID_MASK;
@@ -626,6 +631,7 @@ static void tcpm_pd_data_request(struct udevice *dev,
 
 	switch (type) {
 	case PD_DATA_SOURCE_CAP:
+		pd_trace("RX_SOURCE_CAP", cnt);
 		for (i = 0; i < cnt; i++)
 			port->source_caps[i] = le32_to_cpu(msg->payload[i]);
 
@@ -668,6 +674,7 @@ static void tcpm_pd_data_request(struct udevice *dev,
 		 * but be prepared to keep waiting for VBUS after it was
 		 * handled.
 		 */
+		pd_trace("SET_SNK_NEGOTIATE", 0);
 		tcpm_set_state(dev, SNK_NEGOTIATE_CAPABILITIES, 0);
 		break;
 	case PD_DATA_REQUEST:
@@ -736,6 +743,7 @@ static void tcpm_pd_ctrl_request(struct udevice *dev,
 	case PD_CTRL_GOTO_MIN:
 		break;
 	case PD_CTRL_PS_RDY:
+		pd_trace("RX_PS_RDY", port->state);
 		switch (port->state) {
 		case SNK_TRANSITION_SINK:
 			if (port->vbus_present) {
@@ -775,6 +783,7 @@ static void tcpm_pd_ctrl_request(struct udevice *dev,
 		}
 		break;
 	case PD_CTRL_ACCEPT:
+		pd_trace("RX_ACCEPT", port->state);
 		switch (port->state) {
 		case SNK_NEGOTIATE_CAPABILITIES:
 			tcpm_set_state(dev, SNK_TRANSITION_SINK, 0);
@@ -1655,9 +1664,13 @@ static void run_state_machine(struct udevice *dev)
 		}
 		break;
 	case SNK_NEGOTIATE_CAPABILITIES:
+		pd_trace("SNK_NEGOTIATE_ENTER", 0);
 		port->pd_capable = true;
 		port->hard_reset_count = 0;
 		ret = tcpm_pd_send_request(dev);
+		pd_trace("SNK_NEGOTIATE_SENT", ret);
+		pd_trace("REQ_MV", port->req_supply_voltage);
+		pd_trace("REQ_MA", port->req_current_limit);
 		if (ret < 0) {
 			/* Let the Source send capabilities again. */
 			tcpm_set_state(dev, SNK_WAIT_CAPABILITIES, 0);
@@ -1672,8 +1685,10 @@ static void run_state_machine(struct udevice *dev)
 			       PD_T_PS_TRANSITION);
 		break;
 	case SNK_READY:
+		pd_trace("SNK_READY", 0);
 		port->update_sink_caps = false;
 		tcpm_typec_connect(port);
+
 		/*
 		 * Here poll_event_cnt is cleared, waiting for self-powered Type-C devices
 		 * to send DR_swap Messge until 1s (TCPM_POLL_EVENT_TIME_OUT * 500us)timeout
@@ -2255,11 +2270,13 @@ static void tcpm_poll_event(struct udevice *dev)
 	if (port->state == SNK_READY || port->state == SRC_READY) {
 		int settle;
 
+		pd_trace("POST_READY_POLL_START", port->state);
 		for (settle = 0; settle < 1000; settle++) {
 			drvops->poll_event(dev);
 			udelay(500);
 			tcpm_check_and_run_delayed_work(dev);
 		}
+		pd_trace("POST_READY_POLL_DONE", port->state);
 	}
 
 	if (port->state != SNK_READY && port->state != SRC_READY)

-- 
2.51.0