usb: core: Improve device lifecycle debuggability

[PATCH 2/2] usb: core: Add tracepoints for device allocation and state changes

Posted by Kuen-Han Tsai 2 months, 1 week ago

Introduce new tracepoints to the USB core to improve debuggability of
USB device lifecycle events.

The following tracepoints are added:

- usb_alloc_dev: Triggered when a new USB device structure is allocated,
providing insights into early device setup.
- usb_set_device_state: Triggered when the USB device state changes,
allowing observation of the device's state transitions.

These tracepoints capture detailed information about the USB device,
including its name, speed, state, bus current value, and authorized
flag. This will aid developers in diagnosing issues related to device
enumeration within the USB subsystem.

Examples:
 usb_alloc_dev: usb 1-1 speed 0 state 1 0mA [authorized]
 usb_set_device_state: usb 1-1 speed 0 state 2 0mA [authorized]
 usb_set_device_state: usb 1-1 speed 2 state 5 500mA [authorized]
 usb_set_device_state: usb 1-1 speed 2 state 5 500mA [authorized]
 usb_set_device_state: usb 1-1 speed 2 state 6 500mA [authorized]
 usb_set_device_state: usb 1-1 speed 2 state 7 500mA [authorized]
 usb_set_device_state: usb 1-1 speed 2 state 8 500mA [authorized]
 usb_set_device_state: usb 1-1 speed 2 state 0 500mA [authorized]

Signed-off-by: Kuen-Han Tsai <khtsai@google.com>
---
 drivers/usb/core/Makefile |  4 ++++
 drivers/usb/core/hub.c    |  2 ++
 drivers/usb/core/trace.c  |  6 +++++
 drivers/usb/core/trace.h  | 61 +++++++++++++++++++++++++++++++++++++++++++++++
 drivers/usb/core/usb.c    |  2 ++
 5 files changed, 75 insertions(+)

diff --git a/drivers/usb/core/Makefile b/drivers/usb/core/Makefile
index 766000b4939ef937a04848aa9cc45d8bb8860fe5..11647942ff3ae6c688dac043218f7d886a3e2f88 100644
--- a/drivers/usb/core/Makefile
+++ b/drivers/usb/core/Makefile
@@ -3,10 +3,14 @@
 # Makefile for USB Core files and filesystem
 #
 
+# define_trace.h needs to know how to find our header
+CFLAGS_trace.o                  := -I$(src)
+
 usbcore-y := usb.o hub.o hcd.o urb.o message.o driver.o
 usbcore-y += config.o file.o buffer.o sysfs.o endpoint.o
 usbcore-y += devio.o notify.o generic.o quirks.o devices.o
 usbcore-y += phy.o port.o
+usbcore-y += trace.o
 
 usbcore-$(CONFIG_OF)		+= of.o
 usbcore-$(CONFIG_USB_XHCI_SIDEBAND)	+= offload.o
diff --git a/drivers/usb/core/hub.c b/drivers/usb/core/hub.c
index ce3d94c960470e9be7979b1021551eab5fd03517..f66a197700c8b3414c624b8ec1bb94c629e3280c 100644
--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -40,6 +40,7 @@
 #include "hub.h"
 #include "phy.h"
 #include "otg_productlist.h"
+#include "trace.h"
 
 #define USB_VENDOR_GENESYS_LOGIC		0x05e3
 #define USB_VENDOR_SMSC				0x0424
@@ -2159,6 +2160,7 @@ static inline void update_usb_device_state(struct usb_device *udev,
 
 	udev->state = new_state;
 	update_port_device_state(udev);
+	trace_usb_set_device_state(udev);
 }
 
 static void recursively_mark_NOTATTACHED(struct usb_device *udev)
diff --git a/drivers/usb/core/trace.c b/drivers/usb/core/trace.c
new file mode 100644
index 0000000000000000000000000000000000000000..607bcf639d27f15a628537a86155fa92df33fa14
--- /dev/null
+++ b/drivers/usb/core/trace.c
@@ -0,0 +1,6 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2025 Google LLC
+ */
+#define CREATE_TRACE_POINTS
+#include "trace.h"
diff --git a/drivers/usb/core/trace.h b/drivers/usb/core/trace.h
new file mode 100644
index 0000000000000000000000000000000000000000..db6edf570640e7af0598ccf2c7bd71b187605a42
--- /dev/null
+++ b/drivers/usb/core/trace.h
@@ -0,0 +1,61 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * Copyright (C) 2025 Google LLC
+ */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM usbcore
+
+#if !defined(_USB_CORE_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _USB_CORE_TRACE_H
+
+#include <linux/types.h>
+#include <linux/tracepoint.h>
+#include <linux/usb.h>
+
+DECLARE_EVENT_CLASS(usb_core_log_usb_device,
+	TP_PROTO(struct usb_device *udev),
+	TP_ARGS(udev),
+	TP_STRUCT__entry(
+		__string(name, dev_name(&udev->dev))
+		__field(enum usb_device_speed, speed)
+		__field(enum usb_device_state, state)
+		__field(unsigned short, bus_mA)
+		__field(unsigned, authorized)
+	),
+	TP_fast_assign(
+		__assign_str(name);
+		__entry->speed = udev->speed;
+		__entry->state = udev->state;
+		__entry->bus_mA = udev->bus_mA;
+		__entry->authorized = udev->authorized;
+	),
+	TP_printk("usb %s speed %d state %d %dmA [%s]",
+		__get_str(name),
+		__entry->speed,
+		__entry->state,
+		__entry->bus_mA,
+		__entry->authorized ? "authorized" : "unauthorized")
+);
+
+DEFINE_EVENT(usb_core_log_usb_device, usb_set_device_state,
+	TP_PROTO(struct usb_device *udev),
+	TP_ARGS(udev)
+);
+
+DEFINE_EVENT(usb_core_log_usb_device, usb_alloc_dev,
+	TP_PROTO(struct usb_device *udev),
+	TP_ARGS(udev)
+);
+
+
+#endif /* _USB_CORE_TRACE_H */
+
+/* this part has to be here */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE trace
+
+#include <trace/define_trace.h>
diff --git a/drivers/usb/core/usb.c b/drivers/usb/core/usb.c
index b6b0b84895237e2c49b5e8015627ad2c24ee31c2..e740f7852bcdebdbcc30025dcddb16c062265d47 100644
--- a/drivers/usb/core/usb.c
+++ b/drivers/usb/core/usb.c
@@ -46,6 +46,7 @@
 #include <linux/dma-mapping.h>
 
 #include "hub.h"
+#include "trace.h"
 
 const char *usbcore_name = "usbcore";
 
@@ -746,6 +747,7 @@ struct usb_device *usb_alloc_dev(struct usb_device *parent,
 #endif
 
 	dev->authorized = usb_dev_authorized(dev, usb_hcd);
+	trace_usb_alloc_dev(dev);
 	return dev;
 }
 EXPORT_SYMBOL_GPL(usb_alloc_dev);

-- 
2.51.0.740.g6adb054d12-goog

Re: [PATCH 2/2] usb: core: Add tracepoints for device allocation and state changes

Posted by Greg Kroah-Hartman 2 months ago

On Mon, Oct 13, 2025 at 10:01:23AM +0800, Kuen-Han Tsai wrote:
> Introduce new tracepoints to the USB core to improve debuggability of
> USB device lifecycle events.
> 
> The following tracepoints are added:
> 
> - usb_alloc_dev: Triggered when a new USB device structure is allocated,
> providing insights into early device setup.
> - usb_set_device_state: Triggered when the USB device state changes,
> allowing observation of the device's state transitions.
> 
> These tracepoints capture detailed information about the USB device,
> including its name, speed, state, bus current value, and authorized
> flag. This will aid developers in diagnosing issues related to device
> enumeration within the USB subsystem.
> 
> Examples:
>  usb_alloc_dev: usb 1-1 speed 0 state 1 0mA [authorized]

If you are going to change the state to be a string, can you also change
the speed to be a string as well?  That will help out with people
wondering what is going on with the speed of the device a lot.

thanks,

greg k-h

Re: [PATCH 2/2] usb: core: Add tracepoints for device allocation and state changes

Posted by Alan Stern 2 months, 1 week ago

On Mon, Oct 13, 2025 at 10:01:23AM +0800, Kuen-Han Tsai wrote:
> Introduce new tracepoints to the USB core to improve debuggability of
> USB device lifecycle events.
> 
> The following tracepoints are added:
> 
> - usb_alloc_dev: Triggered when a new USB device structure is allocated,
> providing insights into early device setup.
> - usb_set_device_state: Triggered when the USB device state changes,
> allowing observation of the device's state transitions.
> 
> These tracepoints capture detailed information about the USB device,
> including its name, speed, state, bus current value, and authorized
> flag. This will aid developers in diagnosing issues related to device
> enumeration within the USB subsystem.
> 
> Examples:
>  usb_alloc_dev: usb 1-1 speed 0 state 1 0mA [authorized]
>  usb_set_device_state: usb 1-1 speed 0 state 2 0mA [authorized]
>  usb_set_device_state: usb 1-1 speed 2 state 5 500mA [authorized]
>  usb_set_device_state: usb 1-1 speed 2 state 5 500mA [authorized]
>  usb_set_device_state: usb 1-1 speed 2 state 6 500mA [authorized]
>  usb_set_device_state: usb 1-1 speed 2 state 7 500mA [authorized]
>  usb_set_device_state: usb 1-1 speed 2 state 8 500mA [authorized]
>  usb_set_device_state: usb 1-1 speed 2 state 0 500mA [authorized]
> 
> Signed-off-by: Kuen-Han Tsai <khtsai@google.com>
> ---

> diff --git a/drivers/usb/core/Makefile b/drivers/usb/core/Makefile
> index 766000b4939ef937a04848aa9cc45d8bb8860fe5..11647942ff3ae6c688dac043218f7d886a3e2f88 100644
> --- a/drivers/usb/core/Makefile
> +++ b/drivers/usb/core/Makefile
> @@ -3,10 +3,14 @@
>  # Makefile for USB Core files and filesystem
>  #
>  
> +# define_trace.h needs to know how to find our header
> +CFLAGS_trace.o                  := -I$(src)
> +
>  usbcore-y := usb.o hub.o hcd.o urb.o message.o driver.o
>  usbcore-y += config.o file.o buffer.o sysfs.o endpoint.o
>  usbcore-y += devio.o notify.o generic.o quirks.o devices.o
>  usbcore-y += phy.o port.o
> +usbcore-y += trace.o

This looks a little odd.  Why not put trace.o at the end of the 
preceding line?

> diff --git a/drivers/usb/core/trace.h b/drivers/usb/core/trace.h
> new file mode 100644
> index 0000000000000000000000000000000000000000..db6edf570640e7af0598ccf2c7bd71b187605a42
> --- /dev/null
> +++ b/drivers/usb/core/trace.h
> @@ -0,0 +1,61 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +/*
> + * Copyright (C) 2025 Google LLC
> + */
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM usbcore
> +
> +#if !defined(_USB_CORE_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _USB_CORE_TRACE_H
> +
> +#include <linux/types.h>
> +#include <linux/tracepoint.h>
> +#include <linux/usb.h>
> +
> +DECLARE_EVENT_CLASS(usb_core_log_usb_device,
> +	TP_PROTO(struct usb_device *udev),
> +	TP_ARGS(udev),
> +	TP_STRUCT__entry(
> +		__string(name, dev_name(&udev->dev))
> +		__field(enum usb_device_speed, speed)
> +		__field(enum usb_device_state, state)
> +		__field(unsigned short, bus_mA)
> +		__field(unsigned, authorized)
> +	),
> +	TP_fast_assign(
> +		__assign_str(name);
> +		__entry->speed = udev->speed;
> +		__entry->state = udev->state;
> +		__entry->bus_mA = udev->bus_mA;
> +		__entry->authorized = udev->authorized;
> +	),
> +	TP_printk("usb %s speed %d state %d %dmA [%s]",
> +		__get_str(name),
> +		__entry->speed,
> +		__entry->state,

Suggestion: Rather than printing the meaningless numerical value of 
__entry->state, print the string value returned by 
usb_state_string(__entry->state).

Alan Stern

Re: [PATCH 2/2] usb: core: Add tracepoints for device allocation and state changes

Posted by Kuen-Han Tsai 2 months ago

Hi Alan,

On Mon, Oct 13, 2025 at 9:20 PM Alan Stern <stern@rowland.harvard.edu> wrote:
>
> On Mon, Oct 13, 2025 at 10:01:23AM +0800, Kuen-Han Tsai wrote:
> > Introduce new tracepoints to the USB core to improve debuggability of
> > USB device lifecycle events.
> >
> > The following tracepoints are added:
> >
> > - usb_alloc_dev: Triggered when a new USB device structure is allocated,
> > providing insights into early device setup.
> > - usb_set_device_state: Triggered when the USB device state changes,
> > allowing observation of the device's state transitions.
> >
> > These tracepoints capture detailed information about the USB device,
> > including its name, speed, state, bus current value, and authorized
> > flag. This will aid developers in diagnosing issues related to device
> > enumeration within the USB subsystem.
> >
> > Examples:
> >  usb_alloc_dev: usb 1-1 speed 0 state 1 0mA [authorized]
> >  usb_set_device_state: usb 1-1 speed 0 state 2 0mA [authorized]
> >  usb_set_device_state: usb 1-1 speed 2 state 5 500mA [authorized]
> >  usb_set_device_state: usb 1-1 speed 2 state 5 500mA [authorized]
> >  usb_set_device_state: usb 1-1 speed 2 state 6 500mA [authorized]
> >  usb_set_device_state: usb 1-1 speed 2 state 7 500mA [authorized]
> >  usb_set_device_state: usb 1-1 speed 2 state 8 500mA [authorized]
> >  usb_set_device_state: usb 1-1 speed 2 state 0 500mA [authorized]
> >
> > Signed-off-by: Kuen-Han Tsai <khtsai@google.com>
> > ---
>
> > diff --git a/drivers/usb/core/Makefile b/drivers/usb/core/Makefile
> > index 766000b4939ef937a04848aa9cc45d8bb8860fe5..11647942ff3ae6c688dac043218f7d886a3e2f88 100644
> > --- a/drivers/usb/core/Makefile
> > +++ b/drivers/usb/core/Makefile
> > @@ -3,10 +3,14 @@
> >  # Makefile for USB Core files and filesystem
> >  #
> >
> > +# define_trace.h needs to know how to find our header
> > +CFLAGS_trace.o                  := -I$(src)
> > +
> >  usbcore-y := usb.o hub.o hcd.o urb.o message.o driver.o
> >  usbcore-y += config.o file.o buffer.o sysfs.o endpoint.o
> >  usbcore-y += devio.o notify.o generic.o quirks.o devices.o
> >  usbcore-y += phy.o port.o
> > +usbcore-y += trace.o
>
> This looks a little odd.  Why not put trace.o at the end of the
> preceding line?
>

Thanks for the review. I will move trace.o to the preceding line.

> > diff --git a/drivers/usb/core/trace.h b/drivers/usb/core/trace.h
> > new file mode 100644
> > index 0000000000000000000000000000000000000000..db6edf570640e7af0598ccf2c7bd71b187605a42
> > --- /dev/null
> > +++ b/drivers/usb/core/trace.h
> > @@ -0,0 +1,61 @@
> > +/* SPDX-License-Identifier: GPL-2.0 */
> > +/*
> > + * Copyright (C) 2025 Google LLC
> > + */
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM usbcore
> > +
> > +#if !defined(_USB_CORE_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _USB_CORE_TRACE_H
> > +
> > +#include <linux/types.h>
> > +#include <linux/tracepoint.h>
> > +#include <linux/usb.h>
> > +
> > +DECLARE_EVENT_CLASS(usb_core_log_usb_device,
> > +     TP_PROTO(struct usb_device *udev),
> > +     TP_ARGS(udev),
> > +     TP_STRUCT__entry(
> > +             __string(name, dev_name(&udev->dev))
> > +             __field(enum usb_device_speed, speed)
> > +             __field(enum usb_device_state, state)
> > +             __field(unsigned short, bus_mA)
> > +             __field(unsigned, authorized)
> > +     ),
> > +     TP_fast_assign(
> > +             __assign_str(name);
> > +             __entry->speed = udev->speed;
> > +             __entry->state = udev->state;
> > +             __entry->bus_mA = udev->bus_mA;
> > +             __entry->authorized = udev->authorized;
> > +     ),
> > +     TP_printk("usb %s speed %d state %d %dmA [%s]",
> > +             __get_str(name),
> > +             __entry->speed,
> > +             __entry->state,
>
> Suggestion: Rather than printing the meaningless numerical value of
> __entry->state, print the string value returned by
> usb_state_string(__entry->state).

I kept it consistent with the udc_log_gadget tracepoint, which also
uses the numerical value for the USB state.

If we change the state to a string, should we convert the speed field
to a string using usb_speed_string()?

I lean toward keeping both as numerical values, but I am happy to
switch both to strings if you prefer. Please let me know what you
think is best.

Regards,
Kuen-Han

>
> Alan Stern

Re: [PATCH 2/2] usb: core: Add tracepoints for device allocation and state changes

Posted by Alan Stern 2 months ago

On Tue, Oct 14, 2025 at 08:05:25AM +0800, Kuen-Han Tsai wrote:
> Hi Alan,
> 
> On Mon, Oct 13, 2025 at 9:20 PM Alan Stern <stern@rowland.harvard.edu> wrote:
> >
> > Suggestion: Rather than printing the meaningless numerical value of
> > __entry->state, print the string value returned by
> > usb_state_string(__entry->state).
> 
> I kept it consistent with the udc_log_gadget tracepoint, which also
> uses the numerical value for the USB state.
> 
> If we change the state to a string, should we convert the speed field
> to a string using usb_speed_string()?
> 
> I lean toward keeping both as numerical values, but I am happy to
> switch both to strings if you prefer. Please let me know what you
> think is best.

I agree that if one of them uses strings then so should the other.

As for whether you should change them...  I don't care very much, since 
I haven't used tracepoints in my gadget debugging.  I was just thinking 
of what other people might like.

Greg, do you have a recommendation?

Alan Stern

Re: [PATCH 2/2] usb: core: Add tracepoints for device allocation and state changes

Posted by Greg Kroah-Hartman 2 months ago

On Mon, Oct 13, 2025 at 11:24:47PM -0400, Alan Stern wrote:
> On Tue, Oct 14, 2025 at 08:05:25AM +0800, Kuen-Han Tsai wrote:
> > Hi Alan,
> > 
> > On Mon, Oct 13, 2025 at 9:20 PM Alan Stern <stern@rowland.harvard.edu> wrote:
> > >
> > > Suggestion: Rather than printing the meaningless numerical value of
> > > __entry->state, print the string value returned by
> > > usb_state_string(__entry->state).
> > 
> > I kept it consistent with the udc_log_gadget tracepoint, which also
> > uses the numerical value for the USB state.
> > 
> > If we change the state to a string, should we convert the speed field
> > to a string using usb_speed_string()?
> > 
> > I lean toward keeping both as numerical values, but I am happy to
> > switch both to strings if you prefer. Please let me know what you
> > think is best.
> 
> I agree that if one of them uses strings then so should the other.
> 
> As for whether you should change them...  I don't care very much, since 
> I haven't used tracepoints in my gadget debugging.  I was just thinking 
> of what other people might like.
> 
> Greg, do you have a recommendation?

Strings are always easier for people to understand, otherwise we have to
go look the value up somewhere.  So both should use them.

thanks,

greg k-h