Help adding trace events to xHCI
A message that is not in the archive (sent off-list or not yet received): [email protected]
Quoted 1 line · Xenia Ragiadakou
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.)
Quoted 27 lines
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, ...)
Quoted 10 lines
{
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.)
Quoted 2 lines
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.
Quoted 30 lines
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); } }
Quoted 3 lines
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);
Quoted 2 lines
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
Quoted 9 lines · Sarah Sharp
Quoted 3 lines · Xenia Ragiadakou
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_printkis 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.
Quoted 19 lines
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);
Quoted 8 lines
Quoted 2 lines
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
[also adding Steven, he's the tracing expert after all :-)]
Hi Xenia, Sarah, all,
Quoted 4 lines
(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.
Quoted 3 lines
Quoted 3 lines
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.
Quoted 6 lines
The ath driver defines a new trace event class,
ath6kl_log_event. Various types of tracepoints, liketrace_ath6kl_log_warn, use that event class. Wrappers likeath6kl_warn()call those trace points, passing it a structva_formaton the stack:int
ath6kl_warn(const char *fmt, ...)
Quoted 10 lines
{
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 :-)
Quoted 1 line
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?
Quoted 10 lines
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.
Quoted 4 lines
And then code in
xhci_address_device()indrivers/usb/host/xhci.ccan 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)
Quoted 3 lines
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.
Quoted 9 lines
Quoted 9 lines
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.
Quoted 2 lines
I'm actually wondering if the call to
ath6kl_printkis 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
Quoted 19 lines · Johannes Berg
[also adding Steven, he's the tracing expert after all :-)]
Hi Xenia, Sarah, all,
Quoted 4 lines
(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.
Quoted 3 lines
Quoted 3 lines
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
Quoted 7 lines
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?
Quoted 13 lines
Quoted 13 lines
The ath driver defines a new trace event class,
ath6kl_log_event. Various types of tracepoints, liketrace_ath6kl_log_warn, use that event class. Wrappers likeath6kl_warn()call those trace points, passing it a structva_formaton the stack:int
ath6kl_warn(const char *fmt, ...){ struct va_format vaf = { .fmt = fmt, }; va_list args; int ret;
Quoted 7 lines
Quoted 3 lines
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.
Quoted 4 lines
Quoted 1 line
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. :)
Quoted 5 lines
Quoted 5 lines
DEFINE_EVENT(xhci_log_event,
xhci_dbg_address,
TP_PROTO(struct va_format *vaf),
TP_ARGS(vaf)
);
Quoted 7 lines
Quoted 5 lines
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.
Quoted 2 lines
And this is what I talked about before -- it always allocates the max in the ringbuffer even for really short messages.
Noted.
Quoted 15 lines
Quoted 4 lines
And then code in
xhci_address_device()indrivers/usb/host/xhci.ccan 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)
Quoted 3 lines
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.
Quoted 8 lines
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_iosystem indrivers/net/wireless/iwlwifi/iwl-devtrace.hmight (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?
Quoted 7 lines
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?
Quoted 5 lines
Quoted 2 lines
I'm actually wondering if the call to
ath6kl_printkis 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
Quoted 18 lines · Sarah Sharp
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 commands4. Tracepoints for all USB transfer types:
* Control TX output (only for non-successful transfers)
* Bulk TX
* Interrupt TX
* Isoc TX
Quoted 5 lines
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.
Signature · 1 line
Kalle Valo
Quoted 22 lines · Kalle Valo
Quoted 20 lines · Sarah Sharp
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 commands4. Tracepoints for all USB transfer types:
* Control TX output (only for non-successful transfers)
* Bulk TX
* Interrupt TX
* Isoc TX5. URB cancellation
Quoted 8 lines
Quoted 3 lines
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
Quoted 7 lines · Sarah Sharp
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
Quoted 9 lines · Steven Rostedt
Quoted 7 lines · Sarah Sharp
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?
Quoted 3 lines
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
Quoted 32 lines · * Sarah Sharp ([email protected]) wrote:
Quoted 22 lines · Kalle Valo
Quoted 20 lines · Sarah Sharp
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 commands4. Tracepoints for all USB transfer types:
* Control TX output (only for non-successful transfers)
* Bulk TX
* Interrupt TX
* Isoc TX5. URB cancellation
Quoted 8 lines
Quoted 3 lines
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.
Quoted 4 lines
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
Quoted 6 lines
Sarah Sharp
--
To unsubscribe from this list: send the line "unsubscribe linux-trace-users" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Signature · 3 lines
Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com
Hi Mathieu,
Quoted 10 lines · Mathieu Desnoyers
Quoted 4 lines · * Sarah Sharp ([email protected]) 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()andtracepoint()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
Hi Mathieu,
Quoted 10 lines · Mathieu Desnoyers
Quoted 4 lines · * Sarah Sharp ([email protected]) 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()andtracepoint()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
Hi Mathieu,
Quoted 10 lines · Mathieu Desnoyers
Quoted 4 lines · * Sarah Sharp ([email protected]) 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()andtracepoint()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
Quoted 9 lines · * Mark Wielaard ([email protected]) wrote:
Hi Mathieu,
Quoted 6 lines · Mathieu Desnoyers
Quoted 4 lines · * Sarah Sharp ([email protected]) 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?
Quoted 8 lines
Quoted 4 lines
You might want to try out LTTng-UST. It provides
TRACEPOINT_EVENT()andtracepoint()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.
Quoted 3 lines
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
Quoted 4 lines
Thanks,
Mark
Signature · 3 lines
Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com
Quoted 11 lines · Sarah Sharp
Quoted 4 lines · Kalle Valo
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:
And as usual, Johannes is a good source of information ;)
Signature · 1 line
Kalle Valo
[sorry for the late response!]
Quoted 4 lines
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.
Quoted 5 lines
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.
Quoted 11 lines
Quoted 4 lines
Quoted 1 line
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.
Quoted 27 lines
Quoted 8 lines
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_iosystem indrivers/net/wireless/iwlwifi/iwl-devtrace.hmight (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 messagesMy 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 commands4. Tracepoints for all USB transfer types:
* Control TX output (only for non-successful transfers)
* Bulk TX
* Interrupt TX
* Isoc TX
Quoted 5 lines
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.
Quoted 6 lines
Quoted 3 lines
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')
Quoted 7 lines
Quoted 5 lines
Quoted 2 lines
I'm actually wondering if the call to
ath6kl_printkis 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
Quoted 6 lines · Johannes Berg
Quoted 3 lines
Quoted 3 lines
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
Quoted 7 lines
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
Quoted 8 lines · Steven Rostedt
Quoted 3 lines
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
Quoted 7 lines · Johannes Berg
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
Quoted 7 lines · Steven Rostedt
Quoted 6 lines
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.
Quoted 5 lines
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
Quoted 6 lines · Johannes Berg
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.
Quoted 10 lines
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 reservationbut 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
Quoted 9 lines · Steven Rostedt
Quoted 6 lines · Johannes Berg
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.
Quoted 7 lines
Quoted 7 lines
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
Quoted 8 lines
Quoted 2 lines
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
Quoted 9 lines · Johannes Berg
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
Quoted 8 lines · Johannes Berg
Quoted 4 lines
(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.
Quoted 7 lines
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.
Signature · 1 line
Kalle Valo