Hi Doug,
Very good idea here, I used to add some local patch and with USB
analyzer to debug this part of code, and we can use more tools with
your patch now, I can try kernelshark next time.
Do you consider to add tracing for qtd? Then we can track the whole
lift cycle of urb in dwc2 driver.
For this patch:
Reviewed-by: Kever Yang <kever.yang at rock-chips.com>
Thanks,
- Kever
On 01/23/2016 02:18 AM, Douglas Anderson wrote:
> In preparation for future changes to the scheduler let's add some
> tracing that makes it easy for us to see what's happening. By default
> this tracing will be off.
>
> By changing "core.h" you can easily trace to ftrace, the console, or
> nowhere.
>
> Signed-off-by: Douglas Anderson <dianders at chromium.org>
> ---
> Changes in v5: None
> Changes in v4:
> - Retooled scheduler tracing a bit, so left off John's Ack from v3.
>
> Changes in v3: None
> Changes in v2: None
>
> drivers/usb/dwc2/core.h | 20 ++++++++++++++++++++
> drivers/usb/dwc2/hcd.h | 5 +++++
> drivers/usb/dwc2/hcd_intr.c | 6 +++++-
> drivers/usb/dwc2/hcd_queue.c | 24 +++++++++++++++++++++++-
> 4 files changed, 53 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/usb/dwc2/core.h b/drivers/usb/dwc2/core.h
> index 538cf38af0e4..18f9e4045643 100644
> --- a/drivers/usb/dwc2/core.h
> +++ b/drivers/usb/dwc2/core.h
> @@ -44,6 +44,26 @@
> #include <linux/usb/phy.h>
> #include "hw.h"
>
> +/*
> + * Suggested defines for tracers:
> + * - no_printk: Disable tracing
> + * - pr_info: Print this info to the console
> + * - trace_printk: Print this info to trace buffer (good for verbose logging)
> + */
> +
> +#define DWC2_TRACE_SCHEDULER no_printk
> +#define DWC2_TRACE_SCHEDULER_VB no_printk
> +
> +/* Detailed scheduler tracing, but won't overwhelm console */
> +#define dwc2_sch_dbg(hsotg, fmt, ...) \
> + DWC2_TRACE_SCHEDULER(pr_fmt("%s: SCH: " fmt), \
> + dev_name(hsotg->dev), ##__VA_ARGS__)
> +
> +/* Verbose scheduler tracing */
> +#define dwc2_sch_vdbg(hsotg, fmt, ...) \
> + DWC2_TRACE_SCHEDULER_VB(pr_fmt("%s: SCH: " fmt), \
> + dev_name(hsotg->dev), ##__VA_ARGS__)
> +
> static inline u32 dwc2_readl(const void __iomem *addr)
> {
> u32 value = __raw_readl(addr);
> diff --git a/drivers/usb/dwc2/hcd.h b/drivers/usb/dwc2/hcd.h
> index 1b46e2e617cc..809bc4ff9116 100644
> --- a/drivers/usb/dwc2/hcd.h
> +++ b/drivers/usb/dwc2/hcd.h
> @@ -563,6 +563,11 @@ static inline u16 dwc2_frame_num_inc(u16 frame, u16 inc)
> return (frame + inc) & HFNUM_MAX_FRNUM;
> }
>
> +static inline u16 dwc2_frame_num_dec(u16 frame, u16 dec)
> +{
> + return (frame + HFNUM_MAX_FRNUM + 1 - dec) & HFNUM_MAX_FRNUM;
> +}
> +
> static inline u16 dwc2_full_frame_num(u16 frame)
> {
> return (frame & HFNUM_MAX_FRNUM) >> 3;
> diff --git a/drivers/usb/dwc2/hcd_intr.c b/drivers/usb/dwc2/hcd_intr.c
> index 577c91096a51..5d25a5ec9736 100644
> --- a/drivers/usb/dwc2/hcd_intr.c
> +++ b/drivers/usb/dwc2/hcd_intr.c
> @@ -138,13 +138,17 @@ static void dwc2_sof_intr(struct dwc2_hsotg *hsotg)
> while (qh_entry != &hsotg->periodic_sched_inactive) {
> qh = list_entry(qh_entry, struct dwc2_qh, qh_list_entry);
> qh_entry = qh_entry->next;
> - if (dwc2_frame_num_le(qh->sched_frame, hsotg->frame_number))
> + if (dwc2_frame_num_le(qh->sched_frame, hsotg->frame_number)) {
> + dwc2_sch_vdbg(hsotg, "QH=%p ready fn=%04x, sch=%04x\n",
> + qh, hsotg->frame_number, qh->sched_frame);
> +
> /*
> * Move QH to the ready list to be executed next
> * (micro)frame
> */
> list_move_tail(&qh->qh_list_entry,
> &hsotg->periodic_sched_ready);
> + }
> }
> tr_type = dwc2_hcd_select_transactions(hsotg);
> if (tr_type != DWC2_TRANSACTION_NONE)
> diff --git a/drivers/usb/dwc2/hcd_queue.c b/drivers/usb/dwc2/hcd_queue.c
> index bc632a72f611..0e9faa75593c 100644
> --- a/drivers/usb/dwc2/hcd_queue.c
> +++ b/drivers/usb/dwc2/hcd_queue.c
> @@ -113,6 +113,9 @@ static void dwc2_qh_init(struct dwc2_hsotg *hsotg, struct dwc2_qh *qh,
> qh->sched_frame = dwc2_frame_num_inc(hsotg->frame_number,
> SCHEDULE_SLOP);
> qh->interval = urb->interval;
> + dwc2_sch_dbg(hsotg, "QH=%p init sch=%04x, fn=%04x, int=%#x\n",
> + qh, qh->sched_frame, hsotg->frame_number,
> + qh->interval);
> #if 0
> /* Increase interrupt polling rate for debugging */
> if (qh->ep_type == USB_ENDPOINT_XFER_INT)
> @@ -126,6 +129,11 @@ static void dwc2_qh_init(struct dwc2_hsotg *hsotg, struct dwc2_qh *qh,
> qh->interval *= 8;
> qh->sched_frame |= 0x7;
> qh->start_split_frame = qh->sched_frame;
> + dwc2_sch_dbg(hsotg,
> + "QH=%p init*8 sch=%04x, fn=%04x, int=%#x\n",
> + qh, qh->sched_frame, hsotg->frame_number,
> + qh->interval);
> +
> }
> dev_dbg(hsotg->dev, "interval=%d\n", qh->interval);
> }
> @@ -482,6 +490,8 @@ static int dwc2_schedule_periodic(struct dwc2_hsotg *hsotg, struct dwc2_qh *qh)
> if (frame >= 0) {
> qh->sched_frame &= ~0x7;
> qh->sched_frame |= (frame & 7);
> + dwc2_sch_dbg(hsotg, "QH=%p sched_p sch=%04x, uf=%d\n",
> + qh, qh->sched_frame, frame);
> }
>
> if (status > 0)
> @@ -583,10 +593,16 @@ int dwc2_hcd_qh_add(struct dwc2_hsotg *hsotg, struct dwc2_qh *qh)
>
> if (!dwc2_frame_num_le(qh->sched_frame, hsotg->frame_number) &&
> !hsotg->frame_number) {
> + u16 new_frame;
> +
> dev_dbg(hsotg->dev,
> "reset frame number counter\n");
> - qh->sched_frame = dwc2_frame_num_inc(hsotg->frame_number,
> + new_frame = dwc2_frame_num_inc(hsotg->frame_number,
> SCHEDULE_SLOP);
> +
> + dwc2_sch_vdbg(hsotg, "QH=%p reset sch=%04x=>%04x\n",
> + qh, qh->sched_frame, new_frame);
> + qh->sched_frame = new_frame;
> }
>
> /* Add the new QH to the appropriate schedule */
> @@ -652,6 +668,7 @@ static void dwc2_sched_periodic_split(struct dwc2_hsotg *hsotg,
> int sched_next_periodic_split)
> {
> u16 incr;
> + u16 old_frame = qh->sched_frame;
>
> if (sched_next_periodic_split) {
> qh->sched_frame = frame_number;
> @@ -677,6 +694,11 @@ static void dwc2_sched_periodic_split(struct dwc2_hsotg *hsotg,
> qh->sched_frame |= 0x7;
> qh->start_split_frame = qh->sched_frame;
> }
> +
> + dwc2_sch_vdbg(hsotg, "QH=%p next(%d) fn=%04x, sch=%04x=>%04x (%+d)\n",
> + qh, sched_next_periodic_split, frame_number, old_frame,
> + qh->sched_frame,
> + dwc2_frame_num_dec(qh->sched_frame, old_frame));
> }
>
> /*
