From 7069fa2e585a1b5642c428d0466c69168ae40196 Mon Sep 17 00:00:00 2001 From: Diana Z Date: Mon, 4 May 2020 16:48:58 -0600 Subject: TCPMv2: Add PRL state entry prints for debugging This commit adds printing of the PRL states on entry when debug level 2 has been selected. BRANCH=None BUG=b:155229288 TEST=on kindred with TCPMv2, no PRL states print by default but when debug level is set to 2 states are seen Signed-off-by: Diana Z Change-Id: I7049205c44ebf9e98b910d773603adde844e6849 Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/2181714 Reviewed-by: Denis Brockus --- common/usbc/usb_prl_sm.c | 212 ++++++++++++++++++++++++++++++++++++----------- 1 file changed, 165 insertions(+), 47 deletions(-) diff --git a/common/usbc/usb_prl_sm.c b/common/usbc/usb_prl_sm.c index fc3e8c54f0..f49f9810a3 100644 --- a/common/usbc/usb_prl_sm.c +++ b/common/usbc/usb_prl_sm.c @@ -32,6 +32,14 @@ #include "vpd_api.h" #include "version.h" +#ifdef CONFIG_COMMON_RUNTIME +#define CPRINTF(format, args...) cprintf(CC_USBPD, format, ## args) +#define CPRINTS(format, args...) cprints(CC_USBPD, format, ## args) +#else +#define CPRINTF(format, args...) +#define CPRINTS(format, args...) +#endif + #define RCH_SET_FLAG(port, flag) atomic_or(&rch[port].flags, (flag)) #define RCH_CLR_FLAG(port, flag) atomic_clear(&rch[port].flags, (flag)) #define RCH_CHK_FLAG(port, flag) (rch[port].flags & (flag)) @@ -91,7 +99,7 @@ * Debug log level - higher number == more log * Level 0: disabled * Level 1: not currently used - * Level 2: plus non-ping messages + * Level 2: plus non-ping messages and PRL states * Level 3: plus ping packet and packet dump on error * * Note that higher log level causes timing changes and thus may affect @@ -148,6 +156,50 @@ enum usb_tch_state { TCH_REPORT_ERROR, }; +static const char * const prl_tx_state_names[] = { + [PRL_TX_PHY_LAYER_RESET] = "PRL_TX_PHY_LAYER_RESET", + [PRL_TX_WAIT_FOR_MESSAGE_REQUEST] = "PRL_TX_WAIT_FOR_MESSAGE_REQUEST", + [PRL_TX_LAYER_RESET_FOR_TRANSMIT] = "PRL_TX_LAYER_RESET_FOR_TRANSMIT", + [PRL_TX_WAIT_FOR_PHY_RESPONSE] = "PRL_TX_WAIT_FOR_PHY_RESPONSE", + [PRL_TX_SRC_SOURCE_TX] = "PRL_TX_SRC_SOURCE_TX", + [PRL_TX_SNK_START_AMS] = "PRL_TX_SNK_START_AMS", + [PRL_TX_SRC_PENDING] = "PRL_TX_SRC_PENDING", + [PRL_TX_SNK_PENDING] = "PRL_TX_SNK_PENDING", + [PRL_TX_DISCARD_MESSAGE] = "PRL_TX_DISCARD_MESSAGE", +}; + +static const char * const prl_hr_state_names[] = { + [PRL_HR_WAIT_FOR_REQUEST] = "PRL_HR_WAIT_FOR_REQUEST", + [PRL_HR_RESET_LAYER] = "PRL_HR_RESET_LAYER", + [PRL_HR_WAIT_FOR_PHY_HARD_RESET_COMPLETE] + = "PRL_HR_WAIT_FOR_PHY_HARD_RESET_COMPLETE", + [PRL_HR_WAIT_FOR_PE_HARD_RESET_COMPLETE] + = "PRL_HR_WAIT_FOR_PE_HARD_RESET_COMPLETE", +}; + +static const char * const rch_state_names[] = { + [RCH_WAIT_FOR_MESSAGE_FROM_PROTOCOL_LAYER] + = "RCH_WAIT_FOR_MESSAGE_FROM_PROTOCOL_LAYER", + [RCH_PASS_UP_MESSAGE] = "RCH_PASS_UP_MESSAGE", + [RCH_PROCESSING_EXTENDED_MESSAGE] = "RCH_PROCESSING_EXTENDED_MESSAGE", + [RCH_REQUESTING_CHUNK] = "RCH_REQUESTING_CHUNK", + [RCH_WAITING_CHUNK] = "RCH_WAITING_CHUNK", + [RCH_REPORT_ERROR] = "RCH_REPORT_ERROR", +}; + +static const char * const tch_state_names[] = { + [TCH_WAIT_FOR_MESSAGE_REQUEST_FROM_PE] + = "TCH_WAIT_FOR_MESSAGE_REQUEST_FROM_PE", + [TCH_WAIT_FOR_TRANSMISSION_COMPLETE] + = "TCH_WAIT_FOR_TRANSMISSION_COMPLETE", + [TCH_CONSTRUCT_CHUNKED_MESSAGE] = "TCH_CONSTRUCT_CHUNKED_MESSAGE", + [TCH_SENDING_CHUNKED_MESSAGE] = "TCH_SENDING_CHUNKED_MESSAGE", + [TCH_WAIT_CHUNK_REQUEST] = "TCH_WAIT_CHUNK_REQUEST", + [TCH_MESSAGE_RECEIVED] = "TCH_MESSAGE_RECEIVED", + [TCH_MESSAGE_SENT] = "TCH_MESSAGE_SENT", + [TCH_REPORT_ERROR] = "TCH_REPORT_ERROR", +}; + /* Forward declare full list of states. Index by above enums. */ static const struct usb_state prl_tx_states[]; static const struct usb_state prl_hr_states[]; @@ -257,6 +309,14 @@ test_export_static enum usb_prl_tx_state prl_tx_get_state(const int port) return prl_tx[port].ctx.current - &prl_tx_states[0]; } +/* Print the protocol transmit statemachine's current state. */ +static void print_current_prl_tx_state(const int port) +{ + if (prl_debug_level >= 2) + CPRINTS("C%d: %s", port, + prl_tx_state_names[prl_tx_get_state(port)]); +} + /* Set the hard reset statemachine to a new state. */ static void set_state_prl_hr(const int port, const enum usb_prl_hr_state new_state) @@ -264,13 +324,19 @@ static void set_state_prl_hr(const int port, set_state(port, &prl_hr[port].ctx, &prl_hr_states[new_state]); } -#ifdef TEST_BUILD /* Get the hard reset statemachine's current state. */ enum usb_prl_hr_state prl_hr_get_state(const int port) { return prl_hr[port].ctx.current - &prl_hr_states[0]; } -#endif + +/* Print the hard reset statemachine's current state. */ +static void print_current_prl_hr_state(const int port) +{ + if (prl_debug_level >= 2) + CPRINTS("C%d: %s", port, + prl_hr_state_names[prl_hr_get_state(port)]); +} /* Set the chunked Rx statemachine to a new state. */ static void set_state_rch(const int port, const enum usb_rch_state new_state) @@ -284,6 +350,15 @@ test_export_static enum usb_rch_state rch_get_state(const int port) return rch[port].ctx.current - &rch_states[0]; } +/* Print the chunked Rx statemachine's current state. */ +static void print_current_rch_state(const int port) +{ + if (prl_debug_level >= 2) + CPRINTS("C%d: %s", port, + rch_state_names[rch_get_state(port)]); +} + + /* Set the chunked Tx statemachine to a new state. */ static void set_state_tch(const int port, const enum usb_tch_state new_state) { @@ -296,6 +371,15 @@ test_export_static enum usb_tch_state tch_get_state(const int port) return tch[port].ctx.current - &tch_states[0]; } +/* Print the chunked Tx statemachine's current state. */ +static void print_current_tch_state(const int port) +{ + if (prl_debug_level >= 2) + CPRINTS("C%d: %s", port, + tch_state_names[tch_get_state(port)]); +} + + void pd_transmit_complete(int port, int status) { prl_tx[port].xmit_status = status; @@ -506,6 +590,8 @@ static int pdmsg_xmit_type_is_rev30(const int port) /* Common Protocol Layer Message Transmission */ static void prl_tx_phy_layer_reset_entry(const int port) { + print_current_prl_tx_state(port); + if (IS_ENABLED(CONFIG_USB_CTVPD) || IS_ENABLED(CONFIG_USB_VPD)) { vpd_rx_enable(pd_is_connected(port)); @@ -522,6 +608,8 @@ static void prl_tx_phy_layer_reset_run(const int port) static void prl_tx_wait_for_message_request_entry(const int port) { + print_current_prl_tx_state(port); + /* Reset RetryCounter */ prl_tx[port].retry_counter = 0; } @@ -616,6 +704,8 @@ static void increment_msgid_counter(int port) */ static void prl_tx_discard_message_entry(const int port) { + print_current_prl_tx_state(port); + /* Increment msgidCounter */ increment_msgid_counter(port); set_state_prl_tx(port, PRL_TX_PHY_LAYER_RESET); @@ -626,6 +716,8 @@ static void prl_tx_discard_message_entry(const int port) */ static void prl_tx_src_source_tx_entry(const int port) { + print_current_prl_tx_state(port); + /* Set Rp = SinkTxNG */ tcpm_select_rp_value(port, SINK_TX_NG); tcpm_set_cc(port, TYPEC_CC_RP); @@ -643,6 +735,11 @@ static void prl_tx_src_source_tx_run(const int port) /* * PrlTxSnkStartAms */ +static void prl_tx_snk_start_ams_entry(const int port) +{ + print_current_prl_tx_state(port); +} + static void prl_tx_snk_start_ams_run(const int port) { if (PRL_TX_CHK_FLAG(port, PRL_FLAGS_MSG_XMIT)) { @@ -659,6 +756,8 @@ static void prl_tx_layer_reset_for_transmit_entry(const int port) { int i; + print_current_prl_tx_state(port); + /* Reset MessageIdCounters */ for (i = 0; i < NUM_SOP_STAR_TYPES; i++) prl_tx[port].msg_id_counter[i] = 0; @@ -715,6 +814,8 @@ static void prl_tx_construct_message(const int port) */ static void prl_tx_wait_for_phy_response_entry(const int port) { + print_current_prl_tx_state(port); + prl_tx[port].tcpc_tx_timeout = get_time().val + PD_T_TCPC_TX_TIMEOUT; } @@ -795,6 +896,8 @@ static void prl_tx_wait_for_phy_response_exit(const int port) */ static void prl_tx_src_pending_entry(const int port) { + print_current_prl_tx_state(port); + /* Start SinkTxTimer */ prl_tx[port].sink_tx_timer = get_time().val + PD_T_SINK_TX; } @@ -826,6 +929,11 @@ static void prl_tx_src_pending_run(const int port) /* * PrlTxSnkPending */ +static void prl_tx_snk_pending_entry(const int port) +{ + print_current_prl_tx_state(port); +} + static void prl_tx_snk_pending_run(const int port) { enum tcpc_cc_voltage_status cc1, cc2; @@ -856,6 +964,8 @@ static void prl_tx_snk_pending_run(const int port) static void prl_hr_wait_for_request_entry(const int port) { + print_current_prl_hr_state(port); + prl_hr[port].flags = 0; } @@ -873,6 +983,8 @@ static void prl_hr_reset_layer_entry(const int port) { int i; + print_current_prl_hr_state(port); + /* reset messageIDCounters */ for (i = 0; i < NUM_SOP_STAR_TYPES; i++) prl_tx[port].msg_id_counter[i] = 0; @@ -929,6 +1041,8 @@ static void prl_hr_reset_layer_run(const int port) */ static void prl_hr_wait_for_phy_hard_reset_complete_entry(const int port) { + print_current_prl_hr_state(port); + /* Start HardResetCompleteTimer */ prl_hr[port].hard_reset_complete_timer = get_time().val + PD_T_PS_HARD_RESET; @@ -955,6 +1069,11 @@ static void prl_hr_wait_for_phy_hard_reset_complete_run(const int port) /* * PrlHrWaitForPeHardResetComplete */ +static void prl_hr_wait_for_pe_hard_reset_complete_entry(const int port) +{ + print_current_prl_hr_state(port); +} + static void prl_hr_wait_for_pe_hard_reset_complete_run(const int port) { /* @@ -995,6 +1114,8 @@ static void copy_chunk_to_ext(int port) */ static void rch_wait_for_message_from_protocol_layer_entry(const int port) { + print_current_rch_state(port); + /* Clear Abort flag */ PDMSG_CLR_FLAG(port, PRL_FLAGS_ABORT); @@ -1078,6 +1199,8 @@ static void rch_wait_for_message_from_protocol_layer_run(const int port) */ static void rch_pass_up_message_entry(const int port) { + print_current_rch_state(port); + /* Pass Message to Policy Engine */ pe_message_received(port); set_state_rch(port, RCH_WAIT_FOR_MESSAGE_FROM_PROTOCOL_LAYER); @@ -1086,6 +1209,11 @@ static void rch_pass_up_message_entry(const int port) /* * RchProcessingExtendedMessage */ +static void rch_processing_extended_message_entry(const int port) +{ + print_current_rch_state(port); +} + static void rch_processing_extended_message_run(const int port) { uint16_t exhdr = GET_EXT_HEADER(pdmsg[port].rx_chk_buf[0]); @@ -1153,6 +1281,8 @@ static void rch_processing_extended_message_run(const int port) */ static void rch_requesting_chunk_entry(const int port) { + print_current_rch_state(port); + /* * Send Chunk Request to Protocol Layer * with chunk number = Chunk_Number_Expected @@ -1197,6 +1327,8 @@ static void rch_requesting_chunk_run(const int port) */ static void rch_waiting_chunk_entry(const int port) { + print_current_rch_state(port); + /* * Start ChunkSenderResponseTimer */ @@ -1250,6 +1382,8 @@ static void rch_waiting_chunk_run(const int port) */ static void rch_report_error_entry(const int port) { + print_current_rch_state(port); + /* * If the state was entered because a message was received, * this message is passed to the Policy Engine. @@ -1283,6 +1417,8 @@ static void rch_report_error_run(const int port) */ static void tch_wait_for_message_request_from_pe_entry(const int port) { + print_current_tch_state(port); + /* Clear Abort flag */ PDMSG_CLR_FLAG(port, PRL_FLAGS_ABORT); @@ -1365,6 +1501,11 @@ static void tch_wait_for_message_request_from_pe_run(const int port) /* * TchWaitForTransmissionComplete */ +static void tch_wait_for_transmission_complete_entry(const int port) +{ + print_current_tch_state(port); +} + static void tch_wait_for_transmission_complete_run(const int port) { /* @@ -1393,6 +1534,8 @@ static void tch_construct_chunked_message_entry(const int port) uint8_t *data; uint16_t num; + print_current_tch_state(port); + /* * Any message received and not in state TCH_Wait_Chunk_Request */ @@ -1446,6 +1589,11 @@ static void tch_construct_chunked_message_run(const int port) /* * TchSendingChunkedMessage */ +static void tch_sending_chunked_message_entry(const int port) +{ + print_current_tch_state(port); +} + static void tch_sending_chunked_message_run(const int port) { /* @@ -1481,6 +1629,8 @@ static void tch_sending_chunked_message_run(const int port) */ static void tch_wait_chunk_request_entry(const int port) { + print_current_tch_state(port); + /* Increment Chunk Number to Send */ pdmsg[port].chunk_number_to_send++; /* Start Chunk Sender Request Timer */ @@ -1538,6 +1688,8 @@ static void tch_wait_chunk_request_run(const int port) */ static void tch_message_received_entry(const int port) { + print_current_tch_state(port); + /* Pass message to chunked Rx */ RCH_SET_FLAG(port, PRL_FLAGS_MSG_RECEIVED); } @@ -1552,6 +1704,8 @@ static void tch_message_received_run(const int port) */ static void tch_message_sent_entry(const int port) { + print_current_tch_state(port); + /* Tell PE message was sent */ pe_message_sent(port); set_state_tch(port, TCH_WAIT_FOR_MESSAGE_REQUEST_FROM_PE); @@ -1562,6 +1716,8 @@ static void tch_message_sent_entry(const int port) */ static void tch_report_error_entry(const int port) { + print_current_tch_state(port); + /* Report Error To Policy Engine */ pe_report_error(port, tch[port].error, prl_tx[port].last_xmit_type); set_state_tch(port, TCH_WAIT_FOR_MESSAGE_REQUEST_FROM_PE); @@ -1716,6 +1872,7 @@ static const struct usb_state prl_tx_states[] = { .run = prl_tx_src_source_tx_run, }, [PRL_TX_SNK_START_AMS] = { + .entry = prl_tx_snk_start_ams_entry, .run = prl_tx_snk_start_ams_run, }, [PRL_TX_SRC_PENDING] = { @@ -1723,6 +1880,7 @@ static const struct usb_state prl_tx_states[] = { .run = prl_tx_src_pending_run, }, [PRL_TX_SNK_PENDING] = { + .entry = prl_tx_snk_pending_entry, .run = prl_tx_snk_pending_run, }, [PRL_TX_DISCARD_MESSAGE] = { @@ -1745,6 +1903,7 @@ static const struct usb_state prl_hr_states[] = { .run = prl_hr_wait_for_phy_hard_reset_complete_run, }, [PRL_HR_WAIT_FOR_PE_HARD_RESET_COMPLETE] = { + .entry = prl_hr_wait_for_pe_hard_reset_complete_entry, .run = prl_hr_wait_for_pe_hard_reset_complete_run, .exit = prl_hr_wait_for_pe_hard_reset_complete_exit, }, @@ -1760,6 +1919,7 @@ static const struct usb_state rch_states[] = { .entry = rch_pass_up_message_entry, }, [RCH_PROCESSING_EXTENDED_MESSAGE] = { + .entry = rch_processing_extended_message_entry, .run = rch_processing_extended_message_run, }, [RCH_REQUESTING_CHUNK] = { @@ -1783,6 +1943,7 @@ static const struct usb_state tch_states[] = { .run = tch_wait_for_message_request_from_pe_run, }, [TCH_WAIT_FOR_TRANSMISSION_COMPLETE] = { + .entry = tch_wait_for_transmission_complete_entry, .run = tch_wait_for_transmission_complete_run, }, [TCH_CONSTRUCT_CHUNKED_MESSAGE] = { @@ -1790,6 +1951,7 @@ static const struct usb_state tch_states[] = { .run = tch_construct_chunked_message_run, }, [TCH_SENDING_CHUNKED_MESSAGE] = { + .entry = tch_sending_chunked_message_entry, .run = tch_sending_chunked_message_run, }, [TCH_WAIT_CHUNK_REQUEST] = { @@ -1810,50 +1972,6 @@ static const struct usb_state tch_states[] = { #ifdef TEST_BUILD -static const char * const prl_tx_state_names[] = { - [PRL_TX_PHY_LAYER_RESET] = "PRL_TX_PHY_LAYER_RESET", - [PRL_TX_WAIT_FOR_MESSAGE_REQUEST] = "PRL_TX_WAIT_FOR_MESSAGE_REQUEST", - [PRL_TX_LAYER_RESET_FOR_TRANSMIT] = "PRL_TX_LAYER_RESET_FOR_TRANSMIT", - [PRL_TX_WAIT_FOR_PHY_RESPONSE] = "PRL_TX_WAIT_FOR_PHY_RESPONSE", - [PRL_TX_SRC_SOURCE_TX] = "PRL_TX_SRC_SOURCE_TX", - [PRL_TX_SNK_START_AMS] = "PRL_TX_SNK_START_AMS", - [PRL_TX_SRC_PENDING] = "PRL_TX_SRC_PENDING", - [PRL_TX_SNK_PENDING] = "PRL_TX_SNK_PENDING", - [PRL_TX_DISCARD_MESSAGE] = "PRL_TX_DISCARD_MESSAGE", -}; - -static const char * const prl_hr_state_names[] = { - [PRL_HR_WAIT_FOR_REQUEST] = "PRL_HR_WAIT_FOR_REQUEST", - [PRL_HR_RESET_LAYER] = "PRL_HR_RESET_LAYER", - [PRL_HR_WAIT_FOR_PHY_HARD_RESET_COMPLETE] - = "PRL_HR_WAIT_FOR_PHY_HARD_RESET_COMPLETE", - [PRL_HR_WAIT_FOR_PE_HARD_RESET_COMPLETE] - = "PRL_HR_WAIT_FOR_PE_HARD_RESET_COMPLETE", -}; - -static const char * const rch_state_names[] = { - [RCH_WAIT_FOR_MESSAGE_FROM_PROTOCOL_LAYER] - = "RCH_WAIT_FOR_MESSAGE_FROM_PROTOCOL_LAYER", - [RCH_PASS_UP_MESSAGE] = "RCH_PASS_UP_MESSAGE", - [RCH_PROCESSING_EXTENDED_MESSAGE] = "RCH_PROCESSING_EXTENDED_MESSAGE", - [RCH_REQUESTING_CHUNK] = "RCH_REQUESTING_CHUNK", - [RCH_WAITING_CHUNK] = "RCH_WAITING_CHUNK", - [RCH_REPORT_ERROR] = "RCH_REPORT_ERROR", -}; - -static const char * const tch_state_names[] = { - [TCH_WAIT_FOR_MESSAGE_REQUEST_FROM_PE] - = "TCH_WAIT_FOR_MESSAGE_REQUEST_FROM_PE", - [TCH_WAIT_FOR_TRANSMISSION_COMPLETE] - = "TCH_WAIT_FOR_TRANSMISSION_COMPLETE", - [TCH_CONSTRUCT_CHUNKED_MESSAGE] = "TCH_CONSTRUCT_CHUNKED_MESSAGE", - [TCH_SENDING_CHUNKED_MESSAGE] = "TCH_SENDING_CHUNKED_MESSAGE", - [TCH_WAIT_CHUNK_REQUEST] = "TCH_WAIT_CHUNK_REQUEST", - [TCH_MESSAGE_RECEIVED] = "TCH_MESSAGE_RECEIVED", - [TCH_MESSAGE_SENT] = "TCH_MESSAGE_SENT", - [TCH_REPORT_ERROR] = "TCH_REPORT_ERROR", -}; - const struct test_sm_data test_prl_sm_data[] = { { .base = prl_tx_states, -- cgit v1.2.1