After the Dmitry's suggestion to use PSMOUSE_CMD_RESET_DIS during suspend
(and analogously for atkbd), I found that it reduced the suspend time
significantly and changed the picture quite a bit. For this reason I re-ran
the async suspend and resume tests on the nx6325 and Wind U100.
This time I marked the following devices as "async":
- all USB devices (including interfaces and endpoints)
- ACPI battery
- sd and its parent
- serio and i8042
- all PCI devices (including bridges)
for all tests (except for the sync suspend/resume test).
The results are as follows (all times in milliseconds):
HP nx6325 MSI Wind U100
sync suspend 1391 (+/- 32) 703 (+/- 26)
sync resume 3027 (+/- 6) 3562 (+/- 25)
async suspend 1306 (+/- 66) 659 (+/- 22)
async resume 2809 (+/- 250) 3564 (+/- 35)
async "upfront" suspend 1038 (+/- 46) 564 (+/- 50)
async "upfront" resume 1783 (+/- 7) 1925 (+/- 41)
where the "upfront" versions are with all of the async threads started in an
additional loop over dpm_list before the main "sync" suspend/resume loop.
The raw data are at:
http://www.sisk.pl/kernel/data/async-suspend-new.pdf
http://www.sisk.pl/kernel/data/nx6325/
http://www.sisk.pl/kernel/data/wind/
(hopefully this time I didn't make mistakes in the file names).
The data seem to suggest that "normal" async suspend and resume may be a little
(10% - 20%) faster than sync suspend and resume, but not as much as the
versions where all of the async threads had been started before the main
suspend (resume) thread began handling the "sync" devices.
IMO it also is worth noting that the "async upfront suspend" time on the Wind
is pretty close to the suspend time of the slowest device (~ .5 s). The same
applies to the "async upfront resume" time on the Wind (the slowest device
resumes in ~1.5 s) and the "async upfront suspend" time on the nx6325 (the
slowest device suspends in ~1 s). So, it looks like with the above set of
async devices we can approach pretty close to the achievable limit on both
test boxes.
I'm not sure what the next step should be at this point. To me, the picture is
quite clear now, but perhaps we ought to run more tests on some other machines
or something. Please let me know what you think.
Rafael
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majo...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Rafael J. Wysocki wrote:
> I'm not sure what the next step should be at this point. To me, the picture is
> quite clear now, but perhaps we ought to run more tests on some other machines
> or something. Please let me know what you think.
Looks great. If you do decide you want other machines tested, I'll
happily try the machines around here:
- Dell M1530
- Omnibook XE3-GF.
- Via LN10000 based Mythtv Box
- Desktop machine - Some Intel-based mobo I've forgotten the name of.
I've been quietly following the thread, but have lost track of what
iteration of the patch you're on, so if you'd give me a pointer to it,
I'd be grateful.
By the way, I haven't forgotten about sending some real patches for
swsusp (ie more than just cleanups). I'm just busy with other things and
also thinking carefully about what order to do things in.
Regards,
Nigel
On Mon, Dec 21, 2009 at 06:25:35PM +1100, Nigel Cunningham wrote:
> Hi.
>
> Rafael J. Wysocki wrote:
> > I'm not sure what the next step should be at this point. To me, the picture is
> > quite clear now, but perhaps we ought to run more tests on some other machines
> > or something. Please let me know what you think.
>
> Looks great. If you do decide you want other machines tested, I'll
> happily try the machines around here:
>
> - Dell M1530
> - Omnibook XE3-GF.
> - Via LN10000 based Mythtv Box
> - Desktop machine - Some Intel-based mobo I've forgotten the name of.
>
Would you mind also testing patch that I just posted that changes full
PS/2 keyboard and mouse resets to more lightweight versions?
Thanks!
--
Dmitry
I vote for ability to save all ram to the disk.
After several days of testing I managed to make my system do s2disk
really reliable (~300 cycles tested), but suspending when memory is
tight still fails sometimes.
I didn't yet use your tuxonice system though.
Best regards,
Maxim Levisky
Maxim Levitsky wrote:
> On Mon, 2009-12-21 at 18:25 +1100, Nigel Cunningham wrote:
>> Hi.
>>
>> Rafael J. Wysocki wrote:
>>> I'm not sure what the next step should be at this point. To me, the picture is
>>> quite clear now, but perhaps we ought to run more tests on some other machines
>>> or something. Please let me know what you think.
>> Looks great. If you do decide you want other machines tested, I'll
>> happily try the machines around here:
>>
>> - Dell M1530
>> - Omnibook XE3-GF.
>> - Via LN10000 based Mythtv Box
>> - Desktop machine - Some Intel-based mobo I've forgotten the name of.
>>
>> I've been quietly following the thread, but have lost track of what
>> iteration of the patch you're on, so if you'd give me a pointer to it,
>> I'd be grateful.
>>
>> By the way, I haven't forgotten about sending some real patches for
>> swsusp (ie more than just cleanups). I'm just busy with other things and
>> also thinking carefully about what order to do things in.
>
> I vote for ability to save all ram to the disk.
> After several days of testing I managed to make my system do s2disk
> really reliable (~300 cycles tested), but suspending when memory is
> tight still fails sometimes.
>
> I didn't yet use your tuxonice system though.
Well, I want to and intend on working towards merging as much of
TuxOnIce as people will allow in, but it will take a long time because
there are so many modifications to do, I don't have that much time to
work on it, am splitting the time I do have and am still have a couple
of new features I want to do to TuxOnIce.
Regards,
Nigel
> Hi,
>
> After the Dmitry's suggestion to use PSMOUSE_CMD_RESET_DIS during suspend
> (and analogously for atkbd), I found that it reduced the suspend time
> significantly and changed the picture quite a bit. For this reason I re-ran
> the async suspend and resume tests on the nx6325 and Wind U100.
>
> This time I marked the following devices as "async":
> - all USB devices (including interfaces and endpoints)
> - ACPI battery
> - sd and its parent
Apparently not. On nx6325 the sd device is 0:0:0:0, which did suspend
in a different thread, but its parent is target0:0:0 which suspended
and resumed in the main thread. And its grandparent, host0, also
suspended and resumed in the main thread.
There are still some odd things going on. Look at
nx6325-async-suspend-upfront-dmesg.log. There's a peculiar gap between
[ 233.176029] call 0000:00:14.2+ returned 0 after 217543 usecs
and
[ 234.059948] call 0:0:0:0+ returned 0 after 1078047 usecs
A lot of stuff could have happened during that gap, but nothing did.
That's because the target0:0:0 device was synchronous, and it was
waiting for its child (the long-running async 0:0:0:0) to finish. Not
that it made much difference in the end, because the entire suspend
finished about 16 ms later. But if there was more than one disk or if
the disk had been a USB drive, it would have mattered.
You should also make SCSI targets and hosts async. Hosts are added in
drivers/scsi/hosts.c:scsi_add_host_with_dma() (in 2.6.32 this was
named scsi_add_host()). Targets are added in
drivers/scsi/scsi_sysfs.c:scsi_target_add(). And for thoroughness,
SCSI devices are added in scsi_sysfs_add_sdev() in the same file.
More importantly, why did 0:0:0:0 wait almost 20 ms to begin
suspending? Undoubtedly because it was blocked, waiting for some
unlogged synchronous device. That's why you need to print out log
entries for devices without methods. In this case it was probably a
class device.
Although USB host controllers aren't the longest-running devices to
resume, they do tend to be on the longest paths. Speeding them up
would help. One change you could try is in the patch below.
Currently when a controller has to be reset, the root hub beneath it is
also reset and then re-suspended. However there's no reason to suspend
it if the PM core is only going to resume it a little bit later. The
patch gets rid of the unnecessary suspend. Note: I haven't tested it.
Alan Stern
Index: usb-2.6/drivers/usb/host/ohci-hub.c
===================================================================
--- usb-2.6.orig/drivers/usb/host/ohci-hub.c
+++ usb-2.6/drivers/usb/host/ohci-hub.c
@@ -333,14 +333,12 @@ static void ohci_finish_controller_resum
}
}
- /* If needed, reinitialize and suspend the root hub */
+ /* If needed, reinitialize the root hub */
if (need_reinit) {
spin_lock_irq(&ohci->lock);
hcd->state = HC_STATE_RESUMING;
- ohci_rh_resume(ohci);
- hcd->state = HC_STATE_QUIESCING;
- ohci_rh_suspend(ohci, 0);
- hcd->state = HC_STATE_SUSPENDED;
+ if (ohci_rh_resume(ohci) == 0)
+ hcd->state = HC_STATE_RUNNING;
spin_unlock_irq(&ohci->lock);
}
Index: usb-2.6/drivers/usb/host/uhci-hcd.c
===================================================================
--- usb-2.6.orig/drivers/usb/host/uhci-hcd.c
+++ usb-2.6/drivers/usb/host/uhci-hcd.c
@@ -835,7 +835,6 @@ static int uhci_pci_resume(struct usb_hc
/* The controller had to be reset */
usb_root_hub_lost_power(hcd->self.root_hub);
- suspend_rh(uhci, UHCI_RH_SUSPENDED);
}
spin_unlock_irq(&uhci->lock);
Hmm. I must have confused things, then.
...
> There are still some odd things going on. Look at
> nx6325-async-suspend-upfront-dmesg.log. There's a peculiar gap between
>
> [ 233.176029] call 0000:00:14.2+ returned 0 after 217543 usecs
>
> and
>
> [ 234.059948] call 0:0:0:0+ returned 0 after 1078047 usecs
>
> A lot of stuff could have happened during that gap, but nothing did.
> That's because the target0:0:0 device was synchronous, and it was
> waiting for its child (the long-running async 0:0:0:0) to finish. Not
> that it made much difference in the end, because the entire suspend
> finished about 16 ms later. But if there was more than one disk or if
> the disk had been a USB drive, it would have mattered.
>
> You should also make SCSI targets and hosts async. Hosts are added in
> drivers/scsi/hosts.c:scsi_add_host_with_dma() (in 2.6.32 this was
> named scsi_add_host()). Targets are added in
> drivers/scsi/scsi_sysfs.c:scsi_target_add(). And for thoroughness,
> SCSI devices are added in scsi_sysfs_add_sdev() in the same file.
Thanks a lot for the pointers.
Do you think it's a good idea to mark all SCSI devices as async? Well, for
testing it probably is, but I doubt in general.
> More importantly, why did 0:0:0:0 wait almost 20 ms to begin
> suspending? Undoubtedly because it was blocked, waiting for some
> unlogged synchronous device. That's why you need to print out log
> entries for devices without methods. In this case it was probably a
> class device.
OK
> Although USB host controllers aren't the longest-running devices to
> resume, they do tend to be on the longest paths. Speeding them up
> would help. One change you could try is in the patch below.
> Currently when a controller has to be reset, the root hub beneath it is
> also reset and then re-suspended. However there's no reason to suspend
> it if the PM core is only going to resume it a little bit later. The
> patch gets rid of the unnecessary suspend. Note: I haven't tested it.
OK, I'll try it.
Rafael
> Do you think it's a good idea to mark all SCSI devices as async? Well, for
> testing it probably is, but I doubt in general.
That would be a good question to post on Linux-SCSI.
In most respects it's probably okay. But some people with large disk
farms might not like it if their drives should suddenly start to spin
up (with a correspondingly large power draw) all at the same time.
Alan Stern
On Mon, 21 Dec 2009, Rafael J. Wysocki wrote:
>
> Do you think it's a good idea to mark all SCSI devices as async? Well, for
> testing it probably is, but I doubt in general.
As long as things aren't multi-path, or multi-lun, it's probably fine.
With multi-path (ie same disk reachable multiple ways), it's probably fine
too, but let's face it, who the hell knows? But it's not going to be an
issue for laptops and normal desktops.
For multi-lun, I suspect the luns are related, and there might be some
ordering issues. But it's _likely_ all fine there too.
The nice thing about systems with wires (ie USB, SCSI, SATA) is that it's
really hard to make different devices have odd dependencies on each other.
The wires tend to _be_ the topology.
Linus
I put device_enable_async_suspend() in all of these places and that resulted in
major reduction of suspend time without starting the async threads upfront.
Now, however, starting them upfront helps only a little, within the standard
deviation from the "non-upfront" case.
In turn, resume _without_ starting the async threads upfront makes a little
sense on my test boxes. In fact, it only helped on the nx6325 and made things
worse on the other two (I added the results from Toshiba Portege R500, but it
has the same chipset as the Wind U100, ie. ICH7).
The results are as follows:
HP nx6325 MSI Wind U100 Toshiba Portege R500
sync suspend 1357 (+/- 35) 656 (+/- 50) 889 (+/- 29)
sync resume 3027 (+/- 6) 3372 (+/- 30) 4552 (+/- 35)
async suspend 1053 (+/- 50) 490 (+/- 42) 620 (+/- 52)
async resume 2291 (+/- 7) 3406 (+/- 52) 4557 (+/- 26)
async "upfront" suspend 1040 (+/- 35) 476 (+/- 9) 585 (+/- 29)
async "upfront" resume 1787 (+/- 7) 1724 (+/- 48) 1990 (+/- 25)
The raw data are at
http://www.sisk.pl/kernel/data/async-suspend-updated.pdf
http://www.sisk.pl/kernel/data/r500/
http://www.sisk.pl/kernel/data/nx6325/
http://www.sisk.pl/kernel/data/wind/
and the previous results were moved into
http://www.sisk.pl/kernel/data/091220/
The patches used in the testing are in my async branch at
http://git.kernel.org/?p=linux/kernel/git/rafael/suspend-2.6.git;a=shortlog;h=refs/heads/async
The patches in this branch are not for upstream, but it's on top of the
linux-next branch containing patches for the 2.6.34 merge window.
...
> > Although USB host controllers aren't the longest-running devices to
> > resume, they do tend to be on the longest paths. Speeding them up
> > would help. One change you could try is in the patch below.
> > Currently when a controller has to be reset, the root hub beneath it is
> > also reset and then re-suspended. However there's no reason to suspend
> > it if the PM core is only going to resume it a little bit later. The
> > patch gets rid of the unnecessary suspend. Note: I haven't tested it.
>
> OK, I'll try it.
Unfortunately it breaks the second suspend (suspend process returns error code
and says that the controller was not suspended, more or less).
Rafael
Yes, that would be useful. If the results are in agreement with my data at
http://www.sisk.pl/kernel/data/, we will have a strong support for starting the
async threads upfront during resume.
The patches I used for testing are in the async branch in my tree:
git://git.kernel.org/pub/scm/linux/kernel/git/rafael/suspend-2.6.git
The first of them is
http://git.kernel.org/?p=linux/kernel/git/rafael/suspend-2.6.git;a=commit;h=91bbe0161cab7efcda5de3dfdf6a93f07314ed58
and the others are on top of this one (but it will apply on top of the current
mainline, so I'd suggest to pull the latest Linus' tree and then rebase the
commits from my async branch on top of it).
The "upfront * async" results were obtained with the full patchset applied.
The "sync" results where with /sys/power/pm_async = 0 and the "bare async"
results were with the last two commits reverted.
> By the way, I haven't forgotten about sending some real patches for
> swsusp (ie more than just cleanups). I'm just busy with other things and
> also thinking carefully about what order to do things in.
Great, I hope you're in contact with Jiri Slaby, as he's also been working on
this.
Rafael
Hi,
> I built the async branch of your tree and tested it, also running
> 2.6.33-rc1 + TuxOnIce for comparison. Dmesg for both are attached. Is
> there anything I can/should be doing for you on top of this?
No, thanks a lot.
> I'll try Dmitry's patch on top of this a little later - other things to do first.
No need for that, the patchset contains an equivalent of the Dmitry's patch.
> I noticed that you were doing standard deviations in your stats - how
> many runs were you basing them on?
I usually run 10 iterations of suspend-resume for each configuration.
The raw data are at http://www.sisk.pl/kernel/data/async-suspend-updated.pdf
if you're interested.
> Not sure that I can be bothered to do too many - too much else to do!
Sure, thanks a lot anyway. Your data confirn that there's a measurable gain
from suspending and resuming devices asynchronously.
Have a merry Christmas and happy new year,
It did? I thought it showed no difference at all!
I'll see if I can find the time to do the other computers, then. We're
going away for a couple of weeks on Monday, though, so I'm not sure that
I'll get the time beforehand.
Nigel
Yes, it did. Please compare these lines:
(from the "sync" dmesg):
[ 31.640676] PM: freeze of devices complete after 709.277 msecs
[ 37.087548] PM: restore of devices complete after 4973.508 msecs
(from the "async" dmesg):
[ 25.600067] PM: freeze of devices complete after 620.429 msecs
[ 29.195366] PM: restore of devices complete after 3057.982 msecs
So clearly, there's a difference. :-)
Of course, in terms of total hibernate/restore time this is only a little
improvement, but if that was suspend to RAM and resume, the reduction of
the device resume time by almost 2 s would be a big deal.
> I'll see if I can find the time to do the other computers, then.
I'd appreciate that very much.
> We're going away for a couple of weeks on Monday, though, so I'm not sure
> that I'll get the time beforehand.
OK
Rafael
Rafael J. Wysocki wrote:
> Yes, it did. Please compare these lines:
>
> (from the "sync" dmesg):
> [ 31.640676] PM: freeze of devices complete after 709.277 msecs
> [ 37.087548] PM: restore of devices complete after 4973.508 msecs
>
> (from the "async" dmesg):
> [ 25.600067] PM: freeze of devices complete after 620.429 msecs
> [ 29.195366] PM: restore of devices complete after 3057.982 msecs
>
> So clearly, there's a difference. :-)
Oh okay.
It still feels like a long time. How do I find out which device took the
longest? It looks to me like the patch is only recording when things
start their restore, not when they finish.
> Of course, in terms of total hibernate/restore time this is only a little
> improvement, but if that was suspend to RAM and resume, the reduction of
> the device resume time by almost 2 s would be a big deal.
>
>> I'll see if I can find the time to do the other computers, then.
>
> I'd appreciate that very much.
I'm not sure I'll find the time now - it's Sunday morning here and we
still have packing and so on to do after I take this morning's service.
Sorry!
Regards,
Nigel
First, you need to boot with initcall_debug in the kernel command line.
Then, after a hibernate-resume cycle do something like this:
$ dmesg | grep "call .* returned " | awk '{print $8 "\t" $4;}' | sort -nr
That will give you both the suspend and resume times for all devices,
sorted in the decreasing order.
If you want to separate suspend times from resume times, you generally need
to save the dmesg output and cut everything except for the interesting part
(eg. device suspend) from it. Then you'll get the times by running the above
command.
> > Of course, in terms of total hibernate/restore time this is only a little
> > improvement, but if that was suspend to RAM and resume, the reduction of
> > the device resume time by almost 2 s would be a big deal.
> >
> >> I'll see if I can find the time to do the other computers, then.
> >
> > I'd appreciate that very much.
>
> I'm not sure I'll find the time now - it's Sunday morning here and we
> still have packing and so on to do after I take this morning's service.
>
> Sorry!
No problem at all. :-)
Rafael
Here's a small update to this I thought might be interesting to someone.
Namely, I replaced the rotational disk in the Toshiba Portege R500 with an SSD
and ran a few suspend/resume speed tests with the KMS on (the previous results
for the R500 are with the userspace modesetting). The results are here:
http://www.sisk.pl/kernel/data/r500-ssd/
As you can see here:
http://www.sisk.pl/kernel/data/r500/times-r500-async-resume.txt
http://www.sisk.pl/kernel/data/r500-ssd/times-r500-async-resume.txt
the resume times changed quite a bit. First, the device 0:0:0:0+ (the SSD) now
takes about 0.33 s to resume (the rotational disk took about 1.7 s), pretty
much as expected. Second, the slowest resuming device is now the graphics
(1.1 s), while without the KMS it resumed in no time.
The device suspend times also changed:
http://www.sisk.pl/kernel/data/r500/times-r500-async-suspend.txt
http://www.sisk.pl/kernel/data/r500-ssd/times-r500-async-suspend.txt
but 0:0:0:0+ is still the slowest suspending device, although it takes 200 ms
less to suspend than the rotational disk.
Overall, synchronous suspend of devices takes about 600 - 700 ms and
synchronous resume takes about 4 s. At the same time, asynchronous suspend of
devices takes about 300 - 350 ms and asynchronous resume takes about
1.1 - 1.2 s (that is with the async resume threads started upfront). So, with
the asynchronous suspend/resume the total times are roughly equal to the
suspend/resume time of the slowest device and the resume speedup is
more than 70%..
Yeah, we've pushed all the work into the kernel, so any needed delays
for i2c or clock settling will be felt by the kernel on resume or mode
set time.
Making the KMS code async was one of the wins for the fast boot stuff
Arjan worked on.
--
Jesse Barnes, Intel Open Source Technology Center