RE: Resume from Memory very slow on 2.6.37+

RE: Resume from Memory very slow on 2.6.37+

[Brown, Len]

added Linux-acpi to cc

> -----Original Message-----
> From: Jeff Chua [mailto:jeff.chua.linux@gmail.com]
> Sent: Monday, January 17, 2011 8:36 AM
> To: Rafael J. Wysocki; Brown, Len; Jack Steiner; Linus Torvalds
> Subject: Resume from Memory very slow on 2.6.37+
> 
> I've just tried the recent linux git pull
> (e78bf5e6cbe837daa6ab628a5f679548742994d3) and suspend-to-memory
> works, but resume takes a very long time (30 seconds doing nothing).
> 
> Bisected and it says first bad commit is
> ca9b600be38c73b7d25acfb8b7e4e9a9e941d881
> 
> commit ca9b600be38c73b7d25acfb8b7e4e9a9e941d881
> Author: Rafael J. Wysocki <rjw@sisk.pl>
> Date:   Fri Jan 7 01:45:58 2011 +0100
> 
>     ACPI / PM: Make suspend_nvs_save() use acpi_os_map_memory()
> 
>     It turns out that the NVS memory region that suspend_nvs_save()
>     attempts to map has been already mapped by acpi_os_map_memory(), so
>     suspend_nvs_save() should better use acpi_os_map_memory() for mapping
>     memory to avoid conflicts.
> 
>     Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
>     Signed-off-by: Len Brown <len.brown@intel.com>
> 
> 
> I reverted the following commits, and system resumes without waiting ...
> 
> commit ca9b600be38c73b7d25acfb8b7e4e9a9e941d881
> Author: Rafael J. Wysocki <rjw@sisk.pl>
> Date:   Fri Jan 7 01:45:58 2011 +0100
> 
>     ACPI / PM: Make suspend_nvs_save() use acpi_os_map_memory()
> 
> commit 6d5bbf00d251cc73223a71422d69e069dc2e0b8d
> Author: Len Brown <len.brown@intel.com>
> Date:   Fri Jan 7 01:46:40 2011 +0100
> 
>     ACPI: Use ioremap_cache()
> 
> commit d146df18c13d16e321efa8ef9b57c95c3bec1722
> Author: Rafael J. Wysocki <rjw@sisk.pl>
> Date:   Fri Jan 7 01:44:28 2011 +0100
> 
>     ACPI / PM: Update file information and the list of includes in nvs.c
> 
> 
> Notebook is Lenovo X201s. 8GB RAM. 256GB SSD.

any difference if you boot with acpi_sleep=nonvs ?

thanks,
-Len

Re: Resume from Memory very slow on 2.6.37+

[Rafael J. Wysocki]

On Monday, January 17, 2011, Jeff Chua wrote:
> I've just tried the recent linux git pull
> (e78bf5e6cbe837daa6ab628a5f679548742994d3) and suspend-to-memory
> works, but resume takes a very long time (30 seconds doing nothing).
> 
> Bisected and it says first bad commit is
> ca9b600be38c73b7d25acfb8b7e4e9a9e941d881

Hmm.  That's probably because acpi_os_unmap_memory() does the
synchronize_rcu(), but I have no idea why it might cause a problem to
occur in suspend_nvs_free().

What happens if you replace the acpi_os_map_memory() in
suspend_nvs_save() with ioremap_cache() and the acpi_os_unmap_memory() in
suspend_nvs_free() with iounmap() ?

Rafael


> commit ca9b600be38c73b7d25acfb8b7e4e9a9e941d881
> Author: Rafael J. Wysocki <rjw@sisk.pl>
> Date:   Fri Jan 7 01:45:58 2011 +0100
> 
>     ACPI / PM: Make suspend_nvs_save() use acpi_os_map_memory()
> 
>     It turns out that the NVS memory region that suspend_nvs_save()
>     attempts to map has been already mapped by acpi_os_map_memory(), so
>     suspend_nvs_save() should better use acpi_os_map_memory() for mapping
>     memory to avoid conflicts.
> 
>     Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
>     Signed-off-by: Len Brown <len.brown@intel.com>
> 
> 
> I reverted the following commits, and system resumes without waiting ...
> 
> commit ca9b600be38c73b7d25acfb8b7e4e9a9e941d881
> Author: Rafael J. Wysocki <rjw@sisk.pl>
> Date:   Fri Jan 7 01:45:58 2011 +0100
> 
>     ACPI / PM: Make suspend_nvs_save() use acpi_os_map_memory()
> 
> commit 6d5bbf00d251cc73223a71422d69e069dc2e0b8d
> Author: Len Brown <len.brown@intel.com>
> Date:   Fri Jan 7 01:46:40 2011 +0100
> 
>     ACPI: Use ioremap_cache()
> 
> commit d146df18c13d16e321efa8ef9b57c95c3bec1722
> Author: Rafael J. Wysocki <rjw@sisk.pl>
> Date:   Fri Jan 7 01:44:28 2011 +0100
> 
>     ACPI / PM: Update file information and the list of includes in nvs.c
> 
> 
> Notebook is Lenovo X201s. 8GB RAM. 256GB SSD.
> 
> 
> Thanks,
> Jeff
> 
> 

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Rafael J. Wysocki]

On Monday, January 17, 2011, Rafael J. Wysocki wrote:
> On Monday, January 17, 2011, Jeff Chua wrote:
> > I've just tried the recent linux git pull
> > (e78bf5e6cbe837daa6ab628a5f679548742994d3) and suspend-to-memory
> > works, but resume takes a very long time (30 seconds doing nothing).
> > 
> > Bisected and it says first bad commit is
> > ca9b600be38c73b7d25acfb8b7e4e9a9e941d881
> 
> Hmm.  That's probably because acpi_os_unmap_memory() does the
> synchronize_rcu(), but I have no idea why it might cause a problem to
> occur in suspend_nvs_free().
> 
> What happens if you replace the acpi_os_map_memory() in
> suspend_nvs_save() with ioremap_cache() and the acpi_os_unmap_memory() in
> suspend_nvs_free() with iounmap() ?

IOW, can you please test if the patch below makes a difference?

Rafael

---
 drivers/acpi/nvs.c |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

Index: linux-2.6/drivers/acpi/nvs.c
===================================================================
--- linux-2.6.orig/drivers/acpi/nvs.c
+++ linux-2.6/drivers/acpi/nvs.c
@@ -80,7 +80,7 @@ void suspend_nvs_free(void)
 			free_page((unsigned long)entry->data);
 			entry->data = NULL;
 			if (entry->kaddr) {
-				acpi_os_unmap_memory(entry->kaddr, entry->size);
+				iounmap(entry->kaddr);
 				entry->kaddr = NULL;
 			}
 		}
@@ -114,8 +114,8 @@ int suspend_nvs_save(void)
 
 	list_for_each_entry(entry, &nvs_list, node)
 		if (entry->data) {
-			entry->kaddr = acpi_os_map_memory(entry->phys_start,
-							  entry->size);
+			entry->kaddr = ioremap_cache(entry->phys_start,
+						     entry->size);
 			if (!entry->kaddr) {
 				suspend_nvs_free();
 				return -ENOMEM;

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Jeff Chua]

On Tue, Jan 18, 2011 at 2:55 AM, Brown, Len <len.brown@intel.com> wrote:
> added Linux-acpi to cc
>
> any difference if you boot with acpi_sleep=nonvs ?

That works.

On Tue, Jan 18, 2011 at 8:14 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
>> What happens if you replace the acpi_os_map_memory() in
>> suspend_nvs_save() with ioremap_cache() and the acpi_os_unmap_memory() in
>> suspend_nvs_free() with iounmap() ?
>
> IOW, can you please test if the patch below makes a difference?
>  drivers/acpi/nvs.c |    6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)

That works too.

Now I have another problem which might be totally unrelated. Just
realized that my notebook can't suspend to "disk" ... used to work
last week. So, something has changed as well. May be someone has
already reported/fixed this.


Thanks,
Jeff
--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Rafael J. Wysocki]

On Tuesday, January 18, 2011, Jeff Chua wrote:
> On Tue, Jan 18, 2011 at 2:55 AM, Brown, Len <len.brown@intel.com> wrote:
> > added Linux-acpi to cc
> >
> > any difference if you boot with acpi_sleep=nonvs ?
> 
> That works.
> 
> On Tue, Jan 18, 2011 at 8:14 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> >> What happens if you replace the acpi_os_map_memory() in
> >> suspend_nvs_save() with ioremap_cache() and the acpi_os_unmap_memory() in
> >> suspend_nvs_free() with iounmap() ?
> >
> > IOW, can you please test if the patch below makes a difference?
> >  drivers/acpi/nvs.c |    6 +++---
> >  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> That works too.

Interesting.

Do you have CONFIG_RCU_CPU_STALL_DETECTOR set?  If not, please set it.  Then,
set CONFIG_RCU_CPU_STALL_TIMEOUT to something like 10 (in either case), run
a suspend-resume cycle and see if there are any CPU stalls reported in the
logs. 

We can avoid calling synchronize_rcu() in suspend_nvs_free(), but I'd like
to know _why_ it's stalling in there.

> Now I have another problem which might be totally unrelated. Just
> realized that my notebook can't suspend to "disk" ... used to work
> last week. So, something has changed as well. May be someone has
> already reported/fixed this.

Not that I know of.  What do you mean by "can't suspend"?

Rafael

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Jeff Chua]

On Tue, Jan 18, 2011 at 9:35 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> Do you have CONFIG_RCU_CPU_STALL_DETECTOR set?  If not, please set it.  Then,
> set CONFIG_RCU_CPU_STALL_TIMEOUT to something like 10 (in either case), run
> a suspend-resume cycle and see if there are any CPU stalls reported in the
> logs.

Configured and see nothing specific. The 30 seconds delays is
indicated below in the dmesg at resume ...

2011-01-18T13:00:48.399866+08:00 boston kernel: PM: early resume of
devices complete after 50.816 msecs
2011-01-18T13:00:48.399868+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
power state changed by ACPI to D0
2011-01-18T13:00:48.399871+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
power state changed by ACPI to D0
2011-01-18T13:00:48.399874+08:00 boston kernel: i915 0000:00:02.0:
power state changed by ACPI to D0
2011-01-18T13:00:48.399877+08:00 boston kernel: i915 0000:00:02.0:
power state changed by ACPI to D0
2011-01-18T13:00:48.399879+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
PCI INT D -> GSI 23 (level, low) -> IRQ 23
2011-01-18T13:00:48.399882+08:00 boston kernel: i915 0000:00:02.0:
setting latency timer to 64
2011-01-18T13:00:48.399884+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
setting latency timer to 64
2011-01-18T13:00:48.399887+08:00 boston kernel: HDA Intel
0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
2011-01-18T13:00:48.399889+08:00 boston kernel: HDA Intel
0000:00:1b.0: setting latency timer to 64
2011-01-18T13:00:48.399892+08:00 boston kernel: HDA Intel
0000:00:1b.0: irq 41 for MSI/MSI-X
2011-01-18T13:00:48.399894+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
power state changed by ACPI to D0
2011-01-18T13:00:48.399898+08:00 boston kernel: pci 0000:00:1e.0:
setting latency timer to 64
2011-01-18T13:00:48.399901+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
power state changed by ACPI to D0
2011-01-18T13:00:48.399904+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
PCI INT D -> GSI 19 (level, low) -> IRQ 19
2011-01-18T13:00:48.399906+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
setting latency timer to 64
2011-01-18T13:00:48.399941+08:00 boston kernel: ahci 0000:00:1f.2:
setting latency timer to 64
2011-01-18T13:00:48.399943+08:00 boston kernel: sd 0:0:0:0: [sda] Starting disk
2011-01-18T13:00:48.399946+08:00 boston kernel: ioremap error for
0xbb77e000-0xbb781000, requested 0x10, got 0x0
2011-01-18T13:00:48.399949+08:00 boston kernel: ata1: SATA link up 3.0
Gbps (SStatus 123 SControl 300)
2011-01-18T13:00:48.399953+08:00 boston kernel: ata1.00: ACPI cmd
ef/02:00:00:00:00:a0 (unknown) succeeded
2011-01-18T13:00:48.399955+08:00 boston kernel: ata1.00: ACPI cmd
f5/00:00:00:00:00:a0 (unknown) filtered out
2011-01-18T13:00:48.399958+08:00 boston kernel: ata1.00: ACPI cmd
ef/10:03:00:00:00:a0 (unknown) filtered out
2011-01-18T13:00:48.399961+08:00 boston kernel: ata1.00: ACPI cmd
ef/02:00:00:00:00:a0 (unknown) succeeded
2011-01-18T13:00:48.399963+08:00 boston kernel: ata1.00: ACPI cmd
f5/00:00:00:00:00:a0 (unknown) filtered out
2011-01-18T13:00:48.399966+08:00 boston kernel: ata1.00: ACPI cmd
ef/10:03:00:00:00:a0 (unknown) filtered out
2011-01-18T13:00:48.399968+08:00 boston kernel: ata1.00: configured for UDMA/100
2011-01-18T13:00:48.399970+08:00 boston kernel: ata5: SATA link down
(SStatus 0 SControl 300)
2011-01-18T13:00:48.399973+08:00 boston kernel: ata6: SATA link down
(SStatus 0 SControl 300)
2011-01-18T13:00:48.399975+08:00 boston kernel: PM: resume of devices
complete after 407.508 msecs
<============= 30 seconds delays here =============>
2011-01-18T13:00:48.399977+08:00 boston kernel: Restarting tasks ... done.


>> Now I have another problem which might be totally unrelated. Just
>> realized that my notebook can't suspend to "disk" ... used to work
>> last week. So, something has changed as well. May be someone has
>> already reported/fixed this.
>
> Not that I know of.  What do you mean by "can't suspend"?


echo platform >/sys/power/disk; echo disk >/sys/power/state

Last line I see is ... "Suspending console(s) (use no_console_suspend
to debug)" .. and activity after that.


Thanks,
Jeff
--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Rafael J. Wysocki]

On Tuesday, January 18, 2011, Jeff Chua wrote:
> On Tue, Jan 18, 2011 at 9:35 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > Do you have CONFIG_RCU_CPU_STALL_DETECTOR set?  If not, please set it.  Then,
> > set CONFIG_RCU_CPU_STALL_TIMEOUT to something like 10 (in either case), run
> > a suspend-resume cycle and see if there are any CPU stalls reported in the
> > logs.
> 
> Configured and see nothing specific. The 30 seconds delays is
> indicated below in the dmesg at resume ...
> 
> 2011-01-18T13:00:48.399866+08:00 boston kernel: PM: early resume of
> devices complete after 50.816 msecs
> 2011-01-18T13:00:48.399868+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
> power state changed by ACPI to D0
> 2011-01-18T13:00:48.399871+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
> power state changed by ACPI to D0
> 2011-01-18T13:00:48.399874+08:00 boston kernel: i915 0000:00:02.0:
> power state changed by ACPI to D0
> 2011-01-18T13:00:48.399877+08:00 boston kernel: i915 0000:00:02.0:
> power state changed by ACPI to D0
> 2011-01-18T13:00:48.399879+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
> PCI INT D -> GSI 23 (level, low) -> IRQ 23
> 2011-01-18T13:00:48.399882+08:00 boston kernel: i915 0000:00:02.0:
> setting latency timer to 64
> 2011-01-18T13:00:48.399884+08:00 boston kernel: ehci_hcd 0000:00:1a.0:
> setting latency timer to 64
> 2011-01-18T13:00:48.399887+08:00 boston kernel: HDA Intel
> 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
> 2011-01-18T13:00:48.399889+08:00 boston kernel: HDA Intel
> 0000:00:1b.0: setting latency timer to 64
> 2011-01-18T13:00:48.399892+08:00 boston kernel: HDA Intel
> 0000:00:1b.0: irq 41 for MSI/MSI-X
> 2011-01-18T13:00:48.399894+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
> power state changed by ACPI to D0
> 2011-01-18T13:00:48.399898+08:00 boston kernel: pci 0000:00:1e.0:
> setting latency timer to 64
> 2011-01-18T13:00:48.399901+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
> power state changed by ACPI to D0
> 2011-01-18T13:00:48.399904+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
> PCI INT D -> GSI 19 (level, low) -> IRQ 19
> 2011-01-18T13:00:48.399906+08:00 boston kernel: ehci_hcd 0000:00:1d.0:
> setting latency timer to 64
> 2011-01-18T13:00:48.399941+08:00 boston kernel: ahci 0000:00:1f.2:
> setting latency timer to 64
> 2011-01-18T13:00:48.399943+08:00 boston kernel: sd 0:0:0:0: [sda] Starting disk
> 2011-01-18T13:00:48.399946+08:00 boston kernel: ioremap error for
> 0xbb77e000-0xbb781000, requested 0x10, got 0x0

Hmm.  That's suspicious.

Do you see that ioremap failure with the patch posted previously?

> 2011-01-18T13:00:48.399949+08:00 boston kernel: ata1: SATA link up 3.0
> Gbps (SStatus 123 SControl 300)
> 2011-01-18T13:00:48.399953+08:00 boston kernel: ata1.00: ACPI cmd
> ef/02:00:00:00:00:a0 (unknown) succeeded
> 2011-01-18T13:00:48.399955+08:00 boston kernel: ata1.00: ACPI cmd
> f5/00:00:00:00:00:a0 (unknown) filtered out
> 2011-01-18T13:00:48.399958+08:00 boston kernel: ata1.00: ACPI cmd
> ef/10:03:00:00:00:a0 (unknown) filtered out
> 2011-01-18T13:00:48.399961+08:00 boston kernel: ata1.00: ACPI cmd
> ef/02:00:00:00:00:a0 (unknown) succeeded
> 2011-01-18T13:00:48.399963+08:00 boston kernel: ata1.00: ACPI cmd
> f5/00:00:00:00:00:a0 (unknown) filtered out
> 2011-01-18T13:00:48.399966+08:00 boston kernel: ata1.00: ACPI cmd
> ef/10:03:00:00:00:a0 (unknown) filtered out
> 2011-01-18T13:00:48.399968+08:00 boston kernel: ata1.00: configured for UDMA/100
> 2011-01-18T13:00:48.399970+08:00 boston kernel: ata5: SATA link down
> (SStatus 0 SControl 300)
> 2011-01-18T13:00:48.399973+08:00 boston kernel: ata6: SATA link down
> (SStatus 0 SControl 300)
> 2011-01-18T13:00:48.399975+08:00 boston kernel: PM: resume of devices
> complete after 407.508 msecs
> <============= 30 seconds delays here =============>
> 2011-01-18T13:00:48.399977+08:00 boston kernel: Restarting tasks ... done.

But the timestamp doesn't seem to reflect the delay, or am I missing anything?

Please apply the appended patch (without the previous one) and post a dmesg
log containing a suspend-resume cycle with the delay.  I wonder where exactly
the delay occurs.

> >> Now I have another problem which might be totally unrelated. Just
> >> realized that my notebook can't suspend to "disk" ... used to work
> >> last week. So, something has changed as well. May be someone has
> >> already reported/fixed this.
> >
> > Not that I know of.  What do you mean by "can't suspend"?
> 
> 
> echo platform >/sys/power/disk; echo disk >/sys/power/state
> 
> Last line I see is ... "Suspending console(s) (use no_console_suspend
> to debug)" .. and activity after that.

That may be related to the NVS code issue, though I'm not sure.

Thanks,
Rafael

---
 drivers/acpi/osl.c |    3 +++
 1 file changed, 3 insertions(+)

Index: linux-2.6/drivers/acpi/osl.c
===================================================================
--- linux-2.6.orig/drivers/acpi/osl.c
+++ linux-2.6/drivers/acpi/osl.c
@@ -383,7 +383,10 @@ void __ref acpi_os_unmap_memory(void __i
 	if (!del)
 		return;
 
+	pr_info("%s: synchronize_rcu()\n", __func__);
 	synchronize_rcu();
+	pr_info("%s: iounmap(%p), physaddr: %llx, size: %u\n", __func__,
+		map->virt, map->phys, map->size);
 	iounmap(map->virt);
 	kfree(map);
 }

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Jeff Chua]

On Wed, Jan 19, 2011 at 4:20 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> Please apply the appended patch (without the previous one) and post a dmesg
> log containing a suspend-resume cycle with the delay.  I wonder where exactly
> the delay occurs.
> +       pr_info("%s: synchronize_rcu()\n", __func__);
>        synchronize_rcu();
> +       pr_info("%s: iounmap(%p), physaddr: %llx, size: %u\n", __func__,
> +               map->virt, map->phys, map->size);

Rafael,

The 30 seconds is due to this ...

PM: Syncing filesystems ... done.
Freezing user space processes ... _memory: synchronize_rcu()
acpi_os_unmap_memory: iounmap(ffffc90001c22000), physaddr: bb398000, size: 4096
acpi_os_unmap_memory: synchronize_rcu()
acpi_os_unmap_memory: iounmap(ffffc90001c26000), physaddr: bb399000, size: 4096
acpi_os_unmap_memory: synchronize_rcu()
acpi_os_unmap_memory: iounmap(ffffc90001c2a000), physaddr: bb39a000, size: 4096
acpi_os_unmap_memory: synchronize_rcu()
acpi_os_unmap_memory: iounmap(ffffc90001c2e000), physaddr: bb39b000, size: 4096
<repeat till ...>
acpi_os_unmap_memory: iounmap(ffffc90003538000), physaddr: bb79d000, size: 4096
acpi_os_unmap_memory: synchronize_rcu()
acpi_os_unmap_memory: iounmap(ffffc9000353c000), physaddr: bb79e000, size: 4096
Restarting tasks ... done.

After this, I see my X windows.


Thanks,
Jeff
--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Rafael J. Wysocki]

On Wednesday, January 19, 2011, Jeff Chua wrote:
> On Wed, Jan 19, 2011 at 4:20 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > Please apply the appended patch (without the previous one) and post a dmesg
> > log containing a suspend-resume cycle with the delay.  I wonder where exactly
> > the delay occurs.
> > +       pr_info("%s: synchronize_rcu()\n", __func__);
> >        synchronize_rcu();
> > +       pr_info("%s: iounmap(%p), physaddr: %llx, size: %u\n", __func__,
> > +               map->virt, map->phys, map->size);
> 
> Rafael,
> 
> The 30 seconds is due to this ...
> 
> PM: Syncing filesystems ... done.
> Freezing user space processes ... _memory: synchronize_rcu()
> acpi_os_unmap_memory: iounmap(ffffc90001c22000), physaddr: bb398000, size: 4096
> acpi_os_unmap_memory: synchronize_rcu()
> acpi_os_unmap_memory: iounmap(ffffc90001c26000), physaddr: bb399000, size: 4096
> acpi_os_unmap_memory: synchronize_rcu()
> acpi_os_unmap_memory: iounmap(ffffc90001c2a000), physaddr: bb39a000, size: 4096
> acpi_os_unmap_memory: synchronize_rcu()
> acpi_os_unmap_memory: iounmap(ffffc90001c2e000), physaddr: bb39b000, size: 4096
> <repeat till ...>
> acpi_os_unmap_memory: iounmap(ffffc90003538000), physaddr: bb79d000, size: 4096
> acpi_os_unmap_memory: synchronize_rcu()
> acpi_os_unmap_memory: iounmap(ffffc9000353c000), physaddr: bb79e000, size: 4096
> Restarting tasks ... done.
> 
> After this, I see my X windows.

Are you able to say whether the synchronize_rcu() or the iounmap() calls block?

Rafael

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Jeff Chua]

On Wed, Jan 19, 2011 at 9:38 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> On Wednesday, January 19, 2011, Jeff Chua wrote:
>> On Wed, Jan 19, 2011 at 4:20 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
>> > Please apply the appended patch (without the previous one) and post a dmesg
>> > log containing a suspend-resume cycle with the delay.  I wonder where exactly
>> > the delay occurs.
>> > +       pr_info("%s: synchronize_rcu()\n", __func__);
>> >        synchronize_rcu();
>> > +       pr_info("%s: iounmap(%p), physaddr: %llx, size: %u\n", __func__,
>> > +               map->virt, map->phys, map->size);
>>
>> Rafael,
>>
>> The 30 seconds is due to this ...
>>
>> PM: Syncing filesystems ... done.
>> Freezing user space processes ... _memory: synchronize_rcu()
>> acpi_os_unmap_memory: iounmap(ffffc90001c22000), physaddr: bb398000, size: 4096
>> acpi_os_unmap_memory: synchronize_rcu()
>> acpi_os_unmap_memory: iounmap(ffffc90001c26000), physaddr: bb399000, size: 4096
00), physaddr: bb79e000, size: 4096
>> Restarting tasks ... done.
>>
>> After this, I see my X windows.
>
> Are you able to say whether the synchronize_rcu() or the iounmap() calls block?

It's "synchronize_rcu()" that's causing the slow down. Removing it
solves the problem.

Does synchronize_rcu() triggers the limiting update rate as described
in Documentation/RCU/whatisRCU.txt?

        In addition, the synchronize_rcu() API has the nice property
        of automatically limiting update rate should grace periods
        be delayed.  This property results in system resilience in face
        of denial-of-service attacks.


Thanks,
Jeff
--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Rafael J. Wysocki]

On Wednesday, January 19, 2011, Jeff Chua wrote:
> On Wed, Jan 19, 2011 at 9:38 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > On Wednesday, January 19, 2011, Jeff Chua wrote:
> >> On Wed, Jan 19, 2011 at 4:20 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> >> > Please apply the appended patch (without the previous one) and post a dmesg
> >> > log containing a suspend-resume cycle with the delay.  I wonder where exactly
> >> > the delay occurs.
> >> > +       pr_info("%s: synchronize_rcu()\n", __func__);
> >> >        synchronize_rcu();
> >> > +       pr_info("%s: iounmap(%p), physaddr: %llx, size: %u\n", __func__,
> >> > +               map->virt, map->phys, map->size);
> >>
> >> Rafael,
> >>
> >> The 30 seconds is due to this ...
> >>
> >> PM: Syncing filesystems ... done.
> >> Freezing user space processes ... _memory: synchronize_rcu()
> >> acpi_os_unmap_memory: iounmap(ffffc90001c22000), physaddr: bb398000, size: 4096
> >> acpi_os_unmap_memory: synchronize_rcu()
> >> acpi_os_unmap_memory: iounmap(ffffc90001c26000), physaddr: bb399000, size: 4096
> 00), physaddr: bb79e000, size: 4096
> >> Restarting tasks ... done.
> >>
> >> After this, I see my X windows.
> >
> > Are you able to say whether the synchronize_rcu() or the iounmap() calls block?
> 
> It's "synchronize_rcu()" that's causing the slow down. Removing it
> solves the problem.

That confirms my theory, thanks.

> Does synchronize_rcu() triggers the limiting update rate as described
> in Documentation/RCU/whatisRCU.txt?
> 
>         In addition, the synchronize_rcu() API has the nice property
>         of automatically limiting update rate should grace periods
>         be delayed.  This property results in system resilience in face
>         of denial-of-service attacks.

Well, I'm not sure.  Anyway, it apparently is better to avoid calling it so
many times in a row and, quite frankly, unnecessarily.

OK, I'd like you to test the two patches I'll send in replies to this
message.

[1/2] - It will go back to using ioremap_cache() for NVS pages allocations.
[2/2] - This one will move suspend_nvs_free() before device drivers' resume
        callbacks (should avoid conflicts with the drivers' mappings).

Thanks,
Rafael

[1/2] ACPI: Introduce acpi_os_ioremap()

[Rafael J. Wysocki]

From: Rafael J. Wysocki <rjw@sisk.pl>

Commit ca9b600 (ACPI / PM: Make suspend_nvs_save() use
acpi_os_map_memory()) attempted to prevent the code in osl.c and
nvs.c from using different ioremap() variants by making the latter
use acpi_os_map_memory() for mapping the NVS pages.  However, that
also requires acpi_os_unmap_memory() to be used for unmapping them,
which causes synchronize_rcu() to be executed many times in a row
unnecessarily and introduces substantial delays during resume on
some systems.

Instead of using acpi_os_map_memory() for mapping the NVS pages in
nvs.c introduce acpi_os_ioremap() calling ioremap_cache() and make
the code in both osl.c and nvs.c use it.

Reported-by: Jeff Chua <jeff.chua.linux@gmail.com>
Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
---
 drivers/acpi/nvs.c      |    7 ++++---
 drivers/acpi/osl.c      |   12 +++++++-----
 include/linux/acpi.h    |    3 ---
 include/linux/acpi_io.h |   16 ++++++++++++++++
 4 files changed, 27 insertions(+), 11 deletions(-)

Index: linux-2.6/drivers/acpi/osl.c
===================================================================
--- linux-2.6.orig/drivers/acpi/osl.c
+++ linux-2.6/drivers/acpi/osl.c
@@ -38,6 +38,7 @@
 #include <linux/workqueue.h>
 #include <linux/nmi.h>
 #include <linux/acpi.h>
+#include <linux/acpi_io.h>
 #include <linux/efi.h>
 #include <linux/ioport.h>
 #include <linux/list.h>
@@ -302,9 +303,10 @@ void __iomem *__init_refok
 acpi_os_map_memory(acpi_physical_address phys, acpi_size size)
 {
 	struct acpi_ioremap *map, *tmp_map;
-	unsigned long flags, pg_sz;
+	unsigned long flags;
 	void __iomem *virt;
-	phys_addr_t pg_off;
+	acpi_physical_address pg_off;
+	acpi_size pg_sz;
 
 	if (phys > ULONG_MAX) {
 		printk(KERN_ERR PREFIX "Cannot map memory that high\n");
@@ -320,7 +322,7 @@ acpi_os_map_memory(acpi_physical_address
 
 	pg_off = round_down(phys, PAGE_SIZE);
 	pg_sz = round_up(phys + size, PAGE_SIZE) - pg_off;
-	virt = ioremap_cache(pg_off, pg_sz);
+	virt = acpi_os_ioremap(pg_off, pg_sz);
 	if (!virt) {
 		kfree(map);
 		return NULL;
@@ -642,7 +644,7 @@ acpi_os_read_memory(acpi_physical_addres
 	virt_addr = acpi_map_vaddr_lookup(phys_addr, size);
 	rcu_read_unlock();
 	if (!virt_addr) {
-		virt_addr = ioremap_cache(phys_addr, size);
+		virt_addr = acpi_os_ioremap(phys_addr, size);
 		unmap = 1;
 	}
 	if (!value)
@@ -678,7 +680,7 @@ acpi_os_write_memory(acpi_physical_addre
 	virt_addr = acpi_map_vaddr_lookup(phys_addr, size);
 	rcu_read_unlock();
 	if (!virt_addr) {
-		virt_addr = ioremap_cache(phys_addr, size);
+		virt_addr = acpi_os_ioremap(phys_addr, size);
 		unmap = 1;
 	}
 
Index: linux-2.6/drivers/acpi/nvs.c
===================================================================
--- linux-2.6.orig/drivers/acpi/nvs.c
+++ linux-2.6/drivers/acpi/nvs.c
@@ -12,6 +12,7 @@
 #include <linux/mm.h>
 #include <linux/slab.h>
 #include <linux/acpi.h>
+#include <linux/acpi_io.h>
 #include <acpi/acpiosxf.h>
 
 /*
@@ -80,7 +81,7 @@ void suspend_nvs_free(void)
 			free_page((unsigned long)entry->data);
 			entry->data = NULL;
 			if (entry->kaddr) {
-				acpi_os_unmap_memory(entry->kaddr, entry->size);
+				iounmap(entry->kaddr);
 				entry->kaddr = NULL;
 			}
 		}
@@ -114,8 +115,8 @@ int suspend_nvs_save(void)
 
 	list_for_each_entry(entry, &nvs_list, node)
 		if (entry->data) {
-			entry->kaddr = acpi_os_map_memory(entry->phys_start,
-							  entry->size);
+			entry->kaddr = acpi_os_ioremap(entry->phys_start,
+						    entry->size);
 			if (!entry->kaddr) {
 				suspend_nvs_free();
 				return -ENOMEM;
Index: linux-2.6/include/linux/acpi.h
===================================================================
--- linux-2.6.orig/include/linux/acpi.h
+++ linux-2.6/include/linux/acpi.h
@@ -306,9 +306,6 @@ extern acpi_status acpi_pci_osc_control_
 					     u32 *mask, u32 req);
 extern void acpi_early_init(void);
 
-int acpi_os_map_generic_address(struct acpi_generic_address *addr);
-void acpi_os_unmap_generic_address(struct acpi_generic_address *addr);
-
 #else	/* !CONFIG_ACPI */
 
 #define acpi_disabled 1
Index: linux-2.6/include/linux/acpi_io.h
===================================================================
--- /dev/null
+++ linux-2.6/include/linux/acpi_io.h
@@ -0,0 +1,16 @@
+#ifndef _ACPI_IO_H_
+#define _ACPI_IO_H_
+
+#include <linux/io.h>
+#include <acpi/acpi.h>
+
+static inline void __iomem *acpi_os_ioremap(acpi_physical_address phys,
+					    acpi_size size)
+{
+       return ioremap_cache(phys, size);
+}
+
+int acpi_os_map_generic_address(struct acpi_generic_address *addr);
+void acpi_os_unmap_generic_address(struct acpi_generic_address *addr);
+
+#endif

[2/2] ACPI / PM: Call suspend_nvs_free() earlier during resume

[Rafael J. Wysocki]

From: Rafael J. Wysocki <rjw@sisk.pl>

It turns out that some device drivers map pages from the ACPI NVS
region during resume using ioremap(), which conflicts with
ioremap_cache() used for mapping those pages by the NVS save/restore
code in nvs.c.

Make the NVS pages mapped by the code in nvs.c be unmapped before
device drivers' resume routines run.

Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
---
 drivers/acpi/sleep.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Index: linux-2.6/drivers/acpi/sleep.c
===================================================================
--- linux-2.6.orig/drivers/acpi/sleep.c
+++ linux-2.6/drivers/acpi/sleep.c
@@ -166,6 +166,7 @@ static void acpi_pm_finish(void)
 	u32 acpi_state = acpi_target_sleep_state;
 
 	acpi_ec_unblock_transactions();
+	suspend_nvs_free();
 
 	if (acpi_state == ACPI_STATE_S0)
 		return;
@@ -186,7 +187,6 @@ static void acpi_pm_finish(void)
  */
 static void acpi_pm_end(void)
 {
-	suspend_nvs_free();
 	/*
 	 * This is necessary in case acpi_pm_finish() is not called during a
 	 * failing transition to a sleep state.

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Jeff Chua]

On Thu, Jan 20, 2011 at 5:19 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> OK, I'd like you to test the two patches I'll send in replies to this
> message.
> [1/2] - It will go back to using ioremap_cache() for NVS pages allocations.

Applied. This one makes resume effective.

> [2/2] - This one will move suspend_nvs_free() before device drivers' resume
>        callbacks (should avoid conflicts with the drivers' mappings).

Applied. This one makes no difference. Without applying [1/2], this
one makes resume hangs, so definitely needs to go along with [1/2].

Applied both and I've tried a few cycles and resume still working ok.

Thanks,
Jeff
--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [linux-pm] Resume from Memory very slow on 2.6.37+

[Rafael J. Wysocki]

On Thursday, January 20, 2011, Jeff Chua wrote:
> On Thu, Jan 20, 2011 at 5:19 AM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > OK, I'd like you to test the two patches I'll send in replies to this
> > message.
> > [1/2] - It will go back to using ioremap_cache() for NVS pages allocations.
> 
> Applied. This one makes resume effective.
> 
> > [2/2] - This one will move suspend_nvs_free() before device drivers' resume
> >        callbacks (should avoid conflicts with the drivers' mappings).
> 
> Applied. This one makes no difference. Without applying [1/2], this
> one makes resume hangs, so definitely needs to go along with [1/2].
> 
> Applied both and I've tried a few cycles and resume still working ok.

OK, thanks.

Len, can you push https://patchwork.kernel.org/patch/490071/ and
https://patchwork.kernel.org/patch/490061/ to Linus, please?

Rafael