Hi, Lu Baolu <baolu...@linux.intel.com> 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.ba...@linux.intel.com> >> --- >> 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.
Again, compile the branch and look at the 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.
> 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
>> 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).
--
balbi
signature.asc
Description: PGP signature
