diff mbox

usb: dwc3: add tracepoints to aid debugging

Message ID 1406305145-1409-1-git-send-email-balbi@ti.com
State New
Headers show

Commit Message

Felipe Balbi July 25, 2014, 4:19 p.m. UTC 
When we're debugging hard-to-reproduce and time-sensitive
use cases, printk() poses too much overhead. That's when
the kernel's tracing infrastructure comes into play.

This patch implements a few initial tracepoints for the
dwc3 driver. More traces can be added as necessary in order
to ease the task of debugging dwc3.

Signed-off-by: Felipe Balbi <balbi@ti.com>
---

Hi folks,

I have been meaning to send this for quite a while now but
never had the time to test everything and make sure it works.

Logs are looking pretty good to my eyes with a much smaller
overhead than with dev_* macros.

If you have a real good reason to add more logs, just let
me know and we will look at the possibility for adding it,
I have a feeling people will want traces for endpoint 0
state machine but I'm not entirely sure it's needed, so I
left it out for now. If folks think it's important, I'll add
it in no time.

Please give it a good review because we will have to support
tracepoints for the next 60 years.

cheers

 drivers/usb/dwc3/Makefile |   5 +-
 drivers/usb/dwc3/debug.c  |  33 ++++++++++++
 drivers/usb/dwc3/debug.h  |   3 ++
 drivers/usb/dwc3/ep0.c    |   2 +
 drivers/usb/dwc3/gadget.c |  22 ++++++++
 drivers/usb/dwc3/io.h     |  30 +++++++++--
 drivers/usb/dwc3/trace.c  |  19 +++++++
 drivers/usb/dwc3/trace.h  | 130 ++++++++++++++++++++++++++++++++++++++++++++++
 8 files changed, 240 insertions(+), 4 deletions(-)
 create mode 100644 drivers/usb/dwc3/debug.c
 create mode 100644 drivers/usb/dwc3/trace.c
 create mode 100644 drivers/usb/dwc3/trace.h

Comments

Felipe Balbi July 25, 2014, 4:47 p.m. UTC | #1 
Hi,

changed one detail

On Fri, Jul 25, 2014 at 11:19:05AM -0500, Felipe Balbi wrote:
> +DECLARE_EVENT_CLASS(dwc3_log_ctrl,
> +	TP_PROTO(struct usb_ctrlrequest *ctrl),
> +	TP_ARGS(ctrl),
> +	TP_STRUCT__entry(
> +		__field(struct usb_ctrlrequest *, ctrl)
> +	),
> +	TP_fast_assign(
> +		__entry->ctrl = ctrl;
> +	),
> +	TP_printk("bRequestType %x bRequest %x wValue %02x wIndex %02x wLength %02x",

fixed this for proper field sizes so it looks like:

         TP_printk("bRequestType %02x bRequest %02x wValue %04x wIndex %04x wLength %d",
Greg KH July 26, 2014, 5:01 a.m. UTC | #2 
On Fri, Jul 25, 2014 at 11:19:05AM -0500, Felipe Balbi wrote:
> When we're debugging hard-to-reproduce and time-sensitive
> use cases, printk() poses too much overhead. That's when
> the kernel's tracing infrastructure comes into play.
> 
> This patch implements a few initial tracepoints for the
> dwc3 driver. More traces can be added as necessary in order
> to ease the task of debugging dwc3.
> 
> Signed-off-by: Felipe Balbi <balbi@ti.com>
> ---
> 
> Hi folks,
> 
> I have been meaning to send this for quite a while now but
> never had the time to test everything and make sure it works.
> 
> Logs are looking pretty good to my eyes with a much smaller
> overhead than with dev_* macros.
> 
> If you have a real good reason to add more logs, just let
> me know and we will look at the possibility for adding it,
> I have a feeling people will want traces for endpoint 0
> state machine but I'm not entirely sure it's needed, so I
> left it out for now. If folks think it's important, I'll add
> it in no time.
> 
> Please give it a good review because we will have to support
> tracepoints for the next 60 years.

Can you delete the dev_vdbg() calls at the same place as well?

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Felipe Balbi July 28, 2014, 3:11 p.m. UTC | #3 
On Fri, Jul 25, 2014 at 10:01:52PM -0700, Greg KH wrote:
> On Fri, Jul 25, 2014 at 11:19:05AM -0500, Felipe Balbi wrote:
> > When we're debugging hard-to-reproduce and time-sensitive
> > use cases, printk() poses too much overhead. That's when
> > the kernel's tracing infrastructure comes into play.
> > 
> > This patch implements a few initial tracepoints for the
> > dwc3 driver. More traces can be added as necessary in order
> > to ease the task of debugging dwc3.
> > 
> > Signed-off-by: Felipe Balbi <balbi@ti.com>
> > ---
> > 
> > Hi folks,
> > 
> > I have been meaning to send this for quite a while now but
> > never had the time to test everything and make sure it works.
> > 
> > Logs are looking pretty good to my eyes with a much smaller
> > overhead than with dev_* macros.
> > 
> > If you have a real good reason to add more logs, just let
> > me know and we will look at the possibility for adding it,
> > I have a feeling people will want traces for endpoint 0
> > state machine but I'm not entirely sure it's needed, so I
> > left it out for now. If folks think it's important, I'll add
> > it in no time.
> > 
> > Please give it a good review because we will have to support
> > tracepoints for the next 60 years.
> 
> Can you delete the dev_vdbg() calls at the same place as well?

Sure, I guess I could.
diff mbox

Patch

diff --git a/drivers/usb/dwc3/Makefile b/drivers/usb/dwc3/Makefile
index 10ac3e7..7793e6c 100644
--- a/drivers/usb/dwc3/Makefile
+++ b/drivers/usb/dwc3/Makefile
@@ -1,9 +1,12 @@ 
+# define_trace.h needs to know how to find our header
+CFLAGS_trace.o				:= -I$(src)
+
 ccflags-$(CONFIG_USB_DWC3_DEBUG)	:= -DDEBUG
 ccflags-$(CONFIG_USB_DWC3_VERBOSE)	+= -DVERBOSE_DEBUG
 
 obj-$(CONFIG_USB_DWC3)			+= dwc3.o
 
-dwc3-y					:= core.o
+dwc3-y					:= core.o debug.o trace.o
 
 ifneq ($(filter y,$(CONFIG_USB_DWC3_HOST) $(CONFIG_USB_DWC3_DUAL_ROLE)),)
 	dwc3-y				+= host.o
diff --git a/drivers/usb/dwc3/debug.c b/drivers/usb/dwc3/debug.c
new file mode 100644
index 0000000..6d01e0c
--- /dev/null
+++ b/drivers/usb/dwc3/debug.c
@@ -0,0 +1,33 @@ 
+/**
+ * debug.c - DesignWare USB3 DRD Controller Debug/Trace Support
+ *
+ * Copyright (C) 2014 Texas Instruments Incorporated - http://www.ti.com
+ *
+ * Author: Felipe Balbi <balbi@ti.com>
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2  of
+ * the License as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ */
+
+#include "debug.h"
+
+void dwc3_trace(void (*trace)(struct va_format *),
+		const char *fmt, ...)
+{
+	struct va_format vaf;
+	va_list args;
+
+	va_start(args, fmt);
+	vaf.fmt = fmt;
+	vaf.va = &args;
+
+	trace(&vaf);
+
+	va_end(args);
+}
diff --git a/drivers/usb/dwc3/debug.h b/drivers/usb/dwc3/debug.h
index fceb39d..ff5e524 100644
--- a/drivers/usb/dwc3/debug.h
+++ b/drivers/usb/dwc3/debug.h
@@ -18,6 +18,9 @@ 
 
 #include "core.h"
 
+void dwc3_trace(void (*trace)(struct va_format *),
+		const char *fmt, ...);
+
 #ifdef CONFIG_DEBUG_FS
 extern int dwc3_debugfs_init(struct dwc3 *);
 extern void dwc3_debugfs_exit(struct dwc3 *);
diff --git a/drivers/usb/dwc3/ep0.c b/drivers/usb/dwc3/ep0.c
index 21a3520..8ec8d84 100644
--- a/drivers/usb/dwc3/ep0.c
+++ b/drivers/usb/dwc3/ep0.c
@@ -726,6 +726,8 @@  static void dwc3_ep0_inspect_setup(struct dwc3 *dwc,
 	if (!dwc->gadget_driver)
 		goto out;
 
+	trace_dwc3_ctrl_req(ctrl);
+
 	len = le16_to_cpu(ctrl->wLength);
 	if (!len) {
 		dwc->three_stage_setup = false;
diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
index 349cacc..ac06447 100644
--- a/drivers/usb/dwc3/gadget.c
+++ b/drivers/usb/dwc3/gadget.c
@@ -266,6 +266,7 @@  void dwc3_gadget_giveback(struct dwc3_ep *dep, struct dwc3_request *req,
 	dev_dbg(dwc->dev, "request %p from %s completed %d/%d ===> %d\n",
 			req, dep->name, req->request.actual,
 			req->request.length, status);
+	trace_dwc3_gadget_giveback(dwc, req);
 
 	spin_unlock(&dwc->lock);
 	req->request.complete(&dep->endpoint, &req->request);
@@ -800,6 +801,8 @@  static struct usb_request *dwc3_gadget_ep_alloc_request(struct usb_ep *ep,
 	req->epnum	= dep->number;
 	req->dep	= dep;
 
+	trace_dwc3_alloc_request(dwc, req);
+
 	return &req->request;
 }
 
@@ -807,7 +810,10 @@  static void dwc3_gadget_ep_free_request(struct usb_ep *ep,
 		struct usb_request *request)
 {
 	struct dwc3_request		*req = to_dwc3_request(request);
+	struct dwc3_ep			*dep = to_dwc3_ep(ep);
+	struct dwc3			*dwc = dep->dwc;
 
+	trace_dwc3_free_request(dwc, req);
 	kfree(req);
 }
 
@@ -1233,6 +1239,7 @@  static int dwc3_gadget_ep_queue(struct usb_ep *ep, struct usb_request *request,
 
 	dev_vdbg(dwc->dev, "queing request %p to %s length %d\n",
 			request, ep->name, request->length);
+	trace_dwc3_ep_queue(dwc, req);
 
 	spin_lock_irqsave(&dwc->lock, flags);
 	ret = __dwc3_gadget_ep_queue(dep, req);
@@ -1253,6 +1260,8 @@  static int dwc3_gadget_ep_dequeue(struct usb_ep *ep,
 	unsigned long			flags;
 	int				ret = 0;
 
+	trace_dwc3_ep_dequeue(dwc, req);
+
 	spin_lock_irqsave(&dwc->lock, flags);
 
 	list_for_each_entry(r, &dep->request_list, list) {
@@ -2022,6 +2031,8 @@  static void dwc3_endpoint_interrupt(struct dwc3 *dwc,
 
 	dev_vdbg(dwc->dev, "%s: %s\n", dep->name,
 			dwc3_ep_event_string(event->endpoint_event));
+	dwc3_trace(trace_dwc3_event, "%s: %s", dep->name,
+			dwc3_ep_event_string(event->endpoint_event));
 
 	if (epnum == 0 || epnum == 1) {
 		dwc3_ep0_interrupt(dwc, event);
@@ -2216,6 +2227,7 @@  static void dwc3_gadget_disconnect_interrupt(struct dwc3 *dwc)
 	int			reg;
 
 	dev_vdbg(dwc->dev, "%s\n", __func__);
+	dwc3_trace(trace_dwc3_event, "disconnect interrupt");
 
 	reg = dwc3_readl(dwc->regs, DWC3_DCTL);
 	reg &= ~DWC3_DCTL_INITU1ENA;
@@ -2236,6 +2248,7 @@  static void dwc3_gadget_reset_interrupt(struct dwc3 *dwc)
 	u32			reg;
 
 	dev_vdbg(dwc->dev, "%s\n", __func__);
+	dwc3_trace(trace_dwc3_event, "reset interrupt");
 
 	/*
 	 * WORKAROUND: DWC3 revisions <1.88a have an issue which
@@ -2322,6 +2335,7 @@  static void dwc3_gadget_conndone_interrupt(struct dwc3 *dwc)
 	u8			speed;
 
 	dev_vdbg(dwc->dev, "%s\n", __func__);
+	dwc3_trace(trace_dwc3_event, "connection done interrupt");
 
 	reg = dwc3_readl(dwc->regs, DWC3_DSTS);
 	speed = reg & DWC3_DSTS_CONNECTSPD;
@@ -2421,6 +2435,7 @@  static void dwc3_gadget_conndone_interrupt(struct dwc3 *dwc)
 static void dwc3_gadget_wakeup_interrupt(struct dwc3 *dwc)
 {
 	dev_vdbg(dwc->dev, "%s\n", __func__);
+	dwc3_trace(trace_dwc3_event, "wakeup interrupt");
 
 	/*
 	 * TODO take core out of low power mode when that's
@@ -2530,6 +2545,10 @@  static void dwc3_gadget_linksts_change_interrupt(struct dwc3 *dwc,
 			dwc3_gadget_link_string(dwc->link_state),
 			dwc->link_state, dwc3_gadget_link_string(next), next);
 
+	dwc3_trace(trace_dwc3_event, "link change: %s [%d] -> %s [%d]",
+			dwc3_gadget_link_string(dwc->link_state),
+			dwc->link_state, dwc3_gadget_link_string(next), next);
+
 	dwc->link_state = next;
 }
 
@@ -2538,6 +2557,8 @@  static void dwc3_gadget_hibernation_interrupt(struct dwc3 *dwc,
 {
 	unsigned int is_ss = evtinfo & BIT(4);
 
+	dwc3_trace(trace_dwc3_event, "hibernation interrupt");
+
 	/**
 	 * WORKAROUND: DWC3 revison 2.20a with hibernation support
 	 * have a known issue which can cause USB CV TD.9.23 to fail
@@ -2699,6 +2720,7 @@  static irqreturn_t dwc3_check_event_buf(struct dwc3 *dwc, u32 buf)
 	if (!count)
 		return IRQ_NONE;
 
+	dwc3_trace(trace_dwc3_event, "pending %d events", count);
 	evt->count = count;
 	evt->flags |= DWC3_EVENT_PENDING;
 
diff --git a/drivers/usb/dwc3/io.h b/drivers/usb/dwc3/io.h
index d94441c..df8ac17 100644
--- a/drivers/usb/dwc3/io.h
+++ b/drivers/usb/dwc3/io.h
@@ -20,27 +20,51 @@ 
 #define __DRIVERS_USB_DWC3_IO_H
 
 #include <linux/io.h>
-
+#include "trace.h"
+#include "debug.h"
 #include "core.h"
 
 static inline u32 dwc3_readl(void __iomem *base, u32 offset)
 {
+	u32 offs = offset - DWC3_GLOBALS_REGS_START;
+	u32 value;
+
 	/*
 	 * We requested the mem region starting from the Globals address
 	 * space, see dwc3_probe in core.c.
 	 * However, the offsets are given starting from xHCI address space.
 	 */
-	return readl(base + (offset - DWC3_GLOBALS_REGS_START));
+	value = readl(base + offs);
+
+	/*
+	 * When tracing we want to make it easy to find the correct address on
+	 * documentation, so we revert it back to the proper addresses, the
+	 * same way they are described on SNPS documentation
+	 */
+	dwc3_trace(trace_dwc3_readl, "add %p value %08x",
+			base - DWC3_GLOBALS_REGS_START + offset, value);
+
+	return value;
 }
 
 static inline void dwc3_writel(void __iomem *base, u32 offset, u32 value)
 {
+	u32 offs = offset - DWC3_GLOBALS_REGS_START;
+
 	/*
 	 * We requested the mem region starting from the Globals address
 	 * space, see dwc3_probe in core.c.
 	 * However, the offsets are given starting from xHCI address space.
 	 */
-	writel(value, base + (offset - DWC3_GLOBALS_REGS_START));
+	writel(value, base + offs);
+
+	/*
+	 * When tracing we want to make it easy to find the correct address on
+	 * documentation, so we revert it back to the proper addresses, the
+	 * same way they are described on SNPS documentation
+	 */
+	dwc3_trace(trace_dwc3_writel, "addr %p value %08x",
+			base - DWC3_GLOBALS_REGS_START + offset, value);
 }
 
 #endif /* __DRIVERS_USB_DWC3_IO_H */
diff --git a/drivers/usb/dwc3/trace.c b/drivers/usb/dwc3/trace.c
new file mode 100644
index 0000000..6cd1664
--- /dev/null
+++ b/drivers/usb/dwc3/trace.c
@@ -0,0 +1,19 @@ 
+/**
+ * trace.c - DesignWare USB3 DRD Controller Trace Support
+ *
+ * Copyright (C) 2014 Texas Instruments Incorporated - http://www.ti.com
+ *
+ * Author: Felipe Balbi <balbi@ti.com>
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2  of
+ * the License as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ */
+
+#define CREATE_TRACE_POINTS
+#include "trace.h"
diff --git a/drivers/usb/dwc3/trace.h b/drivers/usb/dwc3/trace.h
new file mode 100644
index 0000000..ed602608
--- /dev/null
+++ b/drivers/usb/dwc3/trace.h
@@ -0,0 +1,130 @@ 
+/**
+ * trace.h - DesignWare USB3 DRD Controller Trace Support
+ *
+ * Copyright (C) 2014 Texas Instruments Incorporated - http://www.ti.com
+ *
+ * Author: Felipe Balbi <balbi@ti.com>
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2  of
+ * the License as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM dwc3
+
+#if !defined(__DWC3_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define __DWC3_TRACE_H
+
+#include <linux/types.h>
+#include <linux/tracepoint.h>
+#include <asm/byteorder.h>
+#include "core.h"
+
+#define DWC3_MSG_MAX	500
+
+DECLARE_EVENT_CLASS(dwc3_log_msg,
+	TP_PROTO(struct va_format *vaf),
+	TP_ARGS(vaf),
+	TP_STRUCT__entry(__dynamic_array(char, msg, DWC3_MSG_MAX)),
+	TP_fast_assign(
+		vsnprintf(__get_str(msg), DWC3_MSG_MAX, vaf->fmt, *vaf->va);
+	),
+	TP_printk("%s", __get_str(msg))
+);
+
+DEFINE_EVENT(dwc3_log_msg, dwc3_readl,
+	TP_PROTO(struct va_format *vaf),
+	TP_ARGS(vaf)
+);
+
+DEFINE_EVENT(dwc3_log_msg, dwc3_writel,
+	TP_PROTO(struct va_format *vaf),
+	TP_ARGS(vaf)
+);
+
+DEFINE_EVENT(dwc3_log_msg, dwc3_event,
+	TP_PROTO(struct va_format *vaf),
+	TP_ARGS(vaf)
+);
+
+DECLARE_EVENT_CLASS(dwc3_log_ctrl,
+	TP_PROTO(struct usb_ctrlrequest *ctrl),
+	TP_ARGS(ctrl),
+	TP_STRUCT__entry(
+		__field(struct usb_ctrlrequest *, ctrl)
+	),
+	TP_fast_assign(
+		__entry->ctrl = ctrl;
+	),
+	TP_printk("bRequestType %x bRequest %x wValue %02x wIndex %02x wLength %02x",
+		__entry->ctrl->bRequestType, __entry->ctrl->bRequest,
+		le16_to_cpu(__entry->ctrl->wValue), le16_to_cpu(__entry->ctrl->wIndex),
+		le16_to_cpu(__entry->ctrl->wLength)
+	)
+);
+
+DEFINE_EVENT(dwc3_log_ctrl, dwc3_ctrl_req,
+	TP_PROTO(struct usb_ctrlrequest *ctrl),
+	TP_ARGS(ctrl)
+);
+
+DECLARE_EVENT_CLASS(dwc3_log_request,
+	TP_PROTO(struct dwc3 *dwc, struct dwc3_request *req),
+	TP_ARGS(dwc, req),
+	TP_STRUCT__entry(
+		__field(struct dwc3 *, dwc)
+		__field(struct dwc3_request *, req)
+	),
+	TP_fast_assign(
+		__entry->dwc = dwc;
+		__entry->req = req;
+	),
+	TP_printk("%s: %s req %p length %u/%u ==> %d",
+		dev_name(__entry->dwc->dev), __entry->req->dep->name,
+		__entry->req, __entry->req->request.actual,
+		__entry->req->request.length, __entry->req->request.status
+	)
+);
+
+DEFINE_EVENT(dwc3_log_request, dwc3_alloc_request,
+	TP_PROTO(struct dwc3 *dwc, struct dwc3_request *req),
+	TP_ARGS(dwc, req)
+);
+
+DEFINE_EVENT(dwc3_log_request, dwc3_free_request,
+	TP_PROTO(struct dwc3 *dwc, struct dwc3_request *req),
+	TP_ARGS(dwc, req)
+);
+
+DEFINE_EVENT(dwc3_log_request, dwc3_ep_queue,
+	TP_PROTO(struct dwc3 *dwc, struct dwc3_request *req),
+	TP_ARGS(dwc, req)
+);
+
+DEFINE_EVENT(dwc3_log_request, dwc3_ep_dequeue,
+	TP_PROTO(struct dwc3 *dwc, struct dwc3_request *req),
+	TP_ARGS(dwc, req)
+);
+
+DEFINE_EVENT(dwc3_log_request, dwc3_gadget_giveback,
+	TP_PROTO(struct dwc3 *dwc, struct dwc3_request *req),
+	TP_ARGS(dwc, req)
+);
+
+#endif /* __DWC3_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>