Pavel,
I've just tried to suspend my box and I must admit I've given up after 30
minutes (sic!) of waiting when there were only 12% of pages written to disk.
Apparently, swsusp slows down to an unacceptable level after saying "PM:
Writing image to disk".
The box is an Athlon 64-based notebook. The .config is available at:
http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3.config
and the output of dmesg is available at:
http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3-dmesg.log
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"
Rafael J. Wysocki wrote:
> Pavel,
>
> I've just tried to suspend my box and I must admit I've given up after 30
> minutes (sic!) of waiting when there were only 12% of pages written to disk.
> Apparently, swsusp slows down to an unacceptable level after saying "PM:
> Writing image to disk".
is this reproducible? can you get sysrq-t / sysrq-p while it is slow
writing to disk?
I have seen this, too but i cannot nail it down to some specific
pattern, it just "sometimes" is slow. Sysrq-p shows me it's almost
always in "pccardd" (where it shouldn't be during suspend, iiuc).
Unfortunately Pavel does not see this so we have to convince him that
this is really a problem ;-)
So if you can reproduce this, it would be a step in the right direction.
Stefan
Hi!
> I've just tried to suspend my box and I must admit I've given up after 30
> minutes (sic!) of waiting when there were only 12% of pages written to disk.
> Apparently, swsusp slows down to an unacceptable level after saying "PM:
> Writing image to disk".
>
> The box is an Athlon 64-based notebook. The .config is available at:
> http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3.config
> and the output of dmesg is available at:
> http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3-dmesg.log
We have seen something similar after hdparm was used on specific
machines. Are you using hdparm?
Pavel
--
People were complaining that M$ turns users into beta-testers...
...jr ghea gurz vagb qrirybcref, naq gurl frrz gb yvxr vg gung jnl!
On Saturday 25 of September 2004 23:33, Stefan Seyfried wrote:
> Rafael J. Wysocki wrote:
> > Pavel,
> >
> > I've just tried to suspend my box and I must admit I've given up after 30
> > minutes (sic!) of waiting when there were only 12% of pages written to
disk.
> > Apparently, swsusp slows down to an unacceptable level after saying "PM:
> > Writing image to disk".
>
> is this reproducible?
Yes, it is. 100% of the time, AFAICT, though I've tried it for only a couple
of times.
> can you get sysrq-t / sysrq-p while it is slow
> writing to disk?
Well, I'll try, but sysrq didn't work for me at all on 2.6.9-rc2-mm1, so I'm
not sure if I really can.
> I have seen this, too but i cannot nail it down to some specific
> pattern, it just "sometimes" is slow. Sysrq-p shows me it's almost
> always in "pccardd" (where it shouldn't be during suspend, iiuc).
> Unfortunately Pavel does not see this so we have to convince him that
> this is really a problem ;-)
> So if you can reproduce this, it would be a step in the right direction.
It seems that I can. ;-)
Could it be possible to printk time along with the percentage info (for
debugging purposes only, of course)?
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"
On Sunday 26 of September 2004 01:40, Pavel Machek wrote:
> Hi!
>
> > I've just tried to suspend my box and I must admit I've given up after 30
> > minutes (sic!) of waiting when there were only 12% of pages written to
disk.
> > Apparently, swsusp slows down to an unacceptable level after saying "PM:
> > Writing image to disk".
> >
> > The box is an Athlon 64-based notebook. The .config is available at:
> > http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3.config
> > and the output of dmesg is available at:
> > http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3-dmesg.log
>
> We have seen something similar after hdparm was used on specific
> machines. Are you using hdparm?
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.
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"
Hi!
> > > I've just tried to suspend my box and I must admit I've given up after 30
> > > minutes (sic!) of waiting when there were only 12% of pages written to
> disk.
> > > Apparently, swsusp slows down to an unacceptable level after saying "PM:
> > > Writing image to disk".
> > >
> > > The box is an Athlon 64-based notebook. The .config is available at:
> > > http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3.config
> > > and the output of dmesg is available at:
> > > http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3-dmesg.log
> >
> > We have seen something similar after hdparm was used on specific
> > machines. Are you using hdparm?
>
> 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 and try to locate
change that breaks it...
Pavel
--
People were complaining that M$ turns users into beta-testers...
...jr ghea gurz vagb qrirybcref, naq gurl frrz gb yvxr vg gung jnl!
Hi!
> > I have seen this, too but i cannot nail it down to some specific
> > pattern, it just "sometimes" is slow. Sysrq-p shows me it's almost
> > always in "pccardd" (where it shouldn't be during suspend, iiuc).
> > Unfortunately Pavel does not see this so we have to convince him that
> > this is really a problem ;-)
> > So if you can reproduce this, it would be a step in the right direction.
>
> It seems that I can. ;-)
>
> Could it be possible to printk time along with the percentage info (for
> debugging purposes only, of course)?
Sure, feel free to printk("%d", jiffies/HZ).
Pavel
--
People were complaining that M$ turns users into beta-testers...
...jr ghea gurz vagb qrirybcref, naq gurl frrz gb yvxr vg gung jnl!
On Sunday 26 of September 2004 12:09, Pavel Machek wrote:
> Hi!
>
> > > > I've just tried to suspend my box and I must admit I've given up after
30
> > > > minutes (sic!) of waiting when there were only 12% of pages written to
> > disk.
> > > > Apparently, swsusp slows down to an unacceptable level after saying
"PM:
> > > > Writing image to disk".
> > > >
> > > > The box is an Athlon 64-based notebook. The .config is available at:
> > > > http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3.config
> > > > and the output of dmesg is available at:
> > > > http://www.sisk.pl/kernel/040925/2.6.9-rc2-mm3-dmesg.log
> > >
> > > We have seen something similar after hdparm was used on specific
> > > machines. Are you using hdparm?
> >
> > 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:
--- linux-2.6.9-rc2-mm1/kernel/power/swsusp.c 2004-09-16 14:06:56.000000000
+0200
+++ linux-2.6.9-rc2-mm3/kernel/power/swsusp.c 2004-09-24 11:35:18.000000000
+0200
@@ -862,8 +862,8 @@
error = swsusp_arch_suspend();
/* Restore control flow magically appears here */
restore_processor_state();
- local_irq_enable();
restore_highmem();
+ local_irq_enable();
return error;
}
What else should I look for?
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"
On Sunday 26 of September 2004 12:02, Rafael J. Wysocki wrote:
> On Saturday 25 of September 2004 23:33, Stefan Seyfried wrote:
> > Rafael J. Wysocki wrote:
> > > Pavel,
> > >
> > > I've just tried to suspend my box and I must admit I've given up after
30
> > > minutes (sic!) of waiting when there were only 12% of pages written to
> disk.
> > > Apparently, swsusp slows down to an unacceptable level after saying "PM:
> > > Writing image to disk".
> >
> > is this reproducible?
>
> Yes, it is. 100% of the time, AFAICT, though I've tried it for only a
couple
> of times.
I can confirm that it's 100% reproducible.
> > can you get sysrq-t / sysrq-p while it is slow
> > writing to disk?
>
> Well, I'll try, but sysrq didn't work for me at all on 2.6.9-rc2-mm1, so I'm
> not sure if I really can.
As I suspected, the damn sysrq doesn't work (/proc/sysrq-trigger does, so it
_is_ compiled in, sigh).
I'm only able to get swsusp output from the serial console:
Stopping tasks: ==============================|
Freeing memory... done (18812 pages freed)
PM: Attempting to suspend to disk.
PM: snapshotting memory.
swsusp: critical section:
..<7>[nosave pfn 0x588]......................................swsusp: Need to
copy 11017 pages
suspend: (pages needed: 11017 + 512 free: 119862)
..<7>[nosave pfn 0x588]......................................swsusp: critical
section/: done (11145 pages copied)
PM: writing image.
and it slows down _here_:
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.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-mm3
swsusp: UTS Version: #1 Fri Sep 24 11:52:15 CEST 2004
swsusp: UTS Machine: x86_64
swsusp: UTS Domain:
swsusp: CPUs: 1
swsusp: Image: 11145 Pages
swsusp: Pagedir: 0 Pages
Writing data to swap (11145 pages)... 0%
Here I have to press the red button unless I want to wait for a couple of
hours. I'll send you more info when there's more.
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"
On Sunday 26 of September 2004 13:45, Rafael J. Wysocki wrote:
[-- snip --]
> swsusp: Image: 11145 Pages
> swsusp: Pagedir: 0 Pages
> Writing data to swap (11145 pages)... 0%
>
> Here I have to press the red button unless I want to wait for a couple of
> hours. I'll send you more info when there's more.
I figured out that the slowdown occurs in device_resume(), so I put a printk()
in dpm_resume(), like this:
--- drivers/base/power/resume.c 2004-09-26 16:44:09.000000000 +0200
+++ drivers/base/power/resume.c.rjw 2004-09-26 16:43:57.000000000 +0200
@@ -34,6 +34,7 @@
while(!list_empty(&dpm_off)) {
struct list_head * entry = dpm_off.next;
struct device * dev = to_device(entry);
+ printk("%ld\n", jiffies/HZ);
list_del_init(entry);
if (!dev->power.prev_state)
>From it, I have got the following results:
PM: writing image.
4294807
[ ... ]
4294807
PCI: Setting latency timer of device 0000:00:02.0 to 64
4294813
PCI: Setting latency timer of device 0000:00:02.1 to 64
4294817
PCI: Setting latency timer of device 0000:00:02.2 to 64
4294821
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
4294822
[ ... ]
4294822
ACPI: PCI interrupt 0000:02:00.0[A] -> GSI 11 (level, low) -> IRQ 11
4294822
4294825
4294828
ACPI: PCI interrupt 0000:02:01.2[C] -> GSI 11 (level, low) -> IRQ 11
4294828
[ ... ]
4294828
4294829
[ ... ]
4294829
As you can see, the difference between the first and the last timestamp is 22.
However, if I make the same change in 2.6.9-rc2-mm1, I get:
PM: writing image.
4294761
[ ... ]
4294761
PCI: Setting latency timer of device 0000:00:02.0 to 64
4294761
PCI: Setting latency timer of device 0000:00:02.1 to 64
4294761
PCI: Setting latency timer of device 0000:00:02.2 to 64
4294761
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
4294762
[ ... ]
4294762
ACPI: PCI interrupt 0000:02:00.0[A] -> GSI 11 (level, low) -> IRQ 11
4294762
4294762
4294762
ACPI: PCI interrupt 0000:02:01.2[C] -> GSI 11 (level, low) -> IRQ 11
4294762
[ ... ]
4294762
so the difference between the first and the last timestamp is 1 (ie 22 times
less).
Now, I have no idea about what may be responsible for such a slowdown, but I
suspect that it's related to PCI. I really don't know what to look for, so
if you can give me any hint, please do.
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"
Hi!
> [-- snip --]
> > swsusp: Image: 11145 Pages
> > swsusp: Pagedir: 0 Pages
> > Writing data to swap (11145 pages)... 0%
> >
> > Here I have to press the red button unless I want to wait for a couple of
> > hours. I'll send you more info when there's more.
>
> I figured out that the slowdown occurs in device_resume(), so I put a printk()
> in dpm_resume(), like this:
When you hit "writing data to swap", device_resume should be no longer
happening.
Try to unload all modules etc, see if it goes away. If not, fix sysrq
to work for you, and look at backtrace.
Pavel
--
People were complaining that M$ turns users into beta-testers...
...jr ghea gurz vagb qrirybcref, naq gurl frrz gb yvxr vg gung jnl!
On Sunday 26 of September 2004 20:34, Pavel Machek wrote:
> Hi!
>
> > [-- snip --]
> > > swsusp: Image: 11145 Pages
> > > swsusp: Pagedir: 0 Pages
> > > Writing data to swap (11145 pages)... 0%
> > >
> > > Here I have to press the red button unless I want to wait for a couple
of
> > > hours. I'll send you more info when there's more.
> >
> > I figured out that the slowdown occurs in device_resume(), so I put a
printk()
> > in dpm_resume(), like this:
>
> When you hit "writing data to swap", device_resume should be no longer
> happening.
It isn't. Still, device_resume() is called explicitly by swsusp_write() and
IMO what happens is that the resume() function of one of the drivers does
something that causes the system to slow down, which affects the writing
operation (please note that the clock seems to be unaffected, though). I'll
try to narrow it.
> Try to unload all modules etc, see if it goes away.
I guess it will, but I'll check.
> If not, fix sysrq to work for you, and look at backtrace.
This would be more time-consuming. :-)
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"
Rafael J. Wysocki wrote:
>>Try to unload all modules etc, see if it goes away.
>
> I guess it will, but I'll check.
please try attached patch first. The comments should explain it pretty
well. It seems to have helped me: without it, sysrq-p during writing
(even if not that slow) almost always was in pccardd, now it is idling
in swapper task.
Maybe i am totally wrong but you may give it a shot.
>>If not, fix sysrq to work for you, and look at backtrace.
>
> This would be more time-consuming. :-)
maybe you just press wrong keys? On my Dell D600, although SysRQ is in
blue on PrtSc, no Fn-Key is needed but only ALT-PrtSc.
--
Stefan Seyfried, QA / R&D Team Mobile Devices, SUSE LINUX AG N?rnberg.
"Any ideas, John?"
"Well, surrounding them's out."
Rafael J. Wysocki wrote:
> On Sunday 26 of September 2004 12:09, Pavel Machek wrote:
>>>>We have seen something similar after hdparm was used on specific
>>>>machines. Are you using hdparm?
Pavel, i am pretty sure the issue with hdparm and 32-bit disk access was
just a symptom, not the cause. Rafael, please try the patch i posted in
the other mail, i believe this is the right thing to do.
>>>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. :-)
That's what i expected.
>>and try to locate change that breaks it...
> Well, I'm a bit confused:
>
> --- linux-2.6.9-rc2-mm1/kernel/power/swsusp.c 2004-09-16 14:06:56.000000000
> +0200
> +++ linux-2.6.9-rc2-mm3/kernel/power/swsusp.c 2004-09-24 11:35:18.000000000
> +0200
> @@ -862,8 +862,8 @@
> error = swsusp_arch_suspend();
> /* Restore control flow magically appears here */
> restore_processor_state();
> - local_irq_enable();
> restore_highmem();
> + local_irq_enable();
> return error;
> }
without this one is needed or highmem will break "sometimes". Was really
nasty. You did have highmem-resume problems, didn't you?
Stefan
On Sunday 26 of September 2004 23:00, Stefan Seyfried wrote:
> Rafael J. Wysocki wrote:
> > On Sunday 26 of September 2004 12:09, Pavel Machek wrote:
>
> >>>>We have seen something similar after hdparm was used on specific
> >>>>machines. Are you using hdparm?
>
> Pavel, i am pretty sure the issue with hdparm and 32-bit disk access was
> just a symptom, not the cause. Rafael, please try the patch i posted in
> the other mail, i believe this is the right thing to do.
In summary:
1) The patch does not fix the problem. :-(
2) In the meantime, I've made the following change to pci-driver.c:
--- pci-driver.c 2004-09-26 23:35:32.701574416 +0200
+++ pci-driver.c.rjw 2004-09-26 23:35:18.441742240 +0200
@@ -328,6 +328,7 @@
*/
static void pci_default_resume(struct pci_dev *pci_dev)
{
+ printk("pci_default_resume (0x%04x, 0x%04x): %ld\n", pci_dev->vendor,
pci_dev->device, jiffies/HZ);
/* restore the PCI config space */
pci_restore_state(pci_dev, pci_dev->saved_config_space);
/* if the device was enabled before suspend, reenable */
@@ -343,6 +344,7 @@
struct pci_dev * pci_dev = to_pci_dev(dev);
struct pci_driver * drv = pci_dev->driver;
+ printk("pci_device_resume (0x%04x, 0x%04x): %ld\n", pci_dev->vendor,
pci_dev->device, jiffies/HZ);
if (drv && drv->resume)
drv->resume(pci_dev);
else
in order to identify the offending device. I'm now almost sure that the
NVidia chipset is to blame but I don't know which part of it exactly.
I've got two logs (attached), one of which is taken from the system with all
modules loaded (swsusp.log), and the other comes from the system with no
modules except for ipv6 (swsusp-nomod.log). As you can see from the first
log, the system with all modules loaded slows down significantly after
pci_device_resume() is called for the device having vendor id = 0x10de
(NVidia) and device id = 0x00d7 (no idea). The system without modules is
capable of writing 80-83% of pages to the swap _before_ slows down too and I
have to wait for 1/2 h for the remaining ~20%.
I'm afraid I can't get any more info until I sort out the sysrq problem.
[-- snip --]
> > /* Restore control flow magically appears here */
> > restore_processor_state();
> > - local_irq_enable();
> > restore_highmem();
> > + local_irq_enable();
> > return error;
> > }
>
> without this one is needed or highmem will break "sometimes". Was really
> nasty. You did have highmem-resume problems, didn't you?
Yup, probably. I only need to apply it to 2.6.9-rc2-mm1 to confirm that it
fixes what I've seen.
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"
On Sunday 26 of September 2004 22:48, Stefan Seyfried wrote:
> Rafael J. Wysocki wrote:
>
> >>Try to unload all modules etc, see if it goes away.
> >
> > I guess it will, but I'll check.
>
> please try attached patch first. The comments should explain it pretty
> well. It seems to have helped me: without it, sysrq-p during writing
> (even if not that slow) almost always was in pccardd, now it is idling
> in swapper task.
> Maybe i am totally wrong but you may give it a shot.
Does not help, sorry. :-(
> >>If not, fix sysrq to work for you, and look at backtrace.
> >
> > This would be more time-consuming. :-)
>
> maybe you just press wrong keys? On my Dell D600, although SysRQ is in
> blue on PrtSc, no Fn-Key is needed but only ALT-PrtSc.
It is possible, but I have two x86-64 boxes, one of which is a regular PC with
no Fn-Key whatsoever, and it doesn't work on both, apparently.
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"
Hi!
> --- pci-driver.c 2004-09-26 23:35:32.701574416 +0200
> +++ pci-driver.c.rjw 2004-09-26 23:35:18.441742240 +0200
> @@ -328,6 +328,7 @@
> */
> static void pci_default_resume(struct pci_dev *pci_dev)
> {
> + printk("pci_default_resume (0x%04x, 0x%04x): %ld\n", pci_dev->vendor,
> pci_dev->device, jiffies/HZ);
> /* restore the PCI config space */
> pci_restore_state(pci_dev, pci_dev->saved_config_space);
> /* if the device was enabled before suspend, reenable */
> @@ -343,6 +344,7 @@
> struct pci_dev * pci_dev = to_pci_dev(dev);
> struct pci_driver * drv = pci_dev->driver;
>
> + printk("pci_device_resume (0x%04x, 0x%04x): %ld\n", pci_dev->vendor,
> pci_dev->device, jiffies/HZ);
> if (drv && drv->resume)
> drv->resume(pci_dev);
> else
>
> in order to identify the offending device. I'm now almost sure that the
> NVidia chipset is to blame but I don't know which part of it exactly.
>
> I've got two logs (attached), one of which is taken from the system with all
> modules loaded (swsusp.log), and the other comes from the system with no
> modules except for ipv6 (swsusp-nomod.log). As you can see from the first
> log, the system with all modules loaded slows down significantly after
> pci_device_resume() is called for the device having vendor id = 0x10de
> (NVidia) and device id = 0x00d7 (no idea). The system without modules is
lspci, and take a look?
> capable of writing 80-83% of pages to the swap _before_ slows down too and I
> have to wait for 1/2 h for the remaining ~20%.
Strange, *very* strange.
> I'm afraid I can't get any more info until I sort out the sysrq
> problem.
This should remap magic key to both-shifts-both-alts-key. Worked for
me once...
Pavel
--- clean-mm/drivers/char/keyboard.c 2004-09-26 01:34:24.000000000 +0200
+++ linux-mm/drivers/char/keyboard.c 2004-09-26 01:42:24.000000000 +0200
@@ -1079,6 +1079,23 @@
sysrq_down = down;
return;
}
+ if (test_bit(KEY_LEFTALT, key_down) &&
+ test_bit(KEY_RIGHTALT, key_down) &&
+ test_bit(KEY_LEFTSHIFT, key_down) &&
+ test_bit(KEY_RIGHTSHIFT, key_down) &&
+ down && !rep) {
+ handle_sysrq(kbd_sysrq_xlate[keycode], regs, tty);
+#ifdef CONFIG_KGDB_SYSRQ
+ sysrq_down = 0; /* in case we miss the "up" event */
+#endif
+ return;
+ }
+
+ if (down)
+ set_bit(keycode, key_down);
+ else
+ clear_bit(keycode, key_down);
+
if (sysrq_down && down && !rep) {
handle_sysrq(kbd_sysrq_xlate[keycode], regs, tty);
#ifdef CONFIG_KGDB_SYSRQ
@@ -1114,11 +1131,6 @@
raw_mode = 1;
}
- if (down)
- set_bit(keycode, key_down);
- else
- clear_bit(keycode, key_down);
-
if (rep && (!vc_kbd_mode(kbd, VC_REPEAT) || (tty &&
(!L_ECHO(tty) && tty->driver->chars_in_buffer(tty))))) {
/*
--
People were complaining that M$ turns users into beta-testers...
...jr ghea gurz vagb qrirybcref, naq gurl frrz gb yvxr vg gung jnl!
Hi!
> > I guess it will, but I'll check.
>
> please try attached patch first. The comments should explain it pretty
> well. It seems to have helped me: without it, sysrq-p during writing
> (even if not that slow) almost always was in pccardd, now it is idling
> in swapper task.
> Maybe i am totally wrong but you may give it a shot.
I do not think it is right, interrupts may be needed for writing
image.
Pavel
--
People were complaining that M$ turns users into beta-testers...
...jr ghea gurz vagb qrirybcref, naq gurl frrz gb yvxr vg gung jnl!
Hi,
On Monday 27 of September 2004 00:33, Pavel Machek wrote:
[-- snip --]
> > I've got two logs (attached), one of which is taken from the system with
all
> > modules loaded (swsusp.log), and the other comes from the system with no
> > modules except for ipv6 (swsusp-nomod.log). As you can see from the first
> > log, the system with all modules loaded slows down significantly after
> > pci_device_resume() is called for the device having vendor id = 0x10de
> > (NVidia) and device id = 0x00d7 (no idea). The system without modules is
>
> lspci, and take a look?
albercik:~ # lspci -n
[ ... ]
0000:00:02.0 Class 0c03: 10de:00d7 (rev a5)
0000:00:02.1 Class 0c03: 10de:00d7 (rev a5)
0000:00:02.2 Class 0c03: 10de:00d8 (rev a2)
[ ... ]
albercik:~ # lspci
[ ... ]
0000:00:02.0 USB Controller: nVidia Corporation nForce3 USB 1.1 (rev a5)
0000:00:02.1 USB Controller: nVidia Corporation nForce3 USB 1.1 (rev a5)
0000:00:02.2 USB Controller: nVidia Corporation nForce3 USB 2.0 (rev a2)
[ ... ]
So, it's the USB 1.1 controller (OHCI).
> > capable of writing 80-83% of pages to the swap _before_ slows down too and
I
> > have to wait for 1/2 h for the remaining ~20%.
>
> Strange, *very* strange.
Yes, it is.
> > I'm afraid I can't get any more info until I sort out the sysrq
> > problem.
>
> This should remap magic key to both-shifts-both-alts-key. Worked for
> me once...
Thanks a lot, but it turned out to be much simpler: sysrq was disabled by an
initscript (shame on me, shame, shame). I'll get the traces as soon as I can
get something to attach to the serial console. In the meantime, I'll try to
look at the USB stuff.
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"
Hi!
> > Well, I'll try, but sysrq didn't work for me at all on 2.6.9-rc2-mm1, so I'm
> > not sure if I really can.
>
> As I suspected, the damn sysrq doesn't work (/proc/sysrq-trigger does, so it
> _is_ compiled in, sigh).
Map sysrq to some other key; sysrq is hard to press on notebooks.
Pavel
--
64 bytes from 195.113.31.123: icmp_seq=28 ttl=51 time=448769.1 ms
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.
Is it still slow with init=/bin/bash? If no, locate module that
causes slowdown. We've seen pcmcia support behaving strange.
Pavel
--
64 bytes from 195.113.31.123: icmp_seq=28 ttl=51 time=448769.1 ms
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"
Hi,
I have verified that the odd symptoms described previously in this thread
result from the zaphod-scheduler.patch.
To show this, I took the 2.6.9-rc2-mm2 kernel, reverted the
zaphod-scheduler.patch and applied the following changes to swsusp.c:
--- a/kernel/power/swsusp.c 2004-09-29 21:45:15.000000000 +0200
+++ b/kernel/power/swsusp.c 2004-09-29 22:08:33.971404368 +0200
@@ -295,18 +295,20 @@
int error = 0;
int i;
unsigned int mod = nr_copy_pages / 100;
+ unsigned long start_time = jiffies;
if (!mod)
mod = 1;
- printk( "Writing data to swap (%d pages)... ", nr_copy_pages );
+ printk( "Writing data to swap (%d pages)... ",
nr_copy_pages );
for (i = 0; i < nr_copy_pages && !error; i++) {
if (!(i%mod))
- printk( "\b\b\b\b%3d%%", i / mod );
+ printk( "\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b%3d%%, time: %3ld",
+ i / mod, (jiffies - start_time)/HZ);
error = write_page((pagedir_nosave+i)->address,
&((pagedir_nosave+i)->swap_address));
}
- printk("\b\b\b\bdone\n");
+ printk(" ... done\n");
return error;
}
Then, I obtained the following result:
Stopping tasks: ===============================|
Freeing memory... done (17507 pages freed)
PM: Attempting to suspend to disk.
PM: snapshotting memory.
swsusp: critical section:
..<7>[nosave pfn 0x582].............................................swsusp:
Need to copy 10738 pages
suspend: (pages needed: 10738 + 512 free: 120141)
..<7>[nosave pfn 0x582].............................................swsusp:
critical section/: done (10866 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.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-mm2
swsusp: UTS Version: #4 Wed Sep 29 22:09:48 CEST 2004
swsusp: UTS Machine: x86_64
swsusp: UTS Domain:
swsusp: CPUs: 1
swsusp: Image: 10866 Pages
swsusp: Pagedir: 0 Pages
Writing data to swap (10866 pages)... 100%, time: 2 ... done
Writing pagedir (85 pages)
S|
Powering off system
Shutdown: hdc
acpi_power_off called
which is OK, IMO. However, for the vanilla 2.6.9-rc2-mm2 (with the same
changes to swsusp.c), I get:
[-- snip --]
swsusp: Version: 132617
swsusp: Num Pages: 130880
swsusp: UTS Sys: Linux
swsusp: UTS Node: albercik
swsusp: UTS Release: 2.6.9-rc2-mm2
swsusp: UTS Version: #2 Wed Sep 29 23:12:00 CEST 2004
swsusp: UTS Machine: x86_64
swsusp: UTS Domain:
swsusp: CPUs: 1
swsusp: Image: 11115 Pages
swsusp: Pagedir: 0 Pages
Writing data to swap (11115 pages)... 6%, time: 738<6>SysRq : Resetting
which should give you an idea what kind of a slowdown I was talking about
earlier.
Well, zaphod-scheduler.patch is a big patch and I know to little to be able to
figure out what's wrong with it so it causes the observed symptoms to appear.
If you can, please help me fix this.
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"
Hi!
> I have verified that the odd symptoms described previously in this thread
> result from the zaphod-scheduler.patch.
>
> To show this, I took the 2.6.9-rc2-mm2 kernel, reverted the
> zaphod-scheduler.patch and applied the following changes to
> swsusp.c:
Hmm, similar behaviour was observed when we had missing unplug in
-suse kernels (IIRC; Andrea debugged it, he might know more).
Pavel
--
People were complaining that M$ turns users into beta-testers...
...jr ghea gurz vagb qrirybcref, naq gurl frrz gb yvxr vg gung jnl!