diff mbox

[v2] usb: dwc3: add tracepoints to aid debugging

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

Commit Message

Felipe Balbi Aug. 19, 2014, 7:08 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 guys,

here's v2 of my dwc3 tracepoints patch. Please have a look and
*CAREFULLY* consider if we want to add anything else.

Paul, I believe you have much more experience in debugging early
HW releases with FPGA models than any of us, so tracing is likely
to help you, is there anything you'd want me to add to as a tracepoint ?

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 |  24 ++++++---
 drivers/usb/dwc3/io.h     |  30 +++++++++--
 drivers/usb/dwc3/trace.c  |  19 +++++++
 drivers/usb/dwc3/trace.h  | 130 ++++++++++++++++++++++++++++++++++++++++++++++
 8 files changed, 236 insertions(+), 10 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

Paul Zimmerman Aug. 19, 2014, 8 p.m. UTC | #1 
> From: Felipe Balbi [mailto:balbi@ti.com]
> Sent: Tuesday, August 19, 2014 12:09 PM
> 
> 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 guys,
> 
> here's v2 of my dwc3 tracepoints patch. Please have a look and
> *CAREFULLY* consider if we want to add anything else.
> 
> Paul, I believe you have much more experience in debugging early
> HW releases with FPGA models than any of us, so tracing is likely
> to help you, is there anything you'd want me to add to as a tracepoint ?

What about the "unexpected" interrupt events? It would be nice to see if
we receive e.g. an EVENT_OVERFLOW interrupt. Especially since you have
some of those events enabled, but don't have handlers for all of them.

Maybe a single tracepoint for all of the unexpected events?
Felipe Balbi Aug. 19, 2014, 8:10 p.m. UTC | #2 
On Tue, Aug 19, 2014 at 08:00:27PM +0000, Paul Zimmerman wrote:
> > From: Felipe Balbi [mailto:balbi@ti.com]
> > Sent: Tuesday, August 19, 2014 12:09 PM
> > 
> > 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 guys,
> > 
> > here's v2 of my dwc3 tracepoints patch. Please have a look and
> > *CAREFULLY* consider if we want to add anything else.
> > 
> > Paul, I believe you have much more experience in debugging early
> > HW releases with FPGA models than any of us, so tracing is likely
> > to help you, is there anything you'd want me to add to as a tracepoint ?
> 
> What about the "unexpected" interrupt events? It would be nice to see if
> we receive e.g. an EVENT_OVERFLOW interrupt. Especially since you have
> some of those events enabled, but don't have handlers for all of them.
> 
> Maybe a single tracepoint for all of the unexpected events?

Makes sense, I was thinking of a neater way to just pass the event
structure and decode it withing the trace itself. Then we can even
remove all the event-specific traces, would that help ?

I guess with that we would have a pretty neat setup where we can trace
TRB lifetime, all register accesses and events.
Paul Zimmerman Aug. 19, 2014, 8:14 p.m. UTC | #3 
> From: Felipe Balbi [mailto:balbi@ti.com]
> Sent: Tuesday, August 19, 2014 1:10 PM
> 
> On Tue, Aug 19, 2014 at 08:00:27PM +0000, Paul Zimmerman wrote:
> > > From: Felipe Balbi [mailto:balbi@ti.com]
> > > Sent: Tuesday, August 19, 2014 12:09 PM
> > >
> > > 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 guys,
> > >
> > > here's v2 of my dwc3 tracepoints patch. Please have a look and
> > > *CAREFULLY* consider if we want to add anything else.
> > >
> > > Paul, I believe you have much more experience in debugging early
> > > HW releases with FPGA models than any of us, so tracing is likely
> > > to help you, is there anything you'd want me to add to as a tracepoint ?
> >
> > What about the "unexpected" interrupt events? It would be nice to see if
> > we receive e.g. an EVENT_OVERFLOW interrupt. Especially since you have
> > some of those events enabled, but don't have handlers for all of them.
> >
> > Maybe a single tracepoint for all of the unexpected events?
> 
> Makes sense, I was thinking of a neater way to just pass the event
> structure and decode it withing the trace itself. Then we can even
> remove all the event-specific traces, would that help ?

Yeah, that's sounds even better.

> I guess with that we would have a pretty neat setup where we can trace
> TRB lifetime, all register accesses and events.

Nice.
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..7e1f2c3 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) {
@@ -2020,7 +2029,7 @@  static void dwc3_endpoint_interrupt(struct dwc3 *dwc,
 	if (!(dep->flags & DWC3_EP_ENABLED))
 		return;
 
-	dev_vdbg(dwc->dev, "%s: %s\n", dep->name,
+	dwc3_trace(trace_dwc3_event, "%s: %s", dep->name,
 			dwc3_ep_event_string(event->endpoint_event));
 
 	if (epnum == 0 || epnum == 1) {
@@ -2215,7 +2224,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;
@@ -2235,7 +2244,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
@@ -2321,7 +2330,7 @@  static void dwc3_gadget_conndone_interrupt(struct dwc3 *dwc)
 	u32			reg;
 	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;
@@ -2420,7 +2429,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
@@ -2526,7 +2535,7 @@  static void dwc3_gadget_linksts_change_interrupt(struct dwc3 *dwc,
 		break;
 	}
 
-	dev_vdbg(dwc->dev, "link change: %s [%d] -> %s [%d]\n",
+	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);
 
@@ -2538,6 +2547,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 +2710,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..3b8013e
--- /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 %02x bRequest %02x wValue %04x wIndex %04x wLength %d",
+		__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>