1 files changed, 106 insertions, 22 deletions

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 1a216c114a0f..48adf80926a0 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -161,6 +161,32 @@ void device_pm_move_last(struct device *dev)
         list_move_tail(&dev->power.entry, &dpm_list);
 }
 
+static ktime_t initcall_debug_start(struct device *dev)
+{
+        ktime_t calltime = ktime_set(0, 0);
+
+        if (initcall_debug) {
+                pr_info("calling  %s+ @ %i\n",
+                                dev_name(dev), task_pid_nr(current));
+                calltime = ktime_get();
+        }
+
+        return calltime;
+}
+
+static void initcall_debug_report(struct device *dev, ktime_t calltime,
+                                  int error)
+{
+        ktime_t delta, rettime;
+
+        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);
+        }
+}
+
 /**
  * pm_op - Execute the PM operation appropriate for given PM event.
  * @dev: Device to handle.
@@ -172,13 +198,9 @@ static int pm_op(struct device *dev,
                  pm_message_t state)
 {
         int error = 0;
-        ktime_t calltime, delta, rettime;
+        ktime_t calltime;
 
-        if (initcall_debug) {
-                pr_info("calling  %s+ @ %i\n",
-                                dev_name(dev), task_pid_nr(current));
-                calltime = ktime_get();
-        }
+        calltime = initcall_debug_start(dev);
 
         switch (state.event) {
 #ifdef CONFIG_SUSPEND
@@ -227,12 +249,7 @@ static int pm_op(struct device *dev,
                 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);
-        }
+        initcall_debug_report(dev, calltime, error);
 
         return error;
 }
@@ -309,8 +326,9 @@ static int pm_noirq_op(struct device *dev,
         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);
+                printk("initcall %s_i+ returned %d after %Ld usecs\n",
+                        dev_name(dev), error,
+                        (unsigned long long)ktime_to_ns(delta) >> 10);
         }
 
         return error;
@@ -354,6 +372,23 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info,
                 kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+static void dpm_show_time(ktime_t starttime, pm_message_t state, char *info)
+{
+        ktime_t calltime;
+        s64 usecs64;
+        int usecs;
+
+        calltime = ktime_get();
+        usecs64 = ktime_to_ns(ktime_sub(calltime, starttime));
+        do_div(usecs64, NSEC_PER_USEC);
+        usecs = usecs64;
+        if (usecs == 0)
+                usecs = 1;
+        pr_info("PM: %s%s%s of devices complete after %ld.%03ld msecs\n",
+                info ?: "", info ? " " : "", pm_verb(state.event),
+                usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
+}
+
 /*------------------------- Resume routines -------------------------*/
 
 /**
@@ -390,6 +425,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state)
 void dpm_resume_noirq(pm_message_t state)
 {
         struct device *dev;
+        ktime_t starttime = ktime_get();
 
         mutex_lock(&dpm_list_mtx);
         transition_started = false;
@@ -403,11 +439,32 @@ void dpm_resume_noirq(pm_message_t state)
                                 pm_dev_err(dev, state, " early", error);
                 }
         mutex_unlock(&dpm_list_mtx);
+        dpm_show_time(starttime, state, "early");
         resume_device_irqs();
 }
 EXPORT_SYMBOL_GPL(dpm_resume_noirq);
 
 /**
+ * legacy_resume - Execute a legacy (bus or class) resume callback for device.
+ * dev: Device to resume.
+ * cb: Resume callback to execute.
+ */
+static int legacy_resume(struct device *dev, int (*cb)(struct device *dev))
+{
+        int error;
+        ktime_t calltime;
+
+        calltime = initcall_debug_start(dev);
+
+        error = cb(dev);
+        suspend_report_result(cb, error);
+
+        initcall_debug_report(dev, calltime, error);
+
+        return error;
+}
+
+/**
  * device_resume - Execute "resume" callbacks for given device.
  * @dev: Device to handle.
  * @state: PM transition of the system being carried out.
@@ -427,7 +484,7 @@ static int device_resume(struct device *dev, pm_message_t state)
                         error = pm_op(dev, dev->bus->pm, state);
                 } else if (dev->bus->resume) {
                         pm_dev_dbg(dev, state, "legacy ");
-                        error = dev->bus->resume(dev);
+                        error = legacy_resume(dev, dev->bus->resume);
                 }
                 if (error)
                         goto End;
@@ -448,7 +505,7 @@ static int device_resume(struct device *dev, pm_message_t state)
                         error = pm_op(dev, dev->class->pm, state);
                 } else if (dev->class->resume) {
                         pm_dev_dbg(dev, state, "legacy class ");
-                        error = dev->class->resume(dev);
+                        error = legacy_resume(dev, dev->class->resume);
                 }
         }
  End:
@@ -468,6 +525,7 @@ static int device_resume(struct device *dev, pm_message_t state)
 static void dpm_resume(pm_message_t state)
 {
         struct list_head list;
+        ktime_t starttime = ktime_get();
 
         INIT_LIST_HEAD(&list);
         mutex_lock(&dpm_list_mtx);
@@ -496,6 +554,7 @@ static void dpm_resume(pm_message_t state)
         }
         list_splice(&list, &dpm_list);
         mutex_unlock(&dpm_list_mtx);
+        dpm_show_time(starttime, state, NULL);
 }
 
 /**
@@ -548,7 +607,7 @@ static void dpm_complete(pm_message_t state)
                         mutex_unlock(&dpm_list_mtx);
 
                         device_complete(dev, state);
-                        pm_runtime_put_noidle(dev);
+                        pm_runtime_put_sync(dev);
 
                         mutex_lock(&dpm_list_mtx);
                 }
@@ -628,6 +687,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state)
 int dpm_suspend_noirq(pm_message_t state)
 {
         struct device *dev;
+        ktime_t starttime = ktime_get();
         int error = 0;
 
         suspend_device_irqs();
@@ -643,11 +703,34 @@ int dpm_suspend_noirq(pm_message_t state)
         mutex_unlock(&dpm_list_mtx);
         if (error)
                 dpm_resume_noirq(resume_event(state));
+        else
+                dpm_show_time(starttime, state, "late");
         return error;
 }
 EXPORT_SYMBOL_GPL(dpm_suspend_noirq);
 
 /**
+ * legacy_suspend - Execute a legacy (bus or class) suspend callback for device.
+ * dev: Device to suspend.
+ * cb: Suspend callback to execute.
+ */
+static int legacy_suspend(struct device *dev, pm_message_t state,
+                          int (*cb)(struct device *dev, pm_message_t state))
+{
+        int error;
+        ktime_t calltime;
+
+        calltime = initcall_debug_start(dev);
+
+        error = cb(dev, state);
+        suspend_report_result(cb, error);
+
+        initcall_debug_report(dev, calltime, error);
+
+        return error;
+}
+
+/**
  * device_suspend - Execute "suspend" callbacks for given device.
  * @dev: Device to handle.
  * @state: PM transition of the system being carried out.
@@ -664,8 +747,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
                         error = pm_op(dev, dev->class->pm, state);
                 } else if (dev->class->suspend) {
                         pm_dev_dbg(dev, state, "legacy class ");
-                        error = dev->class->suspend(dev, state);
-                        suspend_report_result(dev->class->suspend, error);
+                        error = legacy_suspend(dev, state, dev->class->suspend);
                 }
                 if (error)
                         goto End;
@@ -686,8 +768,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
                         error = pm_op(dev, dev->bus->pm, state);
                 } else if (dev->bus->suspend) {
                         pm_dev_dbg(dev, state, "legacy ");
-                        error = dev->bus->suspend(dev, state);
-                        suspend_report_result(dev->bus->suspend, error);
+                        error = legacy_suspend(dev, state, dev->bus->suspend);
                 }
         }
  End:
@@ -703,6 +784,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
 static int dpm_suspend(pm_message_t state)
 {
         struct list_head list;
+        ktime_t starttime = ktime_get();
         int error = 0;
 
         INIT_LIST_HEAD(&list);
@@ -728,6 +810,8 @@ static int dpm_suspend(pm_message_t state)
         }
         list_splice(&list, dpm_list.prev);
         mutex_unlock(&dpm_list_mtx);
+        if (!error)
+                dpm_show_time(starttime, state, NULL);
         return error;
 }
 
@@ -796,7 +880,7 @@ static int dpm_prepare(pm_message_t state)
                 pm_runtime_get_noresume(dev);
                 if (pm_runtime_barrier(dev) && device_may_wakeup(dev)) {
                         /* Wake-up requested during system sleep transition. */
-                        pm_runtime_put_noidle(dev);
+                        pm_runtime_put_sync(dev);
                         error = -EBUSY;
                 } else {
                         error = device_prepare(dev, state);