Re: Help adding trace events to xHCI

[Johannes Berg <johannes@sipsolutions.net>]

[also adding Steven, he's the tracing expert after all :-)]

Hi Xenia, Sarah, all,

> (Mentors and wireless folks, we're struggling a bit with adding trace
> events to the xHCI USB host controller driver.  I'm trying to look at
> the ath6kl driver trace events as an example.  We could use some help
> and/or advice.)

Those were in turn modelled on mac80211, cfg80211 and/or iwlwifi, I
think; might be worth also looking there. In general though, it's all
pretty similar.

> > lets say that we want the tracepoint function to have the prototype:
> > 
> > void trace_cmd_address_device(const char *fmt, ...).

I'm not sure this is possible. I think we (wireless) do this with

void trace_cmd_address_device(struct va_format *vaf)

instead only.

Note that there's no easy way to dynamically allocate the right amount
of space in the ringbuffer, or at least I haven't found one. We
therefore have a static size, which is somewhat inefficient.


> The ath driver defines a new trace event class, ath6kl_log_event.
> Various types of tracepoints, like trace_ath6kl_log_warn, use that event
> class.  Wrappers like ath6kl_warn() call those trace points, passing it
> a struct va_format on the stack:
> 
> int ath6kl_warn(const char *fmt, ...)
> {
>         struct va_format vaf = {
>                 .fmt = fmt,
>         };
>         va_list args;
>         int ret;
> 
>         va_start(args, fmt);
>         vaf.va = &args;
>         ret = ath6kl_printk(KERN_WARNING, "%pV", &vaf);

Note also on older kernels you used to have to do va_copy() here because
"%pV" didn't do it by itself. Guess you don't care though, but I
sometimes have to worry about backporting :-)

> int xhci_debug_address(const char *fmt, ...)

This confuses me somewhat -- why is it called "xhci_debug_address()"
when it takes arbitrary parameters? Where's the "address" part?

> DEFINE_EVENT(xhci_log_event, xhci_dbg_address,
>              TP_PROTO(struct va_format *vaf),
>              TP_ARGS(vaf)
> );
> 
> DECLARE_EVENT_CLASS(xhci_log_event,
>         TP_PROTO(struct va_format *vaf),
>         TP_ARGS(vaf),
>         TP_STRUCT__entry(
>                 __dynamic_array(char, msg, ATH6KL_MSG_MAX)

Should probably not be ATH6KL_MSG_MAX :-)

And this is what I talked about before -- it always allocates the max in
the ringbuffer even for really short messages.


> And then code in xhci_address_device() in drivers/usb/host/xhci.c can do
> things like:
> 
> xhci_debug_address(xhci, "Bad Slot ID %d\n", udev->slot_id);

Otherwise this looks about right (you have an xhci argument you didn't
declare above, but this is obviously pseudo-code only)

> And we can define similar trace event classes for the various xHCI
> commands or ring debugging, so that we can enable or disable trace
> points individually for different parts of the xHCI driver.

I think it'd be worth (also) doing more specific tracepoints instead
though.

I don't really know what xhci does, but I suppose it has register
read/write, maybe packet (urb?) submissions etc. so something like the
iwlwifi_io system in drivers/net/wireless/iwlwifi/iwl-devtrace.h might
(also) be (more) useful. In iwlwifi I have tracing for
 * IO accesses & interrupt notifications/reasons
 * commands and TX packets submitted to the device
 * notifications/RX packets received from the device
 * previously existing debug messages

The message tracing was really more of an after-thought in iwlwifi (and
ath6kl as well I guess) because we already had a lot of debug messages
and capturing it all together can be useful.

However, tracing all the debug messages is actually fairly expensive, I
think in part because of the string formatting and in part because of
the always-max allocations in the ringbuffer.


> > That would have worked if the tracepoint was just :
> > 
> > void trace_cmd_address_device(const char *fmt, ...)
> > {
> >           if (trace event cmd_address_device is enabled) do {
> >                     (void(*)(const char *fmt, ...)) callback ((const
> > char *)&fmt);
> >           }
> > }

I'm not really sure what the whole "callback()" part is about?

Are you trying to use the "tracepoint is enabled" to do something
unrelated to the tracing? I'm guessing that's _possible_, but I wouldn't
recommend it.


> I'm actually wondering if the call to ath6kl_printk is somehow necessary
> in order to be able to pass arguments on the stack.

I don't think it is, but formatting the messages *only* for tracing
seems a bit odd?

Hth,
johannes