Hi,
On 01/16/2017 03:03 PM, Felipe Balbi wrote:
> Hi,
>
> Lu Baolu <baolu.lu@xxxxxxxxxxxxxxx> writes:
>> On 12/29/2016 07:01 PM, Felipe Balbi wrote:
>>> instead of having a tracer that can only trace command completions,
>>> let's promote this tracer so it can trace and decode any TRB.
>>>
>>> With that, it will be easier to extrapolate the lifetime of any TRB
>>> which might help debugging certain issues.
>>>
>>> Signed-off-by: Felipe Balbi <felipe.balbi@xxxxxxxxxxxxxxx>
>>> ---
>>> drivers/usb/host/xhci-ring.c | 14 +-
>>> drivers/usb/host/xhci-trace.h | 55 +++++---
>>> drivers/usb/host/xhci.h | 311 ++++++++++++++++++++++++++++++++++++++++++
>>> 3 files changed, 357 insertions(+), 23 deletions(-)
>>>
>>> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
>>> index 393c64f8acef..0ee7d358b812 100644
>>> --- a/drivers/usb/host/xhci-ring.c
>>> +++ b/drivers/usb/host/xhci-ring.c
>>> @@ -1346,6 +1346,9 @@ static void handle_cmd_completion(struct xhci_hcd *xhci,
>>>
>>> cmd_dma = le64_to_cpu(event->cmd_trb);
>>> cmd_trb = xhci->cmd_ring->dequeue;
>>> +
>>> + trace_xhci_handle_command(xhci->cmd_ring, &cmd_trb->generic);
>>> +
>> This is duplicated with trace_xhci_handle_event().
> no it's not. They separate events from the same event class, but they're
> different things.
Comments below.
>
>>> @@ -2407,6 +2408,10 @@ static int handle_tx_event(struct xhci_hcd *xhci,
>>>
>>> ep_trb = &ep_seg->trbs[(ep_trb_dma - ep_seg->dma) /
>>> sizeof(*ep_trb)];
>>> +
>>> + trace_xhci_handle_transfer(ep_ring,
>>> + (struct xhci_generic_trb *) ep_trb);
>>> +
>> This is duplicated with trace_xhci_handle_event().
> ditto
>
>>> + __entry->type = ring->type;
>>> + __entry->field0 = le32_to_cpu(trb->field[0]);
>>> + __entry->field1 = le32_to_cpu(trb->field[1]);
>>> + __entry->field2 = le32_to_cpu(trb->field[2]);
>>> + __entry->field3 = le32_to_cpu(trb->field[3]);
>>> ),
>>> - TP_printk("\ntrb_dma=@%llx, trb_va=@%p, status=%08x, flags=%08x",
>>> - (unsigned long long) __entry->dma, __entry->va,
>>> - __entry->status, __entry->flags
>>> + TP_printk("%s: %s", xhci_ring_type_string(__entry->type),
>> How about moving the common fields of a TRB (like TRB type and
>> the cycle bit) to the place between ring type and trb decoding string?
>> And remove type and cycle decoding in xhci_decode_trb() as well.
>>
>> Something like:
>>
>> diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
>> index d01524b..f8ef7b8 100644
>> --- a/drivers/usb/host/xhci-trace.h
>> +++ b/drivers/usb/host/xhci-trace.h
>> @@ -132,9 +132,11 @@ DECLARE_EVENT_CLASS(xhci_log_trb,
>> __entry->field2 = le32_to_cpu(trb->field[2]);
>> __entry->field3 = le32_to_cpu(trb->field[3]);
>> ),
>> - TP_printk("%s: %s", xhci_ring_type_string(__entry->type),
>> - xhci_decode_trb(__entry->field0, __entry->field1,
>> - __entry->field2, __entry->field3)
>> + TP_printk("%s: %s: %c: %s", xhci_ring_type_string(__entry->type),
>> + xhci_trb_type_string(TRB_FIELD_TO_TYPE(__entry->field3)),
>> + __entry->field3 & TRB_CYCLE ? 'C' : 'c',
>> + xhci_decode_trb(__entry->field0, __entry->field1,
>> + __entry->field2, __entry->field3)
> and what do I get with that? What's the actual benefit?
I thought that it could make xhci_decode_trb() a bit simpler.
>
>> )
>> );
>>
>>
>>> + xhci_decode_trb(__entry->field0, __entry->field1,
>>> + __entry->field2, __entry->field3)
>>> )
>>> );
>>>
>>> -DEFINE_EVENT(xhci_log_event, xhci_cmd_completion,
>>> - TP_PROTO(void *trb_va, struct xhci_generic_trb *ev),
>>> - TP_ARGS(trb_va, ev)
>>> +DEFINE_EVENT(xhci_log_trb, xhci_handle_event,
>>> + TP_PROTO(struct xhci_ring *ring, struct xhci_generic_trb *trb),
>>> + TP_ARGS(ring, trb)
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_trb, xhci_handle_command,
>>> + TP_PROTO(struct xhci_ring *ring, struct xhci_generic_trb *trb),
>>> + TP_ARGS(ring, trb)
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_trb, xhci_handle_transfer,
>>> + TP_PROTO(struct xhci_ring *ring, struct xhci_generic_trb *trb),
>>> + TP_ARGS(ring, trb)
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_trb, xhci_queue_trb,
>>> + TP_PROTO(struct xhci_ring *ring, struct xhci_generic_trb *trb),
>>> + TP_ARGS(ring, trb)
>>> );
>> xhci_handle_command and xhci_handle_transfer are duplications
>> of xhci_handle_event. I suggest to remove them.
> no, they are not. They give us more granularity into which events we
> want to enable.
Fair enough.
But why not defining events for all possible event types as well
and dropping the all-in-one xhci_handle_event switch.
A single event TRB will be traced twice in the same execution
path if xhci_handle_event and xhci_handle_command/transfer
are both enabled.
> They also make it clear where the even is coming
> from. Imagine how the trace would look like if I had a single event and
> just called trace_xhci_handle_event() from all locations. How would you
> differentiate from all possible call sites?
These events happen only in interrupt handler. There are no other
possible call sites.
>
>> How about adding an event for the link TRBs. Something like,
>>
>> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
>> index 4bad432..6dc8efb 100644
>> --- a/drivers/usb/host/xhci-ring.c
>> +++ b/drivers/usb/host/xhci-ring.c
>> @@ -173,6 +173,7 @@ static void inc_deq(struct xhci_hcd *xhci, struct xhci_ring *ring)
>> ring->num_trbs_free++;
>> }
>> while (trb_is_link(ring->dequeue)) {
>> + trace_xhci_link_trb(ring, ring->dequeue);
>> ring->deq_seg = ring->deq_seg->next;
>> ring->dequeue = ring->deq_seg->trbs;
>> }
>> @@ -211,6 +212,7 @@ static void inc_enq(struct xhci_hcd *xhci, struct xhci_ring *ring,
>> ring->enq_updates++;
>> /* Update the dequeue pointer further if that was a link TRB */
>> while (trb_is_link(next)) {
>> + trace_xhci_link_trb(ring, next);
>>
>> /*
>> * If the caller doesn't plan on enqueueing more TDs before
>> diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
>> index d01524b..f1a06b5 100644
>> --- a/drivers/usb/host/xhci-trace.h
>> +++ b/drivers/usb/host/xhci-trace.h
>> @@ -158,6 +158,10 @@ DEFINE_EVENT(xhci_log_trb, xhci_queue_trb,
>> TP_ARGS(ring, trb)
>> );
>>
>> +DEFINE_EVENT(xhci_log_trb, xhci_link_trb,
>> + TP_PROTO(struct xhci_ring *ring, struct xhci_generic_trb *trb),
>> + TP_ARGS(ring, trb)
>> +);
>> #endif /* __XHCI_TRACE_H */
> what are you trying to achieve with this?
To trace and debug the ring itself, especially for ring auto expending and shrinking.
>
>>> +static inline const char *xhci_decode_trb(u32 field0, u32 field1, u32 field2,
>>> + u32 field3)
>>> +{
>>> + static char str[256];
>>> + int type = TRB_FIELD_TO_TYPE(field3);
>>> +
>>> + switch (type) {
>>> + case TRB_LINK:
>>> + sprintf(str, "TRB %08x%08x status '%s' len %d slot %d ep %d type '%s' flags %c:%c",
>> How about using snprintf() to avoid buffer over flow?
> sure
>
>>> + 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,
>>> + xhci_trb_type_string(TRB_FIELD_TO_TYPE(field3)),
>> "TRB_FIELD_TO_TYPE(field3)" could be replaced with "type". The same for other
>> places in this function.
> good catch
>
>>> + field3 & EVENT_DATA ? 'E' : 'e',
>>> + field3 & TRB_CYCLE ? 'C' : 'c');
>> This decoding seems not for a link trb, but an event one. :-)
> copy paste error
>
Best regards,
Lu Baolu
--
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
