Re: [Bug #13306] hibernate slow on _second_ run

[Johannes Berg]

On Mon, 2009-06-08 at 22:54 +0200, Rafael J. Wysocki wrote:
> On Thursday 04 June 2009, Johannes Berg wrote:
> > Alright, I have managed to trace this.
> > 
> > http://johannes.sipsolutions.net/files/hibernate-delay-dmesg.txt
> > 
> > has the dmesg, you can clearly see the delay:
> > [50265.143330] ACPI: Waking up from system sleep state S4
> > [50265.679141] HDA Intel 0000:00:08.0: restoring config space at offset 0x1 (was 0xb00006, writing 0xb00002)
> > [50265.689525] forcedeth 0000:00:0a.0: restoring config space at offset 0x1 (was 0xb00003, writing 0xb00007)
> > [50265.699775] ahci 0000:00:0b.0: restoring config space at offset 0x1 (was 0xb00403, writing 0xb00407)
> > [50286.294910] pci 0000:00:03.2: PME# disabled
> 
> Quite frankly, it looks like resume_device_irqs() itself causes the delay to happen.
> 
> The next step would be to put a couple of printk()s in there and see which part
> of it triggers the delay.

--- a/kernel/irq/pm.c
+++ b/kernel/irq/pm.c
@@ -56,8 +56,11 @@ void resume_device_irqs(void)
                if (!(desc->status & IRQ_SUSPENDED))
                        continue;
 
+               printk(KERN_DEBUG "lock irq %d\n", irq);
                spin_lock_irqsave(&desc->lock, flags);
+               printk(KERN_DEBUG "locked\n");
                __enable_irq(desc, irq, true);
+               printk(KERN_DEBUG "enabled\n");
                spin_unlock_irqrestore(&desc->lock, flags);
        }
 }


and I get:
[63702.285944] ACPI: Waking up from system sleep state S4
[63702.811457] HDA Intel 0000:00:08.0: restoring config space at offset 0x1 (was 0xb00006, writing 0xb00002)
[63702.819369] pci 0000:00:09.0: restoring config space at offset 0x7 (was 0x228000f0, writing 0x428000f0)
[63702.827574] forcedeth 0000:00:0a.0: restoring config space at offset 0x1 (was 0xb00003, writing 0xb00007)
[63702.836052] ahci 0000:00:0b.0: restoring config space at offset 0x1 (was 0xb00403, writing 0xb00407)
[63702.845288] lock irq 9
[63702.853902] locked
[63702.862433] enabled
[63702.870967] lock irq 17
[63702.879377] locked
[63702.880964] enabled
[63702.895811] lock irq 18
[63702.903919] locked
[63702.911879] enabled
[63702.919781] lock irq 19
[63702.927595] locked
[63702.935260] enabled
[63702.942989] lock irq 20
[63702.950764] locked
[63702.958425] enabled
[63702.966061] lock irq 25
[63702.973641] locked
[63702.981102] enabled
[63722.620744] pci 0000:00:03.2: PME# disabled
[63722.628069] ohci_hcd 0000:00:04.0: PME# disabled

so it doesn't look like the delay is there.

johannes

Attachment: signature.asc
Description: This is a digitally signed message part