| Message ID | alpine.DEB.2.00.1001241900310.27200@hungry |
|---|---|
| State | Rejected |
| Delegated to: | Andy Whitcroft |
| Headers | show |
On Sun, Jan 24, 2010 at 07:05:53PM -0600, Manoj Iyer wrote: > > The following patch from Rafael measures the suspend/resume times of > devices. It logs the total suspend/resume times of devices as follows: > > [ 62.820296] PM: suspend of devices complete after 2108.836 msecs > [ 62.820300] PM: suspend devices took 2.110 seconds > [ 62.860107] PM: late suspend of devices complete after 39.801 msecs > [ 63.440105] PM: early resume of devices complete after 20.013 msecs > [ 67.337821] PM: resume of devices complete after 3887.665 msecs > [ 67.338078] PM: resume devices took 3.890 seconds > [ 67.338117] PM: Finishing wakeup. How does this help us above and beyond the counts we already have? In karmic and lucid we already get these: [55841.240147] PM: suspend devices took 1.500 seconds [55845.696481] PM: resume devices took 3.850 seconds It looks to my eye all I am getting from this patch is the late suspend and early resume numbers? Are these useful enough to warrent patching? What do they represent? Convince me :) -apw
Maybe I'm missing something, but it would be even more useful to get the resume time of each device so that we can see where resume bottlenecks are occurring. I'd like to know which device is causing the hangs. Colin On Sun, 2010-01-24 at 19:05 -0600, Manoj Iyer wrote: > The following patch from Rafael measures the suspend/resume times of > devices. It logs the total suspend/resume times of devices as follows: > > [ 62.820296] PM: suspend of devices complete after 2108.836 msecs > [ 62.820300] PM: suspend devices took 2.110 seconds > [ 62.860107] PM: late suspend of devices complete after 39.801 msecs > [ 63.440105] PM: early resume of devices complete after 20.013 msecs > [ 67.337821] PM: resume of devices complete after 3887.665 msecs > [ 67.338078] PM: resume devices took 3.890 seconds > [ 67.338117] PM: Finishing wakeup. > > > The following changes since commit > 8275e80fb72b97750d338c905ed7575df8967b95: > Rafael J. Wysocki (1): > PM: Measure device suspend and resume times > > are available in the git repository at: > > > ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git > suspendresume > > From 8275e80fb72b97750d338c905ed7575df8967b95 Mon Sep 17 00:00:00 2001 > From: Rafael J. Wysocki <rjw@sisk.pl> > Date: Fri, 18 Dec 2009 01:57:47 +0100 > Subject: [PATCH] PM: Measure device suspend and resume times > > Measure and print the time of suspending and resuming all devices. > > Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl> > (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899) > > Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> > --- > drivers/base/power/main.c | 27 +++++++++++++++++++++++++++ > 1 files changed, 27 insertions(+), 0 deletions(-) > > diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c > index 8aa2443..d72d4b3 100644 > --- a/drivers/base/power/main.c > +++ b/drivers/base/power/main.c > @@ -324,6 +324,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 -------------------------*/ > > /** > @@ -363,6 +380,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; > @@ -376,6 +394,7 @@ 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); > @@ -441,6 +460,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); > @@ -469,6 +489,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); > } > > /** > @@ -604,6 +625,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(); > @@ -619,6 +641,8 @@ 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); > @@ -679,6 +703,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); > @@ -704,6 +729,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; > } > > -- > 1.6.3.3 > > > > Cheers > --- manjo >
On 10 Jan 24, Manoy Iyer wrote: > > The following patch from Rafael measures the suspend/resume times of > devices. It logs the total suspend/resume times of devices as follows: > > [ 62.820296] PM: suspend of devices complete after 2108.836 msecs > [ 62.820300] PM: suspend devices took 2.110 seconds > [ 62.860107] PM: late suspend of devices complete after 39.801 msecs > [ 63.440105] PM: early resume of devices complete after 20.013 msecs > [ 67.337821] PM: resume of devices complete after 3887.665 msecs > [ 67.338078] PM: resume devices took 3.890 seconds > [ 67.338117] PM: Finishing wakeup. > > > The following changes since commit > 8275e80fb72b97750d338c905ed7575df8967b95: > Rafael J. Wysocki (1): > PM: Measure device suspend and resume times > > are available in the git repository at: > > > ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git > suspendresume > > From 8275e80fb72b97750d338c905ed7575df8967b95 Mon Sep 17 00:00:00 2001 > From: Rafael J. Wysocki <rjw@sisk.pl> > Date: Fri, 18 Dec 2009 01:57:47 +0100 > Subject: [PATCH] PM: Measure device suspend and resume times > > Measure and print the time of suspending and resuming all devices. > > Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl> > (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899) > > Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> > --- > drivers/base/power/main.c | 27 +++++++++++++++++++++++++++ > 1 files changed, 27 insertions(+), 0 deletions(-) > > diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c > index 8aa2443..d72d4b3 100644 > --- a/drivers/base/power/main.c > +++ b/drivers/base/power/main.c > @@ -324,6 +324,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 -------------------------*/ > > /** > @@ -363,6 +380,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; > @@ -376,6 +394,7 @@ 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); > @@ -441,6 +460,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); > @@ -469,6 +489,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); > } > > /** > @@ -604,6 +625,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(); > @@ -619,6 +641,8 @@ 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); > @@ -679,6 +703,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); > @@ -704,6 +729,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; > } > > -- > 1.6.3.3 > > > > Cheers > --- manjo It seems to me that this patch enables the extra logging unconditionally. Is that true? Or does it require PM_DEBUG to be enabled? /Amit
Yes, I do have a patch for that, but I not sure we want to have that in Lucid kernel as it populates dmesg with a ton of info. Cheers --- manjo On Mon, 25 Jan 2010, Colin Ian King wrote: > Maybe I'm missing something, but it would be even more useful to get the > resume time of each device so that we can see where resume bottlenecks > are occurring. I'd like to know which device is causing the hangs. > > Colin > > On Sun, 2010-01-24 at 19:05 -0600, Manoj Iyer wrote: >> The following patch from Rafael measures the suspend/resume times of >> devices. It logs the total suspend/resume times of devices as follows: >> >> [ 62.820296] PM: suspend of devices complete after 2108.836 msecs >> [ 62.820300] PM: suspend devices took 2.110 seconds >> [ 62.860107] PM: late suspend of devices complete after 39.801 msecs >> [ 63.440105] PM: early resume of devices complete after 20.013 msecs >> [ 67.337821] PM: resume of devices complete after 3887.665 msecs >> [ 67.338078] PM: resume devices took 3.890 seconds >> [ 67.338117] PM: Finishing wakeup. >> >> >> The following changes since commit >> 8275e80fb72b97750d338c905ed7575df8967b95: >> Rafael J. Wysocki (1): >> PM: Measure device suspend and resume times >> >> are available in the git repository at: >> >> >> ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git >> suspendresume >> >> From 8275e80fb72b97750d338c905ed7575df8967b95 Mon Sep 17 00:00:00 2001 >> From: Rafael J. Wysocki <rjw@sisk.pl> >> Date: Fri, 18 Dec 2009 01:57:47 +0100 >> Subject: [PATCH] PM: Measure device suspend and resume times >> >> Measure and print the time of suspending and resuming all devices. >> >> Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl> >> (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899) >> >> Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> >> --- >> drivers/base/power/main.c | 27 +++++++++++++++++++++++++++ >> 1 files changed, 27 insertions(+), 0 deletions(-) >> >> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c >> index 8aa2443..d72d4b3 100644 >> --- a/drivers/base/power/main.c >> +++ b/drivers/base/power/main.c >> @@ -324,6 +324,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 -------------------------*/ >> >> /** >> @@ -363,6 +380,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; >> @@ -376,6 +394,7 @@ 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); >> @@ -441,6 +460,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); >> @@ -469,6 +489,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); >> } >> >> /** >> @@ -604,6 +625,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(); >> @@ -619,6 +641,8 @@ 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); >> @@ -679,6 +703,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); >> @@ -704,6 +729,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; >> } >> >> -- >> 1.6.3.3 >> >> >> >> Cheers >> --- manjo >> > > >
Hi Manjom > Yes, I do have a patch for that, but I not sure we want to have that in > Lucid kernel as it populates dmesg with a ton of info. Perhaps we could do this with tracepoints, which should have very little overhead (and not pollute dmesg) when we're not tracing. Do you want me to put a patch together? Cheers, Jeremy
Jeremy, There is a generate_resume_trace() in trace.c under drivers/base/power/trace.c, but it did not look like it generated what I was looking for. Cheers --- manjo On Wed, 27 Jan 2010, Jeremy Kerr wrote: > Hi Manjom > >> Yes, I do have a patch for that, but I not sure we want to have that in >> Lucid kernel as it populates dmesg with a ton of info. > > Perhaps we could do this with tracepoints, which should have very little > overhead (and not pollute dmesg) when we're not tracing. > > Do you want me to put a patch together? > > Cheers, > > > Jeremy >
On Tue, Jan 26, 2010 at 01:56:04PM +0530, Amit Kucheria wrote: > It seems to me that this patch enables the extra logging unconditionally. Is > that true? Or does it require PM_DEBUG to be enabled? The original is unconditional but only adds two lines of additional output to a suspend/resume. Though I am not sure its adding anything to the data we have. I suspect we need a modified version of the 'per device' data which can be turned on somehow when we have an issue. -apw
diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 8aa2443..d72d4b3 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -324,6 +324,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 -------------------------*/ /** @@ -363,6 +380,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; @@ -376,6 +394,7 @@ 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); @@ -441,6 +460,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); @@ -469,6 +489,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); } /** @@ -604,6 +625,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(); @@ -619,6 +641,8 @@ 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); @@ -679,6 +703,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); @@ -704,6 +729,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; }
The following patch from Rafael measures the suspend/resume times of devices. It logs the total suspend/resume times of devices as follows: [ 62.820296] PM: suspend of devices complete after 2108.836 msecs [ 62.820300] PM: suspend devices took 2.110 seconds [ 62.860107] PM: late suspend of devices complete after 39.801 msecs [ 63.440105] PM: early resume of devices complete after 20.013 msecs [ 67.337821] PM: resume of devices complete after 3887.665 msecs [ 67.338078] PM: resume devices took 3.890 seconds [ 67.338117] PM: Finishing wakeup. The following changes since commit 8275e80fb72b97750d338c905ed7575df8967b95: Rafael J. Wysocki (1): PM: Measure device suspend and resume times are available in the git repository at: ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git suspendresume From 8275e80fb72b97750d338c905ed7575df8967b95 Mon Sep 17 00:00:00 2001 From: Rafael J. Wysocki <rjw@sisk.pl> Date: Fri, 18 Dec 2009 01:57:47 +0100 Subject: [PATCH] PM: Measure device suspend and resume times Measure and print the time of suspending and resuming all devices. Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl> (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899) Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> --- drivers/base/power/main.c | 27 +++++++++++++++++++++++++++ 1 files changed, 27 insertions(+), 0 deletions(-)