| From 48ecaf14091fa21627c3837d4488d166fe588fba Mon Sep 17 00:00:00 2001 |
| From: Felipe Balbi <felipe.balbi@linux.intel.com> |
| Date: Fri, 7 Apr 2017 17:56:57 +0300 |
| Subject: [PATCH 183/286] usb: host: xhci: add Slot and EP Context tracers |
| |
| With these, we can track what's happening with the HW while executing |
| each and every command. It will give us visibility into how the |
| different contexts are being modified by xHC which can bring insight |
| into problems while debugging. |
| |
| Signed-off-by: Felipe Balbi <felipe.balbi@linux.intel.com> |
| Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com> |
| Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org> |
| (cherry picked from commit 19a7d0d65c4a813069f4bc4ca701d6a163c337e9) |
| Signed-off-by: Simon Horman <horms+renesas@verge.net.au> |
| --- |
| drivers/usb/host/xhci-ring.c | 42 ++++++++++++ |
| drivers/usb/host/xhci-trace.h | 101 +++++++++++++++++++++++++++++ |
| drivers/usb/host/xhci.c | 15 ++++- |
| drivers/usb/host/xhci.h | 146 ++++++++++++++++++++++++++++++++++++++++++ |
| 4 files changed, 302 insertions(+), 2 deletions(-) |
| |
| diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c |
| index a3309aa02993..2f700c9893bd 100644 |
| --- a/drivers/usb/host/xhci-ring.c |
| +++ b/drivers/usb/host/xhci-ring.c |
| @@ -689,6 +689,8 @@ static void xhci_handle_cmd_stop_ep(struct xhci_hcd *xhci, int slot_id, |
| struct xhci_virt_ep *ep; |
| struct xhci_td *cur_td = NULL; |
| struct xhci_td *last_unlinked_td; |
| + struct xhci_ep_ctx *ep_ctx; |
| + struct xhci_virt_device *vdev; |
| |
| struct xhci_dequeue_state deq_state; |
| |
| @@ -702,6 +704,11 @@ static void xhci_handle_cmd_stop_ep(struct xhci_hcd *xhci, int slot_id, |
| |
| memset(&deq_state, 0, sizeof(deq_state)); |
| ep_index = TRB_TO_EP_INDEX(le32_to_cpu(trb->generic.field[3])); |
| + |
| + vdev = xhci->devs[slot_id]; |
| + ep_ctx = xhci_get_ep_ctx(xhci, vdev->out_ctx, ep_index); |
| + trace_xhci_handle_cmd_stop_ep(ep_ctx); |
| + |
| ep = &xhci->devs[slot_id]->eps[ep_index]; |
| last_unlinked_td = list_last_entry(&ep->cancelled_td_list, |
| struct xhci_td, cancelled_td_list); |
| @@ -1029,6 +1036,8 @@ static void xhci_handle_cmd_set_deq(struct xhci_hcd *xhci, int slot_id, |
| |
| ep_ctx = xhci_get_ep_ctx(xhci, dev->out_ctx, ep_index); |
| slot_ctx = xhci_get_slot_ctx(xhci, dev->out_ctx); |
| + trace_xhci_handle_cmd_set_deq(slot_ctx); |
| + trace_xhci_handle_cmd_set_deq_ep(ep_ctx); |
| |
| if (cmd_comp_code != COMP_SUCCESS) { |
| unsigned int ep_state; |
| @@ -1099,9 +1108,15 @@ static void xhci_handle_cmd_set_deq(struct xhci_hcd *xhci, int slot_id, |
| static void xhci_handle_cmd_reset_ep(struct xhci_hcd *xhci, int slot_id, |
| union xhci_trb *trb, u32 cmd_comp_code) |
| { |
| + struct xhci_virt_device *vdev; |
| + struct xhci_ep_ctx *ep_ctx; |
| unsigned int ep_index; |
| |
| ep_index = TRB_TO_EP_INDEX(le32_to_cpu(trb->generic.field[3])); |
| + vdev = xhci->devs[slot_id]; |
| + ep_ctx = xhci_get_ep_ctx(xhci, vdev->out_ctx, ep_index); |
| + trace_xhci_handle_cmd_reset_ep(ep_ctx); |
| + |
| /* This command will only fail if the endpoint wasn't halted, |
| * but we don't care. |
| */ |
| @@ -1143,10 +1158,15 @@ static void xhci_handle_cmd_enable_slot(struct xhci_hcd *xhci, int slot_id, |
| static void xhci_handle_cmd_disable_slot(struct xhci_hcd *xhci, int slot_id) |
| { |
| struct xhci_virt_device *virt_dev; |
| + struct xhci_slot_ctx *slot_ctx; |
| |
| virt_dev = xhci->devs[slot_id]; |
| if (!virt_dev) |
| return; |
| + |
| + slot_ctx = xhci_get_slot_ctx(xhci, virt_dev->out_ctx); |
| + trace_xhci_handle_cmd_disable_slot(slot_ctx); |
| + |
| if (xhci->quirks & XHCI_EP_LIMIT_QUIRK) |
| /* Delete default control endpoint resources */ |
| xhci_free_device_endpoint_resources(xhci, virt_dev, true); |
| @@ -1158,6 +1178,7 @@ static void xhci_handle_cmd_config_ep(struct xhci_hcd *xhci, int slot_id, |
| { |
| struct xhci_virt_device *virt_dev; |
| struct xhci_input_control_ctx *ctrl_ctx; |
| + struct xhci_ep_ctx *ep_ctx; |
| unsigned int ep_index; |
| unsigned int ep_state; |
| u32 add_flags, drop_flags; |
| @@ -1182,6 +1203,9 @@ static void xhci_handle_cmd_config_ep(struct xhci_hcd *xhci, int slot_id, |
| /* Input ctx add_flags are the endpoint index plus one */ |
| ep_index = xhci_last_valid_endpoint(add_flags) - 1; |
| |
| + ep_ctx = xhci_get_ep_ctx(xhci, virt_dev->out_ctx, ep_index); |
| + trace_xhci_handle_cmd_config_ep(ep_ctx); |
| + |
| /* A usb_set_interface() call directly after clearing a halted |
| * condition may race on this quirky hardware. Not worth |
| * worrying about, since this is prototype hardware. Not sure |
| @@ -1206,9 +1230,26 @@ static void xhci_handle_cmd_config_ep(struct xhci_hcd *xhci, int slot_id, |
| return; |
| } |
| |
| +static void xhci_handle_cmd_addr_dev(struct xhci_hcd *xhci, int slot_id) |
| +{ |
| + struct xhci_virt_device *vdev; |
| + struct xhci_slot_ctx *slot_ctx; |
| + |
| + vdev = xhci->devs[slot_id]; |
| + slot_ctx = xhci_get_slot_ctx(xhci, vdev->out_ctx); |
| + trace_xhci_handle_cmd_addr_dev(slot_ctx); |
| +} |
| + |
| static void xhci_handle_cmd_reset_dev(struct xhci_hcd *xhci, int slot_id, |
| struct xhci_event_cmd *event) |
| { |
| + struct xhci_virt_device *vdev; |
| + struct xhci_slot_ctx *slot_ctx; |
| + |
| + vdev = xhci->devs[slot_id]; |
| + slot_ctx = xhci_get_slot_ctx(xhci, vdev->out_ctx); |
| + trace_xhci_handle_cmd_reset_dev(slot_ctx); |
| + |
| xhci_dbg(xhci, "Completed reset device command.\n"); |
| if (!xhci->devs[slot_id]) |
| xhci_warn(xhci, "Reset device command completion " |
| @@ -1384,6 +1425,7 @@ static void handle_cmd_completion(struct xhci_hcd *xhci, |
| case TRB_EVAL_CONTEXT: |
| break; |
| case TRB_ADDR_DEV: |
| + xhci_handle_cmd_addr_dev(xhci, slot_id); |
| break; |
| case TRB_STOP_RING: |
| WARN_ON(slot_id != TRB_TO_SLOT_ID( |
| diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h |
| index fecd226b422d..f24a45ae153d 100644 |
| --- a/drivers/usb/host/xhci-trace.h |
| +++ b/drivers/usb/host/xhci-trace.h |
| @@ -285,6 +285,107 @@ DEFINE_EVENT(xhci_log_urb, xhci_urb_dequeue, |
| TP_ARGS(urb) |
| ); |
| |
| +DECLARE_EVENT_CLASS(xhci_log_ep_ctx, |
| + TP_PROTO(struct xhci_ep_ctx *ctx), |
| + TP_ARGS(ctx), |
| + TP_STRUCT__entry( |
| + __field(u32, info) |
| + __field(u32, info2) |
| + __field(u64, deq) |
| + __field(u32, tx_info) |
| + ), |
| + TP_fast_assign( |
| + __entry->info = le32_to_cpu(ctx->ep_info); |
| + __entry->info2 = le32_to_cpu(ctx->ep_info2); |
| + __entry->deq = le64_to_cpu(ctx->deq); |
| + __entry->tx_info = le32_to_cpu(ctx->tx_info); |
| + ), |
| + TP_printk("%s", xhci_decode_ep_context(__entry->info, |
| + __entry->info2, __entry->deq, __entry->tx_info) |
| + ) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_ep_ctx, xhci_handle_cmd_stop_ep, |
| + TP_PROTO(struct xhci_ep_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_ep_ctx, xhci_handle_cmd_set_deq_ep, |
| + TP_PROTO(struct xhci_ep_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_ep_ctx, xhci_handle_cmd_reset_ep, |
| + TP_PROTO(struct xhci_ep_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_ep_ctx, xhci_handle_cmd_config_ep, |
| + TP_PROTO(struct xhci_ep_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DECLARE_EVENT_CLASS(xhci_log_slot_ctx, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx), |
| + TP_STRUCT__entry( |
| + __field(u32, info) |
| + __field(u32, info2) |
| + __field(u32, tt_info) |
| + __field(u32, state) |
| + ), |
| + TP_fast_assign( |
| + __entry->info = le32_to_cpu(ctx->dev_info); |
| + __entry->info2 = le32_to_cpu(ctx->dev_info2); |
| + __entry->tt_info = le64_to_cpu(ctx->tt_info); |
| + __entry->state = le32_to_cpu(ctx->dev_state); |
| + ), |
| + TP_printk("%s", xhci_decode_slot_context(__entry->info, |
| + __entry->info2, __entry->tt_info, |
| + __entry->state) |
| + ) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_alloc_dev, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_free_dev, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_handle_cmd_disable_slot, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_discover_or_reset_device, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_setup_device_slot, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_handle_cmd_addr_dev, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_handle_cmd_reset_dev, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| +DEFINE_EVENT(xhci_log_slot_ctx, xhci_handle_cmd_set_deq, |
| + TP_PROTO(struct xhci_slot_ctx *ctx), |
| + TP_ARGS(ctx) |
| +); |
| + |
| #endif /* __XHCI_TRACE_H */ |
| |
| /* this part must be outside header guard */ |
| diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c |
| index 0f9edee7bab3..6c4cef7e51c9 100644 |
| --- a/drivers/usb/host/xhci.c |
| +++ b/drivers/usb/host/xhci.c |
| @@ -3443,6 +3443,8 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev) |
| SLOT_STATE_DISABLED) |
| return 0; |
| |
| + trace_xhci_discover_or_reset_device(slot_ctx); |
| + |
| xhci_dbg(xhci, "Resetting device with slot ID %u\n", slot_id); |
| /* Allocate the command structure that holds the struct completion. |
| * Assume we're in process context, since the normal device reset |
| @@ -3558,6 +3560,7 @@ void xhci_free_dev(struct usb_hcd *hcd, struct usb_device *udev) |
| { |
| struct xhci_hcd *xhci = hcd_to_xhci(hcd); |
| struct xhci_virt_device *virt_dev; |
| + struct xhci_slot_ctx *slot_ctx; |
| int i, ret; |
| struct xhci_command *command; |
| |
| @@ -3585,6 +3588,8 @@ void xhci_free_dev(struct usb_hcd *hcd, struct usb_device *udev) |
| } |
| |
| virt_dev = xhci->devs[udev->slot_id]; |
| + slot_ctx = xhci_get_slot_ctx(xhci, virt_dev->out_ctx); |
| + trace_xhci_free_dev(slot_ctx); |
| |
| /* Stop any wayward timer functions (which may grab the lock) */ |
| for (i = 0; i < 31; i++) { |
| @@ -3668,6 +3673,8 @@ static int xhci_reserve_host_control_ep_resources(struct xhci_hcd *xhci) |
| int xhci_alloc_dev(struct usb_hcd *hcd, struct usb_device *udev) |
| { |
| struct xhci_hcd *xhci = hcd_to_xhci(hcd); |
| + struct xhci_virt_device *vdev; |
| + struct xhci_slot_ctx *slot_ctx; |
| unsigned long flags; |
| int ret, slot_id; |
| struct xhci_command *command; |
| @@ -3723,6 +3730,10 @@ int xhci_alloc_dev(struct usb_hcd *hcd, struct usb_device *udev) |
| xhci_warn(xhci, "Could not allocate xHCI USB device data structures\n"); |
| goto disable_slot; |
| } |
| + vdev = xhci->devs[slot_id]; |
| + slot_ctx = xhci_get_slot_ctx(xhci, vdev->out_ctx); |
| + trace_xhci_alloc_dev(slot_ctx); |
| + |
| udev->slot_id = slot_id; |
| |
| #ifndef CONFIG_USB_DEFAULT_PERSIST |
| @@ -3792,9 +3803,10 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev, |
| ret = -EINVAL; |
| goto out; |
| } |
| + slot_ctx = xhci_get_slot_ctx(xhci, virt_dev->out_ctx); |
| + trace_xhci_setup_device_slot(slot_ctx); |
| |
| if (setup == SETUP_CONTEXT_ONLY) { |
| - slot_ctx = xhci_get_slot_ctx(xhci, virt_dev->out_ctx); |
| if (GET_SLOT_STATE(le32_to_cpu(slot_ctx->dev_state)) == |
| SLOT_STATE_DEFAULT) { |
| xhci_dbg(xhci, "Slot already in default state\n"); |
| @@ -3915,7 +3927,6 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev, |
| * USB core uses address 1 for the roothubs, so we add one to the |
| * address given back to us by the HC. |
| */ |
| - slot_ctx = xhci_get_slot_ctx(xhci, virt_dev->out_ctx); |
| trace_xhci_address_ctx(xhci, virt_dev->out_ctx, |
| le32_to_cpu(slot_ctx->dev_info) >> 27); |
| /* Zero the input context control for later use */ |
| diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h |
| index facdae3ea5bb..2acb6fe64892 100644 |
| --- a/drivers/usb/host/xhci.h |
| +++ b/drivers/usb/host/xhci.h |
| @@ -618,6 +618,7 @@ struct xhci_slot_ctx { |
| #define ROUTE_STRING_MASK (0xfffff) |
| /* Device speed - values defined by PORTSC Device Speed field - 20:23 */ |
| #define DEV_SPEED (0xf << 20) |
| +#define GET_DEV_SPEED(n) (((n) & DEV_SPEED) >> 20) |
| /* bit 24 reserved */ |
| /* Is this LS/FS device connected through a HS hub? - bit 25 */ |
| #define DEV_MTT (0x1 << 25) |
| @@ -638,6 +639,7 @@ struct xhci_slot_ctx { |
| #define DEVINFO_TO_ROOT_HUB_PORT(p) (((p) >> 16) & 0xff) |
| /* Maximum number of ports under a hub device */ |
| #define XHCI_MAX_PORTS(p) (((p) & 0xff) << 24) |
| +#define DEVINFO_TO_MAX_PORTS(p) (((p) & (0xff << 24)) >> 24) |
| |
| /* tt_info bitmasks */ |
| /* |
| @@ -652,6 +654,7 @@ struct xhci_slot_ctx { |
| */ |
| #define TT_PORT (0xff << 8) |
| #define TT_THINK_TIME(p) (((p) & 0x3) << 16) |
| +#define GET_TT_THINK_TIME(p) (((p) & (0x3 << 16)) >> 16) |
| |
| /* dev_state bitmasks */ |
| /* USB device address - assigned by the HC */ |
| @@ -2381,5 +2384,148 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2, |
| return str; |
| } |
| |
| +static inline const char *xhci_decode_slot_context(u32 info, u32 info2, |
| + u32 tt_info, u32 state) |
| +{ |
| + static char str[1024]; |
| + u32 speed; |
| + u32 hub; |
| + u32 mtt; |
| + int ret = 0; |
| + |
| + speed = info & DEV_SPEED; |
| + hub = info & DEV_HUB; |
| + mtt = info & DEV_MTT; |
| + |
| + ret = sprintf(str, "RS %05x %s%s%s Ctx Entries %d MEL %d us Port# %d/%d", |
| + info & ROUTE_STRING_MASK, |
| + ({ char *s; |
| + switch (speed) { |
| + case SLOT_SPEED_FS: |
| + s = "full-speed"; |
| + break; |
| + case SLOT_SPEED_LS: |
| + s = "low-speed"; |
| + break; |
| + case SLOT_SPEED_HS: |
| + s = "high-speed"; |
| + break; |
| + case SLOT_SPEED_SS: |
| + s = "super-speed"; |
| + break; |
| + case SLOT_SPEED_SSP: |
| + s = "super-speed plus"; |
| + break; |
| + default: |
| + s = "UNKNOWN speed"; |
| + } s; }), |
| + mtt ? " multi-TT" : "", |
| + hub ? " Hub" : "", |
| + (info & LAST_CTX_MASK) >> 27, |
| + info2 & MAX_EXIT, |
| + DEVINFO_TO_ROOT_HUB_PORT(info2), |
| + DEVINFO_TO_MAX_PORTS(info2)); |
| + |
| + ret += sprintf(str + ret, " [TT Slot %d Port# %d TTT %d Intr %d] Addr %d State %s", |
| + tt_info & TT_SLOT, (tt_info & TT_PORT) >> 8, |
| + GET_TT_THINK_TIME(tt_info), GET_INTR_TARGET(tt_info), |
| + state & DEV_ADDR_MASK, |
| + xhci_slot_state_string(GET_SLOT_STATE(state))); |
| + |
| + return str; |
| +} |
| + |
| +static inline const char *xhci_ep_state_string(u8 state) |
| +{ |
| + switch (state) { |
| + case EP_STATE_DISABLED: |
| + return "disabled"; |
| + case EP_STATE_RUNNING: |
| + return "running"; |
| + case EP_STATE_HALTED: |
| + return "halted"; |
| + case EP_STATE_STOPPED: |
| + return "stopped"; |
| + case EP_STATE_ERROR: |
| + return "error"; |
| + default: |
| + return "INVALID"; |
| + } |
| +} |
| + |
| +static inline const char *xhci_ep_type_string(u8 type) |
| +{ |
| + switch (type) { |
| + case ISOC_OUT_EP: |
| + return "Isoc OUT"; |
| + case BULK_OUT_EP: |
| + return "Bulk OUT"; |
| + case INT_OUT_EP: |
| + return "Int OUT"; |
| + case CTRL_EP: |
| + return "Ctrl"; |
| + case ISOC_IN_EP: |
| + return "Isoc IN"; |
| + case BULK_IN_EP: |
| + return "Bulk IN"; |
| + case INT_IN_EP: |
| + return "Int IN"; |
| + default: |
| + return "INVALID"; |
| + } |
| +} |
| + |
| +static inline const char *xhci_decode_ep_context(u32 info, u32 info2, u64 deq, |
| + u32 tx_info) |
| +{ |
| + static char str[1024]; |
| + int ret; |
| + |
| + u32 esit; |
| + u16 maxp; |
| + u16 avg; |
| + |
| + u8 max_pstr; |
| + u8 ep_state; |
| + u8 interval; |
| + u8 ep_type; |
| + u8 burst; |
| + u8 cerr; |
| + u8 mult; |
| + u8 lsa; |
| + u8 hid; |
| + |
| + esit = EP_MAX_ESIT_PAYLOAD_HI(info) << 16 | |
| + EP_MAX_ESIT_PAYLOAD_LO(tx_info); |
| + |
| + ep_state = info & EP_STATE_MASK; |
| + max_pstr = info & EP_MAXPSTREAMS_MASK; |
| + interval = CTX_TO_EP_INTERVAL(info); |
| + mult = CTX_TO_EP_MULT(info) + 1; |
| + lsa = info & EP_HAS_LSA; |
| + |
| + cerr = (info2 & (3 << 1)) >> 1; |
| + ep_type = CTX_TO_EP_TYPE(info2); |
| + hid = info2 & (1 << 7); |
| + burst = CTX_TO_MAX_BURST(info2); |
| + maxp = MAX_PACKET_DECODED(info2); |
| + |
| + avg = EP_AVG_TRB_LENGTH(tx_info); |
| + |
| + ret = sprintf(str, "State %s mult %d max P. Streams %d %s", |
| + xhci_ep_state_string(ep_state), mult, |
| + max_pstr, lsa ? "LSA " : ""); |
| + |
| + ret += sprintf(str + ret, "interval %d us max ESIT payload %d CErr %d ", |
| + (1 << interval) * 125, esit, cerr); |
| + |
| + ret += sprintf(str + ret, "Type %s %sburst %d maxp %d deq %016llx ", |
| + xhci_ep_type_string(ep_type), hid ? "HID" : "", |
| + burst, maxp, deq); |
| + |
| + ret += sprintf(str + ret, "avg trb len %d", avg); |
| + |
| + return str; |
| +} |
| |
| #endif /* __LINUX_XHCI_HCD_H */ |
| -- |
| 2.13.3 |
| |