[PATCH 2/6] usb: xhci: enhance xhci_log_ctx trace events

From: Lu Baolu
Date: Tue Feb 14 2017 - 21:35:52 EST

Next message: Lu Baolu: "[PATCH 4/6] usb: xhci: remove xhci_dbg_ctx()"
Previous message: Lu Baolu: "[PATCH 0/6] usb: xhci: several patches for xhci trace"
In reply to: Lu Baolu: "[PATCH 0/6] usb: xhci: several patches for xhci trace"
Next in thread: Felipe Balbi: "Re: [PATCH 2/6] usb: xhci: enhance xhci_log_ctx trace events"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

XHCI driver has defined xhci_log_ctx trace events to trace
the change of an xhci input or output context. This patch
extends the trace class of xhci_log_ctx to print out the
contents of a context block in a human readable way.

This patch also adds some other xhci_log_ctx based events
where the xhci input or output context changes.

Signed-off-by: Lu Baolu <baolu.lu@xxxxxxxxxxxxxxx>
---
drivers/usb/host/xhci-trace.h | 63 ++++++++++++++++++++++++++++++-------------
drivers/usb/host/xhci.c | 23 +++++++++++-----
drivers/usb/host/xhci.h | 60 +++++++++++++++++++++++++++++++++++++++++
3 files changed, 121 insertions(+), 25 deletions(-)

diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
index c31eeaf..8fe01b1 100644
--- a/drivers/usb/host/xhci-trace.h
+++ b/drivers/usb/host/xhci-trace.h
@@ -75,44 +75,71 @@ DEFINE_EVENT(xhci_log_msg, xhci_dbg_ring_expansion,
);

DECLARE_EVENT_CLASS(xhci_log_ctx,
- TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx,
- unsigned int ep_num),
- TP_ARGS(xhci, ctx, ep_num),
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx),
TP_STRUCT__entry(
__field(int, ctx_64)
__field(unsigned, ctx_type)
__field(dma_addr_t, ctx_dma)
__field(u8 *, ctx_va)
__field(unsigned, ctx_ep_num)
- __field(int, slot_id)
__dynamic_array(u32, ctx_data,
((HCC_64BYTE_CONTEXT(xhci->hcc_params) + 1) * 8) *
- ((ctx->type == XHCI_CTX_TYPE_INPUT) + ep_num + 1))
+ ((ctx->type == XHCI_CTX_TYPE_INPUT) + xhci_get_ep_num(xhci, ctx) + 1))
),
TP_fast_assign(
- struct usb_device *udev;
-
- udev = to_usb_device(xhci_to_hcd(xhci)->self.controller);
__entry->ctx_64 = HCC_64BYTE_CONTEXT(xhci->hcc_params);
__entry->ctx_type = ctx->type;
__entry->ctx_dma = ctx->dma;
__entry->ctx_va = ctx->bytes;
- __entry->slot_id = udev->slot_id;
- __entry->ctx_ep_num = ep_num;
+ __entry->ctx_ep_num = xhci_get_ep_num(xhci, ctx);
memcpy(__get_dynamic_array(ctx_data), ctx->bytes,
((HCC_64BYTE_CONTEXT(xhci->hcc_params) + 1) * 32) *
- ((ctx->type == XHCI_CTX_TYPE_INPUT) + ep_num + 1));
+ ((ctx->type == XHCI_CTX_TYPE_INPUT) + xhci_get_ep_num(xhci, ctx) + 1));
),
- TP_printk("ctx_64=%d, ctx_type=%u, ctx_dma=@%llx, ctx_va=@%p",
- __entry->ctx_64, __entry->ctx_type,
- (unsigned long long) __entry->ctx_dma, __entry->ctx_va
+ TP_printk("ctx @%p: ctx_64=%d, ctx_type=%u, ctx_dma=@%llx: %s",
+ __entry->ctx_va, __entry->ctx_64, __entry->ctx_type,
+ (unsigned long long)__entry->ctx_dma,
+ xhci_decode_ctx((u8 *)__get_dynamic_array(ctx_data),
+ __entry->ctx_type,
+ __entry->ctx_ep_num,
+ __entry->ctx_64 ? 64 : 32)
)
);

-DEFINE_EVENT(xhci_log_ctx, xhci_address_ctx,
- TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx,
- unsigned int ep_num),
- TP_ARGS(xhci, ctx, ep_num)
+DEFINE_EVENT(xhci_log_ctx, ctx_xhci_setup_device,
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx)
+);
+
+DEFINE_EVENT(xhci_log_ctx, ctx_xhci_check_maxpacket,
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx)
+);
+
+DEFINE_EVENT(xhci_log_ctx, ctx_xhci_check_bandwidth,
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx)
+);
+
+DEFINE_EVENT(xhci_log_ctx, ctx_xhci_alloc_streams,
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx)
+);
+
+DEFINE_EVENT(xhci_log_ctx, ctx_xhci_free_streams,
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx)
+);
+
+DEFINE_EVENT(xhci_log_ctx, ctx_xhci_update_hub_device,
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx)
+);
+
+DEFINE_EVENT(xhci_log_ctx, ctx_xhci_change_max_exit_latency,
+ TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx),
+ TP_ARGS(xhci, ctx)
);

DECLARE_EVENT_CLASS(xhci_log_trb,
diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c
index dff912e..304f38d 100644
--- a/drivers/usb/host/xhci.c
+++ b/drivers/usb/host/xhci.c
@@ -1311,8 +1311,10 @@ static int xhci_check_maxpacket(struct xhci_hcd *xhci, unsigned int slot_id,
xhci_dbg(xhci, "Slot %d output context\n", slot_id);
xhci_dbg_ctx(xhci, out_ctx, ep_index);

+ trace_ctx_xhci_check_maxpacket(xhci, command->in_ctx);
ret = xhci_configure_endpoint(xhci, urb->dev, command,
true, false);
+ trace_ctx_xhci_check_maxpacket(xhci, out_ctx);

/* Clean up the input context for later use by bandwidth
* functions.
@@ -2745,8 +2747,10 @@ int xhci_check_bandwidth(struct usb_hcd *hcd, struct usb_device *udev)
xhci_dbg_ctx(xhci, virt_dev->in_ctx,
LAST_CTX_TO_EP_NUM(le32_to_cpu(slot_ctx->dev_info)));

+ trace_ctx_xhci_check_bandwidth(xhci, command->in_ctx);
ret = xhci_configure_endpoint(xhci, udev, command,
false, false);
+ trace_ctx_xhci_check_bandwidth(xhci, virt_dev->out_ctx);
if (ret)
/* Callee should call reset_bandwidth() */
goto command_cleanup;
@@ -3207,8 +3211,10 @@ int xhci_alloc_streams(struct usb_hcd *hcd, struct usb_device *udev,
changed_ep_bitmask, changed_ep_bitmask);

/* Issue and wait for the configure endpoint command */
+ trace_ctx_xhci_alloc_streams(xhci, config_cmd->in_ctx);
ret = xhci_configure_endpoint(xhci, udev, config_cmd,
false, false);
+ trace_ctx_xhci_alloc_streams(xhci, vdev->out_ctx);

/* xHC rejected the configure endpoint command for some reason, so we
* leave the old ring intact and free our internal streams data
@@ -3314,8 +3320,10 @@ int xhci_free_streams(struct usb_hcd *hcd, struct usb_device *udev,
/* Issue and wait for the configure endpoint command,
* which must succeed.
*/
+ trace_ctx_xhci_free_streams(xhci, command->in_ctx);
ret = xhci_configure_endpoint(xhci, udev, command,
false, true);
+ trace_ctx_xhci_free_streams(xhci, vdev->out_ctx);

/* xHC rejected the configure endpoint command for some reason, so we
* leave the streams rings intact.
@@ -3819,8 +3827,7 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,

xhci_dbg(xhci, "Slot ID %d Input Context:\n", udev->slot_id);
xhci_dbg_ctx(xhci, virt_dev->in_ctx, 2);
- trace_xhci_address_ctx(xhci, virt_dev->in_ctx,
- le32_to_cpu(slot_ctx->dev_info) >> 27);
+ trace_ctx_xhci_setup_device(xhci, virt_dev->in_ctx);

spin_lock_irqsave(&xhci->lock, flags);
trace_xhci_setup_device(virt_dev);
@@ -3874,7 +3881,7 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
act, command->status);
xhci_dbg(xhci, "Slot ID %d Output Context:\n", udev->slot_id);
xhci_dbg_ctx(xhci, virt_dev->out_ctx, 2);
- trace_xhci_address_ctx(xhci, virt_dev->out_ctx, 1);
+ trace_ctx_xhci_setup_device(xhci, virt_dev->out_ctx);
ret = -EINVAL;
break;
}
@@ -3894,8 +3901,7 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
(unsigned long long)virt_dev->out_ctx->dma);
xhci_dbg(xhci, "Slot ID %d Input Context:\n", udev->slot_id);
xhci_dbg_ctx(xhci, virt_dev->in_ctx, 2);
- trace_xhci_address_ctx(xhci, virt_dev->in_ctx,
- le32_to_cpu(slot_ctx->dev_info) >> 27);
+ trace_ctx_xhci_setup_device(xhci, virt_dev->in_ctx);
xhci_dbg(xhci, "Slot ID %d Output Context:\n", udev->slot_id);
xhci_dbg_ctx(xhci, virt_dev->out_ctx, 2);
/*
@@ -3903,8 +3909,7 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
* 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);
+ trace_ctx_xhci_setup_device(xhci, virt_dev->out_ctx);
/* Zero the input context control for later use */
ctrl_ctx->add_flags = 0;
ctrl_ctx->drop_flags = 0;
@@ -4007,8 +4012,10 @@ static int __maybe_unused xhci_change_max_exit_latency(struct xhci_hcd *xhci,
xhci_dbg_ctx(xhci, command->in_ctx, 0);

/* Issue and wait for the evaluate context command. */
+ trace_ctx_xhci_change_max_exit_latency(xhci, command->in_ctx);
ret = xhci_configure_endpoint(xhci, udev, command,
true, true);
+ trace_ctx_xhci_change_max_exit_latency(xhci, virt_dev->out_ctx);
xhci_dbg(xhci, "Slot %u Output Context:\n", udev->slot_id);
xhci_dbg_ctx(xhci, virt_dev->out_ctx, 0);

@@ -4784,12 +4791,14 @@ int xhci_update_hub_device(struct usb_hcd *hcd, struct usb_device *hdev,
/* Issue and wait for the configure endpoint or
* evaluate context command.
*/
+ trace_ctx_xhci_update_hub_device(xhci, config_cmd->in_ctx);
if (xhci->hci_version > 0x95)
ret = xhci_configure_endpoint(xhci, hdev, config_cmd,
false, false);
else
ret = xhci_configure_endpoint(xhci, hdev, config_cmd,
true, false);
+ trace_ctx_xhci_update_hub_device(xhci, vdev->out_ctx);

xhci_dbg(xhci, "Slot %u Output Context:\n", hdev->slot_id);
xhci_dbg_ctx(xhci, vdev->out_ctx, 0);
diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index da3eb69..d6c4038 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -2359,5 +2359,65 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
return str;
}

+static inline unsigned int
+xhci_get_ep_num(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx)
+{
+ struct xhci_slot_ctx *slot_ctx;
+
+ slot_ctx = xhci_get_slot_ctx(xhci, ctx);
+ return (le32_to_cpu(slot_ctx->dev_info) >> 27);
+}
+
+static inline const char *
+xhci_decode_ctx(u8 *ctx, unsigned int type, unsigned int ep_num,
+ unsigned int ctx_size)
+{
+ char *next;
+ int i, temp, size;
+ unsigned int index;
+ static char str[1600];
+ struct xhci_ep_ctx *ep_ctx;
+ struct xhci_slot_ctx *slot_ctx;
+ struct xhci_input_control_ctx *ctrl_ctx;
+
+ next = str;
+ size = sizeof(str);
+
+ if (type == XHCI_CTX_TYPE_INPUT) {
+ ctrl_ctx = (struct xhci_input_control_ctx *)ctx;
+ temp = scnprintf(next, size,
+ "Input control:%#08x %#08x\n",
+ le32_to_cpu(ctrl_ctx->drop_flags),
+ le32_to_cpu(ctrl_ctx->add_flags));
+ next += temp;
+ size -= temp;
+ }
+
+ index = (type == XHCI_CTX_TYPE_INPUT);
+ slot_ctx = (struct xhci_slot_ctx *)(ctx + index * ctx_size);
+ temp = scnprintf(next, size,
+ "Slot Context:%#08x %#08x %#08x %#08x\n",
+ le32_to_cpu(slot_ctx->dev_info),
+ le32_to_cpu(slot_ctx->dev_info2),
+ le32_to_cpu(slot_ctx->tt_info),
+ le32_to_cpu(slot_ctx->dev_state));
+ next += temp;
+ size -= temp;
+
+ for (i = 0; i < ep_num && size > 0; i++) {
+ index = i + 1 + (type == XHCI_CTX_TYPE_INPUT);
+ ep_ctx = (struct xhci_ep_ctx *)(ctx + index * ctx_size);
+ temp = scnprintf(next, size,
+ "Endpoint Context [index %02d]: %#08x %#08x %#08llx %#08x\n",
+ i + 1, le32_to_cpu(ep_ctx->ep_info),
+ le32_to_cpu(ep_ctx->ep_info2),
+ le64_to_cpu(ep_ctx->deq),
+ le32_to_cpu(ep_ctx->tx_info));
+ next += temp;
+ size -= temp;
+ }
+
+ return str;
+}

#endif /* __LINUX_XHCI_HCD_H */
--
2.1.4

Next message: Lu Baolu: "[PATCH 4/6] usb: xhci: remove xhci_dbg_ctx()"
Previous message: Lu Baolu: "[PATCH 0/6] usb: xhci: several patches for xhci trace"
In reply to: Lu Baolu: "[PATCH 0/6] usb: xhci: several patches for xhci trace"
Next in thread: Felipe Balbi: "Re: [PATCH 2/6] usb: xhci: enhance xhci_log_ctx trace events"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]