Ah, looking over the patch again, there's a couple print statements related to configure endpoint and evaluate context changes that you missed. Are you familiar with completions? If not, I suggest you read the "Completions" section of Chapter 5 of Linux Device Drivers: http://lwn.net/Kernel/LDD3/ When an xHCI command completes, the hardware places an event on the event ring. That event includes a pointer to command on the command ring, and a completion code. The xHCI driver will then receive an interrupt, and it will figure out a command completed. The xHCI driver will then signal to the function that's waiting on that completion. In the Configure Endpoint or Evaluate Context command case, the function xhci_configure_endpoint() calls wait_for_completion_interruptible_timeout(). When the interrupt happens, xhci_irq() in xhci-ring.c gets called, the driver figures out a command completed, and handle_cmd_completion() is called. That function may print statements relating to command completions. The xhci_dbg_context_change trace function also needs to be used for print statements in the TRB_TYPE(TRB_CONFIG_EP) case in the giant switch statement in handle_cmd_completion(). Bonus points if you can refactor that case statement into a separate static function called handle_configure_endpoint(). :) Sarah Sharp On Tue, Jul 23, 2013 at 06:14:55AM +0300, Xenia Ragiadakou wrote: > This patch defines a new trace event, which is called xhci_dbg_context_change > and belongs in the event class xhci_log_msg, and adds tracepoints for tracing > the debug messages related to context updates performed with Configure Endpoint > and Evaluate Context commands. > > Signed-off-by: Xenia Ragiadakou <burzalodowa@xxxxxxxxx> > --- > drivers/usb/host/xhci-mem.c | 4 +++- > drivers/usb/host/xhci-ring.c | 10 +++++++--- > drivers/usb/host/xhci-trace.h | 5 +++++ > drivers/usb/host/xhci.c | 36 ++++++++++++++++++++++++------------ > 4 files changed, 39 insertions(+), 16 deletions(-) > > diff --git a/drivers/usb/host/xhci-mem.c b/drivers/usb/host/xhci-mem.c > index b881bc1..03aa32d 100644 > --- a/drivers/usb/host/xhci-mem.c > +++ b/drivers/usb/host/xhci-mem.c > @@ -26,6 +26,7 @@ > #include <linux/dmapool.h> > > #include "xhci.h" > +#include "xhci-trace.h" > > /* > * Allocates a generic ring segment from the ring pool, sets the dma address, > @@ -661,7 +662,8 @@ void xhci_setup_streams_ep_input_ctx(struct xhci_hcd *xhci, > * fls(0) = 0, fls(0x1) = 1, fls(0x10) = 2, fls(0x100) = 3, etc. > */ > max_primary_streams = fls(stream_info->num_stream_ctxs) - 2; > - xhci_dbg(xhci, "Setting number of stream ctx array entries to %u\n", > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Setting number of stream ctx array entries to %u\n", > 1 << (max_primary_streams + 1)); > ep_ctx->ep_info &= cpu_to_le32(~EP_MAXPSTREAMS_MASK); > ep_ctx->ep_info |= cpu_to_le32(EP_MAXPSTREAMS(max_primary_streams) > diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c > index 1e57eaf..6adf293 100644 > --- a/drivers/usb/host/xhci-ring.c > +++ b/drivers/usb/host/xhci-ring.c > @@ -67,6 +67,7 @@ > #include <linux/scatterlist.h> > #include <linux/slab.h> > #include "xhci.h" > +#include "xhci-trace.h" > > static int handle_cmd_in_cmd_wait_list(struct xhci_hcd *xhci, > struct xhci_virt_device *virt_dev, > @@ -1158,7 +1159,8 @@ static void handle_reset_ep_completion(struct xhci_hcd *xhci, > * because the HW can't handle two commands being queued in a row. > */ > if (xhci->quirks & XHCI_RESET_EP_QUIRK) { > - xhci_dbg(xhci, "Queueing configure endpoint command\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Queueing configure endpoint command\n"); > xhci_queue_configure_endpoint(xhci, > xhci->devs[slot_id]->in_ctx->dma, slot_id, > false); > @@ -1444,7 +1446,8 @@ static void handle_cmd_completion(struct xhci_hcd *xhci, > ep_state = xhci->devs[slot_id]->eps[ep_index].ep_state; > if (!(ep_state & EP_HALTED)) > goto bandwidth_change; > - xhci_dbg(xhci, "Completed config ep cmd - " > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Completed config ep cmd - " > "last ep index = %d, state = %d\n", > ep_index, ep_state); > /* Clear internal halted state and restart ring(s) */ > @@ -1454,7 +1457,8 @@ static void handle_cmd_completion(struct xhci_hcd *xhci, > break; > } > bandwidth_change: > - xhci_dbg(xhci, "Completed config ep cmd\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Completed config ep cmd\n"); > xhci->devs[slot_id]->cmd_status = > GET_COMP_CODE(le32_to_cpu(event->status)); > complete(&xhci->devs[slot_id]->cmd_completion); > diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h > index 432aa67..6286243 100644 > --- a/drivers/usb/host/xhci-trace.h > +++ b/drivers/usb/host/xhci-trace.h > @@ -36,6 +36,11 @@ DEFINE_EVENT(xhci_log_msg, xhci_dbg_address, > TP_ARGS(vaf) > ); > > +DEFINE_EVENT(xhci_log_msg, xhci_dbg_context_change, > + TP_PROTO(struct va_format *vaf), > + TP_ARGS(vaf) > +); > + > #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 081b5b5..8b4a087 100644 > --- a/drivers/usb/host/xhci.c > +++ b/drivers/usb/host/xhci.c > @@ -1153,12 +1153,16 @@ static int xhci_check_maxpacket(struct xhci_hcd *xhci, unsigned int slot_id, > hw_max_packet_size = MAX_PACKET_DECODED(le32_to_cpu(ep_ctx->ep_info2)); > max_packet_size = usb_endpoint_maxp(&urb->dev->ep0.desc); > if (hw_max_packet_size != max_packet_size) { > - xhci_dbg(xhci, "Max Packet Size for ep 0 changed.\n"); > - xhci_dbg(xhci, "Max packet size in usb_device = %d\n", > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Max Packet Size for ep 0 changed.\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Max packet size in usb_device = %d\n", > max_packet_size); > - xhci_dbg(xhci, "Max packet size in xHCI HW = %d\n", > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Max packet size in xHCI HW = %d\n", > hw_max_packet_size); > - xhci_dbg(xhci, "Issuing evaluate context command.\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Issuing evaluate context command.\n"); > > /* Set up the input context flags for the command */ > /* FIXME: This won't work if a non-default control endpoint > @@ -1776,7 +1780,8 @@ static int xhci_configure_endpoint_result(struct xhci_hcd *xhci, > ret = -ENODEV; > break; > case COMP_SUCCESS: > - dev_dbg(&udev->dev, "Successful Endpoint Configure command\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Successful Endpoint Configure command\n"); > ret = 0; > break; > default: > @@ -1822,7 +1827,8 @@ static int xhci_evaluate_context_result(struct xhci_hcd *xhci, > ret = -EINVAL; > break; > case COMP_SUCCESS: > - dev_dbg(&udev->dev, "Successful evaluate context command\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Successful evaluate context command\n"); > ret = 0; > break; > default: > @@ -1888,14 +1894,16 @@ static int xhci_reserve_host_resources(struct xhci_hcd *xhci, > > added_eps = xhci_count_num_new_endpoints(xhci, ctrl_ctx); > if (xhci->num_active_eps + added_eps > xhci->limit_active_eps) { > - xhci_dbg(xhci, "Not enough ep ctxs: " > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Not enough ep ctxs: " > "%u active, need to add %u, limit is %u.\n", > xhci->num_active_eps, added_eps, > xhci->limit_active_eps); > return -ENOMEM; > } > xhci->num_active_eps += added_eps; > - xhci_dbg(xhci, "Adding %u ep ctxs, %u now active.\n", added_eps, > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Adding %u ep ctxs, %u now active.\n", added_eps, > xhci->num_active_eps); > return 0; > } > @@ -1913,7 +1921,8 @@ static void xhci_free_host_resources(struct xhci_hcd *xhci, > > num_failed_eps = xhci_count_num_new_endpoints(xhci, ctrl_ctx); > xhci->num_active_eps -= num_failed_eps; > - xhci_dbg(xhci, "Removing %u failed ep ctxs, %u now active.\n", > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Removing %u failed ep ctxs, %u now active.\n", > num_failed_eps, > xhci->num_active_eps); > } > @@ -1932,7 +1941,8 @@ static void xhci_finish_resource_reservation(struct xhci_hcd *xhci, > num_dropped_eps = xhci_count_num_dropped_endpoints(xhci, ctrl_ctx); > xhci->num_active_eps -= num_dropped_eps; > if (num_dropped_eps) > - xhci_dbg(xhci, "Removing %u dropped ep ctxs, %u now active.\n", > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Removing %u dropped ep ctxs, %u now active.\n", > num_dropped_eps, > xhci->num_active_eps); > } > @@ -2583,7 +2593,8 @@ static int xhci_configure_endpoint(struct xhci_hcd *xhci, > if ((xhci->quirks & XHCI_EP_LIMIT_QUIRK)) > xhci_free_host_resources(xhci, ctrl_ctx); > spin_unlock_irqrestore(&xhci->lock, flags); > - xhci_dbg(xhci, "FIXME allocate a new ring segment\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "FIXME allocate a new ring segment\n"); > return -ENOMEM; > } > xhci_ring_cmd_db(xhci); > @@ -3863,7 +3874,8 @@ static int xhci_change_max_exit_latency(struct xhci_hcd *xhci, > slot_ctx->dev_info2 &= cpu_to_le32(~((u32) MAX_EXIT)); > slot_ctx->dev_info2 |= cpu_to_le32(max_exit_latency); > > - xhci_dbg(xhci, "Set up evaluate context for LPM MEL change.\n"); > + xhci_dbg_trace(xhci, trace_xhci_dbg_context_change, > + "Set up evaluate context for LPM MEL change.\n"); > xhci_dbg(xhci, "Slot %u Input Context:\n", udev->slot_id); > xhci_dbg_ctx(xhci, command->in_ctx, 0); > > -- > 1.8.3.2 > -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
