Re: 2.6.9-rc2-mm3: swsusp horribly slow on AMD64 (update)

Rafael J. Wysocki
2004-09-27T23:22:02Z

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

On Sunday 26 of September 2004 15:20, Pavel Machek wrote:
> Hi!
>
> > > > Not explicitly, but it's used by SuSE initscripts to set IDE DMA,
AFAICS.
> > > > However, the problem did not occur on 2.6.9-rc2-mm1 with the same
> > > > initscripts.
> > >
> > > Okay, so try what happens without the initscripts
> >
> > I turned the stuff off but of course it didn't change anything. :-)
> >
> > > and try to locate change that breaks it...
> >
> > Well, I'm a bit confused:
>
> That's very simple bugfix. Some code outside swsusp is doing this.

You are right, but I don't think it's a module. Read on. ;-)

> Is it still slow with init=/bin/bash? If no, locate module that
> causes slowdown. We've seen pcmcia support behaving strange.

I did some tests on 2.6.9-rc2-mm4, just to make sure that the problem hasn't
been fixed "magically". Apparently, it hasn't.

First, I rebooted the machine, unloaded all modules except for ipv6 (it seems
to be always used) and tried to suspend it. It successfully suspended and
resumed.

Then, I loaded ohci_hcd and ehci_hcd (usbhid and evdev got loaded
automatically) and tried to suspend it again. It successfully suspended and
resumed.

Next, I loaded sk98lin and restarted networking (/etc/init.d/network restart),
so af_packet got loaded automatically. I tried to suspend the box and,
again, everything went OK.

Next, after the box had woken up, I loaded parport and parport_pc and
successfully suspended the box and resumed.

Next, I loaded lp and usbserial, and the box successfully suspended with these
modules, but I got a familiar double fault on resume (trace attached). So, I
tried to recreate the conditions: I rebooted the box, unloaded all modules,
loaded only the modules that had been present previosly (ie usbserial lp
ohci_hcd parport_pc parport af_packet sk98lin ehci_hcd evdev usbhid ipv6) and
tried to suspend the box. It seemed to go just fine:

Stopping tasks: ============================|
Freeing memory... done (19488 pages freed)
PM: Attempting to suspend to disk.
PM: snapshotting memory.
swsusp: critical section:
..<7>[nosave pfn 0x586].....................................swsusp: Need to
copy 10721 pages
suspend: (pages needed: 10721 + 512 free: 120158)
..<7>[nosave pfn 0x586]......................................swsusp: critical
section/: done (10849 pages copied)
PM: writing image.
PCI: Setting latency timer of device 0000:00:02.0 to 64
PCI: Setting latency timer of device 0000:00:02.1 to 64
PCI: Setting latency timer of device 0000:00:02.2 to 64
ACPI: PCI interrupt 0000:00:06.0[A] -> GSI 5 (level, low) -> IRQ 5
PCI: Setting latency timer of device 0000:00:06.0 to 64
ACPI: PCI interrupt 0000:02:00.0[A] -> GSI 11 (level, low) -> IRQ 11
ACPI: PCI interrupt 0000:02:01.0[A] -> GSI 9 (level, low) -> IRQ 9
ACPI: PCI interrupt 0000:02:01.1[B] -> GSI 11 (level, low) -> IRQ 11
ACPI: PCI interrupt 0000:02:01.2[C] -> GSI 11 (level, low) -> IRQ 11
swsusp: Version: 132617
swsusp: Num Pages: 130880
swsusp: UTS Sys: Linux
swsusp: UTS Node: albercik
swsusp: UTS Release: 2.6.9-rc2-mm4
swsusp: UTS Version: #14 Mon Sep 27 19:59:28 CEST 2004
swsusp: UTS Machine: x86_64
swsusp: UTS Domain:
swsusp: CPUs: 1
swsusp: Image: 10849 Pages
swsusp: Pagedir: 0 Pages
Writing data to swap (10849 pages)... 84%

but the system slowed down here, after writing 84% pages to the swap, so I
pressed Alt+sysrq+p:

<6>SysRq : Show Regs

Modules linked in: usbserial lp af_packet sk98lin evdev parport_pc parport
usbhid ehci_hcd ohci_hcd ipv6
Pid: 1035, comm: kjournald Tainted: G M 2.6.9-rc2-mm4
RIP: 0010:[<ffffffff80117b1b>] <ffffffff80117b1b>{sched_clock+11}
RSP: 0018:000001001d7a3d90 EFLAGS: 00000206
RAX: 00000085835f7fdd RBX: 000001001bd854d8 RCX: 00000000fffee984
RDX: 0000008500000000 RSI: 0000000000000000 RDI: 000001001fda8130
RBP: 000001001bd854d8 R08: 000001001d7a2000 R09: 000001001c9ca9e0
R10: 0000000000000000 R11: 0000000000000000 R12: 000001001bd854d8
R13: 000001001bd854d8 R14: 000001001bd854d8 R15: 000001001bd854d8
FS: 0000002a9588d700(0000) GS:ffffffff805582c0(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000415cbf CR3: 0000000000101000 CR4: 00000000000006e0

Call Trace:<ffffffff803a695c>{schedule+204}
<ffffffff801634f7>{refrigerator+743}
<ffffffff80236d12>{kjournald+1042}
<ffffffff8015be70>{autoremove_wake_function+0}
<ffffffff8015be70>{autoremove_wake_function+0}
<ffffffff802370d0>{commit_timeout+0}
<ffffffff80111843>{child_rip+8} <ffffffff80236900>{kjournald+0}
<ffffffff8011183b>{child_rip+0}

Now, can you tell me, please, what the chances of hitting schedule() this way
should be? Not great, I think. Still, I pressed Alt+sysrq+p for several
times after I'd got the above trace and it always hit schedule() (all the
traces were very similar to this one).

I've investigated this a bit more and it turns out that when I press
Alt+sysrq+p after such a slowdown, I almost always hit schedule(). Slowdowns
usually happen sooner or later after swsusp has been started, and the more
modules are in memory at that time, the sooner the system slows down. When
all modules are present, it slows down right after printing "PM: writing
image.".

My theory is that something really bad is going on in the scheduler after
swsusp has been started and the "slowdowns" occur because the processor
spends _a_ _lot_ of time in schedule().

I have verified that the problem was introduced between 2.6.9-rc2-mm1 and
2.6.9-rc2-mm2, but I haven't identified the change that might have caused it,
yet. I've verified that it's not caused by any of the following patches:

cleanup-move-call-to-update_process_times.patch
cleanup-timeh-timesh-timexh-and-jiffiesh.patch

I can also say with a great deal of certainty that it's not caused by any
changes to PCI and/or ACPI. Moreover, I replaced the scheduler in
2.6.9-rc2-mm2 with the Con's staircase scheduler and it made the symptoms
even worse. That is, with the staircase scheduler, the system always "slows
down" before it writes all pages to the swap and if all modules are present
when the system is suspended, the "slowdown" is much more "visible". Of
course, I can do some more tests/measurements if necessary.

Greets,
RJW

--
- Would you tell me, please, which way I ought to go from here?
- That depends a good deal on where you want to get to.
-- Lewis Carroll "Alice's Adventures in Wonderland"

[-- Attachment #2: swsusp-double_fault.log --]
[-- Type: text/x-log, Size: 3784 bytes --]

Relocating pagedir not necessary
Reading image data (9659 pages): 100% 9659 done.
Stopping tasks: ===|
Freeing memory... done (0 pages freed)
PM: Restoring saved image.
<0>double fault: 0000 [1]
CPU 0
Modules linked in: usbserial lp ohci_hcd parport_pc parport af_packet sk98lin ehci_hcd evdev usbhid ipv6
Pid: 17009, comm: hibernate.sh Tainted: G M 2.6.9-rc2-mm4
RIP: 0010:[<ffffffff8012518d>] <ffffffff8012518d>{do_page_fault+1485}
RSP: 0000:000001001fe00008 EFLAGS: 00010002
RAX: 000000001fce8740 RBX: 0000000000000001 RCX: 000ffffffffff000
RDX: 000000001fce8000 RSI: 0000010000000000 RDI: 000001001fe000e8
RBP: 000001001fce8740 R08: 0000000000000000 R09: 000001001fe27e54
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000000 R14: 000001001fe000e8 R15: 000001001b09e200
FS: 0000000000000000(0000) GS:ffffffff805582c0(0000) knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 0000000080050033
CR2: 000001001fdffff8 CR3: 0000000000101000 CR4: 00000000000006e0
Process hibernate.sh (pid: 17009, threadinfo 000001001c6d8000, task 000001001ad16530)
Stack: 000001001fe01000 0000000000000060 000001001ad16530 0000ffff0000001a
fffefffefffefffe fffefffe00030001 fffefffefffefffe fffefffefffefffe
fffefffefffefffe fffefffefffefffe
Call Trace:<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff80282d47>{acpi_os_allocate+12}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff8011168d>{error_exit+0} <ffffffff8012518d>{do_page_fault+1485}
<ffffffff80282d47>{acpi_os_allocate+12} <ffffffff8011168d>{error_exit+0}
<ffffffff8012518d>{do_page_fault+1485} <ffffffff80282d47>{acpi_os_allocate+12}

Code: f6 04 06 81 0f 84 52 fc ff ff 48 8b 05 e2 f9 3a 00 48 89 c2
RIP <ffffffff8012518d>{do_page_fault+1485} RSP <000001001fe00008>