Hi,
On 01/16/2017 05:08 PM, Felipe Balbi wrote:
> Hi,
>
> Lu Baolu <baolu.lu@xxxxxxxxxxxxxxx> writes:
>> Hi,
>>
>> On 12/29/2016 07:01 PM, Felipe Balbi wrote:
>>> Let's start tracing at least part of an xhci_virt_device lifetime. We
>>> might want to extend this tracepoint class later, but for now it already
>>> exposes quite a bit of valuable information.
>>>
>>> Signed-off-by: Felipe Balbi <felipe.balbi@xxxxxxxxxxxxxxx>
>>> ---
>>> drivers/usb/host/xhci-hub.c | 2 ++
>>> drivers/usb/host/xhci-mem.c | 7 ++++++
>>> drivers/usb/host/xhci-trace.h | 57 +++++++++++++++++++++++++++++++++++++++++++
>>> drivers/usb/host/xhci.c | 1 +
>>> 4 files changed, 67 insertions(+)
>>>
>>> diff --git a/drivers/usb/host/xhci-hub.c b/drivers/usb/host/xhci-hub.c
>>> index b99f06f4c421..6fdea9e5e3a5 100644
>>> --- a/drivers/usb/host/xhci-hub.c
>>> +++ b/drivers/usb/host/xhci-hub.c
>>> @@ -389,6 +389,8 @@ static int xhci_stop_device(struct xhci_hcd *xhci, int slot_id, int suspend)
>>> if (!virt_dev)
>>> return -ENODEV;
>>>
>>> + trace_xhci_stop_device(virt_dev);
>>> +
>> I'd suggest move the trace down until all stop endpoint commands complete.
>> The state of a virt_device affects only after the command completes.
> no, that's the wrong thing to do. We're trying to track the *lifetime*
> of things. xhci_stop_device() prepares a command to stop the
> device. There's another command tracer which will trigger on command
> completion IRQ. That command will also be traced.
Got it, thanks.
>
> Again, compile the branch and look at the output.
Yes. I have an output.
>
>>> diff --git a/drivers/usb/host/xhci-mem.c b/drivers/usb/host/xhci-mem.c
>>> index b12631ef160b..2b7c3504a95a 100644
>>> --- a/drivers/usb/host/xhci-mem.c
>>> +++ b/drivers/usb/host/xhci-mem.c
>>> @@ -936,6 +936,9 @@ void xhci_free_virt_device(struct xhci_hcd *xhci, int slot_id)
>>> return;
>>>
>>> dev = xhci->devs[slot_id];
>>> +
>>> + trace_xhci_free_virt_device(dev);
>>> +
>>> xhci->dcbaa->dev_context_ptrs[slot_id] = 0;
>>> if (!dev)
>>> return;
>>> @@ -1041,6 +1044,8 @@ int xhci_alloc_virt_device(struct xhci_hcd *xhci, int slot_id,
>>> &xhci->dcbaa->dev_context_ptrs[slot_id],
>>> le64_to_cpu(xhci->dcbaa->dev_context_ptrs[slot_id]));
>>>
>>> + trace_xhci_alloc_virt_device(dev);
>>> +
>>> return 1;
>>> fail:
>>> xhci_free_virt_device(xhci, slot_id);
>>> @@ -1215,6 +1220,8 @@ int xhci_setup_addressable_virt_dev(struct xhci_hcd *xhci, struct usb_device *ud
>>> ep0_ctx->deq = cpu_to_le64(dev->eps[0].ring->first_seg->dma |
>>> dev->eps[0].ring->cycle_state);
>>>
>>> + trace_xhci_setup_addressable_virt_device(dev);
>>> +
>>> /* Steps 7 and 8 were done in xhci_alloc_virt_device() */
>>>
>>> return 0;
>>> diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
>>> index 08bed2f07e50..1e85c893247d 100644
>>> --- a/drivers/usb/host/xhci-trace.h
>>> +++ b/drivers/usb/host/xhci-trace.h
>>> @@ -158,6 +158,63 @@ DEFINE_EVENT(xhci_log_trb, xhci_queue_trb,
>>> TP_ARGS(ring, trb)
>>> );
>>>
>>> +DECLARE_EVENT_CLASS(xhci_log_virt_dev,
>>> + TP_PROTO(struct xhci_virt_device *vdev),
>>> + TP_ARGS(vdev),
>>> + TP_STRUCT__entry(
>>> + __field(void *, vdev)
>>> + __field(unsigned long long, out_ctx)
>>> + __field(unsigned long long, in_ctx)
>>> + __field(int, devnum)
>>> + __field(int, state)
>>> + __field(int, speed)
>>> + __field(u8, portnum)
>>> + __field(u8, level)
>>> + __field(int, slot_id)
>>> + ),
>>> + TP_fast_assign(
>>> + __entry->vdev = vdev;
>>> + __entry->in_ctx = (unsigned long long) vdev->in_ctx->dma;
>>> + __entry->out_ctx = (unsigned long long) vdev->out_ctx->dma;
>>> + __entry->devnum = vdev->udev->devnum;
>>> + __entry->state = vdev->udev->state;
>>> + __entry->speed = vdev->udev->speed;
>>> + __entry->portnum = vdev->udev->portnum;
>>> + __entry->level = vdev->udev->level;
>>> + __entry->slot_id = vdev->udev->slot_id;
>>> + ),
>>> + TP_printk("vdev %p ctx %llx | %llx num %d state %d speed %d port %d level %d slot %d",
>>> + __entry->vdev, __entry->in_ctx, __entry->out_ctx, __entry->devnum,
>>> + __entry->state, __entry->speed, __entry->portnum, __entry->level,
>>> + __entry->slot_id
>>> + )
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_virt_dev, xhci_alloc_virt_device,
>>> + TP_PROTO(struct xhci_virt_device *vdev),
>>> + TP_ARGS(vdev)
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_virt_dev, xhci_free_virt_device,
>>> + TP_PROTO(struct xhci_virt_device *vdev),
>>> + TP_ARGS(vdev)
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_virt_dev, xhci_setup_device,
>>> + TP_PROTO(struct xhci_virt_device *vdev),
>>> + TP_ARGS(vdev)
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_virt_dev, xhci_setup_addressable_virt_device,
>>> + TP_PROTO(struct xhci_virt_device *vdev),
>>> + TP_ARGS(vdev)
>>> +);
>>> +
>>> +DEFINE_EVENT(xhci_log_virt_dev, xhci_stop_device,
>>> + TP_PROTO(struct xhci_virt_device *vdev),
>>> + TP_ARGS(vdev)
>>> +);
>> The lifetime of a USB virtual device in xhci host is defined by
>> "Figure 10: Slot State Diagram" on spec page 83. These events
>> are partial of the life. It's okay to me as the commit message
>> has covered this anyway.
>>
>> For long term purpose, since the states of a virt_device are driven
>> by the xhci commands, it's better to define the event names according
>> to 1) command name; 2) the new state after command.
> that'll make grepping a lot more difficult. Have you not noticed that
> I'm calling events the same name as the function they're called from?
> There's a reason for that. I want to make my life easier. If I see on my
> trace output that xhci_setup_device() tracer gives me an error, I'll
> look for xhci_setup_device() function.
Ah, yes. Using the function name looks better.
>
>> I am still confused by the difference between xhci_setup_device
>> and xhci_setup_addressable_virt_device. It seems that these
>> two events traces "set address phase" at the same time.
> I can see contexts changing with that. Please compile branch and look at
> output.
Got it. Thanks.
>
>>> diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c
>>> index c0f3670e5a51..e5f095b276fc 100644
>>> --- a/drivers/usb/host/xhci.c
>>> +++ b/drivers/usb/host/xhci.c
>>> @@ -3860,6 +3860,7 @@ static int xhci_setup_device(struct usb_hcd *hcd, struct usb_device *udev,
>>> le32_to_cpu(slot_ctx->dev_info) >> 27);
>>>
>>> spin_lock_irqsave(&xhci->lock, flags);
>>> + trace_xhci_setup_device(virt_dev);
>> Same here.
>>
>> Move the trace down until the address device command completes.
> no. I would loose the tracepoint for the command being queued. I want to
> see queue -> execute -> complete for everything. And I want to know what
> changes along the way (slot context, ep context, etc).
Fair enough. Got it now.
I have no further questions about this patch. Thank you for letting me know
the reasons why you defines the events and the trace points which benefit
debugging.
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
