| Message ID | alpine.DEB.2.00.1002111349390.19816@hungry |
|---|---|
| State | Changes Requested |
| Delegated to: | Andy Whitcroft |
| Headers | show |
Manoj Iyer wrote: > This patch is an extension to a resume report patch submitted to upstream > by Rafael J. Wysocki. cnd tested this kernel and reported that it prints > information correctly. The messages will be printed if suspend/resume of > driver/device took more than 100ms. This default can be changed in CONFIG. > > Feb 11 13:23:05 cndougla kernel: [ 59.848676] PM: suspend of drv:sd > dev:0:0:0:0 complete after 978.535 msecs > Feb 11 13:23:05 cndougla kernel: [ 60.110097] PM: suspend of drv:HDA > Intel dev:0000:00:08.0 complete after 149.996 msecs > Feb 11 13:23:05 cndougla kernel: [ 60.110433] PM: suspend devices took > 1.320 seconds > > Feb 11 13:23:05 cndougla kernel: [ 61.313617] PM: resume of drv:battery > dev:PNP0C0A:00 complete after 141.572 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.300578] PM: resume of drv:nvidia > dev:0000:02:00.0 complete after 4849.583 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.562640] PM: resume of drv:usb > dev:usb3 complete after 109.993 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.672636] PM: resume of drv:usb > dev:usb4 complete after 109.980 msecs > Feb 11 13:23:05 cndougla kernel: [ 67.076900] PM: resume devices took > 5.900 seconds > > > The following changes since commit > a913ef9ba3b23aee8db094d5ab5804777c697ef1: > Andy Whitcroft (1): > UBUNTU: Ubuntu-2.6.32-13.18 > > are available in the git repository at: > > > ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git > srtime > > Manoj Iyer (2): > UBUNTU: SAUCE: PM report driver and device suspend/resume times. > UBUNTU: [Config] Added CONFIG_SR_REPORT_TIME_LIMIT > > debian.master/config/config.common.ubuntu | 1 + > drivers/base/power/main.c | 35 > +++++++++++++++++++++++++++++ > 2 files changed, 36 insertions(+), 0 deletions(-) > > > From b5c3874a49410d148d662b42bf2d305e83ddfc3e Mon Sep 17 00:00:00 2001 > From: Manoj Iyer <manoj.iyer@canonical.com> > Date: Thu, 11 Feb 2010 13:35:42 -0600 > Subject: [PATCH 1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times. > > This patch prints suspend/resume information for each driver/device to > dmesg. I don't think it adds much value to upstream. > > Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> Acked-by: Chase Douglas <chase.douglas@canonical.com> > --- > drivers/base/power/main.c | 35 +++++++++++++++++++++++++++++++++++ > 1 files changed, 35 insertions(+), 0 deletions(-) > > diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c > index 8aa2443..578b43d 100644 > --- a/drivers/base/power/main.c > +++ b/drivers/base/power/main.c > @@ -29,6 +29,13 @@ > #include "../base.h" > #include "power.h" > > +/* Set default to 100 msecs */ > +#ifdef CONFIG_SR_REPORT_TIME_LIMIT > +#define SR_REPORT_TIME_LIMIT CONFIG_SR_REPORT_TIME_LIMIT > +#else > +#define SR_REPORT_TIME_LIMIT 100 > +#endif > + > /* > * The entries in the dpm_list list are in a depth first order, simply > * because children are guaranteed to be discovered after parents, and > @@ -324,6 +331,26 @@ 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 device_show_time(struct device *dev, 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; > + if ((usecs / USEC_PER_MSEC) > SR_REPORT_TIME_LIMIT) > + pr_info("PM: %s%s%s of drv:%s dev:%s complete after %ld.%03ld msecs\n", info ?: "", info ? " " : "", pm_verb(state.event), > + dev_driver_string(dev), dev_name(dev), usecs / USEC_PER_MSEC, > + usecs % USEC_PER_MSEC); > +} > + > + > /*------------------------- Resume routines -------------------------*/ > > /** > @@ -337,6 +364,7 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info, > static int device_resume_noirq(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > TRACE_DEVICE(dev); > TRACE_RESUME(0); > @@ -347,6 +375,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state) > if (dev->bus->pm) { > pm_dev_dbg(dev, state, "EARLY "); > error = pm_noirq_op(dev, dev->bus->pm, state); > + device_show_time(dev, starttime, state, "early"); > } > End: > TRACE_RESUME(error); > @@ -388,6 +417,7 @@ EXPORT_SYMBOL_GPL(dpm_resume_noirq); > static int device_resume(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > TRACE_DEVICE(dev); > TRACE_RESUME(0); > @@ -424,6 +454,7 @@ static int device_resume(struct device *dev, pm_message_t state) > error = dev->class->resume(dev); > } > } > + device_show_time(dev, starttime, state, NULL); > End: > up(&dev->sem); > > @@ -583,6 +614,7 @@ static pm_message_t resume_event(pm_message_t sleep_state) > static int device_suspend_noirq(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > if (!dev->bus) > return 0; > @@ -590,6 +622,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state) > if (dev->bus->pm) { > pm_dev_dbg(dev, state, "LATE "); > error = pm_noirq_op(dev, dev->bus->pm, state); > + device_show_time(dev, starttime, state, "late"); > } > return error; > } > @@ -631,6 +664,7 @@ EXPORT_SYMBOL_GPL(dpm_suspend_noirq); > static int device_suspend(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > down(&dev->sem); > > @@ -666,6 +700,7 @@ static int device_suspend(struct device *dev, pm_message_t state) > suspend_report_result(dev->bus->suspend, error); > } > } > + device_show_time(dev, starttime, state, NULL); > End: > up(&dev->sem); >
On 10 Feb 11, Manoy Iyer wrote: > > This patch is an extension to a resume report patch submitted to upstream > by Rafael J. Wysocki. cnd tested this kernel and reported that it prints > information correctly. The messages will be printed if suspend/resume of > driver/device took more than 100ms. This default can be changed in CONFIG. So you've taken the patch and modified it some more? In that case, let's add the patch as-is with Rafael's signoff (or cherry-pick it from Linus' tree, though I don't see it there yet). Then, add your changes on top separately. > Feb 11 13:23:05 cndougla kernel: [ 59.848676] PM: suspend of drv:sd > dev:0:0:0:0 complete after 978.535 msecs > Feb 11 13:23:05 cndougla kernel: [ 60.110097] PM: suspend of drv:HDA > Intel dev:0000:00:08.0 complete after 149.996 msecs > Feb 11 13:23:05 cndougla kernel: [ 60.110433] PM: suspend devices took > 1.320 seconds > > Feb 11 13:23:05 cndougla kernel: [ 61.313617] PM: resume of drv:battery > dev:PNP0C0A:00 complete after 141.572 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.300578] PM: resume of drv:nvidia > dev:0000:02:00.0 complete after 4849.583 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.562640] PM: resume of drv:usb > dev:usb3 complete after 109.993 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.672636] PM: resume of drv:usb > dev:usb4 complete after 109.980 msecs > Feb 11 13:23:05 cndougla kernel: [ 67.076900] PM: resume devices took > 5.900 seconds > > > The following changes since commit > a913ef9ba3b23aee8db094d5ab5804777c697ef1: > Andy Whitcroft (1): > UBUNTU: Ubuntu-2.6.32-13.18 > > are available in the git repository at: > > > ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git > srtime > > Manoj Iyer (2): > UBUNTU: SAUCE: PM report driver and device suspend/resume times. > UBUNTU: [Config] Added CONFIG_SR_REPORT_TIME_LIMIT > > debian.master/config/config.common.ubuntu | 1 + > drivers/base/power/main.c | 35 > +++++++++++++++++++++++++++++
On Thu, Feb 11, 2010 at 01:55:35PM -0600, Manoj Iyer wrote: > > This patch is an extension to a resume report patch submitted to upstream > by Rafael J. Wysocki. cnd tested this kernel and reported that it prints > information correctly. The messages will be printed if suspend/resume of > driver/device took more than 100ms. This default can be changed in CONFIG. If we require another patch you should send it in here so we have the full history. If that patch is full contained in this one then we should likely pull that one out in its original form for both attribution and to avoid collisions when we rebase up to that version in the future. > Feb 11 13:23:05 cndougla kernel: [ 59.848676] PM: suspend of drv:sd > dev:0:0:0:0 complete after 978.535 msecs > Feb 11 13:23:05 cndougla kernel: [ 60.110097] PM: suspend of drv:HDA > Intel dev:0000:00:08.0 complete after 149.996 msecs > Feb 11 13:23:05 cndougla kernel: [ 60.110433] PM: suspend devices took > 1.320 seconds > > Feb 11 13:23:05 cndougla kernel: [ 61.313617] PM: resume of drv:battery > dev:PNP0C0A:00 complete after 141.572 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.300578] PM: resume of drv:nvidia > dev:0000:02:00.0 complete after 4849.583 msecs Yeeks how slow is Nvidia. This is exactly the sort of information we are looking to get out of the debugging exercise. > Feb 11 13:23:05 cndougla kernel: [ 66.562640] PM: resume of drv:usb > dev:usb3 complete after 109.993 msecs > Feb 11 13:23:05 cndougla kernel: [ 66.672636] PM: resume of drv:usb > dev:usb4 complete after 109.980 msecs > Feb 11 13:23:05 cndougla kernel: [ 67.076900] PM: resume devices took > 5.900 seconds > > > The following changes since commit > a913ef9ba3b23aee8db094d5ab5804777c697ef1: > Andy Whitcroft (1): > UBUNTU: Ubuntu-2.6.32-13.18 > > are available in the git repository at: > > > ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git > srtime > > Manoj Iyer (2): > UBUNTU: SAUCE: PM report driver and device suspend/resume times. > UBUNTU: [Config] Added CONFIG_SR_REPORT_TIME_LIMIT > > debian.master/config/config.common.ubuntu | 1 + > drivers/base/power/main.c | 35 > +++++++++++++++++++++++++++++ > 2 files changed, 36 insertions(+), 0 deletions(-) > > > From b5c3874a49410d148d662b42bf2d305e83ddfc3e Mon Sep 17 00:00:00 2001 > From: Manoj Iyer <manoj.iyer@canonical.com> > Date: Thu, 11 Feb 2010 13:35:42 -0600 > Subject: [PATCH 1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times. > > This patch prints suspend/resume information for each driver/device to > dmesg. I don't think it adds much value to upstream. > > Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> > --- > drivers/base/power/main.c | 35 +++++++++++++++++++++++++++++++++++ > 1 files changed, 35 insertions(+), 0 deletions(-) > > diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c > index 8aa2443..578b43d 100644 > --- a/drivers/base/power/main.c > +++ b/drivers/base/power/main.c > @@ -29,6 +29,13 @@ > #include "../base.h" > #include "power.h" > > +/* Set default to 100 msecs */ > +#ifdef CONFIG_SR_REPORT_TIME_LIMIT > +#define SR_REPORT_TIME_LIMIT CONFIG_SR_REPORT_TIME_LIMIT > +#else > +#define SR_REPORT_TIME_LIMIT 100 > +#endif > + If this is a configuration option you should be handling the default value in the definition of the confuration option and so shouldn't need this here. You should be able to rely on CONFIG_FOO existing and having a proper value and just use it in place below. > /* > * The entries in the dpm_list list are in a depth first order, simply > * because children are guaranteed to be discovered after parents, and > @@ -324,6 +331,26 @@ 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 device_show_time(struct device *dev, 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; > + if ((usecs / USEC_PER_MSEC) > SR_REPORT_TIME_LIMIT) > + pr_info("PM: %s%s%s of drv:%s dev:%s complete after %ld.%03ld msecs\n", info ?: "", info ? " " : "", pm_verb(state.event), > + dev_driver_string(dev), dev_name(dev), usecs / USEC_PER_MSEC, > + usecs % USEC_PER_MSEC); > +} > + > + > /*------------------------- Resume routines -------------------------*/ > > /** > @@ -337,6 +364,7 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info, > static int device_resume_noirq(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > TRACE_DEVICE(dev); > TRACE_RESUME(0); > @@ -347,6 +375,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state) > if (dev->bus->pm) { > pm_dev_dbg(dev, state, "EARLY "); > error = pm_noirq_op(dev, dev->bus->pm, state); > + device_show_time(dev, starttime, state, "early"); > } > End: > TRACE_RESUME(error); > @@ -388,6 +417,7 @@ EXPORT_SYMBOL_GPL(dpm_resume_noirq); > static int device_resume(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > TRACE_DEVICE(dev); > TRACE_RESUME(0); > @@ -424,6 +454,7 @@ static int device_resume(struct device *dev, pm_message_t state) > error = dev->class->resume(dev); > } > } > + device_show_time(dev, starttime, state, NULL); > End: > up(&dev->sem); > > @@ -583,6 +614,7 @@ static pm_message_t resume_event(pm_message_t sleep_state) > static int device_suspend_noirq(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > if (!dev->bus) > return 0; > @@ -590,6 +622,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state) > if (dev->bus->pm) { > pm_dev_dbg(dev, state, "LATE "); > error = pm_noirq_op(dev, dev->bus->pm, state); > + device_show_time(dev, starttime, state, "late"); > } > return error; > } > @@ -631,6 +664,7 @@ EXPORT_SYMBOL_GPL(dpm_suspend_noirq); > static int device_suspend(struct device *dev, pm_message_t state) > { > int error = 0; > + ktime_t starttime = ktime_get(); > > down(&dev->sem); > > @@ -666,6 +700,7 @@ static int device_suspend(struct device *dev, pm_message_t state) > suspend_report_result(dev->bus->suspend, error); > } > } > + device_show_time(dev, starttime, state, NULL); > End: > up(&dev->sem); > You introduce what appears to be a new CONFIG_ option but do not introduce a Kconfig fragment to create it? Where did that go? -apw
I had sent Rafael's patch earlier to the list, I will follow what amit, cherry pick Rafael's, and merge my changes in and resend it. Cheers --- manjo On Fri, 12 Feb 2010, Andy Whitcroft wrote: > On Thu, Feb 11, 2010 at 01:55:35PM -0600, Manoj Iyer wrote: >> >> This patch is an extension to a resume report patch submitted to upstream >> by Rafael J. Wysocki. cnd tested this kernel and reported that it prints >> information correctly. The messages will be printed if suspend/resume of >> driver/device took more than 100ms. This default can be changed in CONFIG. > > If we require another patch you should send it in here so we have the > full history. If that patch is full contained in this one then we should > likely pull that one out in its original form for both attribution and > to avoid collisions when we rebase up to that version in the future. > >> Feb 11 13:23:05 cndougla kernel: [ 59.848676] PM: suspend of drv:sd >> dev:0:0:0:0 complete after 978.535 msecs >> Feb 11 13:23:05 cndougla kernel: [ 60.110097] PM: suspend of drv:HDA >> Intel dev:0000:00:08.0 complete after 149.996 msecs >> Feb 11 13:23:05 cndougla kernel: [ 60.110433] PM: suspend devices took >> 1.320 seconds >> >> Feb 11 13:23:05 cndougla kernel: [ 61.313617] PM: resume of drv:battery >> dev:PNP0C0A:00 complete after 141.572 msecs >> Feb 11 13:23:05 cndougla kernel: [ 66.300578] PM: resume of drv:nvidia >> dev:0000:02:00.0 complete after 4849.583 msecs > > Yeeks how slow is Nvidia. This is exactly the sort of information we > are looking to get out of the debugging exercise. > >> Feb 11 13:23:05 cndougla kernel: [ 66.562640] PM: resume of drv:usb >> dev:usb3 complete after 109.993 msecs >> Feb 11 13:23:05 cndougla kernel: [ 66.672636] PM: resume of drv:usb >> dev:usb4 complete after 109.980 msecs >> Feb 11 13:23:05 cndougla kernel: [ 67.076900] PM: resume devices took >> 5.900 seconds >> >> >> The following changes since commit >> a913ef9ba3b23aee8db094d5ab5804777c697ef1: >> Andy Whitcroft (1): >> UBUNTU: Ubuntu-2.6.32-13.18 >> >> are available in the git repository at: >> >> >> ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git >> srtime >> >> Manoj Iyer (2): >> UBUNTU: SAUCE: PM report driver and device suspend/resume times. >> UBUNTU: [Config] Added CONFIG_SR_REPORT_TIME_LIMIT >> >> debian.master/config/config.common.ubuntu | 1 + >> drivers/base/power/main.c | 35 >> +++++++++++++++++++++++++++++ >> 2 files changed, 36 insertions(+), 0 deletions(-) >> >> >> From b5c3874a49410d148d662b42bf2d305e83ddfc3e Mon Sep 17 00:00:00 2001 >> From: Manoj Iyer <manoj.iyer@canonical.com> >> Date: Thu, 11 Feb 2010 13:35:42 -0600 >> Subject: [PATCH 1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times. >> >> This patch prints suspend/resume information for each driver/device to >> dmesg. I don't think it adds much value to upstream. >> >> Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> >> --- >> drivers/base/power/main.c | 35 +++++++++++++++++++++++++++++++++++ >> 1 files changed, 35 insertions(+), 0 deletions(-) >> >> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c >> index 8aa2443..578b43d 100644 >> --- a/drivers/base/power/main.c >> +++ b/drivers/base/power/main.c >> @@ -29,6 +29,13 @@ >> #include "../base.h" >> #include "power.h" >> >> +/* Set default to 100 msecs */ >> +#ifdef CONFIG_SR_REPORT_TIME_LIMIT >> +#define SR_REPORT_TIME_LIMIT CONFIG_SR_REPORT_TIME_LIMIT >> +#else >> +#define SR_REPORT_TIME_LIMIT 100 >> +#endif >> + > > If this is a configuration option you should be handling the default > value in the definition of the confuration option and so shouldn't need > this here. You should be able to rely on CONFIG_FOO existing and having > a proper value and just use it in place below. > >> /* >> * The entries in the dpm_list list are in a depth first order, simply >> * because children are guaranteed to be discovered after parents, and >> @@ -324,6 +331,26 @@ 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 device_show_time(struct device *dev, 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; >> + if ((usecs / USEC_PER_MSEC) > SR_REPORT_TIME_LIMIT) >> + pr_info("PM: %s%s%s of drv:%s dev:%s complete after %ld.%03ld msecs\n", info ?: "", info ? " " : "", pm_verb(state.event), >> + dev_driver_string(dev), dev_name(dev), usecs / USEC_PER_MSEC, >> + usecs % USEC_PER_MSEC); >> +} >> + >> + >> /*------------------------- Resume routines -------------------------*/ >> >> /** >> @@ -337,6 +364,7 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info, >> static int device_resume_noirq(struct device *dev, pm_message_t state) >> { >> int error = 0; >> + ktime_t starttime = ktime_get(); >> >> TRACE_DEVICE(dev); >> TRACE_RESUME(0); >> @@ -347,6 +375,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state) >> if (dev->bus->pm) { >> pm_dev_dbg(dev, state, "EARLY "); >> error = pm_noirq_op(dev, dev->bus->pm, state); >> + device_show_time(dev, starttime, state, "early"); >> } >> End: >> TRACE_RESUME(error); >> @@ -388,6 +417,7 @@ EXPORT_SYMBOL_GPL(dpm_resume_noirq); >> static int device_resume(struct device *dev, pm_message_t state) >> { >> int error = 0; >> + ktime_t starttime = ktime_get(); >> >> TRACE_DEVICE(dev); >> TRACE_RESUME(0); >> @@ -424,6 +454,7 @@ static int device_resume(struct device *dev, pm_message_t state) >> error = dev->class->resume(dev); >> } >> } >> + device_show_time(dev, starttime, state, NULL); >> End: >> up(&dev->sem); >> >> @@ -583,6 +614,7 @@ static pm_message_t resume_event(pm_message_t sleep_state) >> static int device_suspend_noirq(struct device *dev, pm_message_t state) >> { >> int error = 0; >> + ktime_t starttime = ktime_get(); >> >> if (!dev->bus) >> return 0; >> @@ -590,6 +622,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state) >> if (dev->bus->pm) { >> pm_dev_dbg(dev, state, "LATE "); >> error = pm_noirq_op(dev, dev->bus->pm, state); >> + device_show_time(dev, starttime, state, "late"); >> } >> return error; >> } >> @@ -631,6 +664,7 @@ EXPORT_SYMBOL_GPL(dpm_suspend_noirq); >> static int device_suspend(struct device *dev, pm_message_t state) >> { >> int error = 0; >> + ktime_t starttime = ktime_get(); >> >> down(&dev->sem); >> >> @@ -666,6 +700,7 @@ static int device_suspend(struct device *dev, pm_message_t state) >> suspend_report_result(dev->bus->suspend, error); >> } >> } >> + device_show_time(dev, starttime, state, NULL); >> End: >> up(&dev->sem); >> > > You introduce what appears to be a new CONFIG_ option but do not > introduce a Kconfig fragment to create it? Where did that go? > > -apw >
On 10 Feb 12, Manoy Iyer wrote: > > I had sent Rafael's patch earlier to the list, I will follow what amit, > cherry pick Rafael's, and merge my changes in and resend it. Just to be clear, don't merge your changes into that patch. Make it separate. Cheers, Amit > Cheers > --- manjo > > On Fri, 12 Feb 2010, Andy Whitcroft wrote: > > > On Thu, Feb 11, 2010 at 01:55:35PM -0600, Manoj Iyer wrote: > >> > >> This patch is an extension to a resume report patch submitted to upstream > >> by Rafael J. Wysocki. cnd tested this kernel and reported that it prints > >> information correctly. The messages will be printed if suspend/resume of > >> driver/device took more than 100ms. This default can be changed in CONFIG. > > > > If we require another patch you should send it in here so we have the > > full history. If that patch is full contained in this one then we should > > likely pull that one out in its original form for both attribution and > > to avoid collisions when we rebase up to that version in the future. > > > >> Feb 11 13:23:05 cndougla kernel: [ 59.848676] PM: suspend of drv:sd > >> dev:0:0:0:0 complete after 978.535 msecs > >> Feb 11 13:23:05 cndougla kernel: [ 60.110097] PM: suspend of drv:HDA > >> Intel dev:0000:00:08.0 complete after 149.996 msecs > >> Feb 11 13:23:05 cndougla kernel: [ 60.110433] PM: suspend devices took > >> 1.320 seconds > >> > >> Feb 11 13:23:05 cndougla kernel: [ 61.313617] PM: resume of drv:battery > >> dev:PNP0C0A:00 complete after 141.572 msecs > >> Feb 11 13:23:05 cndougla kernel: [ 66.300578] PM: resume of drv:nvidia > >> dev:0000:02:00.0 complete after 4849.583 msecs > > > > Yeeks how slow is Nvidia. This is exactly the sort of information we > > are looking to get out of the debugging exercise. > > > >> Feb 11 13:23:05 cndougla kernel: [ 66.562640] PM: resume of drv:usb > >> dev:usb3 complete after 109.993 msecs > >> Feb 11 13:23:05 cndougla kernel: [ 66.672636] PM: resume of drv:usb > >> dev:usb4 complete after 109.980 msecs > >> Feb 11 13:23:05 cndougla kernel: [ 67.076900] PM: resume devices took > >> 5.900 seconds > >> > >> > >> The following changes since commit > >> a913ef9ba3b23aee8db094d5ab5804777c697ef1: > >> Andy Whitcroft (1): > >> UBUNTU: Ubuntu-2.6.32-13.18 > >> > >> are available in the git repository at: > >> > >> > >> ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git > >> srtime > >> > >> Manoj Iyer (2): > >> UBUNTU: SAUCE: PM report driver and device suspend/resume times. > >> UBUNTU: [Config] Added CONFIG_SR_REPORT_TIME_LIMIT > >> > >> debian.master/config/config.common.ubuntu | 1 + > >> drivers/base/power/main.c | 35 > >> +++++++++++++++++++++++++++++ > >> 2 files changed, 36 insertions(+), 0 deletions(-) > >> > >> > >> From b5c3874a49410d148d662b42bf2d305e83ddfc3e Mon Sep 17 00:00:00 2001 > >> From: Manoj Iyer <manoj.iyer@canonical.com> > >> Date: Thu, 11 Feb 2010 13:35:42 -0600 > >> Subject: [PATCH 1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times. > >> > >> This patch prints suspend/resume information for each driver/device to > >> dmesg. I don't think it adds much value to upstream. > >> > >> Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> > >> --- > >> drivers/base/power/main.c | 35 +++++++++++++++++++++++++++++++++++ > >> 1 files changed, 35 insertions(+), 0 deletions(-) > >> > >> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c > >> index 8aa2443..578b43d 100644 > >> --- a/drivers/base/power/main.c > >> +++ b/drivers/base/power/main.c > >> @@ -29,6 +29,13 @@ > >> #include "../base.h" > >> #include "power.h" > >> > >> +/* Set default to 100 msecs */ > >> +#ifdef CONFIG_SR_REPORT_TIME_LIMIT > >> +#define SR_REPORT_TIME_LIMIT CONFIG_SR_REPORT_TIME_LIMIT > >> +#else > >> +#define SR_REPORT_TIME_LIMIT 100 > >> +#endif > >> + > > > > If this is a configuration option you should be handling the default > > value in the definition of the confuration option and so shouldn't need > > this here. You should be able to rely on CONFIG_FOO existing and having > > a proper value and just use it in place below. > > > >> /* > >> * The entries in the dpm_list list are in a depth first order, simply > >> * because children are guaranteed to be discovered after parents, and > >> @@ -324,6 +331,26 @@ 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 device_show_time(struct device *dev, 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; > >> + if ((usecs / USEC_PER_MSEC) > SR_REPORT_TIME_LIMIT) > >> + pr_info("PM: %s%s%s of drv:%s dev:%s complete after %ld.%03ld msecs\n", info ?: "", info ? " " : "", pm_verb(state.event), > >> + dev_driver_string(dev), dev_name(dev), usecs / USEC_PER_MSEC, > >> + usecs % USEC_PER_MSEC); > >> +} > >> + > >> + > >> /*------------------------- Resume routines -------------------------*/ > >> > >> /** > >> @@ -337,6 +364,7 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info, > >> static int device_resume_noirq(struct device *dev, pm_message_t state) > >> { > >> int error = 0; > >> + ktime_t starttime = ktime_get(); > >> > >> TRACE_DEVICE(dev); > >> TRACE_RESUME(0); > >> @@ -347,6 +375,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state) > >> if (dev->bus->pm) { > >> pm_dev_dbg(dev, state, "EARLY "); > >> error = pm_noirq_op(dev, dev->bus->pm, state); > >> + device_show_time(dev, starttime, state, "early"); > >> } > >> End: > >> TRACE_RESUME(error); > >> @@ -388,6 +417,7 @@ EXPORT_SYMBOL_GPL(dpm_resume_noirq); > >> static int device_resume(struct device *dev, pm_message_t state) > >> { > >> int error = 0; > >> + ktime_t starttime = ktime_get(); > >> > >> TRACE_DEVICE(dev); > >> TRACE_RESUME(0); > >> @@ -424,6 +454,7 @@ static int device_resume(struct device *dev, pm_message_t state) > >> error = dev->class->resume(dev); > >> } > >> } > >> + device_show_time(dev, starttime, state, NULL); > >> End: > >> up(&dev->sem); > >> > >> @@ -583,6 +614,7 @@ static pm_message_t resume_event(pm_message_t sleep_state) > >> static int device_suspend_noirq(struct device *dev, pm_message_t state) > >> { > >> int error = 0; > >> + ktime_t starttime = ktime_get(); > >> > >> if (!dev->bus) > >> return 0; > >> @@ -590,6 +622,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state) > >> if (dev->bus->pm) { > >> pm_dev_dbg(dev, state, "LATE "); > >> error = pm_noirq_op(dev, dev->bus->pm, state); > >> + device_show_time(dev, starttime, state, "late"); > >> } > >> return error; > >> } > >> @@ -631,6 +664,7 @@ EXPORT_SYMBOL_GPL(dpm_suspend_noirq); > >> static int device_suspend(struct device *dev, pm_message_t state) > >> { > >> int error = 0; > >> + ktime_t starttime = ktime_get(); > >> > >> down(&dev->sem); > >> > >> @@ -666,6 +700,7 @@ static int device_suspend(struct device *dev, pm_message_t state) > >> suspend_report_result(dev->bus->suspend, error); > >> } > >> } > >> + device_show_time(dev, starttime, state, NULL); > >> End: > >> up(&dev->sem); > >> > > > > You introduce what appears to be a new CONFIG_ option but do not > > introduce a Kconfig fragment to create it? Where did that go? > > > > -apw > > > > -- > kernel-team mailing list > kernel-team@lists.ubuntu.com > https://lists.ubuntu.com/mailman/listinfo/kernel-team
diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 8aa2443..578b43d 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -29,6 +29,13 @@ #include "../base.h" #include "power.h" +/* Set default to 100 msecs */ +#ifdef CONFIG_SR_REPORT_TIME_LIMIT +#define SR_REPORT_TIME_LIMIT CONFIG_SR_REPORT_TIME_LIMIT +#else +#define SR_REPORT_TIME_LIMIT 100 +#endif + /* * The entries in the dpm_list list are in a depth first order, simply * because children are guaranteed to be discovered after parents, and @@ -324,6 +331,26 @@ 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 device_show_time(struct device *dev, 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; + if ((usecs / USEC_PER_MSEC) > SR_REPORT_TIME_LIMIT) + pr_info("PM: %s%s%s of drv:%s dev:%s complete after %ld.%03ld msecs\n", info ?: "", info ? " " : "", pm_verb(state.event), + dev_driver_string(dev), dev_name(dev), usecs / USEC_PER_MSEC, + usecs % USEC_PER_MSEC); +} + + /*------------------------- Resume routines -------------------------*/ /** @@ -337,6 +364,7 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info, static int device_resume_noirq(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); TRACE_DEVICE(dev); TRACE_RESUME(0); @@ -347,6 +375,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state) if (dev->bus->pm) { pm_dev_dbg(dev, state, "EARLY "); error = pm_noirq_op(dev, dev->bus->pm, state); + device_show_time(dev, starttime, state, "early"); } End: TRACE_RESUME(error); @@ -388,6 +417,7 @@ EXPORT_SYMBOL_GPL(dpm_resume_noirq); static int device_resume(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); TRACE_DEVICE(dev); TRACE_RESUME(0); @@ -424,6 +454,7 @@ static int device_resume(struct device *dev, pm_message_t state) error = dev->class->resume(dev); } } + device_show_time(dev, starttime, state, NULL); End: up(&dev->sem); @@ -583,6 +614,7 @@ static pm_message_t resume_event(pm_message_t sleep_state) static int device_suspend_noirq(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); if (!dev->bus) return 0; @@ -590,6 +622,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state) if (dev->bus->pm) { pm_dev_dbg(dev, state, "LATE "); error = pm_noirq_op(dev, dev->bus->pm, state); + device_show_time(dev, starttime, state, "late"); } return error; } @@ -631,6 +664,7 @@ EXPORT_SYMBOL_GPL(dpm_suspend_noirq); static int device_suspend(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); down(&dev->sem); @@ -666,6 +700,7 @@ static int device_suspend(struct device *dev, pm_message_t state) suspend_report_result(dev->bus->suspend, error); } } + device_show_time(dev, starttime, state, NULL); End: up(&dev->sem);
This patch is an extension to a resume report patch submitted to upstream by Rafael J. Wysocki. cnd tested this kernel and reported that it prints information correctly. The messages will be printed if suspend/resume of driver/device took more than 100ms. This default can be changed in CONFIG. Feb 11 13:23:05 cndougla kernel: [ 59.848676] PM: suspend of drv:sd dev:0:0:0:0 complete after 978.535 msecs Feb 11 13:23:05 cndougla kernel: [ 60.110097] PM: suspend of drv:HDA Intel dev:0000:00:08.0 complete after 149.996 msecs Feb 11 13:23:05 cndougla kernel: [ 60.110433] PM: suspend devices took 1.320 seconds Feb 11 13:23:05 cndougla kernel: [ 61.313617] PM: resume of drv:battery dev:PNP0C0A:00 complete after 141.572 msecs Feb 11 13:23:05 cndougla kernel: [ 66.300578] PM: resume of drv:nvidia dev:0000:02:00.0 complete after 4849.583 msecs Feb 11 13:23:05 cndougla kernel: [ 66.562640] PM: resume of drv:usb dev:usb3 complete after 109.993 msecs Feb 11 13:23:05 cndougla kernel: [ 66.672636] PM: resume of drv:usb dev:usb4 complete after 109.980 msecs Feb 11 13:23:05 cndougla kernel: [ 67.076900] PM: resume devices took 5.900 seconds The following changes since commit a913ef9ba3b23aee8db094d5ab5804777c697ef1: Andy Whitcroft (1): UBUNTU: Ubuntu-2.6.32-13.18 are available in the git repository at: ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git srtime Manoj Iyer (2): UBUNTU: SAUCE: PM report driver and device suspend/resume times. UBUNTU: [Config] Added CONFIG_SR_REPORT_TIME_LIMIT debian.master/config/config.common.ubuntu | 1 + drivers/base/power/main.c | 35 +++++++++++++++++++++++++++++ 2 files changed, 36 insertions(+), 0 deletions(-) From b5c3874a49410d148d662b42bf2d305e83ddfc3e Mon Sep 17 00:00:00 2001 From: Manoj Iyer <manoj.iyer@canonical.com> Date: Thu, 11 Feb 2010 13:35:42 -0600 Subject: [PATCH 1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times. This patch prints suspend/resume information for each driver/device to dmesg. I don't think it adds much value to upstream. Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com> --- drivers/base/power/main.c | 35 +++++++++++++++++++++++++++++++++++ 1 files changed, 35 insertions(+), 0 deletions(-)