usb: dwc3: gadget: Keep track of IRQ timing statistics

It may be useful to debug how much time is spent in the
DWC3 hard IRQ context. Add low-overhead statistics counters
which keep a histogram of the last 10 interrupts' time of
occurence, time spent, and number of events read (which will
get processed in the bottom half handler).

Change-Id: I466144d8141f4236b9fb834dded93225b56d0422
Signed-off-by: Jack Pham <jackp@codeaurora.org>

diff --git a/drivers/usb/dwc3/core.h b/drivers/usb/dwc3/core.h
index 23213ec..cc98bc0 100644 (file)
--- a/drivers/usb/dwc3/core.h
+++ b/drivers/usb/dwc3/core.h
@@ -712,6 +712,8 @@ struct dwc3_scratchpad_array {
 #define DWC3_CONTROLLER_POST_RESET_EVENT               2
 #define DWC3_CORE_PM_SUSPEND_EVENT                     3
 #define DWC3_CORE_PM_RESUME_EVENT                      4
+
+#define MAX_INTR_STATS                                 10
 /**
  * struct dwc3 - representation of our controller
  * @ctrl_req: usb control request which is used for ep0
@@ -803,6 +805,10 @@ struct dwc3_scratchpad_array {
  * @usb3_u1u2_disable: if true, disable U1U2 low power modes in Superspeed mode.
  * @in_lpm: indicates if controller is in low power mode (no clocks)
  * @tx_fifo_size: Available RAM size for TX fifo allocation
+ * @irq_cnt: total irq count
+ * @bh_completion_time: time taken for taklet completion
+ * @bh_handled_evt_cnt: no. of events handled by tasklet per interrupt
+ * @bh_dbg_index: index for capturing bh_completion_time and bh_handled_evt_cnt
  */
 struct dwc3 {
        struct usb_ctrlrequest  *ctrl_req;
@@ -957,6 +963,16 @@ struct dwc3 {
 
        atomic_t                in_lpm;
        int                     tx_fifo_size;
+
+       /* IRQ timing statistics */
+       unsigned long           irq_cnt;
+       unsigned                bh_completion_time[MAX_INTR_STATS];
+       unsigned                bh_handled_evt_cnt[MAX_INTR_STATS];
+       unsigned                bh_dbg_index;
+       ktime_t                 irq_start_time[MAX_INTR_STATS];
+       unsigned                irq_completion_time[MAX_INTR_STATS];
+       unsigned                irq_event_count[MAX_INTR_STATS];
+       unsigned                irq_dbg_index;
 };
 
 /* -------------------------------------------------------------------------- */

diff --git a/drivers/usb/dwc3/debugfs.c b/drivers/usb/dwc3/debugfs.c
index 5372dac..fbbcbf0 100644 (file)
--- a/drivers/usb/dwc3/debugfs.c
+++ b/drivers/usb/dwc3/debugfs.c
@@ -1154,6 +1154,24 @@ static int dwc3_gadget_int_events_show(struct seq_file *s, void *unused)
                dbg_gadget_events->cmdcmplt);
        seq_printf(s, "unknown_event:%u\n", dbg_gadget_events->unknown_event);
 
+       seq_printf(s, "\n\t== Last %d interrupts stats ==\t\n", MAX_INTR_STATS);
+       seq_puts(s, "@ time (us):\t");
+       for (i = 0; i < MAX_INTR_STATS; i++)
+               seq_printf(s, "%lld\t", ktime_to_us(dwc->irq_start_time[i]));
+       seq_puts(s, "\nhard irq time (us):\t");
+       for (i = 0; i < MAX_INTR_STATS; i++)
+               seq_printf(s, "%d\t", dwc->irq_completion_time[i]);
+       seq_puts(s, "\nevents count:\t\t");
+       for (i = 0; i < MAX_INTR_STATS; i++)
+               seq_printf(s, "%d\t", dwc->irq_event_count[i]);
+       seq_puts(s, "\nbh handled count:\t");
+       for (i = 0; i < MAX_INTR_STATS; i++)
+               seq_printf(s, "%d\t", dwc->bh_handled_evt_cnt[i]);
+       seq_puts(s, "\nirq thread time (us):\t");
+       for (i = 0; i < MAX_INTR_STATS; i++)
+               seq_printf(s, "%d\t", dwc->bh_completion_time[i]);
+       seq_putc(s, '\n');
+
        spin_unlock_irqrestore(&dwc->lock, flags);
        return 0;
 }

diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
index d872bd9..265dad2 100644 (file)
--- a/drivers/usb/dwc3/gadget.c
+++ b/drivers/usb/dwc3/gadget.c
@@ -2997,6 +2997,8 @@ static irqreturn_t dwc3_process_event_buf(struct dwc3 *dwc, u32 buf)
                dwc3_writel(dwc->regs, DWC3_GEVNTCOUNT(buf), 4);
        }
 
+       dwc->bh_handled_evt_cnt[dwc->bh_dbg_index] += (evt->count / 4);
+
        evt->count = 0;
        evt->flags &= ~DWC3_EVENT_PENDING;
        ret = IRQ_HANDLED;
@@ -3015,14 +3017,23 @@ static irqreturn_t dwc3_thread_interrupt(int irq, void *_dwc)
        unsigned long flags;
        irqreturn_t ret = IRQ_NONE;
        int i;
+       unsigned temp_time;
+       ktime_t start_time;
+
+       start_time = ktime_get();
 
        spin_lock_irqsave(&dwc->lock, flags);
+       dwc->bh_handled_evt_cnt[dwc->bh_dbg_index] = 0;
 
        for (i = 0; i < dwc->num_event_buffers; i++)
                ret |= dwc3_process_event_buf(dwc, i);
 
        spin_unlock_irqrestore(&dwc->lock, flags);
 
+       temp_time = ktime_to_us(ktime_sub(ktime_get(), start_time));
+       dwc->bh_completion_time[dwc->bh_dbg_index] = temp_time;
+       dwc->bh_dbg_index = (dwc->bh_dbg_index + 1) % 10;
+
        pm_runtime_put(dwc->dev);
        return ret;
 }
@@ -3056,6 +3067,11 @@ static irqreturn_t dwc3_interrupt(int irq, void *_dwc)
        struct dwc3                     *dwc = _dwc;
        int                             i;
        irqreturn_t                     ret = IRQ_NONE;
+       unsigned                        temp_cnt = 0;
+       ktime_t                         start_time;
+
+       start_time = ktime_get();
+       dwc->irq_cnt++;
 
        /* controller reset is still pending */
        if (dwc->err_evt_seen)
@@ -3067,8 +3083,16 @@ static irqreturn_t dwc3_interrupt(int irq, void *_dwc)
                status = dwc3_check_event_buf(dwc, i);
                if (status == IRQ_WAKE_THREAD)
                        ret = status;
+
+               temp_cnt += dwc->ev_buffs[i]->count;
        }
 
+       dwc->irq_start_time[dwc->irq_dbg_index] = start_time;
+       dwc->irq_completion_time[dwc->irq_dbg_index] =
+               ktime_us_delta(ktime_get(), start_time);
+       dwc->irq_event_count[dwc->irq_dbg_index] = temp_cnt / 4;
+       dwc->irq_dbg_index = (dwc->irq_dbg_index + 1) % MAX_INTR_STATS;
+
        if (ret == IRQ_WAKE_THREAD)
                pm_runtime_get(dwc->dev);