msm: bam_dmux: add downlink processing state logging
State transitions of the downlink packet processing task are not directly
logged. This leads to information gaps when debugging downlink issues.
Add explict logging of the state transitions to provide complete
information on what the downlink processing task has done.
Change-Id: Ie253c9739447da6ed236e865b7f1ed318e13cb6e
Signed-off-by: Jeffrey Hugo <jhugo@codeaurora.org>
Signed-off-by: Arun Kumar Neelakantam <aneela@codeaurora.org>
diff --git a/arch/arm/mach-msm/bam_dmux.c b/arch/arm/mach-msm/bam_dmux.c
index 56922a8..11077dc 100644
--- a/arch/arm/mach-msm/bam_dmux.c
+++ b/arch/arm/mach-msm/bam_dmux.c
@@ -194,6 +194,7 @@
static struct sps_mem_buffer rx_desc_mem_buf;
static struct sps_register_event tx_register_event;
static struct sps_register_event rx_register_event;
+static unsigned long long last_rx_pkt_timestamp;
static struct bam_ch_info bam_ch[BAM_DMUX_NUM_CHANNELS];
static int bam_mux_initialized;
@@ -1116,6 +1117,29 @@
queue_work_on(0, bam_mux_rx_workqueue, &rx_timer_work);
}
+/**
+ * store_rx_timestamp() - store the current raw time as as a timestamp for when
+ * the last rx packet was processed
+ */
+static void store_rx_timestamp(void)
+{
+ last_rx_pkt_timestamp = sched_clock();
+}
+
+/**
+ * log_rx_timestamp() - Log the stored rx pkt timestamp in a human readable
+ * format
+ */
+static void log_rx_timestamp(void)
+{
+ unsigned long long t = last_rx_pkt_timestamp;
+ unsigned long nanosec_rem;
+
+ nanosec_rem = do_div(t, 1000000000U);
+ BAM_DMUX_LOG("Last rx pkt processed at [%6u.%09lu]\n", (unsigned)t,
+ nanosec_rem);
+}
+
static void rx_timer_work_func(struct work_struct *work)
{
struct sps_iovec iov;
@@ -1124,20 +1148,26 @@
int ret;
u32 buffs_unused, buffs_used;
+ BAM_DMUX_LOG("%s: polling start\n", __func__);
while (bam_connection_is_active) { /* timer loop */
++inactive_cycles;
while (bam_connection_is_active) { /* deplete queue loop */
- if (in_global_reset)
+ if (in_global_reset) {
+ BAM_DMUX_LOG(
+ "%s: polling exit, global reset detected\n",
+ __func__);
return;
+ }
ret = sps_get_iovec(bam_rx_pipe, &iov);
if (ret) {
- pr_err("%s: sps_get_iovec failed %d\n",
+ DMUX_LOG_KERR("%s: sps_get_iovec failed %d\n",
__func__, ret);
break;
}
if (iov.addr == 0)
break;
+ store_rx_timestamp();
inactive_cycles = 0;
mutex_lock(&bam_rx_pool_mutexlock);
if (unlikely(list_empty(&bam_rx_pool))) {
@@ -1170,6 +1200,7 @@
}
if (inactive_cycles >= POLLING_INACTIVITY) {
+ BAM_DMUX_LOG("%s: polling exit, no data\n", __func__);
rx_switch_to_interrupt_mode();
break;
}
@@ -1181,7 +1212,8 @@
&buffs_unused);
if (ret) {
- pr_err("%s: error getting num buffers unused after sleep\n",
+ DMUX_LOG_KERR(
+ "%s: error getting num buffers unused after sleep\n",
__func__);
break;
@@ -1767,6 +1799,7 @@
if (time_remaining == 0) {
DMUX_LOG_KERR("%s: shutdown completion timed out\n",
__func__);
+ log_rx_timestamp();
ssrestart_check();
}
}