From: Jack Pham Date: Thu, 16 Oct 2014 01:23:37 +0000 (-0700) Subject: usb: dwc3: gadget: Keep track of IRQ timing statistics X-Git-Url: http://git.osdn.net/view?a=commitdiff_plain;h=78c60a7bf6d61a411c2aa9a9e9ff26c23114ddfb;p=sagit-ice-cold%2Fkernel_xiaomi_msm8998.git 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 --- diff --git a/drivers/usb/dwc3/core.h b/drivers/usb/dwc3/core.h index 23213ecfd590..cc98bc01f49f 100644 --- 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 5372dac984e1..fbbcbf04e558 100644 --- 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 d872bd95f6ce..265dad2b8ad7 100644 --- 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);