From 245e73ca7d86497a33222d47b1298c3dc0f78f3f Mon Sep 17 00:00:00 2001 From: Ulf Hansson Date: Thu, 10 Oct 2019 12:01:48 +0200 Subject: clusteridle: psci: Tracing and debugging Signed-off-by: Ulf Hansson --- drivers/base/power/domain.c | 16 ++++++++++------ drivers/base/power/domain_governor.c | 7 ++++++- drivers/cpuidle/cpuidle-psci-domain.c | 7 ++++++- drivers/cpuidle/cpuidle-psci.c | 18 +++++++++++++++++- 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) { -- cgit v1.2.3