clusteridle: psci: Tracing and debuggingcpuidle_psci_v4_debug

Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>

4 files changed, 39 insertions, 9 deletions

diff --git a/drivers/base/power/domain.c b/drivers/base/power/domain.c
index 8e5725b11ee8..6293d4933f11 100644
--- a/drivers/base/power/domain.c
+++ b/drivers/base/power/domain.c
@@ -536,8 +536,10 @@ static int genpd_power_off(struct generic_pm_domain *genpd, bool one_dev_on,
 		return -EBUSY;
 
 	if (genpd->gov && genpd->gov->power_down_ok) {
-		if (!genpd->gov->power_down_ok(&genpd->domain))
+		if (!genpd->gov->power_down_ok(&genpd->domain)) {
+			trace_printk("power off prevented for %s\n", genpd->name);
 			return -EAGAIN;
+		}
 	}
 
 	/* Default to shallowest state. */
@@ -773,8 +775,10 @@ static int genpd_runtime_suspend(struct device *dev)
 	 * validating/measuring the PM QoS latency.
 	 */
 	suspend_ok = genpd->gov ? genpd->gov->suspend_ok : NULL;
-	if (runtime_pm && suspend_ok && !suspend_ok(dev))
+	if (runtime_pm && suspend_ok && !suspend_ok(dev)) {
+		trace_printk("%s: suspend prevented for dev\n", dev_name(dev));
 		return -EBUSY;
+	}
 
 	/* Measure suspend latency. */
 	time_start = 0;
@@ -796,8 +800,8 @@ static int genpd_runtime_suspend(struct device *dev)
 		elapsed_ns = ktime_to_ns(ktime_sub(ktime_get(), time_start));
 		if (elapsed_ns > td->suspend_latency_ns) {
 			td->suspend_latency_ns = elapsed_ns;
-			dev_dbg(dev, "suspend latency exceeded, %lld ns\n",
-				elapsed_ns);
+			trace_printk("%s: suspend latency exceeded, %lld ns\n",
+				     dev_name(dev), elapsed_ns);
 			genpd->max_off_time_changed = true;
 			td->constraint_changed = true;
 		}
@@ -876,8 +880,8 @@ static int genpd_runtime_resume(struct device *dev)
 		elapsed_ns = ktime_to_ns(ktime_sub(ktime_get(), time_start));
 		if (elapsed_ns > td->resume_latency_ns) {
 			td->resume_latency_ns = elapsed_ns;
-			dev_dbg(dev, "resume latency exceeded, %lld ns\n",
-				elapsed_ns);
+			trace_printk("%s: resume latency exceeded, %lld ns\n",
+				     dev_name(dev), elapsed_ns);
 			genpd->max_off_time_changed = true;
 			td->constraint_changed = true;
 		}
diff --git a/drivers/base/power/domain_governor.c b/drivers/base/power/domain_governor.c
index daa8c7689f7e..beca4911f1e4 100644
--- a/drivers/base/power/domain_governor.c
+++ b/drivers/base/power/domain_governor.c
@@ -258,8 +258,10 @@ static bool cpu_power_down_ok(struct dev_pm_domain *pd)
 	int cpu, i;
 
 	/* Validate dev PM QoS constraints. */
-	if (!default_power_down_ok(pd))
+	if (!default_power_down_ok(pd)) {
+		trace_printk("prevented off becuase dev PM QoS %s\n", genpd->name);
 		return false;
+	}
 
 	if (!(genpd->flags & GENPD_FLAG_CPU_DOMAIN))
 		return true;
@@ -298,6 +300,9 @@ static bool cpu_power_down_ok(struct dev_pm_domain *pd)
 		}
 	} while (--i >= 0);
 
+	trace_printk("residency not satisfied: duration_ns=%lld name=%s\n",
+		idle_duration_ns, genpd->name);
+
 	return false;
 }
 
diff --git a/drivers/cpuidle/cpuidle-psci-domain.c b/drivers/cpuidle/cpuidle-psci-domain.c
index c2f94ba42222..fa56f2442525 100644
--- a/drivers/cpuidle/cpuidle-psci-domain.c
+++ b/drivers/cpuidle/cpuidle-psci-domain.c
@@ -37,13 +37,17 @@ static int psci_pd_power_off(struct generic_pm_domain *pd)
 	if (!osi_mode_enabled)
 		return -EBUSY;
 
-	if (!state->data)
+	if (!state->data) {
+		trace_printk("cpu=%d nostate\n", smp_processor_id());
 		return 0;
+	}
 
 	/* OSI mode is enabled, set the corresponding domain state. */
 	pd_state = state->data;
 	psci_set_domain_state(*pd_state);
 
+	trace_printk("cpu=%d state=%#x\n", smp_processor_id(), *pd_state);
+
 	return 0;
 }
 
@@ -294,5 +298,6 @@ struct device *psci_dt_attach_cpu(int cpu)
 	if (cpu_online(cpu))
 		pm_runtime_get_sync(dev);
 
+	pr_info("Attached CPU%d to PM domain\n", cpu);
 	return dev;
 }
diff --git a/drivers/cpuidle/cpuidle-psci.c b/drivers/cpuidle/cpuidle-psci.c
index 70141090a298..bfd8c0d416cb 100644
--- a/drivers/cpuidle/cpuidle-psci.c
+++ b/drivers/cpuidle/cpuidle-psci.c
@@ -65,7 +65,9 @@ static int psci_enter_domain_idle_state(struct cpuidle_device *dev,
 	if (!state)
 		state = states[idx];
 
+	trace_printk("ENTER cpu=%d idx=%d state=%#x\n", smp_processor_id(), idx, state);
 	ret = psci_enter_state(idx, state);
+	trace_printk("EXIT cpu=%d idx=%d state=%#x ret=%d\n", smp_processor_id(), idx, state, ret);
 
 	pm_runtime_get_sync(pd_dev);
 
@@ -77,6 +79,13 @@ static int psci_enter_domain_idle_state(struct cpuidle_device *dev,
 static int psci_idle_cpuhp_up(unsigned int cpu)
 {
 	struct device *pd_dev = __this_cpu_read(psci_cpuidle_data.dev);
+	int cpuid;
+
+	trace_printk("cpu=%u this_cpu=%d %s\n", cpu, smp_processor_id(),
+		preempt_count() > 0 ? "PREEMPT DISABLED" : "PREEMPT ENABLED");
+
+	for_each_online_cpu(cpuid)
+		trace_printk("online cpu=%d\n", cpuid);
 
 	if (pd_dev)
 		pm_runtime_get_sync(pd_dev);
@@ -87,6 +96,13 @@ static int psci_idle_cpuhp_up(unsigned int cpu)
 static int psci_idle_cpuhp_down(unsigned int cpu)
 {
 	struct device *pd_dev = __this_cpu_read(psci_cpuidle_data.dev);
+	int cpuid;
+
+	trace_printk("cpu=%u this_cpu=%d %s\n", cpu, smp_processor_id(),
+		preempt_count() > 0 ? "PREEMPT DISABLED" : "PREEMPT ENABLED");
+
+	for_each_online_cpu(cpuid)
+		trace_printk("online cpu=%d\n", cpuid);
 
 	if (pd_dev) {
 		pm_runtime_put_sync(pd_dev);
@@ -185,7 +201,7 @@ static int __init psci_dt_cpu_init_idle(struct cpuidle_driver *drv,
 		if (ret)
 			goto free_mem;
 
-		pr_debug("psci-power-state %#x index %d\n", psci_states[i], i);
+		pr_warn("psci-power-state %#x index %d\n", psci_states[i], i);
 	}
 
 	if (i != state_count) {