iwlwifi: add continuous uCode event log capability
authorWey-Yi Guy <wey-yi.w.guy@intel.com>
Thu, 10 Dec 2009 22:37:26 +0000 (14:37 -0800)
committerJohn W. Linville <linville@tuxdriver.com>
Mon, 21 Dec 2009 23:56:16 +0000 (18:56 -0500)
In order to help uCode debugging, adding the capability to provide
continuous uCode event logging function.

uCode events is located in round-robin event queue and filled by uCode,
by enable continuous event logging, driver check the write pointer
and log the newly added events in iwl_bg_ucode_trace() timer function.

There is still possibility of missing events if event queue being
wrapped before next event dump; but with this capability, we can have
much better understanding of the uCode behavior during runtime; it can
help to debug the uCode related issues.

Methods to enable/disable the continuous event log:
step 1: enable ucode trace timer
     "echo 1 >
/sys/kernel/debug/ieee80211/phyX/iwlagn/debug/ucode_tracing"
step 2: start ftrace
     sudo ./trace-cmd record -e iwlwifi_ucode:* sleep 1d
step 3: stop ftrace
     sudo ./trace-cmd report trace.dat
step 4: disable ucode trace timer
     "echo 0 >
/sys/kernel/debug/ieee80211/phyX/iwlagn/debug/ucode_tracing"

use "ucode_tracing" debugfs file to display number of event
queue wrapped when driver attempt the continuous event logging. If event
queue being wrapped more than once when driver has opportunity to log
the event; it indicated there are events missing in the event log trace.

This continuous event log function only available for 4965 and newer
NICs.

Signed-off-by: Wey-Yi Guy <wey-yi.w.guy@intel.com>
Signed-off-by: Reinette Chatre <reinette.chatre@intel.com>
Signed-off-by: John W. Linville <linville@tuxdriver.com>
drivers/net/wireless/iwlwifi/iwl-agn.c
drivers/net/wireless/iwlwifi/iwl-debug.h
drivers/net/wireless/iwlwifi/iwl-debugfs.c
drivers/net/wireless/iwlwifi/iwl-dev.h
drivers/net/wireless/iwlwifi/iwl-devtrace.c
drivers/net/wireless/iwlwifi/iwl-devtrace.h

index 954b8ae2c880cb2a1eb9e7764e48a9de2b46b958..4d85c28e38e2944b2e14578100c1d1c2f65adc92 100644 (file)
@@ -657,6 +657,131 @@ static void iwl_bg_statistics_periodic(unsigned long data)
        iwl_send_statistics_request(priv, CMD_ASYNC, false);
 }
 
+
+static void iwl_print_cont_event_trace(struct iwl_priv *priv, u32 base,
+                                       u32 start_idx, u32 num_events,
+                                       u32 mode)
+{
+       u32 i;
+       u32 ptr;        /* SRAM byte address of log data */
+       u32 ev, time, data; /* event log data */
+       unsigned long reg_flags;
+
+       if (mode == 0)
+               ptr = base + (4 * sizeof(u32)) + (start_idx * 2 * sizeof(u32));
+       else
+               ptr = base + (4 * sizeof(u32)) + (start_idx * 3 * sizeof(u32));
+
+       /* Make sure device is powered up for SRAM reads */
+       spin_lock_irqsave(&priv->reg_lock, reg_flags);
+       if (iwl_grab_nic_access(priv)) {
+               spin_unlock_irqrestore(&priv->reg_lock, reg_flags);
+               return;
+       }
+
+       /* Set starting address; reads will auto-increment */
+       _iwl_write_direct32(priv, HBUS_TARG_MEM_RADDR, ptr);
+       rmb();
+
+       /*
+        * "time" is actually "data" for mode 0 (no timestamp).
+        * place event id # at far right for easier visual parsing.
+        */
+       for (i = 0; i < num_events; i++) {
+               ev = _iwl_read_direct32(priv, HBUS_TARG_MEM_RDAT);
+               time = _iwl_read_direct32(priv, HBUS_TARG_MEM_RDAT);
+               if (mode == 0) {
+                       trace_iwlwifi_dev_ucode_cont_event(priv,
+                                                       0, time, ev);
+               } else {
+                       data = _iwl_read_direct32(priv, HBUS_TARG_MEM_RDAT);
+                       trace_iwlwifi_dev_ucode_cont_event(priv,
+                                               time, data, ev);
+               }
+       }
+       /* Allow device to power down */
+       iwl_release_nic_access(priv);
+       spin_unlock_irqrestore(&priv->reg_lock, reg_flags);
+}
+
+void iwl_continuous_event_trace(struct iwl_priv *priv)
+{
+       u32 capacity;   /* event log capacity in # entries */
+       u32 base;       /* SRAM byte address of event log header */
+       u32 mode;       /* 0 - no timestamp, 1 - timestamp recorded */
+       u32 num_wraps;  /* # times uCode wrapped to top of log */
+       u32 next_entry; /* index of next entry to be written by uCode */
+
+       if (priv->ucode_type == UCODE_INIT)
+               base = le32_to_cpu(priv->card_alive_init.error_event_table_ptr);
+       else
+               base = le32_to_cpu(priv->card_alive.log_event_table_ptr);
+       if (priv->cfg->ops->lib->is_valid_rtc_data_addr(base)) {
+               capacity = iwl_read_targ_mem(priv, base);
+               num_wraps = iwl_read_targ_mem(priv, base + (2 * sizeof(u32)));
+               mode = iwl_read_targ_mem(priv, base + (1 * sizeof(u32)));
+               next_entry = iwl_read_targ_mem(priv, base + (3 * sizeof(u32)));
+       } else
+               return;
+
+       if (num_wraps == priv->event_log.num_wraps) {
+               iwl_print_cont_event_trace(priv,
+                                      base, priv->event_log.next_entry,
+                                      next_entry - priv->event_log.next_entry,
+                                      mode);
+               priv->event_log.non_wraps_count++;
+       } else {
+               if ((num_wraps - priv->event_log.num_wraps) > 1)
+                       priv->event_log.wraps_more_count++;
+               else
+                       priv->event_log.wraps_once_count++;
+               trace_iwlwifi_dev_ucode_wrap_event(priv,
+                               num_wraps - priv->event_log.num_wraps,
+                               next_entry, priv->event_log.next_entry);
+               if (next_entry < priv->event_log.next_entry) {
+                       iwl_print_cont_event_trace(priv, base,
+                              priv->event_log.next_entry,
+                              capacity - priv->event_log.next_entry,
+                              mode);
+
+                       iwl_print_cont_event_trace(priv, base, 0,
+                               next_entry, mode);
+               } else {
+                       iwl_print_cont_event_trace(priv, base,
+                              next_entry, capacity - next_entry,
+                              mode);
+
+                       iwl_print_cont_event_trace(priv, base, 0,
+                               next_entry, mode);
+               }
+       }
+       priv->event_log.num_wraps = num_wraps;
+       priv->event_log.next_entry = next_entry;
+}
+
+/**
+ * iwl_bg_ucode_trace - Timer callback to log ucode event
+ *
+ * The timer is continually set to execute every
+ * UCODE_TRACE_PERIOD milliseconds after the last timer expired
+ * this function is to perform continuous uCode event logging operation
+ * if enabled
+ */
+static void iwl_bg_ucode_trace(unsigned long data)
+{
+       struct iwl_priv *priv = (struct iwl_priv *)data;
+
+       if (test_bit(STATUS_EXIT_PENDING, &priv->status))
+               return;
+
+       if (priv->event_log.ucode_trace) {
+               iwl_continuous_event_trace(priv);
+               /* Reschedule the timer to occur in UCODE_TRACE_PERIOD */
+               mod_timer(&priv->ucode_trace,
+                        jiffies + msecs_to_jiffies(UCODE_TRACE_PERIOD));
+       }
+}
+
 static void iwl_rx_beacon_notif(struct iwl_priv *priv,
                                struct iwl_rx_mem_buffer *rxb)
 {
@@ -3128,6 +3253,10 @@ static void iwl_setup_deferred_work(struct iwl_priv *priv)
        priv->statistics_periodic.data = (unsigned long)priv;
        priv->statistics_periodic.function = iwl_bg_statistics_periodic;
 
+       init_timer(&priv->ucode_trace);
+       priv->ucode_trace.data = (unsigned long)priv;
+       priv->ucode_trace.function = iwl_bg_ucode_trace;
+
        if (!priv->cfg->use_isr_legacy)
                tasklet_init(&priv->irq_tasklet, (void (*)(unsigned long))
                        iwl_irq_tasklet, (unsigned long)priv);
@@ -3146,6 +3275,7 @@ static void iwl_cancel_deferred_work(struct iwl_priv *priv)
        cancel_delayed_work(&priv->alive_start);
        cancel_work_sync(&priv->beacon_update);
        del_timer_sync(&priv->statistics_periodic);
+       del_timer_sync(&priv->ucode_trace);
 }
 
 static void iwl_init_hw_rates(struct iwl_priv *priv,
index 86a67672598dabef28d336087f5ab1adb109c5be..58e0462cafa35744d84f4d252e1cb61f8d9d133e 100644 (file)
@@ -110,6 +110,7 @@ struct iwl_debugfs {
                struct dentry *file_clear_ucode_statistics;
                struct dentry *file_clear_traffic_statistics;
                struct dentry *file_csr;
+               struct dentry *file_ucode_tracing;
        } dbgfs_debug_files;
        u32 sram_offset;
        u32 sram_len;
index 2be3549be01d15a09b6f33be1e36fb5589b21df6..822de46e4f34fd8827abefc85f741974ea45b0cc 100644 (file)
@@ -1867,6 +1867,58 @@ static ssize_t iwl_dbgfs_csr_write(struct file *file,
        return count;
 }
 
+static ssize_t iwl_dbgfs_ucode_tracing_read(struct file *file,
+                                       char __user *user_buf,
+                                       size_t count, loff_t *ppos) {
+
+       struct iwl_priv *priv = (struct iwl_priv *)file->private_data;
+       int pos = 0;
+       char buf[128];
+       const size_t bufsz = sizeof(buf);
+       ssize_t ret;
+
+       pos += scnprintf(buf + pos, bufsz - pos, "ucode trace timer is %s\n",
+                       priv->event_log.ucode_trace ? "On" : "Off");
+       pos += scnprintf(buf + pos, bufsz - pos, "non_wraps_count:\t\t %u\n",
+                       priv->event_log.non_wraps_count);
+       pos += scnprintf(buf + pos, bufsz - pos, "wraps_once_count:\t\t %u\n",
+                       priv->event_log.wraps_once_count);
+       pos += scnprintf(buf + pos, bufsz - pos, "wraps_more_count:\t\t %u\n",
+                       priv->event_log.wraps_more_count);
+
+       ret = simple_read_from_buffer(user_buf, count, ppos, buf, pos);
+       return ret;
+}
+
+static ssize_t iwl_dbgfs_ucode_tracing_write(struct file *file,
+                                        const char __user *user_buf,
+                                        size_t count, loff_t *ppos)
+{
+       struct iwl_priv *priv = file->private_data;
+       char buf[8];
+       int buf_size;
+       int trace;
+
+       memset(buf, 0, sizeof(buf));
+       buf_size = min(count, sizeof(buf) -  1);
+       if (copy_from_user(buf, user_buf, buf_size))
+               return -EFAULT;
+       if (sscanf(buf, "%d", &trace) != 1)
+               return -EFAULT;
+
+       if (trace) {
+               priv->event_log.ucode_trace = true;
+               /* schedule the ucode timer to occur in UCODE_TRACE_PERIOD */
+               mod_timer(&priv->ucode_trace,
+                       jiffies + msecs_to_jiffies(UCODE_TRACE_PERIOD));
+       } else {
+               priv->event_log.ucode_trace = false;
+               del_timer_sync(&priv->ucode_trace);
+       }
+
+       return count;
+}
+
 DEBUGFS_READ_FILE_OPS(rx_statistics);
 DEBUGFS_READ_FILE_OPS(tx_statistics);
 DEBUGFS_READ_WRITE_FILE_OPS(traffic_log);
@@ -1882,6 +1934,7 @@ DEBUGFS_READ_FILE_OPS(power_save_status);
 DEBUGFS_WRITE_FILE_OPS(clear_ucode_statistics);
 DEBUGFS_WRITE_FILE_OPS(clear_traffic_statistics);
 DEBUGFS_WRITE_FILE_OPS(csr);
+DEBUGFS_READ_WRITE_FILE_OPS(ucode_tracing);
 
 /*
  * Create the debugfs files and directories
@@ -1939,6 +1992,7 @@ int iwl_dbgfs_register(struct iwl_priv *priv, const char *name)
                DEBUGFS_ADD_FILE(ucode_general_stats, debug, S_IRUSR);
                DEBUGFS_ADD_FILE(sensitivity, debug, S_IRUSR);
                DEBUGFS_ADD_FILE(chain_noise, debug, S_IRUSR);
+               DEBUGFS_ADD_FILE(ucode_tracing, debug, S_IWUSR | S_IRUSR);
        }
        DEBUGFS_ADD_BOOL(disable_sensitivity, rf, &priv->disable_sens_cal);
        DEBUGFS_ADD_BOOL(disable_chain_noise, rf,
@@ -2002,6 +2056,8 @@ void iwl_dbgfs_unregister(struct iwl_priv *priv)
                        file_sensitivity);
                DEBUGFS_REMOVE(priv->dbgfs->dbgfs_debug_files.
                        file_chain_noise);
+               DEBUGFS_REMOVE(priv->dbgfs->dbgfs_debug_files.
+                       file_ucode_tracing);
        }
        DEBUGFS_REMOVE(priv->dbgfs->dir_debug);
        DEBUGFS_REMOVE(priv->dbgfs->dbgfs_rf_files.file_disable_sensitivity);
index 2673e9a4db92c4992a52bb34a0bbfd0a99cb1f0d..b3a29c7cdbc09d21fdeb21295ccb4c69f6d47f0f 100644 (file)
@@ -984,6 +984,32 @@ struct iwl_switch_rxon {
        __le16 channel;
 };
 
+/*
+ * schedule the timer to wake up every UCODE_TRACE_PERIOD milliseconds
+ * to perform continuous uCode event logging operation if enabled
+ */
+#define UCODE_TRACE_PERIOD (100)
+
+/*
+ * iwl_event_log: current uCode event log position
+ *
+ * @ucode_trace: enable/disable ucode continuous trace timer
+ * @num_wraps: how many times the event buffer wraps
+ * @next_entry:  the entry just before the next one that uCode would fill
+ * @non_wraps_count: counter for no wrap detected when dump ucode events
+ * @wraps_once_count: counter for wrap once detected when dump ucode events
+ * @wraps_more_count: counter for wrap more than once detected
+ *                   when dump ucode events
+ */
+struct iwl_event_log {
+       bool ucode_trace;
+       u32 num_wraps;
+       u32 next_entry;
+       int non_wraps_count;
+       int wraps_once_count;
+       int wraps_more_count;
+};
+
 struct iwl_priv {
 
        /* ieee device used by generic ieee processing code */
@@ -1261,6 +1287,7 @@ struct iwl_priv {
        u32 disable_tx_power_cal;
        struct work_struct run_time_calib_work;
        struct timer_list statistics_periodic;
+       struct timer_list ucode_trace;
        bool hw_ready;
        /*For 3945*/
 #define IWL_DEFAULT_TX_POWER 0x0F
@@ -1268,6 +1295,8 @@ struct iwl_priv {
        struct iwl3945_notif_statistics statistics_39;
 
        u32 sta_supp_rates;
+
+       struct iwl_event_log event_log;
 }; /*iwl_priv */
 
 static inline void iwl_txq_ctx_activate(struct iwl_priv *priv, int txq_id)
index e7d88d1da15d9d5e2c49d11f7b07d1d4ed1f6363..bf46308b17fad9535dbd53b5ebedebdc0b66dbfa 100644 (file)
@@ -11,4 +11,6 @@ EXPORT_TRACEPOINT_SYMBOL(iwlwifi_dev_iowrite32);
 EXPORT_TRACEPOINT_SYMBOL(iwlwifi_dev_rx);
 EXPORT_TRACEPOINT_SYMBOL(iwlwifi_dev_ucode_event);
 EXPORT_TRACEPOINT_SYMBOL(iwlwifi_dev_ucode_error);
+EXPORT_TRACEPOINT_SYMBOL(iwlwifi_dev_ucode_cont_event);
+EXPORT_TRACEPOINT_SYMBOL(iwlwifi_dev_ucode_wrap_event);
 #endif
index 21361968ab7e86ce1ed14bd4d8bc917b5df4213c..0819f990be6ccaadcf37971ccf25483c5eb171d2 100644 (file)
@@ -64,6 +64,50 @@ TRACE_EVENT(iwlwifi_dev_iowrite32,
        TP_printk("[%p] write io[%#x] = %#x)", __entry->priv, __entry->offs, __entry->val)
 );
 
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM iwlwifi_ucode
+
+TRACE_EVENT(iwlwifi_dev_ucode_cont_event,
+       TP_PROTO(struct iwl_priv *priv, u32 time, u32 data, u32 ev),
+       TP_ARGS(priv, time, data, ev),
+       TP_STRUCT__entry(
+               PRIV_ENTRY
+
+               __field(u32, time)
+               __field(u32, data)
+               __field(u32, ev)
+       ),
+       TP_fast_assign(
+               PRIV_ASSIGN;
+               __entry->time = time;
+               __entry->data = data;
+               __entry->ev = ev;
+       ),
+       TP_printk("[%p] EVT_LOGT:%010u:0x%08x:%04u",
+                 __entry->priv, __entry->time, __entry->data, __entry->ev)
+);
+
+TRACE_EVENT(iwlwifi_dev_ucode_wrap_event,
+       TP_PROTO(struct iwl_priv *priv, u32 wraps, u32 n_entry, u32 p_entry),
+       TP_ARGS(priv, wraps, n_entry, p_entry),
+       TP_STRUCT__entry(
+               PRIV_ENTRY
+
+               __field(u32, wraps)
+               __field(u32, n_entry)
+               __field(u32, p_entry)
+       ),
+       TP_fast_assign(
+               PRIV_ASSIGN;
+               __entry->wraps = wraps;
+               __entry->n_entry = n_entry;
+               __entry->p_entry = p_entry;
+       ),
+       TP_printk("[%p] wraps=#%02d n=0x%X p=0x%X",
+                 __entry->priv, __entry->wraps, __entry->n_entry,
+                 __entry->p_entry)
+);
+
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM iwlwifi