From: Peng Fan <[email protected]> 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 <[email protected]> --- 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
