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  writes:
>>> Lu Baolu  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 :-)
>

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Felipe Balbi]

Hi,

Lu Baolu  writes:
>> Lu Baolu  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


signature.asc
Description: PGP signature

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  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
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Felipe Balbi]

Hi,

Lu Baolu  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


signature.asc
Description: PGP signature

[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 
---
 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(>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_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, >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",
+