Long delays while hibernating

Long delays while hibernating

[Pedro Ribeiro]

Hi,

I have a 2.6.32.2 kernel with the TuxOnIce and KDB patches. When I
hibernate, the penultimate phase is the "Atomic copy/restore". On
normal conditions, this takes 1 second or less.

I have a Thinkpad T400 with an ultrabay, which is a hot-swappable
drive enclosure, which can take in an optical drive (my case), hard
disk or extra battery.
To save some battery, I use the script here
http://www.thinkwiki.org/wiki/How_to_hotswap_UltraBay_devices#Script_for_Ultrabay_eject
to power off the ultrabay.

Then when I hibernate with the ultrabay powered off, the "Atomic
copy/restore" phase takes 30 seconds and sometimes even a hard lockup
occurs.
Just at the start of "Atomic copy/restore", the drive gets polled (the
light flashes for a second and makes some loading noise) and then
takes the CPU to 100% (I can hear the fan roar) for 30 seconds.

I'm sure this is related to the fact that the ultrabay is powered off.
There nothing else that triggers this.

I tried using KDB to interrupt during this phase but that doesn't
work. Only after the operation is complete KDB jumps in, so there is
no way to interrupt whatever is happening.

I reported this issue to the TuxOnIce developer, and he asked me to
report it to you.

What happens in dmesg after I exec the eject script:
Dec 23 03:43:03 portatel botto: ultrabay_eject starting eject of
/sys/devices/platform/dock.2
Dec 23 03:43:03 portatel botto: ultrabay_eject dock occupied, shutting
down storage device
/devices/pci0000:00/0000:00:1f.2/host1/target1:0:0/1:0:0:0
Dec 23 03:43:03 portatel kernel: [10244.666018] ata2.00: exception
Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
Dec 23 03:43:03 portatel kernel: [10244.666023] ata2.00: waking up from sleep
Dec 23 03:43:03 portatel kernel: [10244.666031] ata2: hard resetting link
Dec 23 03:43:04 portatel kernel: [10244.971059] ata2: SATA link up 1.5
Gbps (SStatus 113 SControl 300)
Dec 23 03:43:04 portatel kernel: [10245.042095] ata2.00: ACPI cmd
e3/00:79:00:00:00:a0 (IDLE) succeeded
Dec 23 03:43:04 portatel kernel: [10245.042954] ata2.00: ACPI cmd
e3/00:01:00:00:00:a0 (IDLE) succeeded
Dec 23 03:43:04 portatel kernel: [10245.053309] ata2.00: ACPI cmd
e3/00:79:00:00:00:a0 (IDLE) succeeded
Dec 23 03:43:04 portatel kernel: [10245.054188] ata2.00: ACPI cmd
e3/00:01:00:00:00:a0 (IDLE) succeeded
Dec 23 03:43:04 portatel kernel: [10245.057976] ata2.00: configured for UDMA/133
Dec 23 03:43:04 portatel kernel: [10245.167055] ata2: EH complete
Dec 23 03:43:05 portatel kernel: [10245.858366] ata2.00: disabled
Dec 23 03:43:05 portatel kernel: [10245.858422] scsi 1:0:0:0:
rejecting I/O to dead device
Dec 23 03:43:05 portatel kernel: [10245.858788] scsi 1:0:0:0:
rejecting I/O to dead device
Dec 23 03:43:06 portatel botto: ultrabay_eject undocking
/sys/devices/platform/dock.2
Dec 23 03:43:06 portatel kernel: [10246.765655] ACPI:
\_SB_.PCI0.SATA.PRT1 - undocking
Dec 23 03:43:06 portatel kernel: [10246.766119] ata2: exception Emask
0x10 SAct 0x0 SErr 0x4010000 action 0xe frozen
Dec 23 03:43:06 portatel kernel: [10246.766122] ata2: irq_stat
0x00400040, connection status changed
Dec 23 03:43:06 portatel kernel: [10246.766125] ata2: SError: {
PHYRdyChg DevExch }
Dec 23 03:43:06 portatel kernel: [10246.766132] ata2: hard resetting link
Dec 23 03:43:06 portatel botto: ultrabay_eject done
Dec 23 03:43:06 portatel kernel: [10247.490097] ata2: SATA link down
(SStatus 0 SControl 300)
Dec 23 03:43:06 portatel kernel: [10247.490119] ata2: EH complete

Some info you might find interesting:
lspci -vv, http://pastebin.com/m2c217b4e
dmesg, http://pastebin.com/m491ab4db
.config, http://pastebin.com/m2e4352fe

Thanks for your help,
Pedro

Re: Long delays while hibernating

[Tejun Heo]

On 12/23/2009 12:50 PM, Pedro Ribeiro wrote:
> Hi,
> 
> I have a 2.6.32.2 kernel with the TuxOnIce and KDB patches. When I
> hibernate, the penultimate phase is the "Atomic copy/restore". On
> normal conditions, this takes 1 second or less.
> 
> I have a Thinkpad T400 with an ultrabay, which is a hot-swappable
> drive enclosure, which can take in an optical drive (my case), hard
> disk or extra battery.
> To save some battery, I use the script here
> http://www.thinkwiki.org/wiki/How_to_hotswap_UltraBay_devices#Script_for_Ultrabay_eject
> to power off the ultrabay.
> 
> Then when I hibernate with the ultrabay powered off, the "Atomic
> copy/restore" phase takes 30 seconds and sometimes even a hard lockup
> occurs.
> Just at the start of "Atomic copy/restore", the drive gets polled (the
> light flashes for a second and makes some loading noise) and then
> takes the CPU to 100% (I can hear the fan roar) for 30 seconds.
> 
> I'm sure this is related to the fact that the ultrabay is powered off.
> There nothing else that triggers this.
> 
> I tried using KDB to interrupt during this phase but that doesn't
> work. Only after the operation is complete KDB jumps in, so there is
> no way to interrupt whatever is happening.
> 
> I reported this issue to the TuxOnIce developer, and he asked me to
> report it to you.

Can you please attach the output of dmidecode?

Thanks.

-- 
tejun

Re: Long delays while hibernating

[Pedro Ribeiro]

On Wed, Dec 23, 2009 at 7:47 AM, Tejun Heo <tj@kernel.org> wrote:
> On 12/23/2009 12:50 PM, Pedro Ribeiro wrote:
>> Hi,
>>
>> I have a 2.6.32.2 kernel with the TuxOnIce and KDB patches. When I
>> hibernate, the penultimate phase is the "Atomic copy/restore". On
>> normal conditions, this takes 1 second or less.
>>
>> I have a Thinkpad T400 with an ultrabay, which is a hot-swappable
>> drive enclosure, which can take in an optical drive (my case), hard
>> disk or extra battery.
>> To save some battery, I use the script here
>> http://www.thinkwiki.org/wiki/How_to_hotswap_UltraBay_devices#Script_for_Ultrabay_eject
>> to power off the ultrabay.
>>
>> Then when I hibernate with the ultrabay powered off, the "Atomic
>> copy/restore" phase takes 30 seconds and sometimes even a hard lockup
>> occurs.
>> Just at the start of "Atomic copy/restore", the drive gets polled (the
>> light flashes for a second and makes some loading noise) and then
>> takes the CPU to 100% (I can hear the fan roar) for 30 seconds.
>>
>> I'm sure this is related to the fact that the ultrabay is powered off.
>> There nothing else that triggers this.
>>
>> I tried using KDB to interrupt during this phase but that doesn't
>> work. Only after the operation is complete KDB jumps in, so there is
>> no way to interrupt whatever is happening.
>>
>> I reported this issue to the TuxOnIce developer, and he asked me to
>> report it to you.
>
> Can you please attach the output of dmidecode?
>
> Thanks.
>
> --
> tejun
>

Thanks for the quick reply, here is what you requested.
http://pastebin.com/m72748645


Pedro

Re: Long delays while hibernating

[Tejun Heo]

[-- Attachment #1: Type: text/plain, Size: 248 bytes --]

On 12/23/2009 10:50 PM, Pedro Ribeiro wrote:
>> Can you please attach the output of dmidecode?
> 
> Thanks for the quick reply, here is what you requested.
> http://pastebin.com/m72748645

Can you please try the attached patch?

Thanks.

-- 
tejun

[-- Attachment #2: tp-t400-broken-suspend.patch --]
[-- Type: text/x-patch, Size: 458 bytes --]

diff --git a/drivers/ata/ata_piix.c b/drivers/ata/ata_piix.c
index 19136a7..a90d52f 100644
--- a/drivers/ata/ata_piix.c
+++ b/drivers/ata/ata_piix.c
@@ -1085,6 +1085,13 @@ static int piix_broken_suspend(void)
 				DMI_MATCH(DMI_PRODUCT_NAME, "VGN-BX297XP"),
 			},
 		},
+		{
+			.ident = "ThinkPad T400",
+			.matches = {
+				DMI_MATCH(DMI_SYS_VENDOR, "LENOVO"),
+				DMI_MATCH(DMI_PRODUCT_NAME, "7417PLU"),
+			},
+		},
 
 		{ }	/* terminate list */
 	};

Re: Long delays while hibernating

[Pedro Ribeiro]

On Thu, Dec 24, 2009 at 7:45 AM, Tejun Heo <tj@kernel.org> wrote:
> On 12/23/2009 10:50 PM, Pedro Ribeiro wrote:
>>> Can you please attach the output of dmidecode?
>>
>> Thanks for the quick reply, here is what you requested.
>> http://pastebin.com/m72748645
>
> Can you please try the attached patch?
>
> Thanks.
>
> --
> tejun
>

Hi,

I tried the patch but I still have the same issue.

Thanks,
Pedro

Re: Long delays while hibernating

[Pedro Ribeiro]

On Thu, Dec 24, 2009 at 2:34 PM, Pedro Ribeiro <pedrib@gmail.com> wrote:
> On Thu, Dec 24, 2009 at 7:45 AM, Tejun Heo <tj@kernel.org> wrote:
>> On 12/23/2009 10:50 PM, Pedro Ribeiro wrote:
>>>> Can you please attach the output of dmidecode?
>>>
>>> Thanks for the quick reply, here is what you requested.
>>> http://pastebin.com/m72748645
>>
>> Can you please try the attached patch?
>>
>> Thanks.
>>
>> --
>> tejun
>>
>
> Hi,
>
> I tried the patch but I still have the same issue.
>
> Thanks,
> Pedro
>

Hi again,

I just noticed that this patch is for ata_piix. I don't have this
module loaded, as I have an ICH9 chip. The module used is ahci. Here
is the output of lsmod:
http://pastebin.com/m5468985b

Regards,
Pedro

Re: Long delays while hibernating

[Tejun Heo]

[-- Attachment #1: Type: text/plain, Size: 303 bytes --]

On 12/25/2009 12:59 AM, Pedro Ribeiro wrote:
> I just noticed that this patch is for ata_piix. I don't have this
> module loaded, as I have an ICH9 chip. The module used is ahci. Here
> is the output of lsmod:
> http://pastebin.com/m5468985b

Oh... Can you please try this one then?

Thanks.

-- 
tejun

[-- Attachment #2: insomnia.patch --]
[-- Type: text/x-patch, Size: 8910 bytes --]

diff --git a/drivers/ata/ahci.c b/drivers/ata/ahci.c
index b8bea10..dadf8b2 100644
--- a/drivers/ata/ahci.c
+++ b/drivers/ata/ahci.c
@@ -2980,6 +2980,35 @@ static inline void ahci_gtf_filter_workaround(struct ata_host *host)
 {}
 #endif
 
+#ifdef CONFIG_PM
+static void ahci_insomnia_workaround(struct ata_host *host)
+{
+	static const struct dmi_system_id sysids[] = {
+		{
+			.ident = "ThinkPad T400",
+			.matches = {
+				DMI_MATCH(DMI_SYS_VENDOR, "LENOVO"),
+				DMI_MATCH(DMI_PRODUCT_NAME, "7417PLU"),
+			},
+		},
+
+		{ }	/* terminate list */
+	};
+	struct pci_dev *pdev = to_pci_dev(host->dev);
+
+	if (pdev->bus->number != 0 || pdev->devfn != PCI_DEVFN(0x1f, 2) ||
+	    !dmi_check_system(sysids))
+		return;
+
+	dev_printk(KERN_INFO, &pdev->dev, "BIOS may access controller "
+		   "after suspend, setting INSOMNIA\n");
+	host->flags |= ATA_HOST_INSOMNIA;
+}
+#else
+static inline void ahci_insomnia_workaround(struct ata_host *host)
+{}
+#endif
+
 static int ahci_init_one(struct pci_dev *pdev, const struct pci_device_id *ent)
 {
 	static int printed_version;
@@ -3156,6 +3185,9 @@ static int ahci_init_one(struct pci_dev *pdev, const struct pci_device_id *ent)
 	/* apply gtf filter quirk */
 	ahci_gtf_filter_workaround(host);
 
+	/* need to set insomnia? */
+	ahci_insomnia_workaround(host);
+
 	/* initialize adapter */
 	rc = ahci_configure_dma_masks(pdev, hpriv->cap & HOST_CAP_64);
 	if (rc)
diff --git a/drivers/ata/ata_piix.c b/drivers/ata/ata_piix.c
index 19136a7..5ef948d 100644
--- a/drivers/ata/ata_piix.c
+++ b/drivers/ata/ata_piix.c
@@ -125,9 +125,6 @@ enum {
 	RV			= -3, /* reserved */
 
 	PIIX_AHCI_DEVICE	= 6,
-
-	/* host->flags bits */
-	PIIX_HOST_BROKEN_SUSPEND = (1 << 24),
 };
 
 enum piix_controller_ids {
@@ -173,10 +170,6 @@ static int piix_sidpr_scr_read(struct ata_link *link,
 			       unsigned int reg, u32 *val);
 static int piix_sidpr_scr_write(struct ata_link *link,
 				unsigned int reg, u32 val);
-#ifdef CONFIG_PM
-static int piix_pci_device_suspend(struct pci_dev *pdev, pm_message_t mesg);
-static int piix_pci_device_resume(struct pci_dev *pdev);
-#endif
 
 static unsigned int in_module_init = 1;
 
@@ -300,8 +293,8 @@ static struct pci_driver piix_pci_driver = {
 	.probe			= piix_init_one,
 	.remove			= piix_remove_one,
 #ifdef CONFIG_PM
-	.suspend		= piix_pci_device_suspend,
-	.resume			= piix_pci_device_resume,
+	.suspend		= ata_pci_device_suspend,
+	.resume			= ata_pci_device_resume,
 #endif
 };
 
@@ -963,7 +956,7 @@ static int piix_sidpr_scr_write(struct ata_link *link,
 }
 
 #ifdef CONFIG_PM
-static int piix_broken_suspend(void)
+static void piix_insomnia_workaround(struct ata_host *host)
 {
 	static const struct dmi_system_id sysids[] = {
 		{
@@ -1091,14 +1084,15 @@ static int piix_broken_suspend(void)
 	static const char *oemstrs[] = {
 		"Tecra M3,",
 	};
+	struct pci_dev *pdev = to_pci_dev(host->dev);
 	int i;
 
 	if (dmi_check_system(sysids))
-		return 1;
+		goto apply;
 
 	for (i = 0; i < ARRAY_SIZE(oemstrs); i++)
 		if (dmi_find_device(DMI_DEV_TYPE_OEM_STRING, oemstrs[i], NULL))
-			return 1;
+			goto apply;
 
 	/* TECRA M4 sometimes forgets its identify and reports bogus
 	 * DMI information.  As the bogus information is a bit
@@ -1113,76 +1107,18 @@ static int piix_broken_suspend(void)
 	    dmi_match(DMI_BOARD_VENDOR, "TOSHIBA") &&
 	    dmi_match(DMI_BOARD_NAME, "Portable PC") &&
 	    dmi_match(DMI_BOARD_VERSION, "Version A0"))
-		return 1;
-
-	return 0;
-}
-
-static int piix_pci_device_suspend(struct pci_dev *pdev, pm_message_t mesg)
-{
-	struct ata_host *host = dev_get_drvdata(&pdev->dev);
-	unsigned long flags;
-	int rc = 0;
-
-	rc = ata_host_suspend(host, mesg);
-	if (rc)
-		return rc;
-
-	/* Some braindamaged ACPI suspend implementations expect the
-	 * controller to be awake on entry; otherwise, it burns cpu
-	 * cycles and power trying to do something to the sleeping
-	 * beauty.
-	 */
-	if (piix_broken_suspend() && (mesg.event & PM_EVENT_SLEEP)) {
-		pci_save_state(pdev);
-
-		/* mark its power state as "unknown", since we don't
-		 * know if e.g. the BIOS will change its device state
-		 * when we suspend.
-		 */
-		if (pdev->current_state == PCI_D0)
-			pdev->current_state = PCI_UNKNOWN;
-
-		/* tell resume that it's waking up from broken suspend */
-		spin_lock_irqsave(&host->lock, flags);
-		host->flags |= PIIX_HOST_BROKEN_SUSPEND;
-		spin_unlock_irqrestore(&host->lock, flags);
-	} else
-		ata_pci_device_do_suspend(pdev, mesg);
-
-	return 0;
-}
-
-static int piix_pci_device_resume(struct pci_dev *pdev)
-{
-	struct ata_host *host = dev_get_drvdata(&pdev->dev);
-	unsigned long flags;
-	int rc;
-
-	if (host->flags & PIIX_HOST_BROKEN_SUSPEND) {
-		spin_lock_irqsave(&host->lock, flags);
-		host->flags &= ~PIIX_HOST_BROKEN_SUSPEND;
-		spin_unlock_irqrestore(&host->lock, flags);
-
-		pci_set_power_state(pdev, PCI_D0);
-		pci_restore_state(pdev);
+		goto apply;
 
-		/* PCI device wasn't disabled during suspend.  Use
-		 * pci_reenable_device() to avoid affecting the enable
-		 * count.
-		 */
-		rc = pci_reenable_device(pdev);
-		if (rc)
-			dev_printk(KERN_ERR, &pdev->dev, "failed to enable "
-				   "device after resume (%d)\n", rc);
-	} else
-		rc = ata_pci_device_do_resume(pdev);
+	return;
 
-	if (rc == 0)
-		ata_host_resume(host);
-
-	return rc;
+apply:
+	dev_printk(KERN_INFO, &pdev->dev, "BIOS may access controller "
+		   "after suspend, setting INSOMNIA\n");
+	host->flags |= ATA_HOST_INSOMNIA;
 }
+#else
+static inline void piix_insomnia_workaround(struct ata_host *host)
+{ }
 #endif
 
 static u8 piix_vmw_bmdma_status(struct ata_port *ap)
@@ -1604,6 +1540,9 @@ static int __devinit piix_init_one(struct pci_dev *pdev,
 		host->ports[1]->mwdma_mask = 0;
 		host->ports[1]->udma_mask = 0;
 	}
+
+	piix_insomnia_workaround(host);
+
 	host->flags |= ATA_HOST_PARALLEL_SCAN;
 
 	pci_set_master(pdev);
diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 22ff51b..3c7a1f3 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -6381,21 +6381,62 @@ int pci_test_config_bits(struct pci_dev *pdev, const struct pci_bits *bits)
 #ifdef CONFIG_PM
 void ata_pci_device_do_suspend(struct pci_dev *pdev, pm_message_t mesg)
 {
+	struct ata_host *host = dev_get_drvdata(&pdev->dev);
+	unsigned long flags;
+
 	pci_save_state(pdev);
-	pci_disable_device(pdev);
 
-	if (mesg.event & PM_EVENT_SLEEP)
-		pci_set_power_state(pdev, PCI_D3hot);
+	/*
+	 * Some braindamaged ACPI suspend implementations expect the
+	 * controller to be awake on entry; otherwise, it burns cpu
+	 * cycles and power trying to do something to the sleeping
+	 * beauty.
+	 */
+	if ((host->flags & ATA_HOST_INSOMNIA) &&
+	    (mesg.event & PM_EVENT_SLEEP)) {
+		/*
+		 * Mark its power state as "unknown", since we don't
+		 * know if e.g. the BIOS will change its device state
+		 * when we suspend.
+		 */
+		if (pdev->current_state == PCI_D0)
+			pdev->current_state = PCI_UNKNOWN;
+
+		/* tell resume that it's waking up from insomnia */
+		spin_lock_irqsave(&host->lock, flags);
+		host->flags |= ATA_HOST_IN_INSOMNIA;
+		spin_unlock_irqrestore(&host->lock, flags);
+	} else {
+		pci_disable_device(pdev);
+
+		if (mesg.event & PM_EVENT_SLEEP)
+			pci_set_power_state(pdev, PCI_D3hot);
+	}
 }
 
 int ata_pci_device_do_resume(struct pci_dev *pdev)
 {
+	struct ata_host *host = dev_get_drvdata(&pdev->dev);
+	unsigned long flags;
 	int rc;
 
 	pci_set_power_state(pdev, PCI_D0);
 	pci_restore_state(pdev);
 
-	rc = pcim_enable_device(pdev);
+	if (host->flags & ATA_HOST_IN_INSOMNIA) {
+		spin_lock_irqsave(&host->lock, flags);
+		host->flags &= ~ATA_HOST_IN_INSOMNIA;
+		spin_unlock_irqrestore(&host->lock, flags);
+
+		/*
+		 * PCI device wasn't disabled during suspend.  Use
+		 * pci_reenable_device() to avoid affecting the enable
+		 * count.
+		 */
+		rc = pci_reenable_device(pdev);
+	} else
+		rc = pcim_enable_device(pdev);
+
 	if (rc) {
 		dev_printk(KERN_ERR, &pdev->dev,
 			   "failed to enable device after resume (%d)\n", rc);
diff --git a/include/linux/libata.h b/include/linux/libata.h
index 6a9c4dd..8b60fed 100644
--- a/include/linux/libata.h
+++ b/include/linux/libata.h
@@ -243,9 +243,11 @@ enum {
 	ATA_QCFLAG_EH_SCHEDULED = (1 << 18), /* EH scheduled (obsolete) */
 
 	/* host set flags */
-	ATA_HOST_SIMPLEX	= (1 << 0),	/* Host is simplex, one DMA channel per host only */
-	ATA_HOST_STARTED	= (1 << 1),	/* Host started */
-	ATA_HOST_PARALLEL_SCAN	= (1 << 2),	/* Ports on this host can be scanned in parallel */
+	ATA_HOST_SIMPLEX	= (1 << 0), /* Host is simplex, one DMA channel per host only */
+	ATA_HOST_STARTED	= (1 << 1), /* Host started */
+	ATA_HOST_PARALLEL_SCAN	= (1 << 2), /* Ports on this host can be scanned in parallel */
+	ATA_HOST_INSOMNIA	= (1 << 3), /* Don't power down on suspend */
+	ATA_HOST_IN_INSOMNIA	= (1 << 4), /* Insomnia in progress */
 
 	/* bits 24:31 of host->flags are reserved for LLD specific flags */
 

Re: Long delays while hibernating

[Pedro Ribeiro]

On Fri, Dec 25, 2009 at 2:56 PM, Tejun Heo <tj@kernel.org> wrote:
> On 12/25/2009 12:59 AM, Pedro Ribeiro wrote:
>> I just noticed that this patch is for ata_piix. I don't have this
>> module loaded, as I have an ICH9 chip. The module used is ahci. Here
>> is the output of lsmod:
>> http://pastebin.com/m5468985b
>
> Oh... Can you please try this one then?
>
> Thanks.
>
> --
> tejun
>

Sorry, still hangs with this patch :(

This only happens in hibernation... suspend is fine.

Pedro

Re: Long delays while hibernating

[Tejun Heo]

(cc'ing Rafael)

On 12/26/2009 03:10 AM, Pedro Ribeiro wrote:
>> Oh... Can you please try this one then?
> 
> Sorry, still hangs with this patch :(
> 
> This only happens in hibernation... suspend is fine.

Hmmm... the patch does apply to both suspend and hibernation.  Rafael,
Pedro's ThinkPad T400 burns cpu cycle for 30secs on "Atomic
copy/restore" step of hibernation if the ultrabay is powered off.  The
original report can be found at...

  http://thread.gmane.org/gmane.linux.ide/44190

Please note that it's with TuxOnIce patches.  Anyways, ata_piix on
certain configurations have similar issues where after the OS is done
suspending and powering off the piix controller, the BIOS tries to
access it and ends up burning cpu cycles which can be worked around by
leaving the controller on after suspend.  Applying the same workaround
didn't resolve the issue.  Do you know what can make cpu burn for
30secs on the atomic copy/restore step?

Pedro, can you please try to reproduce the problem without TuxOnIce
patches?

Thanks.

-- 
tejun

Re: Long delays while hibernating

[Pedro Ribeiro]

On Sat, Dec 26, 2009 at 1:26 AM, Tejun Heo <tj@kernel.org> wrote:
> (cc'ing Rafael)
>
> On 12/26/2009 03:10 AM, Pedro Ribeiro wrote:
>>> Oh... Can you please try this one then?
>>
>> Sorry, still hangs with this patch :(
>>
>> This only happens in hibernation... suspend is fine.
>
> Hmmm... the patch does apply to both suspend and hibernation.  Rafael,
> Pedro's ThinkPad T400 burns cpu cycle for 30secs on "Atomic
> copy/restore" step of hibernation if the ultrabay is powered off.  The
> original report can be found at...
>
>  http://thread.gmane.org/gmane.linux.ide/44190
>
> Please note that it's with TuxOnIce patches.  Anyways, ata_piix on
> certain configurations have similar issues where after the OS is done
> suspending and powering off the piix controller, the BIOS tries to
> access it and ends up burning cpu cycles which can be worked around by
> leaving the controller on after suspend.  Applying the same workaround
> didn't resolve the issue.  Do you know what can make cpu burn for
> 30secs on the atomic copy/restore step?
>
> Pedro, can you please try to reproduce the problem without TuxOnIce
> patches?
>
> Thanks.
>
> --
> tejun
>

Hi Rafael and Tejun,

I am experiencing the same delay with the kernel swsusp, so this is
definitely not a TuxOnIce issue.

Regards,
Pedro

Re: Long delays while hibernating

[Rafael J. Wysocki]

On Saturday 26 December 2009, Pedro Ribeiro wrote:
> On Sat, Dec 26, 2009 at 1:26 AM, Tejun Heo <tj@kernel.org> wrote:
> > (cc'ing Rafael)
> >
> > On 12/26/2009 03:10 AM, Pedro Ribeiro wrote:
> >>> Oh... Can you please try this one then?
> >>
> >> Sorry, still hangs with this patch :(
> >>
> >> This only happens in hibernation... suspend is fine.
> >
> > Hmmm... the patch does apply to both suspend and hibernation.  Rafael,
> > Pedro's ThinkPad T400 burns cpu cycle for 30secs on "Atomic
> > copy/restore" step of hibernation if the ultrabay is powered off.  The
> > original report can be found at...
> >
> >  http://thread.gmane.org/gmane.linux.ide/44190
> >
> > Please note that it's with TuxOnIce patches.  Anyways, ata_piix on
> > certain configurations have similar issues where after the OS is done
> > suspending and powering off the piix controller, the BIOS tries to
> > access it and ends up burning cpu cycles which can be worked around by
> > leaving the controller on after suspend.  Applying the same workaround
> > didn't resolve the issue.  Do you know what can make cpu burn for
> > 30secs on the atomic copy/restore step?

No idea.

Is this reproducible with /sys/power/pm_test = core?

[If you echo "core" to /sys/power/pm_test and then attempt to hibernate,
it should just simulate snapshotting the system, sleep for 5 seconds and go
back to your command prompt (or wherever you started the "hibernation").]

> > Pedro, can you please try to reproduce the problem without TuxOnIce
> > patches?
> >
> > Thanks.
> >
> > --
> > tejun
> >
> 
> Hi Rafael and Tejun,
> 
> I am experiencing the same delay with the kernel swsusp, so this is
> definitely not a TuxOnIce issue.

I don't think this can be a TuxOnIce.  Most likely, ACPI is trying to do
something stupid in _PTS.

Rafael

Re: Long delays while hibernating

[Pedro Ribeiro]

[-- Attachment #1: Type: text/plain, Size: 2435 bytes --]

On Sat, Dec 26, 2009 at 9:21 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> On Saturday 26 December 2009, Pedro Ribeiro wrote:
>> On Sat, Dec 26, 2009 at 1:26 AM, Tejun Heo <tj@kernel.org> wrote:
>> > (cc'ing Rafael)
>> >
>> > On 12/26/2009 03:10 AM, Pedro Ribeiro wrote:
>> >>> Oh... Can you please try this one then?
>> >>
>> >> Sorry, still hangs with this patch :(
>> >>
>> >> This only happens in hibernation... suspend is fine.
>> >
>> > Hmmm... the patch does apply to both suspend and hibernation.  Rafael,
>> > Pedro's ThinkPad T400 burns cpu cycle for 30secs on "Atomic
>> > copy/restore" step of hibernation if the ultrabay is powered off.  The
>> > original report can be found at...
>> >
>> >  http://thread.gmane.org/gmane.linux.ide/44190
>> >
>> > Please note that it's with TuxOnIce patches.  Anyways, ata_piix on
>> > certain configurations have similar issues where after the OS is done
>> > suspending and powering off the piix controller, the BIOS tries to
>> > access it and ends up burning cpu cycles which can be worked around by
>> > leaving the controller on after suspend.  Applying the same workaround
>> > didn't resolve the issue.  Do you know what can make cpu burn for
>> > 30secs on the atomic copy/restore step?
>
> No idea.
>
> Is this reproducible with /sys/power/pm_test = core?
>
> [If you echo "core" to /sys/power/pm_test and then attempt to hibernate,
> it should just simulate snapshotting the system, sleep for 5 seconds and go
> back to your command prompt (or wherever you started the "hibernation").]
>
>> > Pedro, can you please try to reproduce the problem without TuxOnIce
>> > patches?
>> >
>> > Thanks.
>> >
>> > --
>> > tejun
>> >
>>
>> Hi Rafael and Tejun,
>>
>> I am experiencing the same delay with the kernel swsusp, so this is
>> definitely not a TuxOnIce issue.
>
> I don't think this can be a TuxOnIce.  Most likely, ACPI is trying to do
> something stupid in _PTS.
>
> Rafael
>

Hi,

The issue also occurs with pm_test.
Attached are two files, the one ending with "ok" shows a good pm_test
cycle, with the ultrabay powered on. The one ending in "bad" shows the
bad pm_test cycle with a 30 second delay between:

[  545.764159] ACPI: Waking up from system sleep state S4
[  575.844179] ACPI: \_SB_.PCI0.SATA.PRT1 - docking
(lines 48/49)

Please let me know how I can assist you.

Thanks for everything,
Pedro

[-- Attachment #2: dmesg_pmTest_ok --]
[-- Type: application/octet-stream, Size: 7942 bytes --]

[  458.301324] PM: Marking nosave pages: 000000000009e000 - 0000000000100000
[  458.301337] PM: Basic memory bitmaps created
[  458.301341] PM: Syncing filesystems ... done.
[  458.953417] Stopping fuse filesystems.
[  458.957168] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  458.962328] Stopping normal filesystems.
[  459.340747] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[  459.344812] PM: Preallocating image memory... done (allocated 861679 pages)
[  460.488840] PM: Allocated 3446716 kbytes in 1.14 seconds (3023.43 MB/s)
[  460.735931] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  460.742642] ACPI handle has no context!
[  460.786419] HDA Intel 0000:00:1b.0: PCI INT B disabled
[  460.856519] e1000e 0000:00:19.0: PCI INT A disabled
[  460.857875] e1000e 0000:00:19.0: PME# enabled
[  460.859265] e1000e 0000:00:19.0: wake-up capability enabled by ACPI
[  460.884814] ACPI: Preparing to enter system sleep state S4
[  460.952239] PM: Saving platform NVS memory
[  460.992829] Disabling non-boot CPUs ...
[  460.996465] CPU 1 is now offline
[  460.997875] SMP alternatives: switching to UP code
[  461.004094] CPU0 attaching NULL sched-domain.
[  461.004097] CPU1 attaching NULL sched-domain.
[  461.004107] CPU0 attaching NULL sched-domain.
[  461.004267] CPU1 is down
[  461.005702] Extended CMOS year: 2000
[  461.006656] hibernation debug: Waiting for 5 seconds.
[  461.006656] CPU0: Thermal monitoring enabled (TM2)
[  461.006656] Extended CMOS year: 2000
[  461.007129] Enabling non-boot CPUs ...
[  461.011129] SMP alternatives: switching to SMP code
[  461.016674] Booting processor 1 APIC 0x1 ip 0x6000
[  461.003826] Initializing CPU#1
[  461.003826] Calibrating delay using timer specific routine.. 4521.97 BogoMIPS (lpj=2260987)
[  461.003826] CPU: L1 I cache: 32K, L1 D cache: 32K
[  461.003826] CPU: L2 cache: 3072K
[  461.003826] CPU: Physical Processor ID: 0
[  461.003826] CPU: Processor Core ID: 1
[  461.003826] CPU1: Thermal monitoring enabled (TM2)
[  461.089077] CPU1: Intel(R) Core(TM)2 Duo CPU     P8400  @ 2.26GHz stepping 0a
[  461.100477] CPU0 attaching NULL sched-domain.
[  461.103015] CPU0 attaching sched-domain:
[  461.103018]  domain 0: span 0-1 level MC
[  461.103020]   groups: 0 1
[  461.103025] CPU1 attaching sched-domain:
[  461.103027]  domain 0: span 0-1 level MC
[  461.103029]   groups: 1 0
[  461.104144] CPU1 is up
[  461.106386] ACPI: Waking up from system sleep state S4
[  461.213083] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[  461.213126] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[  461.215147] uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[  461.221146] uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0
[  461.236078] HDA Intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x200, writing 0x20b)
[  461.236115] HDA Intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)
[  461.236130] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100102)
[  461.238144] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[  461.242355] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00403, writing 0x2b00407)
[  461.253203] iwlagn 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[  461.253364] iwlagn 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100506)
[  461.264095] ohci1394 0000:15:00.1: restoring config space at offset 0x3 (was 0x800000, writing 0x802010)
[  461.264112] ohci1394 0000:15:00.1: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106)
[  461.454154] PM: Device PNP0C0D:00 failed to restore: error 1
[  461.473993] i915 0000:00:02.0: setting latency timer to 64
[  461.851109] [drm] LVDS-8: set mode 1280x800 18
[  462.082938] e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[  462.084343] e1000e 0000:00:19.0: setting latency timer to 64
[  462.084363] e1000e 0000:00:19.0: wake-up capability disabled by ACPI
[  462.085798] e1000e 0000:00:19.0: PME# disabled
[  462.087288] e1000e 0000:00:19.0: irq 27 for MSI/MSI-X
[  462.144402] uhci_hcd 0000:00:1a.0: setting latency timer to 64
[  462.144454] usb usb2: root hub lost power or was reset
[  462.148466] uhci_hcd 0000:00:1a.1: setting latency timer to 64
[  462.148523] usb usb4: root hub lost power or was reset
[  462.152520] uhci_hcd 0000:00:1a.2: setting latency timer to 64
[  462.152575] usb usb5: root hub lost power or was reset
[  462.154076] ehci_hcd 0000:00:1a.7: setting latency timer to 64
[  462.154089] usb usb1: root hub lost power or was reset
[  462.159414] ehci_hcd 0000:00:1a.7: cache line size of 32 is not supported
[  462.159838] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[  462.161279] HDA Intel 0000:00:1b.0: setting latency timer to 64
[  462.161305] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[  462.161343] usb usb6: root hub lost power or was reset
[  462.162782] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[  462.162831] usb usb7: root hub lost power or was reset
[  462.164253] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[  462.164300] usb usb8: root hub lost power or was reset
[  462.165699] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[  462.165711] usb usb3: root hub lost power or was reset
[  462.170948] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[  462.171422] pci 0000:00:1e.0: setting latency timer to 64
[  462.171437] ahci 0000:00:1f.2: setting latency timer to 64
[  462.171546] pci 0000:15:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[  462.226168] ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[17]  MMIO=[f4801000-f48017ff]  Max Packet=[2048]  IR/IT contexts=[4/4]
[  462.476140] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  462.480095] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  462.485825] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[  462.485836] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[  462.489784] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[  462.489794] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[  462.547918] ata2.00: ACPI cmd e3/00:79:00:00:00:a0 (IDLE) succeeded
[  462.548794] ata2.00: ACPI cmd e3/00:01:00:00:00:a0 (IDLE) succeeded
[  462.553334] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[  462.553345] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[  462.557393] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[  462.557403] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[  462.562902] ata2.00: ACPI cmd e3/00:79:00:00:00:a0 (IDLE) succeeded
[  462.563690] ata2.00: ACPI cmd e3/00:01:00:00:00:a0 (IDLE) succeeded
[  462.563949] ata1.00: configured for UDMA/133
[  462.567401] ata2.00: configured for UDMA/133
[  462.572198] ata1.00: configured for UDMA/133
[  462.574062] ata1: EH complete
[  462.584160] sd 0:0:0:0: [sda] Starting disk
[  462.637919] Registered led device: iwl-phy0::radio
[  462.641697] Registered led device: iwl-phy0::assoc
[  462.645403] Registered led device: iwl-phy0::RX
[  462.649068] Registered led device: iwl-phy0::TX
[  462.765134] smapi smapi: set_real_thresh: set stop to 0 for bat=0
[  462.872130] smapi smapi: set_real_thresh: set start to 9 for bat=0
[  462.978133] smapi smapi: set_real_thresh: set stop to 0 for bat=1
[  463.084133] smapi smapi: set_real_thresh: set start to 0 for bat=1
[  463.088273] PM: Image restored successfully.
[  463.088278] Restarting all filesystems ...
[  463.092052] Restarting tasks ... Restarting tasks ... done.
[  463.110790] PM: Basic memory bitmaps freed
[  463.194088] usb 1-6: reset high speed USB device using ehci_hcd and address 3


[-- Attachment #3: dmesg_pmTest_bad --]
[-- Type: application/octet-stream, Size: 8520 bytes --]

[  543.611322] PM: Marking nosave pages: 000000000009e000 - 0000000000100000
[  543.611335] PM: Basic memory bitmaps created
[  543.611340] PM: Syncing filesystems ... done.
[  543.675068] Stopping fuse filesystems.
[  543.678661] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  543.682064] Stopping normal filesystems.
[  544.208581] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[  544.212628] PM: Preallocating image memory... done (allocated 861683 pages)
[  545.159669] PM: Allocated 3446732 kbytes in 0.94 seconds (3666.73 MB/s)
[  545.403455] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  545.410185] ACPI handle has no context!
[  545.454351] HDA Intel 0000:00:1b.0: PCI INT B disabled
[  545.524526] e1000e 0000:00:19.0: PCI INT A disabled
[  545.525852] e1000e 0000:00:19.0: PME# enabled
[  545.527208] e1000e 0000:00:19.0: wake-up capability enabled by ACPI
[  545.553075] ACPI: Preparing to enter system sleep state S4
[  545.620250] PM: Saving platform NVS memory
[  545.649890] Disabling non-boot CPUs ...
[  545.653511] CPU 1 is now offline
[  545.654894] SMP alternatives: switching to UP code
[  545.661042] CPU0 attaching NULL sched-domain.
[  545.661045] CPU1 attaching NULL sched-domain.
[  545.661050] CPU0 attaching NULL sched-domain.
[  545.661211] CPU1 is down
[  545.662626] Extended CMOS year: 2000
[  545.663581] hibernation debug: Waiting for 5 seconds.
[  545.663581] CPU0: Thermal monitoring enabled (TM2)
[  545.663581] Extended CMOS year: 2000
[  545.664038] Enabling non-boot CPUs ...
[  545.668129] SMP alternatives: switching to SMP code
[  545.673609] Booting processor 1 APIC 0x1 ip 0x6000
[  545.660816] Initializing CPU#1
[  545.660816] Calibrating delay using timer specific routine.. 4522.03 BogoMIPS (lpj=2261018)
[  545.660816] CPU: L1 I cache: 32K, L1 D cache: 32K
[  545.660816] CPU: L2 cache: 3072K
[  545.660816] CPU: Physical Processor ID: 0
[  545.660816] CPU: Processor Core ID: 1
[  545.660816] CPU1: Thermal monitoring enabled (TM2)
[  545.746110] CPU1: Intel(R) Core(TM)2 Duo CPU     P8400  @ 2.26GHz stepping 0a
[  545.757384] CPU0 attaching NULL sched-domain.
[  545.760030] CPU0 attaching sched-domain:
[  545.760034]  domain 0: span 0-1 level MC
[  545.760038]   groups: 0 1
[  545.760044] CPU1 attaching sched-domain:
[  545.760047]  domain 0: span 0-1 level MC
[  545.760050]   groups: 1 0
[  545.761150] CPU1 is up
[  545.764159] ACPI: Waking up from system sleep state S4
[  575.844179] ACPI: \_SB_.PCI0.SATA.PRT1 - docking
[  575.849362] acpi LNXIOBAY:02: parent device:15 should not be sleeping
[  575.886084] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[  575.886127] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[  575.888147] uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[  575.894145] uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0
[  575.909078] HDA Intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x200, writing 0x20b)
[  575.909115] HDA Intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)
[  575.909130] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100102)
[  575.911146] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[  575.915349] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00403, writing 0x2b00407)
[  575.926207] iwlagn 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[  575.926369] iwlagn 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100506)
[  575.937095] ohci1394 0000:15:00.1: restoring config space at offset 0x3 (was 0x800000, writing 0x802010)
[  575.937112] ohci1394 0000:15:00.1: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106)
[  576.125152] PM: Device PNP0C0D:00 failed to restore: error 1
[  576.145468] i915 0000:00:02.0: setting latency timer to 64
[  576.522434] [drm] LVDS-8: set mode 1280x800 18
[  576.676576] e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[  576.678025] e1000e 0000:00:19.0: setting latency timer to 64
[  576.678045] e1000e 0000:00:19.0: wake-up capability disabled by ACPI
[  576.679561] e1000e 0000:00:19.0: PME# disabled
[  576.681050] e1000e 0000:00:19.0: irq 27 for MSI/MSI-X
[  576.738309] uhci_hcd 0000:00:1a.0: setting latency timer to 64
[  576.738352] usb usb2: root hub lost power or was reset
[  576.740433] uhci_hcd 0000:00:1a.1: setting latency timer to 64
[  576.740477] usb usb4: root hub lost power or was reset
[  576.741996] uhci_hcd 0000:00:1a.2: setting latency timer to 64
[  576.742042] usb usb5: root hub lost power or was reset
[  576.743542] ehci_hcd 0000:00:1a.7: setting latency timer to 64
[  576.743547] usb usb1: root hub lost power or was reset
[  576.748844] ehci_hcd 0000:00:1a.7: cache line size of 32 is not supported
[  576.749283] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[  576.750730] HDA Intel 0000:00:1b.0: setting latency timer to 64
[  576.750755] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[  576.750794] usb usb6: root hub lost power or was reset
[  576.752247] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[  576.752294] usb usb7: root hub lost power or was reset
[  576.753719] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[  576.753765] usb usb8: root hub lost power or was reset
[  576.755153] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[  576.755166] usb usb3: root hub lost power or was reset
[  576.760410] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[  576.760874] pci 0000:00:1e.0: setting latency timer to 64
[  576.760885] ahci 0000:00:1f.2: setting latency timer to 64
[  576.760995] pci 0000:15:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[  576.816186] ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[17]  MMIO=[f4801000-f48017ff]  Max Packet=[2048]  IR/IT contexts=[4/4]
[  577.065143] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  577.069055] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  577.074793] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[  577.074804] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[  577.078820] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[  577.078830] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[  577.137946] ata2.00: ACPI cmd e3/00:79:00:00:00:a0 (IDLE) succeeded
[  577.138824] ata2.00: ACPI cmd e3/00:01:00:00:00:a0 (IDLE) succeeded
[  577.142564] ata2.00: ATAPI: HL-DT-ST DVDRAM GSA-U20N, HX12, max UDMA/133
[  577.152663] ata2.00: ACPI cmd e3/00:79:00:00:00:a0 (IDLE) succeeded
[  577.153511] ata2.00: ACPI cmd e3/00:01:00:00:00:a0 (IDLE) succeeded
[  577.157252] ata2.00: configured for UDMA/133
[  577.173223] sd 0:0:0:0: [sda] Starting disk
[  577.437728] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[  577.437740] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[  577.441965] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[  577.441975] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[  577.448290] ata1.00: configured for UDMA/133
[  577.458111] ata1.00: configured for UDMA/133
[  577.462091] ata1: EH complete
[  577.508466] Registered led device: iwl-phy0::radio
[  577.509908] Registered led device: iwl-phy0::assoc
[  577.513665] Registered led device: iwl-phy0::RX
[  577.515145] Registered led device: iwl-phy0::TX
[  577.629132] smapi smapi: set_real_thresh: set stop to 0 for bat=0
[  577.736132] smapi smapi: set_real_thresh: set start to 9 for bat=0
[  577.842132] smapi smapi: set_real_thresh: set stop to 0 for bat=1
[  577.948132] smapi smapi: set_real_thresh: set start to 0 for bat=1
[  577.952878] PM: Image restored successfully.
[  577.952880] Restarting all filesystems ...
[  577.954368] Restarting tasks ... Restarting tasks ... 
[  577.985560] wlan0: deauthenticated from 00:22:6b:48:94:f2 (Reason: 7)
[  578.004018] done.
[  578.005909] PM: Basic memory bitmaps freed
[  578.056093] usb 1-6: reset high speed USB device using ehci_hcd and address 3
[  579.003365] scsi 1:0:0:0: CD-ROM            HL-DT-ST DVDRAM GSA-U20N  HX12 PQ: 0 ANSI: 5
[  579.335589] sr0: scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
[  579.335836] sr 1:0:0:0: Attached scsi CD-ROM sr0
[  579.335989] sr 1:0:0:0: Attached scsi generic sg1 type 5

Re: Long delays while hibernating

[Rafael J. Wysocki]

On Saturday 26 December 2009, Pedro Ribeiro wrote:
> On Sat, Dec 26, 2009 at 9:21 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > On Saturday 26 December 2009, Pedro Ribeiro wrote:
> >> On Sat, Dec 26, 2009 at 1:26 AM, Tejun Heo <tj@kernel.org> wrote:
> >> > (cc'ing Rafael)
> >> >
> >> > On 12/26/2009 03:10 AM, Pedro Ribeiro wrote:
> >> >>> Oh... Can you please try this one then?
> >> >>
> >> >> Sorry, still hangs with this patch :(
> >> >>
> >> >> This only happens in hibernation... suspend is fine.
> >> >
> >> > Hmmm... the patch does apply to both suspend and hibernation.  Rafael,
> >> > Pedro's ThinkPad T400 burns cpu cycle for 30secs on "Atomic
> >> > copy/restore" step of hibernation if the ultrabay is powered off.  The
> >> > original report can be found at...
> >> >
> >> >  http://thread.gmane.org/gmane.linux.ide/44190
> >> >
> >> > Please note that it's with TuxOnIce patches.  Anyways, ata_piix on
> >> > certain configurations have similar issues where after the OS is done
> >> > suspending and powering off the piix controller, the BIOS tries to
> >> > access it and ends up burning cpu cycles which can be worked around by
> >> > leaving the controller on after suspend.  Applying the same workaround
> >> > didn't resolve the issue.  Do you know what can make cpu burn for
> >> > 30secs on the atomic copy/restore step?
> >
> > No idea.
> >
> > Is this reproducible with /sys/power/pm_test = core?
> >
> > [If you echo "core" to /sys/power/pm_test and then attempt to hibernate,
> > it should just simulate snapshotting the system, sleep for 5 seconds and go
> > back to your command prompt (or wherever you started the "hibernation").]
> >
> >> > Pedro, can you please try to reproduce the problem without TuxOnIce
> >> > patches?
> >> >
> >> > Thanks.
> >> >
> >> > --
> >> > tejun
> >> >
> >>
> >> Hi Rafael and Tejun,
> >>
> >> I am experiencing the same delay with the kernel swsusp, so this is
> >> definitely not a TuxOnIce issue.
> >
> > I don't think this can be a TuxOnIce.  Most likely, ACPI is trying to do
> > something stupid in _PTS.
> >
> > Rafael
> >
> 
> Hi,
> 
> The issue also occurs with pm_test.
> Attached are two files, the one ending with "ok" shows a good pm_test
> cycle, with the ultrabay powered on. The one ending in "bad" shows the
> bad pm_test cycle with a 30 second delay between:
> 
> [  545.764159] ACPI: Waking up from system sleep state S4
> [  575.844179] ACPI: \_SB_.PCI0.SATA.PRT1 - docking
> (lines 48/49)
> 
> Please let me know how I can assist you.

Please echo "shutdown" to /sys/power/disk and rerun the test with
/sys/power/pm_test = core.

Rafael

Re: Long delays while hibernating

[Pedro Ribeiro]

[-- Attachment #1: Type: text/plain, Size: 414 bytes --]

>
> Please echo "shutdown" to /sys/power/disk and rerun the test with
> /sys/power/pm_test = core.
>
> Rafael
> --
> To unsubscribe from this list: send the line "unsubscribe linux-ide" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Right on the money Rafael!

This time there was no delay, as both logs show.

Pedro

[-- Attachment #2: dmesg_pmTest_bad2 --]
[-- Type: application/octet-stream, Size: 7122 bytes --]

[ 7198.318249] PM: Marking nosave pages: 000000000009e000 - 0000000000100000
[ 7198.318254] PM: Basic memory bitmaps created
[ 7198.318255] PM: Syncing filesystems ... done.
[ 7211.069972] Stopping fuse filesystems.
[ 7211.073654] Freezing user space processes ... (elapsed 0.00 seconds) done.
[ 7211.075849] Stopping normal filesystems.
[ 7211.467471] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[ 7211.471450] PM: Preallocating image memory... done (allocated 861663 pages)
[ 7212.190630] PM: Allocated 3446652 kbytes in 0.71 seconds (4854.43 MB/s)
[ 7212.434827] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 7212.444402] ACPI handle has no context!
[ 7212.488351] HDA Intel 0000:00:1b.0: PCI INT B disabled
[ 7212.547517] e1000e 0000:00:19.0: PCI INT A disabled
[ 7212.548889] e1000e 0000:00:19.0: PME# enabled
[ 7212.550288] e1000e 0000:00:19.0: wake-up capability enabled by ACPI
[ 7212.575949] Disabling non-boot CPUs ...
[ 7212.582193] CPU 1 is now offline
[ 7212.584704] SMP alternatives: switching to UP code
[ 7212.591016] CPU0 attaching NULL sched-domain.
[ 7212.591019] CPU1 attaching NULL sched-domain.
[ 7212.591024] CPU0 attaching NULL sched-domain.
[ 7212.591186] CPU1 is down
[ 7212.592642] Extended CMOS year: 2000
[ 7212.593596] hibernation debug: Waiting for 5 seconds.
[ 7212.593596] CPU0: Thermal monitoring enabled (TM2)
[ 7212.593596] Extended CMOS year: 2000
[ 7212.594055] Enabling non-boot CPUs ...
[ 7212.598128] SMP alternatives: switching to SMP code
[ 7212.603728] Booting processor 1 APIC 0x1 ip 0x6000
[ 7212.590751] Initializing CPU#1
[ 7212.590751] Calibrating delay using timer specific routine.. 4522.03 BogoMIPS (lpj=2261016)
[ 7212.590751] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 7212.590751] CPU: L2 cache: 3072K
[ 7212.590751] CPU: Physical Processor ID: 0
[ 7212.590751] CPU: Processor Core ID: 1
[ 7212.590751] CPU1: Thermal monitoring enabled (TM2)
[ 7212.676067] CPU1: Intel(R) Core(TM)2 Duo CPU     P8400  @ 2.26GHz stepping 0a
[ 7212.686410] CPU0 attaching NULL sched-domain.
[ 7212.689015] CPU0 attaching sched-domain:
[ 7212.689018]  domain 0: span 0-1 level MC
[ 7212.689020]   groups: 0 1
[ 7212.689025] CPU1 attaching sched-domain:
[ 7212.689027]  domain 0: span 0-1 level MC
[ 7212.689029]   groups: 1 0
[ 7212.690151] CPU1 is up
[ 7212.703065] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 7212.703093] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 7212.705089] uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 7212.709147] uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0
[ 7212.715145] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 7212.719302] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00403, writing 0x2b00407)
[ 7212.730206] iwlagn 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 7212.730368] iwlagn 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100506)
[ 7212.741097] ohci1394 0000:15:00.1: restoring config space at offset 0x3 (was 0x800000, writing 0x802010)
[ 7212.741114] ohci1394 0000:15:00.1: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106)
[ 7212.935151] PM: Device PNP0C0D:00 failed to restore: error 1
[ 7212.955366] i915 0000:00:02.0: setting latency timer to 64
[ 7213.332427] [drm] LVDS-8: set mode 1280x800 18
[ 7213.545628] e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[ 7213.547015] e1000e 0000:00:19.0: setting latency timer to 64
[ 7213.547034] e1000e 0000:00:19.0: wake-up capability disabled by ACPI
[ 7213.548473] e1000e 0000:00:19.0: PME# disabled
[ 7213.549903] e1000e 0000:00:19.0: irq 27 for MSI/MSI-X
[ 7213.606269] uhci_hcd 0000:00:1a.0: setting latency timer to 64
[ 7213.606323] usb usb3: root hub lost power or was reset
[ 7213.610247] uhci_hcd 0000:00:1a.1: setting latency timer to 64
[ 7213.610303] usb usb4: root hub lost power or was reset
[ 7213.611790] uhci_hcd 0000:00:1a.2: setting latency timer to 64
[ 7213.611838] usb usb5: root hub lost power or was reset
[ 7213.613261] ehci_hcd 0000:00:1a.7: setting latency timer to 64
[ 7213.613273] usb usb1: root hub lost power or was reset
[ 7213.618549] ehci_hcd 0000:00:1a.7: cache line size of 32 is not supported
[ 7213.618974] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[ 7213.620399] HDA Intel 0000:00:1b.0: setting latency timer to 64
[ 7213.620423] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[ 7213.620462] usb usb6: root hub lost power or was reset
[ 7213.621906] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[ 7213.621956] usb usb7: root hub lost power or was reset
[ 7213.623386] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[ 7213.623434] usb usb8: root hub lost power or was reset
[ 7213.624847] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[ 7213.624860] usb usb2: root hub lost power or was reset
[ 7213.630116] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[ 7213.630581] pci 0000:00:1e.0: setting latency timer to 64
[ 7213.630595] ahci 0000:00:1f.2: setting latency timer to 64
[ 7213.630705] pci 0000:15:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 7213.686204] ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[17]  MMIO=[f4801000-f48017ff]  Max Packet=[2048]  IR/IT contexts=[4/4]
[ 7213.935127] ata2: SATA link down (SStatus 0 SControl 300)
[ 7213.939193] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 7213.945164] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 7213.945175] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 7213.949338] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 7213.949348] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 7214.011717] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 7214.011728] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 7214.015964] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 7214.015974] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 7214.022288] ata1.00: configured for UDMA/133
[ 7214.031994] ata1.00: configured for UDMA/133
[ 7214.035904] ata1: EH complete
[ 7214.044152] sd 0:0:0:0: [sda] Starting disk
[ 7214.089943] Registered led device: iwl-phy0::radio
[ 7214.093827] Registered led device: iwl-phy0::assoc
[ 7214.097702] Registered led device: iwl-phy0::RX
[ 7214.101479] Registered led device: iwl-phy0::TX
[ 7214.212133] smapi smapi: set_real_thresh: set stop to 0 for bat=0
[ 7214.318131] smapi smapi: set_real_thresh: set start to 9 for bat=0
[ 7214.424131] smapi smapi: set_real_thresh: set stop to 0 for bat=1
[ 7214.530134] smapi smapi: set_real_thresh: set start to 0 for bat=1
[ 7214.534343] PM: Image restored successfully.
[ 7214.534348] Restarting all filesystems ...
[ 7214.538360] Restarting tasks ... Restarting tasks ... done.
[ 7214.568414] PM: Basic memory bitmaps freed
[ 7214.641059] usb 1-6: reset high speed USB device using ehci_hcd and address 2

[-- Attachment #3: dmesg_pmTest_ok2 --]
[-- Type: application/octet-stream, Size: 7636 bytes --]

[ 6890.634427] PM: Hibernation mode set to 'shutdown'
[ 6933.291442] PM: Marking nosave pages: 000000000009e000 - 0000000000100000
[ 6933.291447] PM: Basic memory bitmaps created
[ 6933.291449] PM: Syncing filesystems ... done.
[ 6934.138132] Stopping fuse filesystems.
[ 6934.138178] Freezing user space processes ... (elapsed 0.00 seconds) done.
[ 6934.138975] Stopping normal filesystems.
[ 6934.696960] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[ 6934.697317] PM: Preallocating image memory... 
[ 6934.852963] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
[ 6943.276784] done (allocated 861679 pages)
[ 6943.276824] PM: Allocated 3446716 kbytes in 8.57 seconds (402.18 MB/s)
[ 6943.719076] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 6943.724843] ACPI handle has no context!
[ 6943.869482] HDA Intel 0000:00:1b.0: PCI INT B disabled
[ 6943.924509] e1000e 0000:00:19.0: PCI INT A disabled
[ 6943.924549] e1000e 0000:00:19.0: PME# enabled
[ 6943.924587] e1000e 0000:00:19.0: wake-up capability enabled by ACPI
[ 6943.947764] Disabling non-boot CPUs ...
[ 6943.950227] CPU 1 is now offline
[ 6943.950301] SMP alternatives: switching to UP code
[ 6943.956119] CPU0 attaching NULL sched-domain.
[ 6943.956122] CPU1 attaching NULL sched-domain.
[ 6943.956127] CPU0 attaching NULL sched-domain.
[ 6943.956287] CPU1 is down
[ 6943.956355] Extended CMOS year: 2000
[ 6943.956464] hibernation debug: Waiting for 5 seconds.
[ 6943.957005] CPU0: Thermal monitoring enabled (TM2)
[ 6943.957005] Extended CMOS year: 2000
[ 6943.957005] Enabling non-boot CPUs ...
[ 6943.959142] SMP alternatives: switching to SMP code
[ 6943.963310] Booting processor 1 APIC 0x1 ip 0x6000
[ 6943.955928] Initializing CPU#1
[ 6943.955928] Calibrating delay using timer specific routine.. 4521.75 BogoMIPS (lpj=2260878)
[ 6943.955928] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 6943.955928] CPU: L2 cache: 3072K
[ 6943.955928] CPU: Physical Processor ID: 0
[ 6943.955928] CPU: Processor Core ID: 1
[ 6943.955928] CPU1: Thermal monitoring enabled (TM2)
[ 6944.034114] CPU1: Intel(R) Core(TM)2 Duo CPU     P8400  @ 2.26GHz stepping 0a
[ 6944.034470] CPU0 attaching NULL sched-domain.
[ 6944.036015] CPU0 attaching sched-domain:
[ 6944.036018]  domain 0: span 0-1 level MC
[ 6944.036020]   groups: 0 1
[ 6944.036025] CPU1 attaching sched-domain:
[ 6944.036027]  domain 0: span 0-1 level MC
[ 6944.036029]   groups: 1 0
[ 6944.037018] CPU1 is up
[ 6944.048048] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6944.048076] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 6944.050175] uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6944.052157] uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0
[ 6944.054144] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6944.054699] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00403, writing 0x2b00407)
[ 6944.065185] iwlagn 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6944.065346] iwlagn 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100506)
[ 6944.076093] ohci1394 0000:15:00.1: restoring config space at offset 0x3 (was 0x800000, writing 0x802010)
[ 6944.076109] ohci1394 0000:15:00.1: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106)
[ 6944.273154] PM: Device PNP0C0D:00 failed to restore: error 1
[ 6944.292650] i915 0000:00:02.0: setting latency timer to 64
[ 6944.669709] [drm] LVDS-8: set mode 1280x800 18
[ 6944.857521] e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[ 6944.857573] e1000e 0000:00:19.0: setting latency timer to 64
[ 6944.857585] e1000e 0000:00:19.0: wake-up capability disabled by ACPI
[ 6944.857634] e1000e 0000:00:19.0: PME# disabled
[ 6944.857703] e1000e 0000:00:19.0: irq 27 for MSI/MSI-X
[ 6944.914240] uhci_hcd 0000:00:1a.0: setting latency timer to 64
[ 6944.914282] usb usb3: root hub lost power or was reset
[ 6944.914356] uhci_hcd 0000:00:1a.1: setting latency timer to 64
[ 6944.914399] usb usb4: root hub lost power or was reset
[ 6944.914472] uhci_hcd 0000:00:1a.2: setting latency timer to 64
[ 6944.914517] usb usb5: root hub lost power or was reset
[ 6944.914591] ehci_hcd 0000:00:1a.7: setting latency timer to 64
[ 6944.914597] usb usb1: root hub lost power or was reset
[ 6944.918546] ehci_hcd 0000:00:1a.7: cache line size of 32 is not supported
[ 6944.919033] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[ 6944.919113] HDA Intel 0000:00:1b.0: setting latency timer to 64
[ 6944.975174] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[ 6944.975233] usb usb6: root hub lost power or was reset
[ 6944.975375] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[ 6944.975425] usb usb7: root hub lost power or was reset
[ 6944.975557] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[ 6944.975608] usb usb8: root hub lost power or was reset
[ 6944.979583] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[ 6944.979593] usb usb2: root hub lost power or was reset
[ 6944.987399] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[ 6944.988155] pci 0000:00:1e.0: setting latency timer to 64
[ 6944.988179] ahci 0000:00:1f.2: setting latency timer to 64
[ 6944.988378] pci 0000:15:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 6945.046189] ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[17]  MMIO=[f4801000-f48017ff]  Max Packet=[2048]  IR/IT contexts=[4/4]
[ 6945.295130] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 6945.299222] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 6945.305035] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6945.305046] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 6945.309150] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6945.309160] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 6945.314487] ata2.00: ACPI cmd e3/00:79:00:00:00:a0 (IDLE) succeeded
[ 6945.315507] ata2.00: ACPI cmd e3/00:01:00:00:00:a0 (IDLE) succeeded
[ 6945.326062] ata2.00: ACPI cmd e3/00:79:00:00:00:a0 (IDLE) succeeded
[ 6945.326978] ata2.00: ACPI cmd e3/00:01:00:00:00:a0 (IDLE) succeeded
[ 6945.330767] ata2.00: configured for UDMA/133
[ 6945.370892] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6945.370903] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 6945.375075] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6945.375085] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 6945.381362] ata1.00: configured for UDMA/133
[ 6945.391636] ata1.00: configured for UDMA/133
[ 6945.395549] ata1: EH complete
[ 6945.404200] sd 0:0:0:0: [sda] Starting disk
[ 6945.450763] Registered led device: iwl-phy0::radio
[ 6945.454955] Registered led device: iwl-phy0::assoc
[ 6945.458752] Registered led device: iwl-phy0::RX
[ 6945.462834] Registered led device: iwl-phy0::TX
[ 6945.575079] smapi smapi: set_real_thresh: set stop to 0 for bat=0
[ 6945.682136] smapi smapi: set_real_thresh: set start to 9 for bat=0
[ 6945.789135] smapi smapi: set_real_thresh: set stop to 0 for bat=1
[ 6945.895133] smapi smapi: set_real_thresh: set start to 0 for bat=1
[ 6945.899394] PM: Image restored successfully.
[ 6945.899399] Restarting all filesystems ...
[ 6945.929160] Restarting tasks ... Restarting tasks ... done.
[ 6945.939013] PM: Basic memory bitmaps freed
[ 6946.031064] usb 1-6: reset high speed USB device using ehci_hcd and address 2