[RFC][PATCH 0/2] Minor Suspend debugging patches from Android

[RFC][PATCH 0/2] Minor Suspend debugging patches from Android

[Amit Pundir]

Couple of PM patches from Android tree printing Suspend debug messages.
These messages are used to help debug PM related issues on Android based
devices and look useful enough to troubleshoot PM issues on generic Linux
devices as well.

I'd greatly appreciate any feedback or comments!

Todd Poynor (2):
  PM: Print pending wakeup IRQ preventing suspend to dmesg
  PM: Suspend: Print wall time at suspend entry and exit

 kernel/irq/pm.c        |    7 ++++++-
 kernel/power/suspend.c |   15 +++++++++++++++
 2 files changed, 21 insertions(+), 1 deletion(-)

Cc: Todd Poynor <toddpoynor@google.com>
Cc: Pavel Machek <pavel@ucw.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: "Rafael J. Wysocki" <rjw@rjwysocki.net>
Cc: Len Brown <len.brown@intel.com>
Cc: linux-pm@vger.kernel.org
Cc: Android Kernel Team <kernel-team@android.com>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Sumit Semwal <sumit.semwal@linaro.org>
-- 
1.7.10.4

[RFC][PATCH 1/2] PM: Print pending wakeup IRQ preventing suspend to dmesg

[Amit Pundir]

From: Todd Poynor <toddpoynor@google.com>

Currently when a pending wakeup irq stops suspend, it can be difficult
to determine why suspend was prevented and which IRQ was actually
responsible.

In order to help debug these situations, this patch prints the IRQ
number and action name of that pending wakeup irq which prevents suspend.
This patch comes from the Android patch set, where its been used to debug
suspend problems.

Cc: Pavel Machek <pavel@ucw.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Rafael J. Wysocki <rjw@rjwysocki.net>
Cc: Len Brown <len.brown@intel.com>
Cc: linux-pm@vger.kernel.org
Cc: Android Kernel Team <kernel-team@android.com>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Sumit Semwal <sumit.semwal@linaro.org>
Signed-off-by: Todd Poynor <toddpoynor@google.com>
[Amit Pundir: Reworded the commit message]
Signed-off-by: Amit Pundir <amit.pundir@linaro.org>
---
 kernel/irq/pm.c |    7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/kernel/irq/pm.c b/kernel/irq/pm.c
index abcd6ca..c2bc8d9 100644
--- a/kernel/irq/pm.c
+++ b/kernel/irq/pm.c
@@ -109,8 +109,13 @@ int check_wakeup_irqs(void)
 		 * can abort suspend.
 		 */
 		if (irqd_is_wakeup_set(&desc->irq_data)) {
-			if (desc->depth == 1 && desc->istate & IRQS_PENDING)
+			if (desc->depth == 1 && desc->istate & IRQS_PENDING) {
+				pr_info("Wakeup IRQ %d %s pending, suspend aborted\n",
+					irq,
+					desc->action && desc->action->name ?
+					desc->action->name : "");
 				return -EBUSY;
+			}
 			continue;
 		}
 		/*
-- 
1.7.10.4

[RFC][PATCH 2/2] PM: Suspend: Print wall time at suspend entry and exit

[Amit Pundir]

From: Todd Poynor <toddpoynor@google.com>

Existing printk timestamps in a dmesg only log suspend activities
(e.g. filesystem syncs, freezing/unfreezing tasks etc) while the
system has already started to enter/exit the suspend state. Sometimes
it is handy to have suspend entry/exit overhead information while
debugging suspend issues. This patch print markers with wall
timestamps at suspend Entry and Exit in the kernel log. These
timestamps can be used to compute how long the system spent in
low-power suspend state plus the entry/exit overhead.

This patch comes from the Android patch set, where its been used to
help diagnose battery life problems in various Android-based devices.

Cc: Pavel Machek <pavel@ucw.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Rafael J. Wysocki <rjw@rjwysocki.net>
Cc: Len Brown <len.brown@intel.com>
Cc: linux-pm@vger.kernel.org
Cc: Android Kernel Team <kernel-team@android.com>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Sumit Semwal <sumit.semwal@linaro.org>
Signed-off-by: Todd Poynor <toddpoynor@google.com>
[Amit Pundir: Reworded the commit message]
Signed-off-by: Amit Pundir <amit.pundir@linaro.org>
---

The original patch was submitted to linux-pm couple of years back but
I could not trace any feedback or activity thereafter. Hence I'm
resubmitting this change.

 kernel/power/suspend.c |   15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index ed35a47..28726b6 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -26,6 +26,7 @@
 #include <linux/suspend.h>
 #include <linux/syscore_ops.h>
 #include <linux/ftrace.h>
+#include <linux/rtc.h>
 #include <trace/events/power.h>
 #include <linux/compiler.h>
 
@@ -417,6 +418,18 @@ static int enter_state(suspend_state_t state)
 	return error;
 }
 
+static void pm_suspend_marker(char *annotation)
+{
+	struct timespec ts;
+	struct rtc_time tm;
+
+	getnstimeofday(&ts);
+	rtc_time_to_tm(ts.tv_sec, &tm);
+	pr_info("PM: suspend %s %d-%02d-%02d %02d:%02d:%02d.%09lu UTC\n",
+		annotation, tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+		tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec);
+}
+
 /**
  * pm_suspend - Externally visible function for suspending the system.
  * @state: System sleep state to enter.
@@ -431,6 +444,7 @@ int pm_suspend(suspend_state_t state)
 	if (state <= PM_SUSPEND_ON || state >= PM_SUSPEND_MAX)
 		return -EINVAL;
 
+	pm_suspend_marker("entry");
 	error = enter_state(state);
 	if (error) {
 		suspend_stats.fail++;
@@ -438,6 +452,7 @@ int pm_suspend(suspend_state_t state)
 	} else {
 		suspend_stats.success++;
 	}
+	pm_suspend_marker("exit");
 	return error;
 }
 EXPORT_SYMBOL(pm_suspend);
-- 
1.7.10.4

Re: [RFC][PATCH 2/2] PM: Suspend: Print wall time at suspend entry and exit

[Todd Poynor]

> Existing printk timestamps in a dmesg only log suspend activities
> (e.g. filesystem syncs, freezing/unfreezing tasks etc) while the
> system has already started to enter/exit the suspend state. Sometimes
> it is handy to have suspend entry/exit overhead information while
> debugging suspend issues. This patch print markers with wall
> timestamps at suspend Entry and Exit in the kernel log. These
> timestamps can be used to compute how long the system spent in
> low-power suspend state plus the entry/exit overhead.
>
> This patch comes from the Android patch set, where its been used to
> help diagnose battery life problems in various Android-based devices.

Thanks Amit.  For this patch, we're actually moving away from
primarily analyzing the kernel log of suspend times, instead logging
this info via userspace.  Android is now using the wakeup_count
suspend interface (previously autosleep was employed), allowing
userspace to be informed whenever suspend is entered and resumed.  The
Android batterystats service logs timestamps for these, along with the
wakeup reason info previously discussed on the linux-pm list.  But it
still is occasionally useful to see the suspend times when debugging
problems based on the kernel log.


Todd

Re: [RFC][PATCH 1/2] PM: Print pending wakeup IRQ preventing suspend to dmesg

[Todd Poynor]

On Fri, Aug 1, 2014 at 9:30 AM, Amit Pundir <amit.pundir@linaro.org> wrote:
> From: Todd Poynor <toddpoynor@google.com>
>
> Currently when a pending wakeup irq stops suspend, it can be difficult
> to determine why suspend was prevented and which IRQ was actually
> responsible.
>
> In order to help debug these situations, this patch prints the IRQ
> number and action name of that pending wakeup irq which prevents suspend.
> This patch comes from the Android patch set, where its been used to debug
> suspend problems.

This info is sometimes useful to debugging Android suspend / battery
life problems, such as to detect a driver that is failing to service
or clear a wakeup interrupt condition.

In general, we intend to fold reporting of suspend abort reasons
(wakeup IRQ pending, wakelock grabbed, task refusing to freeze...)
into the wakeup reason reporting API to userspace previously discussed
on the linux-pm list (and also revive discussion of how to rework that
for mainline acceptance soon).

Thanks,


Todd

Re: [RFC][PATCH 1/2] PM: Print pending wakeup IRQ preventing suspend to dmesg

[Pavel Machek]

On Fri 2014-08-01 22:00:48, Amit Pundir wrote:
> From: Todd Poynor <toddpoynor@google.com>
> 
> Currently when a pending wakeup irq stops suspend, it can be difficult
> to determine why suspend was prevented and which IRQ was actually
> responsible.
> 
> In order to help debug these situations, this patch prints the IRQ
> number and action name of that pending wakeup irq which prevents suspend.
> This patch comes from the Android patch set, where its been used to debug
> suspend problems.
> 

Acked-by: Pavel Machek <pavel@ucw.cz>

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html