[PATCH 0/6] usb: xhci: several patches for xhci trace

[PATCH 0/6] usb: xhci: several patches for xhci trace

[Lu Baolu]

Hi Mathias,

This patch set includes several patches for traces in
xhci driver. One trace class is for command. Several
trace events are defined to trace the life cycle of
any xhci command. The other trace class is for context.
Several trace events are defined to trace the change
in input/output device contexts of a USB device.

This also includes some cleanups to remove duplicated
code.

Best regards,
Lu Baolu

Lu Baolu (6):
  usb: xhci: add xhci_log_cmd trace events
  usb: xhci: enhance xhci_log_ctx trace events
  usb: xhci: remove xhci_debug_trb()
  usb: xhci: remove xhci_dbg_ctx()
  usb: xhci: fix link trb decoding
  usb: xhci: cleanup xhci_decode_trb() slightly

 drivers/usb/host/xhci-dbg.c   | 200 ------------------------------------------
 drivers/usb/host/xhci-hub.c   |   2 +
 drivers/usb/host/xhci-ring.c  |  17 ++--
 drivers/usb/host/xhci-trace.h | 153 ++++++++++++++++++++++++++++----
 drivers/usb/host/xhci.c       |  67 +++++---------
 drivers/usb/host/xhci.h       | 111 +++++++++++++++++------
 6 files changed, 252 insertions(+), 298 deletions(-)

-- 
2.1.4

[PATCH 1/6] usb: xhci: add xhci_log_cmd trace events

[Lu Baolu]

This patch creates a new event class called xhci_log_cmd, and
defines the events used for tracing the life cycle of commands
issued for various purposes.

This info can be used, later, to print, in a human readable way,
the life cycle of an xHCI command using the trace-cmd tool and
the appropriate plugin.

Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
---
 drivers/usb/host/xhci-hub.c   |  2 +
 drivers/usb/host/xhci-ring.c  | 13 +++++--
 drivers/usb/host/xhci-trace.h | 90 +++++++++++++++++++++++++++++++++++++++++++
 drivers/usb/host/xhci.c       |  7 ++++
 4 files changed, 108 insertions(+), 4 deletions(-)

diff --git a/drivers/usb/host/xhci-hub.c b/drivers/usb/host/xhci-hub.c
index 3bddeaa..2c3f77f 100644
--- a/drivers/usb/host/xhci-hub.c
+++ b/drivers/usb/host/xhci-hub.c
@@ -411,9 +411,11 @@ static int xhci_stop_device(struct xhci_hcd *xhci, int slot_id, int suspend)
 			}
 			xhci_queue_stop_endpoint(xhci, command, slot_id, i,
 						 suspend);
+			trace_cmd_xhci_stop_device(command);
 		}
 	}
 	xhci_queue_stop_endpoint(xhci, cmd, slot_id, 0, suspend);
+	trace_cmd_xhci_stop_device(cmd);
 	xhci_ring_cmd_db(xhci);
 	spin_unlock_irqrestore(&xhci->lock, flags);
 
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index d9936c7..4cdcd71 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -1124,6 +1124,7 @@ static void xhci_handle_cmd_reset_ep(struct xhci_hcd *xhci, int slot_id,
 		xhci_queue_configure_endpoint(xhci, command,
 				xhci->devs[slot_id]->in_ctx->dma, slot_id,
 				false);
+		trace_cmd_xhci_handle_cmd_reset_ep(command);
 		xhci_ring_cmd_db(xhci);
 	} else {
 		/* Clear our internal halted state */
@@ -1231,13 +1232,13 @@ static void xhci_handle_cmd_nec_get_fw(struct xhci_hcd *xhci,
 static void xhci_complete_del_and_free_cmd(struct xhci_command *cmd, u32 status)
 {
 	list_del(&cmd->cmd_list);
+	cmd->status = status;
+	trace_cmd_xhci_complete_del_and_free_cmd(cmd);
 
-	if (cmd->completion) {
-		cmd->status = status;
+	if (cmd->completion)
 		complete(cmd->completion);
-	} else {
+	else
 		kfree(cmd);
-	}
 }
 
 void xhci_cleanup_command_queue(struct xhci_hcd *xhci)
@@ -1268,6 +1269,7 @@ void xhci_handle_command_timeout(struct work_struct *work)
 	}
 	/* mark this command to be cancelled */
 	xhci->current_cmd->status = COMP_COMMAND_ABORTED;
+	trace_cmd_xhci_handle_command_timeout(xhci->current_cmd);
 
 	/* Make sure command ring is running before aborting it */
 	hw_ring_state = xhci_read_64(xhci, &xhci->op_regs->cmd_ring);
@@ -1432,6 +1434,7 @@ static void handle_cmd_completion(struct xhci_hcd *xhci,
 	}
 
 event_handled:
+	trace_cmd_handle_cmd_completion(cmd);
 	xhci_complete_del_and_free_cmd(cmd, cmd_comp_code);
 
 	inc_deq(xhci, xhci->cmd_ring);
@@ -1773,6 +1776,7 @@ static void xhci_cleanup_halted_endpoint(struct xhci_hcd *xhci,
 	ep->stopped_stream = stream_id;
 
 	xhci_queue_reset_ep(xhci, command, slot_id, ep_index);
+	trace_cmd_xhci_cleanup_halted_endpoint(command);
 	xhci_cleanup_stalled_ring(xhci, ep_index, td);
 
 	ep->stopped_stream = 0;
@@ -3956,6 +3960,7 @@ void xhci_queue_new_dequeue_state(struct xhci_hcd *xhci,
 		xhci_free_command(xhci, cmd);
 		return;
 	}
+	trace_cmd_xhci_queue_new_dequeue_state(cmd);
 
 	/* Stop the TD queueing code from ringing the doorbell until
 	 * this command completes.  The HC won't set the dequeue pointer
diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
index 1ac2cdf..c31eeaf 100644
--- a/drivers/usb/host/xhci-trace.h
+++ b/drivers/usb/host/xhci-trace.h
@@ -285,6 +285,96 @@ DEFINE_EVENT(xhci_log_urb, xhci_urb_dequeue,
 	TP_ARGS(urb)
 );
 
+DECLARE_EVENT_CLASS(xhci_log_cmd,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd),
+	TP_STRUCT__entry(
+		__field(struct xhci_command *, cmd)
+		__field(struct xhci_container_ctx *, in_ctx)
+		__field(union xhci_trb *, cmd_trb)
+		__field(int, slot_id)
+		__field(int, status)
+		__field(int, type)
+	),
+	TP_fast_assign(
+		__entry->cmd = cmd;
+		__entry->in_ctx = cmd->in_ctx;
+		__entry->cmd_trb = cmd->command_trb;
+		__entry->slot_id = cmd->slot_id;
+		__entry->status = cmd->status;
+		__entry->type = TRB_FIELD_TO_TYPE(le32_to_cpu(cmd->command_trb->generic.field[3]))
+	),
+	TP_printk("cmd @%p: %s: in_ctx=@%p, slot_id=%d, cmd_trb=@%p, status=%d",
+		__entry->cmd, xhci_trb_type_string(__entry->type),
+		__entry->in_ctx, __entry->slot_id, __entry->cmd_trb,
+		__entry->status
+	)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_stop_device,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_handle_cmd_reset_ep,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_cleanup_halted_endpoint,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_queue_new_dequeue_state,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_urb_dequeue,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_configure_endpoint,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_discover_or_reset_device,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_free_dev,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_alloc_dev,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_setup_device,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_handle_cmd_completion,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_handle_command_timeout,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
+
+DEFINE_EVENT(xhci_log_cmd, cmd_xhci_complete_del_and_free_cmd,
+	TP_PROTO(struct xhci_command *cmd),
+	TP_ARGS(cmd)
+);
 #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 b3f7766..dff912e 100644
--- a/drivers/usb/host/xhci.c
+++ b/drivers/usb/host/xhci.c
@@ -1549,6 +1549,7 @@ int xhci_urb_dequeue(struct usb_hcd *hcd, struct urb *urb, int status)
 		add_timer(&ep->stop_cmd_timer);
 		xhci_queue_stop_endpoint(xhci, command, urb->dev->slot_id,
 					 ep_index, 0);
+		trace_cmd_xhci_urb_dequeue(command);
 		xhci_ring_cmd_db(xhci);
 	}
 done:
@@ -2631,6 +2632,7 @@ static int xhci_configure_endpoint(struct xhci_hcd *xhci,
 				"FIXME allocate a new ring segment");
 		return -ENOMEM;
 	}
+	trace_cmd_xhci_configure_endpoint(command);
 	xhci_ring_cmd_db(xhci);
 	spin_unlock_irqrestore(&xhci->lock, flags);
 
@@ -3458,6 +3460,7 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev)
 		spin_unlock_irqrestore(&xhci->lock, flags);
 		goto command_cleanup;
 	}
+	trace_cmd_xhci_discover_or_reset_device(reset_device_cmd);
 	xhci_ring_cmd_db(xhci);
 	spin_unlock_irqrestore(&xhci->lock, flags);
 
@@ -3604,6 +3607,7 @@ void xhci_free_dev(struct usb_hcd *hcd, struct usb_device *udev)
 		xhci_dbg(xhci, "FIXME: allocate a command ring segment\n");
 		return;
 	}
+	trace_cmd_xhci_free_dev(command);
 	xhci_ring_cmd_db(xhci);
 	spin_unlock_irqrestore(&xhci->lock, flags);
 
@@ -3662,6 +3666,7 @@ int xhci_alloc_dev(struct usb_hcd *hcd, struct usb_device *udev)
 		xhci_free_command(xhci, command);
 		return 0;
 	}
+	trace_cmd_xhci_alloc_dev(command);
 	xhci_ring_cmd_db(xhci);
 	spin_unlock_irqrestore(&xhci->lock, flags);
 
@@ -3724,6 +3729,7 @@ int xhci_alloc_dev(struct usb_hcd *hcd, struct usb_device *udev)
 	if (!xhci_queue_slot_control(xhci, command, TRB_DISABLE_SLOT,
 				     udev->slot_id))
 		xhci_ring_cmd_db(xhci);
+	trace_cmd_xhci_alloc_dev(command);
 	spin_unlock_irqrestore(&xhci->lock, flags);
 	return 0;
 }
@@ -3826,6 +3832,7 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
 				"FIXME: allocate a command ring segment");
 		goto out;
 	}
+	trace_cmd_xhci_setup_device(command);
 	xhci_ring_cmd_db(xhci);
 	spin_unlock_irqrestore(&xhci->lock, flags);
 
-- 
2.1.4

Re: [PATCH 1/6] usb: xhci: add xhci_log_cmd trace events

[Felipe Balbi]

[-- Attachment #1: Type: text/plain, Size: 1500 bytes --]


Hi,

Lu Baolu <baolu.lu@linux.intel.com> writes:
> diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
> index 1ac2cdf..c31eeaf 100644
> --- a/drivers/usb/host/xhci-trace.h
> +++ b/drivers/usb/host/xhci-trace.h
> @@ -285,6 +285,96 @@ DEFINE_EVENT(xhci_log_urb, xhci_urb_dequeue,
>  	TP_ARGS(urb)
>  );
>  
> +DECLARE_EVENT_CLASS(xhci_log_cmd,
> +	TP_PROTO(struct xhci_command *cmd),
> +	TP_ARGS(cmd),
> +	TP_STRUCT__entry(
> +		__field(struct xhci_command *, cmd)
> +		__field(struct xhci_container_ctx *, in_ctx)
> +		__field(union xhci_trb *, cmd_trb)
> +		__field(int, slot_id)
> +		__field(int, status)
> +		__field(int, type)
> +	),
> +	TP_fast_assign(
> +		__entry->cmd = cmd;
> +		__entry->in_ctx = cmd->in_ctx;
> +		__entry->cmd_trb = cmd->command_trb;
> +		__entry->slot_id = cmd->slot_id;
> +		__entry->status = cmd->status;
> +		__entry->type = TRB_FIELD_TO_TYPE(le32_to_cpu(cmd->command_trb->generic.field[3]))
> +	),
> +	TP_printk("cmd @%p: %s: in_ctx=@%p, slot_id=%d, cmd_trb=@%p, status=%d",
> +		__entry->cmd, xhci_trb_type_string(__entry->type),
> +		__entry->in_ctx, __entry->slot_id, __entry->cmd_trb,
> +		__entry->status
> +	)
> +);

we already have a generic TRB tracer that decodes every single TRB. What
is this bringing that the previous doesn't provide? BTW, I also have
ready Slot and EP context tracers, I didn't send before because I
already had quite a large series pending for Mathias :-p

-- 
balbi

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: [PATCH 1/6] usb: xhci: add xhci_log_cmd trace events

[Lu Baolu]

Hi,

On 02/15/2017 03:58 PM, Felipe Balbi wrote:
> Hi,
>
> Lu Baolu <baolu.lu@linux.intel.com> writes:
>> diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
>> index 1ac2cdf..c31eeaf 100644
>> --- a/drivers/usb/host/xhci-trace.h
>> +++ b/drivers/usb/host/xhci-trace.h
>> @@ -285,6 +285,96 @@ DEFINE_EVENT(xhci_log_urb, xhci_urb_dequeue,
>>  	TP_ARGS(urb)
>>  );
>>  
>> +DECLARE_EVENT_CLASS(xhci_log_cmd,
>> +	TP_PROTO(struct xhci_command *cmd),
>> +	TP_ARGS(cmd),
>> +	TP_STRUCT__entry(
>> +		__field(struct xhci_command *, cmd)
>> +		__field(struct xhci_container_ctx *, in_ctx)
>> +		__field(union xhci_trb *, cmd_trb)
>> +		__field(int, slot_id)
>> +		__field(int, status)
>> +		__field(int, type)
>> +	),
>> +	TP_fast_assign(
>> +		__entry->cmd = cmd;
>> +		__entry->in_ctx = cmd->in_ctx;
>> +		__entry->cmd_trb = cmd->command_trb;
>> +		__entry->slot_id = cmd->slot_id;
>> +		__entry->status = cmd->status;
>> +		__entry->type = TRB_FIELD_TO_TYPE(le32_to_cpu(cmd->command_trb->generic.field[3]))
>> +	),
>> +	TP_printk("cmd @%p: %s: in_ctx=@%p, slot_id=%d, cmd_trb=@%p, status=%d",
>> +		__entry->cmd, xhci_trb_type_string(__entry->type),
>> +		__entry->in_ctx, __entry->slot_id, __entry->cmd_trb,
>> +		__entry->status
>> +	)
>> +);
> we already have a generic TRB tracer that decodes every single TRB. What
> is this bringing that the previous doesn't provide?

This tracer traces the life cycle of a command. It gives,

1) Which function started an xhci command?
2) What was name of that command?
3) Did hardware respond to it, or timed out?
4) If hardware responded, what was the execution result?
5) If timed out, did 'abort command ring operation' abort it successfully?
6) Was the command structure freed at last?

> BTW, I also have
> ready Slot and EP context tracers, I didn't send before because I
> already had quite a large series pending for Mathias :-p
>

Sorry for the duplication.

Best regards,
Lu Baolu

Re: [PATCH 1/6] usb: xhci: add xhci_log_cmd trace events

[Felipe Balbi]

[-- Attachment #1: Type: text/plain, Size: 2703 bytes --]


Hi,

Lu Baolu <baolu.lu@linux.intel.com> writes:
>> Lu Baolu <baolu.lu@linux.intel.com> writes:
>>> diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
>>> index 1ac2cdf..c31eeaf 100644
>>> --- a/drivers/usb/host/xhci-trace.h
>>> +++ b/drivers/usb/host/xhci-trace.h
>>> @@ -285,6 +285,96 @@ DEFINE_EVENT(xhci_log_urb, xhci_urb_dequeue,
>>>  	TP_ARGS(urb)
>>>  );
>>>  
>>> +DECLARE_EVENT_CLASS(xhci_log_cmd,
>>> +	TP_PROTO(struct xhci_command *cmd),
>>> +	TP_ARGS(cmd),
>>> +	TP_STRUCT__entry(
>>> +		__field(struct xhci_command *, cmd)
>>> +		__field(struct xhci_container_ctx *, in_ctx)
>>> +		__field(union xhci_trb *, cmd_trb)
>>> +		__field(int, slot_id)
>>> +		__field(int, status)
>>> +		__field(int, type)
>>> +	),
>>> +	TP_fast_assign(
>>> +		__entry->cmd = cmd;
>>> +		__entry->in_ctx = cmd->in_ctx;
>>> +		__entry->cmd_trb = cmd->command_trb;
>>> +		__entry->slot_id = cmd->slot_id;
>>> +		__entry->status = cmd->status;
>>> +		__entry->type = TRB_FIELD_TO_TYPE(le32_to_cpu(cmd->command_trb->generic.field[3]))
>>> +	),
>>> +	TP_printk("cmd @%p: %s: in_ctx=@%p, slot_id=%d, cmd_trb=@%p, status=%d",
>>> +		__entry->cmd, xhci_trb_type_string(__entry->type),
>>> +		__entry->in_ctx, __entry->slot_id, __entry->cmd_trb,
>>> +		__entry->status
>>> +	)
>>> +);
>> we already have a generic TRB tracer that decodes every single TRB. What
>> is this bringing that the previous doesn't provide?
>
> This tracer traces the life cycle of a command. It gives,
>
> 1) Which function started an xhci command?
> 2) What was name of that command?
> 3) Did hardware respond to it, or timed out?
> 4) If hardware responded, what was the execution result?
> 5) If timed out, did 'abort command ring operation' abort it successfully?
> 6) Was the command structure freed at last?

We already have all that, AFAICT. Command is enqueued, then an event
triggers for command completion, then we look at results. The only thing
missing for completeness is slot/EP context tracers (which I've pointed
you to) so we can see what changes each command cause to the different
contexts.

Frankly, I don't think printing out context pointers brings
anything. What can you do with that address? :-p Same goes for cmd
pointer, it brings nothing; gives no insight into the problem
whatsoever.

We certainly need to know which command was enqueued, the slot, etc. But
addresses... not so sure.

>> BTW, I also have
>> ready Slot and EP context tracers, I didn't send before because I
>> already had quite a large series pending for Mathias :-p
>
> Sorry for the duplication.

no need to apologize, you didn't know :-)

-- 
balbi

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: [PATCH 1/6] usb: xhci: add xhci_log_cmd trace events

[Lu Baolu]

Hi,

On 02/15/2017 04:56 PM, Felipe Balbi wrote:
> Hi,
>
> Lu Baolu <baolu.lu@linux.intel.com> writes:
>>> Lu Baolu <baolu.lu@linux.intel.com> writes:
>>>> diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
>>>> index 1ac2cdf..c31eeaf 100644
>>>> --- a/drivers/usb/host/xhci-trace.h
>>>> +++ b/drivers/usb/host/xhci-trace.h
>>>> @@ -285,6 +285,96 @@ DEFINE_EVENT(xhci_log_urb, xhci_urb_dequeue,
>>>>  	TP_ARGS(urb)
>>>>  );
>>>>  
>>>> +DECLARE_EVENT_CLASS(xhci_log_cmd,
>>>> +	TP_PROTO(struct xhci_command *cmd),
>>>> +	TP_ARGS(cmd),
>>>> +	TP_STRUCT__entry(
>>>> +		__field(struct xhci_command *, cmd)
>>>> +		__field(struct xhci_container_ctx *, in_ctx)
>>>> +		__field(union xhci_trb *, cmd_trb)
>>>> +		__field(int, slot_id)
>>>> +		__field(int, status)
>>>> +		__field(int, type)
>>>> +	),
>>>> +	TP_fast_assign(
>>>> +		__entry->cmd = cmd;
>>>> +		__entry->in_ctx = cmd->in_ctx;
>>>> +		__entry->cmd_trb = cmd->command_trb;
>>>> +		__entry->slot_id = cmd->slot_id;
>>>> +		__entry->status = cmd->status;
>>>> +		__entry->type = TRB_FIELD_TO_TYPE(le32_to_cpu(cmd->command_trb->generic.field[3]))
>>>> +	),
>>>> +	TP_printk("cmd @%p: %s: in_ctx=@%p, slot_id=%d, cmd_trb=@%p, status=%d",
>>>> +		__entry->cmd, xhci_trb_type_string(__entry->type),
>>>> +		__entry->in_ctx, __entry->slot_id, __entry->cmd_trb,
>>>> +		__entry->status
>>>> +	)
>>>> +);
>>> we already have a generic TRB tracer that decodes every single TRB. What
>>> is this bringing that the previous doesn't provide?
>> This tracer traces the life cycle of a command. It gives,
>>
>> 1) Which function started an xhci command?
>> 2) What was name of that command?
>> 3) Did hardware respond to it, or timed out?
>> 4) If hardware responded, what was the execution result?
>> 5) If timed out, did 'abort command ring operation' abort it successfully?
>> 6) Was the command structure freed at last?
> We already have all that, AFAICT. Command is enqueued, then an event
> triggers for command completion, then we look at results.

The TRB tracer can directly tell us above 2 and 4 by tracing the enqueue
and dequeue of command trbs. It doesn't tell us 1 and 6. For 3 and 5, we
might be able to get to know, but it needs deep understand of the driver
code and many efforts to look through the trace log.

This command tracer will make the life easier when we are debugging
command related issues in xhci driver.


>  The only thing
> missing for completeness is slot/EP context tracers (which I've pointed
> you to) so we can see what changes each command cause to the different
> contexts.
>
> Frankly, I don't think printing out context pointers brings
> anything. What can you do with that address? :-p Same goes for cmd
> pointer, it brings nothing; gives no insight into the problem
> whatsoever.
>
> We certainly need to know which command was enqueued, the slot, etc. But
> addresses... not so sure.

My thought was 'if we find a command failed, we might want to
know what parameters did we feed hardware'. The trb and ctx
pointers will let us go through the trb and context trace log.

For the command pointer, it can help us to grep the trace log
of a single command, so we are able to know how did the
command go.

Best regards,
Lu Baolu

>
>>> BTW, I also have
>>> ready Slot and EP context tracers, I didn't send before because I
>>> already had quite a large series pending for Mathias :-p
>> Sorry for the duplication.
> no need to apologize, you didn't know :-)
>

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

[Lu Baolu]

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@linux.intel.com>
---
 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

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

[Felipe Balbi]

[-- Attachment #1: Type: text/plain, Size: 622 bytes --]


Hi,

Lu Baolu <baolu.lu@linux.intel.com> writes:
> 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@linux.intel.com>

how about?

https://git.kernel.org/cgit/linux/kernel/git/balbi/usb.git/commit/?h=xhci-cleanup&id=4c45cec9f399fb3a53b77c4bb63d5e8fbe382171

-- 
balbi

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

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

[Lu Baolu]

Hi,

On 02/15/2017 04:00 PM, Felipe Balbi wrote:
> Hi,
>
> Lu Baolu <baolu.lu@linux.intel.com> writes:
>> 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@linux.intel.com>
> how about?
>
> https://git.kernel.org/cgit/linux/kernel/git/balbi/usb.git/commit/?h=xhci-cleanup&id=4c45cec9f399fb3a53b77c4bb63d5e8fbe382171
>

Great. I will look into this.

Best regards,
Lu Baolu

[PATCH 3/6] usb: xhci: remove xhci_debug_trb()

[Lu Baolu]

Every XHCI TRB has already been traced by the trb trace events.
It is unnecessary to put the same message in kernel log. This
patch removes xhci_debug_trb().

Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
---
 drivers/usb/host/xhci-dbg.c  | 57 --------------------------------------------
 drivers/usb/host/xhci-ring.c |  4 ----
 drivers/usb/host/xhci.h      |  2 --
 3 files changed, 63 deletions(-)

diff --git a/drivers/usb/host/xhci-dbg.c b/drivers/usb/host/xhci-dbg.c
index 363d125..269089c 100644
--- a/drivers/usb/host/xhci-dbg.c
+++ b/drivers/usb/host/xhci-dbg.c
@@ -254,63 +254,6 @@ void xhci_print_registers(struct xhci_hcd *xhci)
 	xhci_print_ports(xhci);
 }
 
-void xhci_print_trb_offsets(struct xhci_hcd *xhci, union xhci_trb *trb)
-{
-	int i;
-	for (i = 0; i < 4; i++)
-		xhci_dbg(xhci, "Offset 0x%x = 0x%x\n",
-				i*4, trb->generic.field[i]);
-}
-
-/**
- * Debug a transfer request block (TRB).
- */
-void xhci_debug_trb(struct xhci_hcd *xhci, union xhci_trb *trb)
-{
-	u64	address;
-	u32	type = le32_to_cpu(trb->link.control) & TRB_TYPE_BITMASK;
-
-	switch (type) {
-	case TRB_TYPE(TRB_LINK):
-		xhci_dbg(xhci, "Link TRB:\n");
-		xhci_print_trb_offsets(xhci, trb);
-
-		address = le64_to_cpu(trb->link.segment_ptr);
-		xhci_dbg(xhci, "Next ring segment DMA address = 0x%llx\n", address);
-
-		xhci_dbg(xhci, "Interrupter target = 0x%x\n",
-			 GET_INTR_TARGET(le32_to_cpu(trb->link.intr_target)));
-		xhci_dbg(xhci, "Cycle bit = %u\n",
-			 le32_to_cpu(trb->link.control) & TRB_CYCLE);
-		xhci_dbg(xhci, "Toggle cycle bit = %u\n",
-			 le32_to_cpu(trb->link.control) & LINK_TOGGLE);
-		xhci_dbg(xhci, "No Snoop bit = %u\n",
-			 le32_to_cpu(trb->link.control) & TRB_NO_SNOOP);
-		break;
-	case TRB_TYPE(TRB_TRANSFER):
-		address = le64_to_cpu(trb->trans_event.buffer);
-		/*
-		 * FIXME: look at flags to figure out if it's an address or if
-		 * the data is directly in the buffer field.
-		 */
-		xhci_dbg(xhci, "DMA address or buffer contents= %llu\n", address);
-		break;
-	case TRB_TYPE(TRB_COMPLETION):
-		address = le64_to_cpu(trb->event_cmd.cmd_trb);
-		xhci_dbg(xhci, "Command TRB pointer = %llu\n", address);
-		xhci_dbg(xhci, "Completion status = %u\n",
-			 GET_COMP_CODE(le32_to_cpu(trb->event_cmd.status)));
-		xhci_dbg(xhci, "Flags = 0x%x\n",
-			 le32_to_cpu(trb->event_cmd.flags));
-		break;
-	default:
-		xhci_dbg(xhci, "Unknown TRB with TRB type ID %u\n",
-				(unsigned int) type>>10);
-		xhci_print_trb_offsets(xhci, trb);
-		break;
-	}
-}
-
 /**
  * Debug a segment with an xHCI ring.
  *
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 4cdcd71..80cdb55 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -2403,10 +2403,6 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 				xhci_warn(xhci, "WARN Event TRB for slot %d ep %d with no TDs queued?\n",
 						TRB_TO_SLOT_ID(le32_to_cpu(event->flags)),
 						ep_index);
-				xhci_dbg(xhci, "Event TRB with TRB type ID %u\n",
-						(le32_to_cpu(event->flags) &
-						 TRB_TYPE_BITMASK)>>10);
-				xhci_print_trb_offsets(xhci, (union xhci_trb *) event);
 			}
 			if (ep->skip) {
 				ep->skip = false;
diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index d6c4038..13ae2ba 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -1918,8 +1918,6 @@ void xhci_print_ir_set(struct xhci_hcd *xhci, int set_num);
 void xhci_print_registers(struct xhci_hcd *xhci);
 void xhci_dbg_regs(struct xhci_hcd *xhci);
 void xhci_print_run_regs(struct xhci_hcd *xhci);
-void xhci_print_trb_offsets(struct xhci_hcd *xhci, union xhci_trb *trb);
-void xhci_debug_trb(struct xhci_hcd *xhci, union xhci_trb *trb);
 void xhci_debug_segment(struct xhci_hcd *xhci, struct xhci_segment *seg);
 void xhci_debug_ring(struct xhci_hcd *xhci, struct xhci_ring *ring);
 void xhci_dbg_erst(struct xhci_hcd *xhci, struct xhci_erst *erst);
-- 
2.1.4

[PATCH 4/6] usb: xhci: remove xhci_dbg_ctx()

[Lu Baolu]

XHCI context changes have already been traced by the trace
events. It's unnecessary to put the same message in kernel
log. This patch removes the use of xhci_dbg_ctx().

Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
---
 drivers/usb/host/xhci-dbg.c | 143 --------------------------------------------
 drivers/usb/host/xhci.c     |  37 ------------
 drivers/usb/host/xhci.h     |   1 -
 3 files changed, 181 deletions(-)

diff --git a/drivers/usb/host/xhci-dbg.c b/drivers/usb/host/xhci-dbg.c
index 269089c..f832050 100644
--- a/drivers/usb/host/xhci-dbg.c
+++ b/drivers/usb/host/xhci-dbg.c
@@ -377,19 +377,6 @@ void xhci_dbg_cmd_ptrs(struct xhci_hcd *xhci)
 			upper_32_bits(val));
 }
 
-/* Print the last 32 bytes for 64-byte contexts */
-static void dbg_rsvd64(struct xhci_hcd *xhci, u64 *ctx, dma_addr_t dma)
-{
-	int i;
-	for (i = 0; i < 4; i++) {
-		xhci_dbg(xhci, "@%p (virt) @%08llx "
-			 "(dma) %#08llx - rsvd64[%d]\n",
-			 &ctx[4 + i], (unsigned long long)dma,
-			 ctx[4 + i], i);
-		dma += 8;
-	}
-}
-
 char *xhci_get_slot_state(struct xhci_hcd *xhci,
 		struct xhci_container_ctx *ctx)
 {
@@ -409,136 +396,6 @@ char *xhci_get_slot_state(struct xhci_hcd *xhci,
 	}
 }
 
-static void xhci_dbg_slot_ctx(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx)
-{
-	/* Fields are 32 bits wide, DMA addresses are in bytes */
-	int field_size = 32 / 8;
-	int i;
-
-	struct xhci_slot_ctx *slot_ctx = xhci_get_slot_ctx(xhci, ctx);
-	dma_addr_t dma = ctx->dma +
-		((unsigned long)slot_ctx - (unsigned long)ctx->bytes);
-	int csz = HCC_64BYTE_CONTEXT(xhci->hcc_params);
-
-	xhci_dbg(xhci, "Slot Context:\n");
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - dev_info\n",
-			&slot_ctx->dev_info,
-			(unsigned long long)dma, slot_ctx->dev_info);
-	dma += field_size;
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - dev_info2\n",
-			&slot_ctx->dev_info2,
-			(unsigned long long)dma, slot_ctx->dev_info2);
-	dma += field_size;
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - tt_info\n",
-			&slot_ctx->tt_info,
-			(unsigned long long)dma, slot_ctx->tt_info);
-	dma += field_size;
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - dev_state\n",
-			&slot_ctx->dev_state,
-			(unsigned long long)dma, slot_ctx->dev_state);
-	dma += field_size;
-	for (i = 0; i < 4; i++) {
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - rsvd[%d]\n",
-				&slot_ctx->reserved[i], (unsigned long long)dma,
-				slot_ctx->reserved[i], i);
-		dma += field_size;
-	}
-
-	if (csz)
-		dbg_rsvd64(xhci, (u64 *)slot_ctx, dma);
-}
-
-static void xhci_dbg_ep_ctx(struct xhci_hcd *xhci,
-		     struct xhci_container_ctx *ctx,
-		     unsigned int last_ep)
-{
-	int i, j;
-	int last_ep_ctx = 31;
-	/* Fields are 32 bits wide, DMA addresses are in bytes */
-	int field_size = 32 / 8;
-	int csz = HCC_64BYTE_CONTEXT(xhci->hcc_params);
-
-	if (last_ep < 31)
-		last_ep_ctx = last_ep + 1;
-	for (i = 0; i < last_ep_ctx; i++) {
-		unsigned int epaddr = xhci_get_endpoint_address(i);
-		struct xhci_ep_ctx *ep_ctx = xhci_get_ep_ctx(xhci, ctx, i);
-		dma_addr_t dma = ctx->dma +
-			((unsigned long)ep_ctx - (unsigned long)ctx->bytes);
-
-		xhci_dbg(xhci, "%s Endpoint %02d Context (ep_index %02d):\n",
-				usb_endpoint_out(epaddr) ? "OUT" : "IN",
-				epaddr & USB_ENDPOINT_NUMBER_MASK, i);
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - ep_info\n",
-				&ep_ctx->ep_info,
-				(unsigned long long)dma, ep_ctx->ep_info);
-		dma += field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - ep_info2\n",
-				&ep_ctx->ep_info2,
-				(unsigned long long)dma, ep_ctx->ep_info2);
-		dma += field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08llx - deq\n",
-				&ep_ctx->deq,
-				(unsigned long long)dma, ep_ctx->deq);
-		dma += 2*field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - tx_info\n",
-				&ep_ctx->tx_info,
-				(unsigned long long)dma, ep_ctx->tx_info);
-		dma += field_size;
-		for (j = 0; j < 3; j++) {
-			xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - rsvd[%d]\n",
-					&ep_ctx->reserved[j],
-					(unsigned long long)dma,
-					ep_ctx->reserved[j], j);
-			dma += field_size;
-		}
-
-		if (csz)
-			dbg_rsvd64(xhci, (u64 *)ep_ctx, dma);
-	}
-}
-
-void xhci_dbg_ctx(struct xhci_hcd *xhci,
-		  struct xhci_container_ctx *ctx,
-		  unsigned int last_ep)
-{
-	int i;
-	/* Fields are 32 bits wide, DMA addresses are in bytes */
-	int field_size = 32 / 8;
-	dma_addr_t dma = ctx->dma;
-	int csz = HCC_64BYTE_CONTEXT(xhci->hcc_params);
-
-	if (ctx->type == XHCI_CTX_TYPE_INPUT) {
-		struct xhci_input_control_ctx *ctrl_ctx =
-			xhci_get_input_control_ctx(ctx);
-		if (!ctrl_ctx) {
-			xhci_warn(xhci, "Could not get input context, bad type.\n");
-			return;
-		}
-
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - drop flags\n",
-			 &ctrl_ctx->drop_flags, (unsigned long long)dma,
-			 ctrl_ctx->drop_flags);
-		dma += field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - add flags\n",
-			 &ctrl_ctx->add_flags, (unsigned long long)dma,
-			 ctrl_ctx->add_flags);
-		dma += field_size;
-		for (i = 0; i < 6; i++) {
-			xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - rsvd2[%d]\n",
-				 &ctrl_ctx->rsvd2[i], (unsigned long long)dma,
-				 ctrl_ctx->rsvd2[i], i);
-			dma += field_size;
-		}
-
-		if (csz)
-			dbg_rsvd64(xhci, (u64 *)ctrl_ctx, dma);
-	}
-
-	xhci_dbg_slot_ctx(xhci, ctx);
-	xhci_dbg_ep_ctx(xhci, ctx, last_ep);
-}
-
 void xhci_dbg_trace(struct xhci_hcd *xhci, void (*trace)(struct va_format *),
 			const char *fmt, ...)
 {
diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c
index 304f38d..138bbef 100644
--- a/drivers/usb/host/xhci.c
+++ b/drivers/usb/host/xhci.c
@@ -1306,11 +1306,6 @@ static int xhci_check_maxpacket(struct xhci_hcd *xhci, unsigned int slot_id,
 		ctrl_ctx->add_flags = cpu_to_le32(EP0_FLAG);
 		ctrl_ctx->drop_flags = 0;
 
-		xhci_dbg(xhci, "Slot %d input context\n", slot_id);
-		xhci_dbg_ctx(xhci, command->in_ctx, ep_index);
-		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);
@@ -1848,7 +1843,6 @@ static int xhci_evaluate_context_result(struct xhci_hcd *xhci,
 		struct usb_device *udev, u32 *cmd_status)
 {
 	int ret;
-	struct xhci_virt_device *virt_dev = xhci->devs[udev->slot_id];
 
 	switch (*cmd_status) {
 	case COMP_COMMAND_ABORTED:
@@ -1869,7 +1863,6 @@ static int xhci_evaluate_context_result(struct xhci_hcd *xhci,
 	case COMP_CONTEXT_STATE_ERROR:
 		dev_warn(&udev->dev,
 			"WARN: invalid context state for evaluate context command.\n");
-		xhci_dbg_ctx(xhci, virt_dev->out_ctx, 1);
 		ret = -EINVAL;
 		break;
 	case COMP_INCOMPATIBLE_DEVICE_ERROR:
@@ -2743,9 +2736,6 @@ int xhci_check_bandwidth(struct usb_hcd *hcd, struct usb_device *udev)
 			break;
 		}
 	}
-	xhci_dbg(xhci, "New Input Control Context:\n");
-	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,
@@ -2755,10 +2745,6 @@ int xhci_check_bandwidth(struct usb_hcd *hcd, struct usb_device *udev)
 		/* Callee should call reset_bandwidth() */
 		goto command_cleanup;
 
-	xhci_dbg(xhci, "Output context after successful config ep cmd:\n");
-	xhci_dbg_ctx(xhci, virt_dev->out_ctx,
-		     LAST_CTX_TO_EP_NUM(le32_to_cpu(slot_ctx->dev_info)));
-
 	/* Free any rings that were dropped, but not changed. */
 	for (i = 1; i < 31; i++) {
 		if ((le32_to_cpu(ctrl_ctx->drop_flags) & (1 << (i + 1))) &&
@@ -2825,9 +2811,6 @@ static void xhci_setup_input_ctx_for_config_ep(struct xhci_hcd *xhci,
 	ctrl_ctx->drop_flags = cpu_to_le32(drop_flags);
 	xhci_slot_copy(xhci, in_ctx, out_ctx);
 	ctrl_ctx->add_flags |= cpu_to_le32(SLOT_FLAG);
-
-	xhci_dbg(xhci, "Input Context:\n");
-	xhci_dbg_ctx(xhci, in_ctx, xhci_last_valid_endpoint(add_flags));
 }
 
 static void xhci_setup_input_ctx_for_quirk(struct xhci_hcd *xhci,
@@ -3543,9 +3526,6 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev)
 	}
 	/* If necessary, update the number of active TTs on this root port */
 	xhci_update_tt_active_eps(xhci, virt_dev, old_active_eps);
-
-	xhci_dbg(xhci, "Output context after successful reset device cmd:\n");
-	xhci_dbg_ctx(xhci, virt_dev->out_ctx, last_freed_endpoint);
 	ret = 0;
 
 command_cleanup:
@@ -3825,8 +3805,6 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
 	ctrl_ctx->add_flags = cpu_to_le32(SLOT_FLAG | EP0_FLAG);
 	ctrl_ctx->drop_flags = 0;
 
-	xhci_dbg(xhci, "Slot ID %d Input Context:\n", udev->slot_id);
-	xhci_dbg_ctx(xhci, virt_dev->in_ctx, 2);
 	trace_ctx_xhci_setup_device(xhci, virt_dev->in_ctx);
 
 	spin_lock_irqsave(&xhci->lock, flags);
@@ -3879,8 +3857,6 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
 		xhci_err(xhci,
 			 "ERROR: unexpected setup %s command completion code 0x%x.\n",
 			 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_ctx_xhci_setup_device(xhci, virt_dev->out_ctx);
 		ret = -EINVAL;
 		break;
@@ -3899,11 +3875,7 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
 	xhci_dbg_trace(xhci, trace_xhci_dbg_address,
 			"Output Context DMA address = %#08llx",
 			(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_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);
 	/*
 	 * USB core uses address 1 for the roothubs, so we add one to the
 	 * address given back to us by the HC.
@@ -4008,16 +3980,12 @@ static int __maybe_unused xhci_change_max_exit_latency(struct xhci_hcd *xhci,
 
 	xhci_dbg_trace(xhci, trace_xhci_dbg_context_change,
 			"Set up evaluate context for LPM MEL change.");
-	xhci_dbg(xhci, "Slot %u Input Context:\n", udev->slot_id);
-	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);
 
 	if (!ret) {
 		spin_lock_irqsave(&xhci->lock, flags);
@@ -4785,8 +4753,6 @@ int xhci_update_hub_device(struct usb_hcd *hcd, struct usb_device *hdev,
 	xhci_dbg(xhci, "Set up %s for hub device.\n",
 			(xhci->hci_version > 0x95) ?
 			"configure endpoint" : "evaluate context");
-	xhci_dbg(xhci, "Slot %u Input Context:\n", hdev->slot_id);
-	xhci_dbg_ctx(xhci, config_cmd->in_ctx, 0);
 
 	/* Issue and wait for the configure endpoint or
 	 * evaluate context command.
@@ -4800,9 +4766,6 @@ int xhci_update_hub_device(struct usb_hcd *hcd, struct usb_device *hdev,
 				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);
-
 	xhci_free_command(xhci, config_cmd);
 	return ret;
 }
diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index 13ae2ba..ef4a342 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -1923,7 +1923,6 @@ void xhci_debug_ring(struct xhci_hcd *xhci, struct xhci_ring *ring);
 void xhci_dbg_erst(struct xhci_hcd *xhci, struct xhci_erst *erst);
 void xhci_dbg_cmd_ptrs(struct xhci_hcd *xhci);
 void xhci_dbg_ring_ptrs(struct xhci_hcd *xhci, struct xhci_ring *ring);
-void xhci_dbg_ctx(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx, unsigned int last_ep);
 char *xhci_get_slot_state(struct xhci_hcd *xhci,
 		struct xhci_container_ctx *ctx);
 void xhci_dbg_ep_rings(struct xhci_hcd *xhci,
-- 
2.1.4

[PATCH 5/6] usb: xhci: fix link trb decoding

[Lu Baolu]

xhci_decode_trb() treats a link trb in the same way as that for
an event trb. This patch fixes this by decoding the link trb
according to the spec.

Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
---
 drivers/usb/host/xhci.h | 12 +++++-------
 1 file changed, 5 insertions(+), 7 deletions(-)

diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index ef4a342..ff12c8a 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -2159,14 +2159,12 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	switch (type) {
 	case TRB_LINK:
 		sprintf(str,
-			"TRB %08x%08x status '%s' len %d slot %d ep %d type '%s' flags %c:%c",
-			field1, field0,
-			xhci_trb_comp_code_string(GET_COMP_CODE(field2)),
-			EVENT_TRB_LEN(field2), TRB_TO_SLOT_ID(field3),
-			/* Macro decrements 1, maybe it shouldn't?!? */
-			TRB_TO_EP_INDEX(field3) + 1,
+			"LINK %08x%08x intr %d type '%s' flags %c:%c:%c:%c",
+			field1, field0, GET_INTR_TARGET(field2),
 			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
-			field3 & EVENT_DATA ? 'E' : 'e',
+			field3 & TRB_IOC ? 'I' : 'i',
+			field3 & TRB_CHAIN ? 'C' : 'c',
+			field3 & TRB_TC ? 'T' : 't',
 			field3 & TRB_CYCLE ? 'C' : 'c');
 		break;
 	case TRB_TRANSFER:
-- 
2.1.4

[PATCH 6/6] usb: xhci: cleanup xhci_decode_trb() slightly

[Lu Baolu]

Replace 'TRB_FIELD_TO_TYPE(field3)' with 'type' to simplify
code.

Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
---
 drivers/usb/host/xhci.h | 36 ++++++++++++++++++------------------
 1 file changed, 18 insertions(+), 18 deletions(-)

diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index ff12c8a..b97fb75 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -2161,7 +2161,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 		sprintf(str,
 			"LINK %08x%08x intr %d type '%s' flags %c:%c:%c:%c",
 			field1, field0, GET_INTR_TARGET(field2),
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field3 & TRB_IOC ? 'I' : 'i',
 			field3 & TRB_CHAIN ? 'C' : 'c',
 			field3 & TRB_TC ? 'T' : 't',
@@ -2182,7 +2182,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 			EVENT_TRB_LEN(field2), TRB_TO_SLOT_ID(field3),
 			/* Macro decrements 1, maybe it shouldn't?!? */
 			TRB_TO_EP_INDEX(field3) + 1,
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field3 & EVENT_DATA ? 'E' : 'e',
 			field3 & TRB_CYCLE ? 'C' : 'c');
 
@@ -2200,7 +2200,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 			(field1 & 0xff0000) >> 16,
 			TRB_LEN(field2), GET_TD_SIZE(field2),
 			GET_INTR_TARGET(field2),
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field3 & TRB_BEI ? 'B' : 'b',
 			field3 & TRB_IDT ? 'I' : 'i',
 			field3 & TRB_IOC ? 'I' : 'i',
@@ -2220,7 +2220,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 			"Buffer %08x%08x length %d TD size %d intr %d type '%s' flags %c:%c:%c:%c:%c:%c:%c:%c",
 			field1, field0, TRB_LEN(field2), GET_TD_SIZE(field2),
 			GET_INTR_TARGET(field2),
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field3 & TRB_BEI ? 'B' : 'b',
 			field3 & TRB_IDT ? 'I' : 'i',
 			field3 & TRB_IOC ? 'I' : 'i',
@@ -2235,21 +2235,21 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_ENABLE_SLOT:
 		sprintf(str,
 			"%s: flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field3 & TRB_CYCLE ? 'C' : 'c');
 		break;
 	case TRB_DISABLE_SLOT:
 	case TRB_NEG_BANDWIDTH:
 		sprintf(str,
 			"%s: slot %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			TRB_TO_SLOT_ID(field3),
 			field3 & TRB_CYCLE ? 'C' : 'c');
 		break;
 	case TRB_ADDR_DEV:
 		sprintf(str,
 			"%s: ctx %08x%08x slot %d flags %c:%c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field1, field0,
 			TRB_TO_SLOT_ID(field3),
 			field3 & TRB_BSR ? 'B' : 'b',
@@ -2258,7 +2258,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_CONFIG_EP:
 		sprintf(str,
 			"%s: ctx %08x%08x slot %d flags %c:%c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field1, field0,
 			TRB_TO_SLOT_ID(field3),
 			field3 & TRB_DC ? 'D' : 'd',
@@ -2267,7 +2267,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_EVAL_CONTEXT:
 		sprintf(str,
 			"%s: ctx %08x%08x slot %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field1, field0,
 			TRB_TO_SLOT_ID(field3),
 			field3 & TRB_CYCLE ? 'C' : 'c');
@@ -2275,7 +2275,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_RESET_EP:
 		sprintf(str,
 			"%s: ctx %08x%08x slot %d ep %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field1, field0,
 			TRB_TO_SLOT_ID(field3),
 			/* Macro decrements 1, maybe it shouldn't?!? */
@@ -2285,7 +2285,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_STOP_RING:
 		sprintf(str,
 			"%s: slot %d sp %d ep %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			TRB_TO_SLOT_ID(field3),
 			TRB_TO_SUSPEND_PORT(field3),
 			/* Macro decrements 1, maybe it shouldn't?!? */
@@ -2295,7 +2295,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_SET_DEQ:
 		sprintf(str,
 			"%s: deq %08x%08x stream %d slot %d ep %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field1, field0,
 			TRB_TO_STREAM_ID(field2),
 			TRB_TO_SLOT_ID(field3),
@@ -2306,14 +2306,14 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_RESET_DEV:
 		sprintf(str,
 			"%s: slot %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			TRB_TO_SLOT_ID(field3),
 			field3 & TRB_CYCLE ? 'C' : 'c');
 		break;
 	case TRB_FORCE_EVENT:
 		sprintf(str,
 			"%s: event %08x%08x vf intr %d vf id %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field1, field0,
 			TRB_TO_VF_INTR_TARGET(field2),
 			TRB_TO_VF_ID(field3),
@@ -2322,14 +2322,14 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_SET_LT:
 		sprintf(str,
 			"%s: belt %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			TRB_TO_BELT(field3),
 			field3 & TRB_CYCLE ? 'C' : 'c');
 		break;
 	case TRB_GET_BW:
 		sprintf(str,
 			"%s: ctx %08x%08x slot %d speed %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field1, field0,
 			TRB_TO_SLOT_ID(field3),
 			TRB_TO_DEV_SPEED(field3),
@@ -2338,7 +2338,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	case TRB_FORCE_HEADER:
 		sprintf(str,
 			"%s: info %08x%08x%08x pkt type %d roothub port %d flags %c",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field2, field1, field0 & 0xffffffe0,
 			TRB_TO_PACKET_TYPE(field0),
 			TRB_TO_ROOTHUB_PORT(field3),
@@ -2347,7 +2347,7 @@ static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
 	default:
 		sprintf(str,
 			"type '%s' -> raw %08x %08x %08x %08x",
-			xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
+			xhci_trb_type_string(type),
 			field0, field1, field2, field3);
 	}
 
-- 
2.1.4