qcacmn: Enhance log for usage_count mismatch debug

Add below change:
1 log level change from error to debug level in
  hif_pci_runtime_pm_warn.
2 Change warn_on to bug_on in hif_pci_runtime_pm_warn.
3 change pm_stats to atomic
4 record last 128 caller both for get/put

Change-Id: I2dae883dfaed22812445c5d50920fb363b9e0ea7
CRs-Fixed: 2638863

hif/src/pcie/if_pci.c

@@ -924,45 +924,50 @@ static void hif_pci_runtime_pm_warn(struct hif_pci_softc *sc, const char *msg)
 {
 	struct hif_pm_runtime_lock *ctx;
 
-	HIF_ERROR("%s: usage_count: %d, pm_state: %s, prevent_suspend_cnt: %d",
-			msg, atomic_read(&sc->dev->power.usage_count),
-			hif_pm_runtime_state_to_string(
-					atomic_read(&sc->pm_state)),
-			sc->prevent_suspend_cnt);
+	HIF_DBG("%s: usage_count: %d, pm_state: %s, prevent_suspend_cnt: %d",
+		msg, atomic_read(&sc->dev->power.usage_count),
+		hif_pm_runtime_state_to_string(
+				atomic_read(&sc->pm_state)),
+		sc->prevent_suspend_cnt);
+
+	HIF_DBG("runtime_status: %d, runtime_error: %d, disable_depth: %d autosuspend_delay: %d",
+		sc->dev->power.runtime_status,
+		sc->dev->power.runtime_error,
+		sc->dev->power.disable_depth,
+		sc->dev->power.autosuspend_delay);
 
-	HIF_ERROR("runtime_status: %d, runtime_error: %d, disable_depth: %d autosuspend_delay: %d",
-			sc->dev->power.runtime_status,
-			sc->dev->power.runtime_error,
-			sc->dev->power.disable_depth,
-			sc->dev->power.autosuspend_delay);
+	HIF_DBG("runtime_get: %u, runtime_put: %u, request_resume: %u",
+		qdf_atomic_read(&sc->pm_stats.runtime_get),
+		qdf_atomic_read(&sc->pm_stats.runtime_put),
+		sc->pm_stats.request_resume);
 
-	HIF_ERROR("runtime_get: %u, runtime_put: %u, request_resume: %u",
-			sc->pm_stats.runtime_get, sc->pm_stats.runtime_put,
-			sc->pm_stats.request_resume);
+	HIF_DBG("runtime_get_caller_index: %u, runtime_put_caller_index: %u",
+		qdf_atomic_read(&sc->pm_stats.runtime_get_caller_index),
+		qdf_atomic_read(&sc->pm_stats.runtime_put_caller_index));
 
-	HIF_ERROR("allow_suspend: %u, prevent_suspend: %u",
-			sc->pm_stats.allow_suspend,
-			sc->pm_stats.prevent_suspend);
+	HIF_DBG("allow_suspend: %u, prevent_suspend: %u",
+		qdf_atomic_read(&sc->pm_stats.allow_suspend),
+		qdf_atomic_read(&sc->pm_stats.prevent_suspend));
 
-	HIF_ERROR("prevent_suspend_timeout: %u, allow_suspend_timeout: %u",
-			sc->pm_stats.prevent_suspend_timeout,
-			sc->pm_stats.allow_suspend_timeout);
+	HIF_DBG("prevent_suspend_timeout: %u, allow_suspend_timeout: %u",
+		sc->pm_stats.prevent_suspend_timeout,
+		sc->pm_stats.allow_suspend_timeout);
 
-	HIF_ERROR("Suspended: %u, resumed: %u count",
-			sc->pm_stats.suspended,
-			sc->pm_stats.resumed);
+	HIF_DBG("Suspended: %u, resumed: %u count",
+		sc->pm_stats.suspended,
+		sc->pm_stats.resumed);
 
-	HIF_ERROR("suspend_err: %u, runtime_get_err: %u",
-			sc->pm_stats.suspend_err,
-			sc->pm_stats.runtime_get_err);
+	HIF_DBG("suspend_err: %u, runtime_get_err: %u",
+		sc->pm_stats.suspend_err,
+		sc->pm_stats.runtime_get_err);
 
-	HIF_ERROR("Active Wakeup Sources preventing Runtime Suspend: ");
+	HIF_DBG("Active Wakeup Sources preventing Runtime Suspend: ");
 
 	list_for_each_entry(ctx, &sc->prevent_suspend_list, list) {
-		HIF_ERROR("source %s; timeout %d ms", ctx->name, ctx->timeout);
+		HIF_DBG("source %s; timeout %d ms", ctx->name, ctx->timeout);
 	}
 
-	WARN_ON(1);
+	QDF_DEBUG_PANIC("hif_pci_runtime_pm_warn");
 }
 
 /**
@@ -1016,11 +1021,20 @@ static int hif_pci_pm_runtime_debugfs_show(struct seq_file *s, void *data)
 	HIF_PCI_RUNTIME_PM_STATS(s, sc, suspended);
 	HIF_PCI_RUNTIME_PM_STATS(s, sc, suspend_err);
 	HIF_PCI_RUNTIME_PM_STATS(s, sc, resumed);
-	HIF_PCI_RUNTIME_PM_STATS(s, sc, runtime_get);
-	HIF_PCI_RUNTIME_PM_STATS(s, sc, runtime_put);
+	seq_printf(s, "%30s: %u\n", "runtime_get",
+		   qdf_atomic_read(&sc->pm_stats.runtime_get));
+	seq_printf(s, "%30s: %u\n", "runtime_put",
+		   qdf_atomic_read(&sc->pm_stats.runtime_put));
+	seq_printf(s, "%30s: %u\n", "runtime_get_caller_index",
+		   qdf_atomic_read(&sc->pm_stats.runtime_get_caller_index));
+	seq_printf(s, "%30s: %u\n", "runtime_put_caller_index",
+		   qdf_atomic_read(&sc->pm_stats.runtime_put_caller_index));
 	HIF_PCI_RUNTIME_PM_STATS(s, sc, request_resume);
-	HIF_PCI_RUNTIME_PM_STATS(s, sc, prevent_suspend);
-	HIF_PCI_RUNTIME_PM_STATS(s, sc, allow_suspend);
+	seq_printf(s, "%30s: %u\n", "prevent_suspend",
+		   qdf_atomic_read(&sc->pm_stats.prevent_suspend));
+	seq_printf(s, "%30s: %u\n", "allow_suspend",
+		   qdf_atomic_read(&sc->pm_stats.allow_suspend));
+
 	HIF_PCI_RUNTIME_PM_STATS(s, sc, prevent_suspend_timeout);
 	HIF_PCI_RUNTIME_PM_STATS(s, sc, allow_suspend_timeout);
 	HIF_PCI_RUNTIME_PM_STATS(s, sc, runtime_get_err);
@@ -1193,6 +1207,12 @@ static void hif_pm_runtime_open(struct hif_pci_softc *sc)
 	qdf_atomic_init(&sc->pm_state);
 	qdf_runtime_lock_init(&sc->prevent_linkdown_lock);
 	qdf_atomic_set(&sc->pm_state, HIF_PM_RUNTIME_STATE_NONE);
+	qdf_atomic_set(&sc->pm_stats.runtime_get, 0);
+	qdf_atomic_set(&sc->pm_stats.runtime_put, 0);
+	qdf_atomic_set(&sc->pm_stats.runtime_get_caller_index, 0);
+	qdf_atomic_set(&sc->pm_stats.runtime_put_caller_index, 0);
+	qdf_atomic_set(&sc->pm_stats.allow_suspend, 0);
+	qdf_atomic_set(&sc->pm_stats.prevent_suspend, 0);
 	INIT_LIST_HEAD(&sc->prevent_suspend_list);
 }
 
@@ -3963,7 +3983,7 @@ int hif_pm_runtime_get_sync(struct hif_opaque_softc *hif_ctx)
 		hif_info_high("Runtime PM resume is requested by %ps",
 			      (void *)_RET_IP_);
 
-	sc->pm_stats.runtime_get++;
+	HIF_PM_STATS_RUNTIME_GET_RECORD(sc);
 	ret = pm_runtime_get_sync(sc->dev);
 
 	/* Get can return 1 if the device is already active, just return
@@ -4018,7 +4038,7 @@ int hif_pm_runtime_put_sync_suspend(struct hif_opaque_softc *hif_ctx)
 		return -EINVAL;
 	}
 
-	sc->pm_stats.runtime_put++;
+	HIF_PM_STATS_RUNTIME_PUT_RECORD(sc);
 	return pm_runtime_put_sync_suspend(sc->dev);
 }
 
@@ -4068,7 +4088,7 @@ void hif_pm_runtime_get_noresume(struct hif_opaque_softc *hif_ctx)
 	if (!pm_runtime_enabled(sc->dev))
 		return;
 
-	sc->pm_stats.runtime_get++;
+	HIF_PM_STATS_RUNTIME_GET_RECORD(sc);
 	pm_runtime_get_noresume(sc->dev);
 }
 
@@ -4104,7 +4124,7 @@ int hif_pm_runtime_get(struct hif_opaque_softc *hif_ctx)
 
 	if (pm_state  == HIF_PM_RUNTIME_STATE_ON ||
 			pm_state == HIF_PM_RUNTIME_STATE_NONE) {
-		sc->pm_stats.runtime_get++;
+		HIF_PM_STATS_RUNTIME_GET_RECORD(sc);
 		ret = __hif_pm_runtime_get(sc->dev);
 
 		/* Get can return 1 if the device is already active, just return
@@ -4185,7 +4205,7 @@ int hif_pm_runtime_put(struct hif_opaque_softc *hif_ctx)
 		return -EINVAL;
 	}
 
-	sc->pm_stats.runtime_put++;
+	HIF_PM_STATS_RUNTIME_PUT_RECORD(sc);
 
 	hif_pm_runtime_mark_last_busy(hif_ctx);
 	hif_pm_runtime_put_auto(sc->dev);
@@ -4228,7 +4248,7 @@ int hif_pm_runtime_put_noidle(struct hif_opaque_softc *hif_ctx)
 		return -EINVAL;
 	}
 
-	sc->pm_stats.runtime_put++;
+	HIF_PM_STATS_RUNTIME_PUT_RECORD(sc);
 	pm_runtime_put_noidle(sc->dev);
 
 	return 0;
@@ -4281,7 +4301,7 @@ static int __hif_pm_runtime_prevent_suspend(struct hif_pci_softc
 
 	list_add_tail(&lock->list, &hif_sc->prevent_suspend_list);
 
-	hif_sc->pm_stats.prevent_suspend++;
+	qdf_atomic_inc(&hif_sc->pm_stats.prevent_suspend);
 
 	HIF_ERROR("%s: in pm_state:%s ret: %d", __func__,
 		hif_pm_runtime_state_to_string(
@@ -4336,7 +4356,7 @@ static int __hif_pm_runtime_allow_suspend(struct hif_pci_softc *hif_sc,
 			qdf_atomic_read(&hif_sc->pm_state)),
 					ret);
 
-	hif_sc->pm_stats.allow_suspend++;
+	qdf_atomic_inc(&hif_sc->pm_stats.allow_suspend);
 	return ret;
 }
 

hif/src/pcie/if_pci.h

@@ -74,6 +74,30 @@ enum hif_pm_runtime_state {
 
 #ifdef FEATURE_RUNTIME_PM
 
+#define PM_STATUS_RUNTIME_CALLER_MAX   128
+
+#define HIF_PM_STATS_RUNTIME_GET_RECORD(sc)  \
+{\
+	typeof(sc) sc_ = (sc); \
+	int32_t index = \
+		qdf_atomic_read(&sc_->pm_stats.runtime_get_caller_index) % \
+		PM_STATUS_RUNTIME_CALLER_MAX; \
+	sc_->pm_stats.runtime_get_caller[index] = (void *)_RET_IP_; \
+	qdf_atomic_inc(&sc_->pm_stats.runtime_get_caller_index); \
+	qdf_atomic_inc(&sc_->pm_stats.runtime_get); \
+}
+
+#define HIF_PM_STATS_RUNTIME_PUT_RECORD(sc)  \
+{\
+	typeof(sc) sc_ = (sc); \
+	int32_t index = \
+		qdf_atomic_read(&sc_->pm_stats.runtime_put_caller_index) % \
+		PM_STATUS_RUNTIME_CALLER_MAX; \
+	sc_->pm_stats.runtime_put_caller[index] = (void *)_RET_IP_; \
+	qdf_atomic_inc(&sc_->pm_stats.runtime_put_caller_index); \
+	qdf_atomic_inc(&sc_->pm_stats.runtime_put); \
+}
+
 /**
  * struct hif_pm_runtime_lock - data structure for preventing runtime suspend
  * @list - global list of runtime locks
@@ -92,11 +116,15 @@ struct hif_pci_pm_stats {
 	u32 suspended;
 	u32 suspend_err;
 	u32 resumed;
-	u32 runtime_get;
-	u32 runtime_put;
+	atomic_t runtime_get;
+	atomic_t runtime_put;
+	atomic_t runtime_get_caller_index;
+	atomic_t runtime_put_caller_index;
+	void *runtime_get_caller[PM_STATUS_RUNTIME_CALLER_MAX];
+	void *runtime_put_caller[PM_STATUS_RUNTIME_CALLER_MAX];
 	u32 request_resume;
-	u32 allow_suspend;
-	u32 prevent_suspend;
+	atomic_t allow_suspend;
+	atomic_t prevent_suspend;
 	u32 prevent_suspend_timeout;
 	u32 allow_suspend_timeout;
 	u32 runtime_get_err;