Help adding trace events to xHCI

Help adding trace events to xHCI

[Sarah Sharp]

On Mon, Jul 08, 2013 at 09:17:59PM +0300, Xenia Ragiadakou wrote:
> Hi Sarah,

Hi Xenia,

Comments below.

(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.)

> lets say that we want the tracepoint function to have the prototype:
> 
> void trace_cmd_address_device(const char *fmt, ...).
> 
> That internally will be implemented as:
> 
> void trace_cmd_address_device(const char *fmt, ...)
> {
>           if (trace event cmd_address_device is enabled) do {
>                     [...some other code will run here]
>                     (void(*)(const char *fmt, ...)) callback (fmt, '
> ' <-- we need to pass args here);
>           }
> }
> 
> callback will be the function that we actually intend to run and
> which we define when we define the trace_event. This function
> we want to create a string from fmt and the args and copy it
> into the ring buffer.
> 
> The only way to pass the args into this function is by doing
> the following:
> 
> Note: remember that the callback and tracepoint functions must
> have the same prototype.
> 
> void trace_cmd_address_device(void *ptr, const char *fmt, ...)
> {
>           if (trace event cmd_address_device is enabled) do {
>                     [...some other code will run here]
>                     va_list args;
>                     va_start(args, fmt);
>                     (void(*)(void *ptr, const char *fmt, ...))
> callback (args, fmt);
>                     va_end(args);
>           }
> }

Right, that looks pretty similar to what's defined in
drivers/net/wireless/ath/ath6kl/trace.h.  (Note that I'm working on the
very latest Linux kernel, so you may need to `git fetch` Greg KH's USB
tree, and rebase against the usb-next branch.)

> But, that cannot be done because the current tracing framework does not
> give a means to add code outside the callback.

I'm confused about why you need to add more code.  Here's how I
understand the code works, so please correct me if I misinterpreted the
code.

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);
        trace_ath6kl_log_warn(&vaf);
        va_end(args);

        return ret;
}       
EXPORT_SYMBOL(ath6kl_warn);

trace_ath6kl_log_warn() uses the log event class:

DEFINE_EVENT(ath6kl_log_event, ath6kl_log_warn,
             TP_PROTO(struct va_format *vaf),
             TP_ARGS(vaf)
);

DECLARE_EVENT_CLASS(ath6kl_log_event,
        TP_PROTO(struct va_format *vaf),
        TP_ARGS(vaf),
        TP_STRUCT__entry(
                __dynamic_array(char, msg, ATH6KL_MSG_MAX)
        ),
        TP_fast_assign(
                WARN_ON_ONCE(vsnprintf(__get_dynamic_array(msg),
                                       ATH6KL_MSG_MAX,
                                       vaf->fmt,
                                       *vaf->va) >= ATH6KL_MSG_MAX);
        ),
        TP_printk("%s", __get_str(msg))
);

And then the code in files like drivers/net/wireless/ath6kl/cfg80211.c
can simply make what look like printk calls to ath6kl_warn:

ath6kl_warn("clear wmi ctrl data failed: %d\n", left);

I think that we can apply a similar technique to define trace events for
the xhci debugging that's printed when we're issuing a Set Address
command.  Something like:

int xhci_debug_address(const char *fmt, ...)
{
        struct va_format vaf = {
                .fmt = fmt,
        };
        va_list args;
        int ret;

        va_start(args, fmt);
        vaf.va = &args;
        ret = xhci_printk(KERN_WARNING, "%pV", &vaf);
        trace_xhci_dbg_address(&vaf);
        va_end(args);

        return ret;
}       
EXPORT_SYMBOL(xhci_debug_address);

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)
        ),
        TP_fast_assign(
                WARN_ON_ONCE(vsnprintf(__get_dynamic_array(msg),
                                       ATH6KL_MSG_MAX,
                                       vaf->fmt,
                                       *vaf->va) >= ATH6KL_MSG_MAX);
        ),
        TP_printk("%s", __get_str(msg))
);

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);

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.

Xenia, if this all something you've tried already, I apologize. :)  I'm
just trying to understand how the trace event system works, and figure
out what the code should look like for the xHCI driver.

> The thing that i was trying to do, was to pass the pointer to the
> fmt on the stack.
> Something, like:
> 
> void trace_cmd_address_device(const char *fmt, ...)
> {
>           if (trace event cmd_address_device is enabled) do {
>                     [...some other code will run here]
>                     (void(*)(const char *fmt, ...)) callback ((const
> char *)&fmt);
>           }
> }
> 
> and then inside the callback to do:
> 
>                 va_list args;
>                 va_start(args, *(char **)fmt);
>                 vsnprintf(msg_string, mesg_max_len, *(char **)fmt, args);
>                 va_end(args);
> 
> 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);
>           }
> }
> 
> But when there are other function calls before the callback call, I don't
> no why but i cannot track anymore the position of the args following the
> fmt argumenent in the stack with the pointer to fmt.

I'm actually wondering if the call to ath6kl_printk is somehow necessary
in order to be able to pass arguments on the stack.  Perhaps you should
try defining a similar function for xHCI and see if that helps?

int ath6kl_printk(const char *level, const char *fmt, ...)
{
	struct va_format vaf;
	va_list args;
	int rtn;

	va_start(args, fmt);

	vaf.fmt = fmt;
	vaf.va = &args;

	rtn = printk("%sath6kl: %pV", level, &vaf);

	va_end(args);

	return rtn;
}
EXPORT_SYMBOL(ath6kl_printk);

> Anyway, something dirty like that will not enter the kernel but i will try
> to do stack debugging on an example program to see why that happens.

I would suggest just copy-pasting parts of the ath6kl trace code into
the xHCI driver, and changing one of the xhci_dbg() calls to use that
code, and see if it works.  If it doesn't work, send out an RFC patch
(using the Cc list I've used), and we'll try to figure out what's going
wrong.

Sarah Sharp

Re: Help adding trace events to xHCI

[Arend van Spriel]

On 07/11/2013 06:20 PM, Sarah Sharp wrote:
> On Mon, Jul 08, 2013 at 09:17:59PM +0300, Xenia Ragiadakou wrote:

>> But when there are other function calls before the callback call, I don't
>> no why but i cannot track anymore the position of the args following the
>> fmt argumenent in the stack with the pointer to fmt.
>
> I'm actually wondering if the call to ath6kl_printk is somehow necessary
> in order to be able to pass arguments on the stack.  Perhaps you should
> try defining a similar function for xHCI and see if that helps?

The ath6klk_printk() is not related to the trace function. It is a 
separate code path to get the message in the kernel log. I have seen 
these constructs before (and implemented it in brcmfmac) but it seems 
not very efficient when tracing as the printk can affect run-time behaviour.

> int ath6kl_printk(const char *level, const char *fmt, ...)
> {
> 	struct va_format vaf;
> 	va_list args;
> 	int rtn;
>
> 	va_start(args, fmt);
>
> 	vaf.fmt = fmt;
> 	vaf.va = &args;
>
> 	rtn = printk("%sath6kl: %pV", level, &vaf);
>
> 	va_end(args);
>
> 	return rtn;
> }
> EXPORT_SYMBOL(ath6kl_printk);
>
>> Anyway, something dirty like that will not enter the kernel but i will try
>> to do stack debugging on an example program to see why that happens.
>
> I would suggest just copy-pasting parts of the ath6kl trace code into
> the xHCI driver, and changing one of the xhci_dbg() calls to use that
> code, and see if it works.  If it doesn't work, send out an RFC patch
> (using the Cc list I've used), and we'll try to figure out what's going
> wrong.

The biggest challenge in adding tracepoints is identifying what you want 
to trace. While tracing debug messages can be convenient the real 
strength is in tracing code artifacts like for USB the thing that comes 
to my mind first is defining tracepoint for the urb and there are 
probably other internals that are informational.

Regards,
Arend

Re: Help adding trace events to xHCI

[Johannes Berg]

[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

Re: Help adding trace events to xHCI

[Sarah Sharp]

On Thu, Jul 11, 2013 at 07:08:53PM +0200, Johannes Berg wrote:
> [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.

Yes, that does look inefficient.  Would it make sense to add a couple
different trace event classes for different sized buffers, and call
those trace classes conditionally, based on the size of the formatted
string?  Or would that be too much of a mess.

Either way, it's only inefficient when trace events are turned on.  We
don't expect xHCI debugging to be enabled by users very often.  I do
expect that there will be a lot of debugging when it gets turned on.
Can userspace increase the size of the ring buffer?  How much space do
we have by default?

> > 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 :-)

The trace events are unlikely to get backported, so I'm not concerned
about that.

> > 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?

It's debugging the xHCI Address command output.  Depending on the status
of the command, we print different statement in the xHCI code.  E.g. we
print when the command times out, or finishes with an error status
because there was a USB transfer error on the bus.

We can work on better names later. :)

> > 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 :-)

Yes.

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

Noted.

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

My initial list of specific trace points was something like:

1. xHCI host initialization and shutdown

2. xHCI memory allocation (dynamic ring resizing, structure alloc, etc)

3. A few individual xHCI host controller command tracepoints:
   * status only for all completed commands
   * Address Device command status and output
   * Configure Endpoint and Evaluate Context output
   * individual trace points for other xHCI commands

4. Tracepoints for all USB transfer types:
   * Control TX output (only for non-successful transfers)
   * Bulk TX
   * Interrupt TX
   * Isoc TX

5. URB cancellation

And probably more.  Basically, I want to be able to control what gets
printed, based on where I think the xHCI bug might be.  Does that sound
reasonable?

> 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.

So are there parts of the driver that don't have the debug messages go
through the trace events code, in order to not fill up the ring buffer?

> > 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?

Why is it odd?

Sarah Sharp

Re: Help adding trace events to xHCI

[Kalle Valo]

Sarah Sharp <sarah.a.sharp@linux.intel.com> writes:

> My initial list of specific trace points was something like:
>
> 1. xHCI host initialization and shutdown
>
> 2. xHCI memory allocation (dynamic ring resizing, structure alloc, etc)
>
> 3. A few individual xHCI host controller command tracepoints:
>    * status only for all completed commands
>    * Address Device command status and output
>    * Configure Endpoint and Evaluate Context output
>    * individual trace points for other xHCI commands
>
> 4. Tracepoints for all USB transfer types:
>    * Control TX output (only for non-successful transfers)
>    * Bulk TX
>    * Interrupt TX
>    * Isoc TX
>
> 5. URB cancellation
>
> And probably more.  Basically, I want to be able to control what gets
> printed, based on where I think the xHCI bug might be.  Does that sound
> reasonable?

Instead of individual trace points for command I would recommend to
consider just pushing the whole command buffer to the trace point and
parse the command in trace-cmd plugin in user space. Kernel code would
be simpler that way.

-- 
Kalle Valo

Re: Help adding trace events to xHCI

[Sarah Sharp]

On Fri, Jul 12, 2013 at 07:25:59AM +0300, Kalle Valo wrote:
> Sarah Sharp <sarah.a.sharp@linux.intel.com> writes:
> 
> > My initial list of specific trace points was something like:
> >
> > 1. xHCI host initialization and shutdown
> >
> > 2. xHCI memory allocation (dynamic ring resizing, structure alloc, etc)
> >
> > 3. A few individual xHCI host controller command tracepoints:
> >    * status only for all completed commands
> >    * Address Device command status and output
> >    * Configure Endpoint and Evaluate Context output
> >    * individual trace points for other xHCI commands
> >
> > 4. Tracepoints for all USB transfer types:
> >    * Control TX output (only for non-successful transfers)
> >    * Bulk TX
> >    * Interrupt TX
> >    * Isoc TX
> >
> > 5. URB cancellation
> >
> > And probably more.  Basically, I want to be able to control what gets
> > printed, based on where I think the xHCI bug might be.  Does that sound
> > reasonable?
> 
> Instead of individual trace points for command I would recommend to
> consider just pushing the whole command buffer to the trace point and
> parse the command in trace-cmd plugin in user space. Kernel code would
> be simpler that way.

Thanks for the suggestion.  I'm not familiar with all the userspace
tools for trace events, so I didn't know about the command parser.  Is
there documentation or a list of resources for all the userspace trace
event plugins?  If so, can you give us a pointer to it?

Sarah Sharp

Re: Help adding trace events to xHCI

[Steven Rostedt]

On Fri, 2013-07-12 at 09:41 -0700, Sarah Sharp wrote:
> On Fri, Jul 12, 2013 at 07:25:59AM +0300, Kalle Valo wrote:

> Thanks for the suggestion.  I'm not familiar with all the userspace
> tools for trace events, so I didn't know about the command parser.  Is
> there documentation or a list of resources for all the userspace trace
> event plugins?  If so, can you give us a pointer to it?
> 

Currently the plugins only exist in trace-cmd. But there's going to be
work done to get them into the kernel tools directory. I was just
talking with Jiri about this today. Perf will require it.

trace-cmd repo is here:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

-- Steve

Re: Help adding trace events to xHCI

[Jiri Olsa]

On Fri, Jul 12, 2013 at 12:55:43PM -0400, Steven Rostedt wrote:
> On Fri, 2013-07-12 at 09:41 -0700, Sarah Sharp wrote:
> > On Fri, Jul 12, 2013 at 07:25:59AM +0300, Kalle Valo wrote:
> 
> > Thanks for the suggestion.  I'm not familiar with all the userspace
> > tools for trace events, so I didn't know about the command parser.  Is
> > there documentation or a list of resources for all the userspace trace
> > event plugins?  If so, can you give us a pointer to it?
> > 
> 
> Currently the plugins only exist in trace-cmd. But there's going to be
> work done to get them into the kernel tools directory. I was just
> talking with Jiri about this today. Perf will require it.

hi,
I made initial backport but got distracted.. ;-)
I'll refresh those patches and resend them out soon..

jirka

Re: Help adding trace events to xHCI

[Mathieu Desnoyers]

* Sarah Sharp (sarah.a.sharp@linux.intel.com) wrote:
> On Fri, Jul 12, 2013 at 07:25:59AM +0300, Kalle Valo wrote:
> > Sarah Sharp <sarah.a.sharp@linux.intel.com> writes:
> > 
> > > My initial list of specific trace points was something like:
> > >
> > > 1. xHCI host initialization and shutdown
> > >
> > > 2. xHCI memory allocation (dynamic ring resizing, structure alloc, etc)
> > >
> > > 3. A few individual xHCI host controller command tracepoints:
> > >    * status only for all completed commands
> > >    * Address Device command status and output
> > >    * Configure Endpoint and Evaluate Context output
> > >    * individual trace points for other xHCI commands
> > >
> > > 4. Tracepoints for all USB transfer types:
> > >    * Control TX output (only for non-successful transfers)
> > >    * Bulk TX
> > >    * Interrupt TX
> > >    * Isoc TX
> > >
> > > 5. URB cancellation
> > >
> > > And probably more.  Basically, I want to be able to control what gets
> > > printed, based on where I think the xHCI bug might be.  Does that sound
> > > reasonable?
> > 
> > Instead of individual trace points for command I would recommend to
> > consider just pushing the whole command buffer to the trace point and
> > parse the command in trace-cmd plugin in user space. Kernel code would
> > be simpler that way.
> 
> Thanks for the suggestion.  I'm not familiar with all the userspace
> tools for trace events, so I didn't know about the command parser.  Is
> there documentation or a list of resources for all the userspace trace
> event plugins?  If so, can you give us a pointer to it?

(CCing lttng-dev)

You might want to try out LTTng-UST. It provides TRACEPOINT_EVENT() and
tracepoint() for user-space instrumentation. See:

- https://lttng.org/files/doc/man-pages/man3/lttng-ust.3.html
- http://lttng.org

Thanks,

Mathieu

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

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: Help adding trace events to xHCI

[Mark Wielaard]

Hi Mathieu,

On Fri, Jul 12, 2013 at 01:08:28PM -0400, Mathieu Desnoyers wrote:
> * Sarah Sharp (sarah.a.sharp@linux.intel.com) wrote:
> > Thanks for the suggestion.  I'm not familiar with all the userspace
> > tools for trace events, so I didn't know about the command parser.  Is
> > there documentation or a list of resources for all the userspace trace
> > event plugins?  If so, can you give us a pointer to it?
> 
> You might want to try out LTTng-UST. It provides TRACEPOINT_EVENT() and
> tracepoint() for user-space instrumentation. See:
> 
> - https://lttng.org/files/doc/man-pages/man3/lttng-ust.3.html

Is that build on the <sys/sdt.h> ust probe points as embedded in glibc
for example that gdb and systemtap use to access user space trace
points? Can tools use lttng-ust and <sys/sdt.h> tracepoints
interchangeably by parsing the ELF notes described in
http://sourceware.org/systemtap/wiki/UserSpaceProbeImplementation

Thanks,

Mark

Re: Help adding trace events to xHCI

[Mathieu Desnoyers]

* Mark Wielaard (mjw@redhat.com) wrote:
> Hi Mathieu,
> 
> On Fri, Jul 12, 2013 at 01:08:28PM -0400, Mathieu Desnoyers wrote:
> > * Sarah Sharp (sarah.a.sharp@linux.intel.com) wrote:
> > > Thanks for the suggestion.  I'm not familiar with all the userspace
> > > tools for trace events, so I didn't know about the command parser.  Is
> > > there documentation or a list of resources for all the userspace trace
> > > event plugins?  If so, can you give us a pointer to it?
> > 
> > You might want to try out LTTng-UST. It provides TRACEPOINT_EVENT() and
> > tracepoint() for user-space instrumentation. See:
> > 
> > - https://lttng.org/files/doc/man-pages/man3/lttng-ust.3.html
> 
> Is that build on the <sys/sdt.h> ust probe points as embedded in glibc
> for example that gdb and systemtap use to access user space trace
> points?

LTTng-UST tracepoints are not built on sdt.h, but they can optionally
emit sdt.h instrumentation. All you need to do is run:

./configure --with-sdt

when configuring lttng-ust, and after a make install, sdt.h
STAP_PROBEV() will be emitted whenever a lttng-ust tracepoint() macro is
used in the system.

> Can tools use lttng-ust and <sys/sdt.h> tracepoints
> interchangeably by parsing the ELF notes described in
> http://sourceware.org/systemtap/wiki/UserSpaceProbeImplementation

Since lttng-ust tracepoints emit sdt.h instrumentation, yes. However,
please note that the reverse is not possible: sdt.h instrumentation does
not allow tracing with LTTng-UST.

Thanks,

Mathieu

> 
> Thanks,
> 
> Mark

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: Help adding trace events to xHCI

[Kalle Valo]

Sarah Sharp <sarah.a.sharp@linux.intel.com> writes:

> On Fri, Jul 12, 2013 at 07:25:59AM +0300, Kalle Valo wrote:
>
>> Instead of individual trace points for command I would recommend to
>> consider just pushing the whole command buffer to the trace point and
>> parse the command in trace-cmd plugin in user space. Kernel code would
>> be simpler that way.
>
> Thanks for the suggestion.  I'm not familiar with all the userspace
> tools for trace events, so I didn't know about the command parser.  Is
> there documentation or a list of resources for all the userspace trace
> event plugins?  If so, can you give us a pointer to it?

For ath6kl I started writing (but did not finish yet) a simple python
plugin for trace-cmd. I really like the idea of implementing of
implementing the parser with python, it's so much faster and more
convenient. I haven't published the plugin yet so that's not going to
help you right now.

But trace-cmd documentation about python plugins should give some ideas
how to use python:

https://git.kernel.org/cgit/linux/kernel/git/rostedt/trace-cmd.git/tree/Documentation/README.PythonPlugin

And as usual, Johannes is a good source of information ;)

-- 
Kalle Valo

Re: Help adding trace events to xHCI

[Johannes Berg]

[sorry for the late response!]

> Yes, that does look inefficient.  Would it make sense to add a couple
> different trace event classes for different sized buffers, and call
> those trace classes conditionally, based on the size of the formatted
> string?  Or would that be too much of a mess.

I don't see a way you could even do that, since you'd have to print the
string to decide which event to use, but then at the time you'd have
done most of the work already, so that'd just penalise the
tracing-disabled case, I think.

> Either way, it's only inefficient when trace events are turned on.  We
> don't expect xHCI debugging to be enabled by users very often.  I do
> expect that there will be a lot of debugging when it gets turned on.
> Can userspace increase the size of the ring buffer?  How much space do
> we have by default?

I don't know, I think it's dynamic up to some maximum.

> > > 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?
> 
> It's debugging the xHCI Address command output.  Depending on the status
> of the command, we print different statement in the xHCI code.  E.g. we
> print when the command times out, or finishes with an error status
> because there was a USB transfer error on the bus.
> 
> We can work on better names later. :)

I was thinking less about the names and more about the semantics of the
tracing. It might be worth, for example, to not print different
statements in the tracepoint but instead add the (partial) command and
its status, and have a tracing plugin that post-processes it into a
better string. But I'm not familiar enough with xHCI to say whether
that's possible or not.

For example, in iwlwifi, I can trace the communication with the device,
so you'd have the actual command I send over the PCIe bus to the device,
and the response I'm getting from the firmware running in the device.
Those are just binary blobs in the trace, but I can post-process to
print their contents.

> > 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
> 
> My initial list of specific trace points was something like:
> 
> 1. xHCI host initialization and shutdown
> 
> 2. xHCI memory allocation (dynamic ring resizing, structure alloc, etc)
> 
> 3. A few individual xHCI host controller command tracepoints:
>    * status only for all completed commands
>    * Address Device command status and output
>    * Configure Endpoint and Evaluate Context output
>    * individual trace points for other xHCI commands
> 
> 4. Tracepoints for all USB transfer types:
>    * Control TX output (only for non-successful transfers)
>    * Bulk TX
>    * Interrupt TX
>    * Isoc TX
> 
> 5. URB cancellation
> 
> And probably more.  Basically, I want to be able to control what gets
> printed, based on where I think the xHCI bug might be.  Does that sound
> reasonable?

You'd have to explain xHCI to me in more detail :-)

Some of these are driver things only, right? Like memory allocation,
etc. Those would make sense as separate tracepoints I think. For the
communication with the device, I've found for our device that having
just partial information usually isn't very useful unless there's a very
specific bug like having the wrong bit set in some command, so I'm
recording all of that without much differentiation.

I think I'd not split it as detailed as you suggested, but rather have a
tracepoint for the xHCI host controller command submission and another
one for status, and similarly two (or need just one maybe?) for the
different transfer types.

Btw, a good thing for something like this is to use multiple trace
systems, like in iwlwifi or mac80211 for example, we #define
TRACE_SYSTEM multiple times so you can record sets of tracepoints more
easily and don't have to select a bunch of single ones.

> > 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.
> 
> So are there parts of the driver that don't have the debug messages go
> through the trace events code, in order to not fill up the ring buffer?

Very very few, but the debug messages have two ways of showing up:
 * tracing (all of them all the time)
 * printk (selected per debug 'level' or 'functional subsystem')

> > > 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?
> 
> Why is it odd?

Well, it's just a feeling really, but if I think about where it comes
from it seems that you might be able to build more detailed tracepoints
(though you don't want to overdo it!) that get the input data, instead
of formatting it.

Let me make an example. In iwlwifi (sorry, but that's what I'm really
familiar with ...) I have device commands, and get a status response
(possibly with more data) for each of them. The status can be an empty
response (just 'ok'), or with a 32-bit status field, or with more
information.

I could now do something like this:

 if (cmd->len == 4)
     trace_msg("empty response for cmd %d", cmd->id);
 else /* must be >= 8 due to alignment etc. */
     trace_msg("response with status %d for cmd %d", cmd->status,
cmd->id);

Instead though, what I did is this:

 trace_status(cmd->len, (void *)cmd);

which will just put the binary data coming from the device there, so I
can analyse it later.

johannes

Re: Help adding trace events to xHCI

[Steven Rostedt]

On Thu, 2013-07-11 at 19:08 +0200, Johannes Berg wrote:

> > > 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.

Can you add a helper function? If these trace events can't nest (one in
interrupt context and another in normal context with interrupts
enabled), then you can just allocate a per-cpu buffer and store the
string in that, and then move the string into the buffer.

	vsnprintf(this_cpu_ptr(trace_buf), MAX_BUF_LEN, fmt, va);
	__assign_str(str, trace_buf);

You could even use the reg, unreg, methods for TRACE_EVENT_FN() that
will allocate the buffers when the tracepoint is created. This will mean
that you don't waste memory when not tracing.

-- Steve

Re: Help adding trace events to xHCI

[Johannes Berg]

On Thu, 2013-07-11 at 15:29 -0400, Steven Rostedt wrote:

> > 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.
> 
> Can you add a helper function? If these trace events can't nest (one in
> interrupt context and another in normal context with interrupts
> enabled), then you can just allocate a per-cpu buffer and store the
> string in that, and then move the string into the buffer.

In my situation personally, I can't, because I can have them in
interrupt and regular context (with interrupts enabled).

My original though here was that we should be able to reserve (maximum)
space on the per-CPU buffer, and then relinquish some of it after the
tracepoint was written to the data, but I never had the time to check if
that was possible to implement. It would make it a little inefficient at
page boundaries, but that seems OK given that our maximum size is only
~100 bytes or so now.

johannes

Re: Help adding trace events to xHCI

[Steven Rostedt]

On Fri, 2013-07-26 at 11:19 +0200, Johannes Berg wrote:

> My original though here was that we should be able to reserve (maximum)
> space on the per-CPU buffer, and then relinquish some of it after the
> tracepoint was written to the data, but I never had the time to check if
> that was possible to implement. It would make it a little inefficient at
> page boundaries, but that seems OK given that our maximum size is only
> ~100 bytes or so now.
> 

Yes that would be trivial to implement. If the max buffer is ~100 bytes,
allocate 256 byte buffers per cpu. Also have a per cpu index, and then
have something like this:


	index = local_add_return(this_cpu_ptr(trace_index), len);

	if (index >= MAX_BUF) {
		/* write tracepoint with failed buffer */
		local_sub(this_cpu_ptr(trace_index));
		return;
	}

	index -= len;

	memcpy(this_cpu_ptr(trace_buf) + index, string, len);

	/* write tracepoint with trace_buf */

	local_sub(this_cpu_ptr(trace_index), len);


This way the trace_buf will work like a stack allocator. The
local_add_return() will reserve the space in the buffer such that if an
interrupt were to come in, it would allocate after that space. The check
for MAX_BUF tests for the case that the buffer was too big and had to
bail. Still trace that event to let the user (yourself) know you need a
bigger buffer.

-- Steve

Re: Help adding trace events to xHCI

[Johannes Berg]

On Fri, 2013-07-26 at 08:28 -0400, Steven Rostedt wrote:

> > My original though here was that we should be able to reserve (maximum)
> > space on the per-CPU buffer, and then relinquish some of it after the
> > tracepoint was written to the data, but I never had the time to check if
> > that was possible to implement. It would make it a little inefficient at
> > page boundaries, but that seems OK given that our maximum size is only
> > ~100 bytes or so now.

> Yes that would be trivial to implement. If the max buffer is ~100 bytes,
> allocate 256 byte buffers per cpu. Also have a per cpu index, and then
> have something like this:
> 
>  [snip]

Ah, yes, that'd work. I was considering putting it into the trace event
handling itself so I don't have to allocate those buffers and put the
handling into every tracepoint, but I don't know how that'd work with
interrupts coming in.

If we assume that interrupts coming in in the middle of a tracepoint
should be rare, we could do something like

 * allocate max buffer in on the tracing ringbuffer page
 * write data into it
 * if no interrupt came in, reduce reservation

but I'm not sure how to implement step 3 :)

johannes

Re: Help adding trace events to xHCI

[Steven Rostedt]

On Fri, 2013-07-26 at 15:06 +0200, Johannes Berg wrote:
> On Fri, 2013-07-26 at 08:28 -0400, Steven Rostedt wrote:

> Ah, yes, that'd work. I was considering putting it into the trace event
> handling itself so I don't have to allocate those buffers and put the
> handling into every tracepoint, but I don't know how that'd work with
> interrupts coming in.

If you create helper functions, it shouldn't be too hard.

> 
> If we assume that interrupts coming in in the middle of a tracepoint
> should be rare, we could do something like
> 
>  * allocate max buffer in on the tracing ringbuffer page
>  * write data into it
>  * if no interrupt came in, reduce reservation
> 
> but I'm not sure how to implement step 3 :)
> 

It's possible to reduce the ring buffer, it's just not implemented. I'm
not sure I want to do that either. Interrupts coming in is not so rare
as it can be any interrupt being traced. This means your tracepoints
will likely waste a lot of buffer space if you are tracing interrupts as
well.

That said, I can probably implement a reduce feature of the ring buffer
if needed.

-- Steve

Re: Help adding trace events to xHCI

[Johannes Berg]

On Fri, 2013-07-26 at 09:17 -0400, Steven Rostedt wrote:
> On Fri, 2013-07-26 at 15:06 +0200, Johannes Berg wrote:
> > On Fri, 2013-07-26 at 08:28 -0400, Steven Rostedt wrote:
> 
> > Ah, yes, that'd work. I was considering putting it into the trace event
> > handling itself so I don't have to allocate those buffers and put the
> > handling into every tracepoint, but I don't know how that'd work with
> > interrupts coming in.
> 
> If you create helper functions, it shouldn't be too hard.

True, and I could even export them somewhere to share the buffers
between all the different subsystems that might use this.


> > If we assume that interrupts coming in in the middle of a tracepoint
> > should be rare, we could do something like
> > 
> >  * allocate max buffer in on the tracing ringbuffer page
> >  * write data into it
> >  * if no interrupt came in, reduce reservation
> > 
> > but I'm not sure how to implement step 3 :)
> > 
> 
> It's possible to reduce the ring buffer, it's just not implemented. I'm
> not sure I want to do that either. Interrupts coming in is not so rare
> as it can be any interrupt being traced. This means your tracepoints
> will likely waste a lot of buffer space if you are tracing interrupts as
> well.

Well, right now I can live with allocation 110 bytes for each
tracepoint, this would just optimise it down. If I was in the middle of
writing one such event while an interrupt came in, I'd not be able to
reduce the ring-buffer allocation again. I doubt that an interrupt would
come in much of the time between allocating the new event and
deallocating it partially. The more difficult question would seem to be
whether or not we can reliably detect an interrupt having written
another event.

Also, this would save the memcpy() your scheme had.

Anyway, I'm fine with the current status quo, but if more people want to
trace variable length things like formatted strings I think it might
make sense to add some way of making that more efficient.

johannes

Re: Help adding trace events to xHCI

[Steven Rostedt]

On Fri, 2013-07-26 at 15:45 +0200, Johannes Berg wrote:

> Well, right now I can live with allocation 110 bytes for each
> tracepoint, this would just optimise it down. If I was in the middle of
> writing one such event while an interrupt came in, I'd not be able to
> reduce the ring-buffer allocation again. I doubt that an interrupt would
> come in much of the time between allocating the new event and
> deallocating it partially. The more difficult question would seem to be
> whether or not we can reliably detect an interrupt having written
> another event.
> 

Hmm, you may be convincing me ;-)

As it just allocates the "max" anyway, this feature will actually help.

Don't worry about the detection of interrupt, it already does that with
the discard event. It wouldn't be that hard to extend that into a
reduction too.

-- Steve

Re: Help adding trace events to xHCI

[Kalle Valo]

Johannes Berg <johannes@sipsolutions.net> writes:

>> (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.

Correct, I used your code as example.

> 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.

The reason why added message tracing to ath6kl was that I wanted to
combine wpasupplicant, cfg80211 and ath6kl debug messages all into file
with synchronised timestamps. In this case I wasn't actually concerned
about performance at all.

-- 
Kalle Valo