PM: Add initcall_debug style timing for suspend/resume

In order to diagnose overall suspend/resume times, we need
basic instrumentation to break down the total time into per
device timing, similar to initcall_debug.

This patch adds the basic timing instrumentation, needed
for a scritps/bootgraph.pl equivalent or humans.
The bootgraph.pl program is still a work in progress, but
is far enough along to know that this patch is sufficient.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 8aa2443182d517ddec760d594f8781029a3e9fe5..30f0ceebd36c3ec32b4e48022dca9ec2fddb76aa 100644 (file)
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -25,6 +25,7 @@
 #include <linux/resume-trace.h>
 #include <linux/rwsem.h>
 #include <linux/interrupt.h>
+#include <linux/sched.h>
 
 #include "../base.h"
 #include "power.h"
@@ -172,6 +173,13 @@ static int pm_op(struct device *dev,
                 pm_message_t state)
 {
        int error = 0;
+       ktime_t calltime, delta, rettime;
+
+       if (initcall_debug) {
+               pr_info("calling  %s+ @ %i\n",
+                               dev_name(dev), task_pid_nr(current));
+               calltime = ktime_get();
+       }
 
        switch (state.event) {
 #ifdef CONFIG_SUSPEND
@@ -219,6 +227,14 @@ static int pm_op(struct device *dev,
        default:
                error = -EINVAL;
        }
+
+       if (initcall_debug) {
+               rettime = ktime_get();
+               delta = ktime_sub(rettime, calltime);
+               pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
+                       error, (unsigned long long)ktime_to_ns(delta) >> 10);
+       }
+
        return error;
 }
 
@@ -236,6 +252,13 @@ static int pm_noirq_op(struct device *dev,
                        pm_message_t state)
 {
        int error = 0;
+       ktime_t calltime, delta, rettime;
+
+       if (initcall_debug) {
+               pr_info("calling  %s_i+ @ %i\n",
+                               dev_name(dev), task_pid_nr(current));
+               calltime = ktime_get();
+       }
 
        switch (state.event) {
 #ifdef CONFIG_SUSPEND
@@ -283,6 +306,14 @@ static int pm_noirq_op(struct device *dev,
        default:
                error = -EINVAL;
        }
+
+       if (initcall_debug) {
+               rettime = ktime_get();
+               delta = ktime_sub(rettime, calltime);
+               printk("initcall %s_i+ returned %d after %Ld usecs\n", dev_name(dev),
+                       error, (unsigned long long)ktime_to_ns(delta) >> 10);
+       }
+
        return error;
 }
 

diff --git a/include/linux/init.h b/include/linux/init.h
index ff8bde520d03b078c5e343dd9437f005fe915fa2..ab1d31f9352bbcefb46369667c145c3615b29a2c 100644 (file)
--- a/include/linux/init.h
+++ b/include/linux/init.h
@@ -149,6 +149,8 @@ void prepare_namespace(void);
 
 extern void (*late_time_init)(void);
 
+extern int initcall_debug;
+
 #endif
   
 #ifndef MODULE