From 6920889361c96610c28b1ca89410138e6d12d5be Mon Sep 17 00:00:00 2001 From: Jack Pham Date: Wed, 15 Oct 2014 18:23:37 -0700 Subject: [PATCH] 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 occurrence, time spent, and number of events read (which will get processed in the bottom half handler). Change-Id: I466144d8141f4236b9fb834dded93225b56d0422 Signed-off-by: Jack Pham --- drivers/usb/dwc3/core.h | 15 +++++++++++++++ drivers/usb/dwc3/debugfs.c | 18 ++++++++++++++++++ drivers/usb/dwc3/gadget.c | 19 +++++++++++++++++++ 3 files changed, 52 insertions(+) diff --git a/drivers/usb/dwc3/core.h b/drivers/usb/dwc3/core.h index bdd964e87c48..ad21dd7fac1a 100644 --- a/drivers/usb/dwc3/core.h +++ b/drivers/usb/dwc3/core.h @@ -946,6 +946,8 @@ struct dwc3_scratchpad_array { __le64 dma_adr[DWC3_MAX_HIBER_SCRATCHBUFS]; }; +#define MAX_INTR_STATS 10 + /** * struct dwc3 - representation of our controller * @drd_work: workqueue used for role swapping @@ -1074,6 +1076,10 @@ struct dwc3_scratchpad_array { * @xhci_imod_value: imod value to use with xhci * @index: dwc3's instance number * @dwc_ipc_log_ctxt: dwc3 ipc log context + * @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 work_struct drd_work; @@ -1268,6 +1274,15 @@ struct dwc3 { unsigned int index; void *dwc_ipc_log_ctxt; struct dwc3_gadget_events dbg_gadget_events; + + /* IRQ timing statistics */ + unsigned long irq_cnt; + unsigned int bh_completion_time[MAX_INTR_STATS]; + unsigned int bh_handled_evt_cnt[MAX_INTR_STATS]; + ktime_t irq_start_time[MAX_INTR_STATS]; + unsigned int irq_completion_time[MAX_INTR_STATS]; + unsigned int irq_event_count[MAX_INTR_STATS]; + unsigned int irq_dbg_index; }; #define INCRX_BURST_MODE 0 diff --git a/drivers/usb/dwc3/debugfs.c b/drivers/usb/dwc3/debugfs.c index 986d2f963508..88cca1179633 100644 --- a/drivers/usb/dwc3/debugfs.c +++ b/drivers/usb/dwc3/debugfs.c @@ -1034,6 +1034,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 ae270c91293f..53382101d5da 100644 --- a/drivers/usb/dwc3/gadget.c +++ b/drivers/usb/dwc3/gadget.c @@ -3205,6 +3205,7 @@ static irqreturn_t dwc3_process_event_buf(struct dwc3_event_buffer *evt) left -= 4; } + dwc->bh_handled_evt_cnt[dwc->irq_dbg_index] += (evt->count / 4); evt->count = 0; evt->flags &= ~DWC3_EVENT_PENDING; ret = IRQ_HANDLED; @@ -3228,11 +3229,19 @@ static irqreturn_t dwc3_thread_interrupt(int irq, void *_evt) struct dwc3 *dwc = evt->dwc; unsigned long flags; irqreturn_t ret = IRQ_NONE; + ktime_t start_time; + + start_time = ktime_get(); spin_lock_irqsave(&dwc->lock, flags); + dwc->bh_handled_evt_cnt[dwc->irq_dbg_index] = 0; ret = dwc3_process_event_buf(evt); spin_unlock_irqrestore(&dwc->lock, flags); + dwc->bh_completion_time[dwc->irq_dbg_index] = + ktime_to_us(ktime_sub(ktime_get(), start_time)); + dwc->irq_dbg_index = (dwc->irq_dbg_index + 1) % MAX_INTR_STATS; + return ret; } @@ -3242,6 +3251,10 @@ static irqreturn_t dwc3_check_event_buf(struct dwc3_event_buffer *evt) u32 amount; u32 count; u32 reg; + ktime_t start_time; + + start_time = ktime_get(); + dwc->irq_cnt++; if (pm_runtime_suspended(dwc->dev)) { pm_runtime_get(dwc->dev); @@ -3280,6 +3293,12 @@ static irqreturn_t dwc3_check_event_buf(struct dwc3_event_buffer *evt) dwc3_writel(dwc->regs, DWC3_GEVNTCOUNT(0), 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] = count / 4; + dwc->irq_dbg_index = (dwc->irq_dbg_index + 1) % MAX_INTR_STATS; + return IRQ_WAKE_THREAD; }