2D rendering slowdown on suspend (NVIDIA NVS 140M, Thinkpad R61)

[ryanschultz]

I've encountered a problem with suspend to RAM on my Thinkpad R61 with NVIDIA graphics (at least one other person has this problem on a T61 as well). The system will correctly suspend to RAM and come back up; however, when it restores, the graphics drawing is slowed down substantially.

Actual performance is not affected, just the speed of redrawing in X -- for example, I've actually watched each icon draw itself in Konqueror while this slowdown was occurring, but I logged in via SSH and everything ran at full speed, including compiles, etc. Restarting X fixes this; there is no need to unload the 'nvidia' module. No process consumes an unusual amount of CPU time after recovering from the suspend, although any of the slowed drawing operations in X quickly cause Xorg to eat a lot of CPU.

Some details about my configuration:
Thinkpad R61, Core 2 Duo 2GHz, NVIDIA Quadro NVS 140M (PCI Express)
-- kernel 2.6.22-r7 + thinkpad, cpuidle patches (same problem occurs on multiple kernels, including 2.6.21-ck2, 2.6.22-r4, 2.6.22-r6, so I don't think this is the origin)
-- NVIDIA drivers 100.14.11 (problem occurs also in 100.14.09, which are the first to support the 140M)

To reproduce:
1. Load into X.
2. s2ram --force
3. Wake computer up.

I have tried all VBE options with s2ram -- these either crash the video or have no affect.

NvAGP 1 or 0 have no effect -- not surprising, since the 140M is PCI Express.

------------------------------------------------------

nvidia-bug-report.sh output: http://rschultz.ath.cx/nvidia-bug-report.log

------------------------------------------------------

dmesg output after 's2ram --force' and wakeup:

Stopping tasks ... done.
Suspending console(s)
hdaps: setting ec_rate=0, filter_order=1
sd 0:0:0:0: [sda] Synchronizing SCSI cache
sd 0:0:0:0: [sda] Stopping disk
ACPI: PCI interrupt for device 0000:15:00.2 disabled
ACPI: PCI interrupt for device 0000:03:00.0 disabled
NVRM: RmPowerManagement: 3
ACPI: PCI interrupt for device 0000:00:1f.2 disabled
ACPI: PCI interrupt for device 0000:00:1d.7 disabled
ACPI: PCI interrupt for device 0000:00:1d.2 disabled
ACPI: PCI interrupt for device 0000:00:1d.1 disabled
ACPI: PCI interrupt for device 0000:00:1d.0 disabled
ACPI: PCI interrupt for device 0000:00:1b.0 disabled
ACPI: PCI interrupt for device 0000:00:1a.7 disabled
ACPI: PCI interrupt for device 0000:00:1a.1 disabled
ACPI: PCI interrupt for device 0000:00:1a.0 disabled
ACPI: PCI interrupt for device 0000:00:19.0 disabled
Disabling non-boot CPUs ...
Breaking affinity for irq 22
CPU 1 is now offline
SMP alternatives: switching to UP code
CPU1 is down
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
Back to C!
Enabling non-boot CPUs ...
SMP alternatives: switching to SMP code
Booting processor 1/1 eip 3000
Initializing CPU#1
Calibrating delay using timer specific routine.. 3990.88 BogoMIPS (lpj=1995444)
CPU: After generic identify, caps: bfebfbff 20100000 00000000 00000000 0000e3bd 00000000 00000001
monitor/mwait feature present.
CPU: L1 I cache: 32K, L1 D cache: 32K
CPU: L2 cache: 4096K
CPU: Physical Processor ID: 0
CPU: Processor Core ID: 1
CPU: After all inits, caps: bfebfbff 20100000 00000000 00003940 0000e3bd 00000000 00000001
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#1.
CPU1: Intel(R) Core(TM)2 Duo CPU T7300 @ 2.00GHz stepping 0a
CPU1 is up
Switched to high resolution mode on CPU 1
PCI: Setting latency timer of device 0000:00:01.0 to 64
ACPI: PCI Interrupt 0000:00:19.0[A] -> GSI 20 (level, low) -> IRQ 17
PCI: Setting latency timer of device 0000:00:19.0 to 64
ACPI: PCI Interrupt 0000:00:1a.0[A] -> GSI 20 (level, low) -> IRQ 17
PCI: Setting latency timer of device 0000:00:1a.0 to 64
usb usb3: root hub lost power or was reset
ACPI: PCI Interrupt 0000:00:1a.1[b] -> GSI 21 (level, low) -> IRQ 18
PCI: Setting latency timer of device 0000:00:1a.1 to 64
usb usb4: root hub lost power or was reset
ACPI: PCI Interrupt 0000:00:1a.7[C] -> GSI 22 (level, low) -> IRQ 19
PCI: Setting latency timer of device 0000:00:1a.7 to 64
PM: Writing back config space on device 0000:00:1b.0 at offset 1 (was 100106, writing 100102)
ACPI: PCI Interrupt 0000:00:1b.0[b] -> GSI 17 (level, low) -> IRQ 22
PCI: Setting latency timer of device 0000:00:1b.0 to 64
PCI: Setting latency timer of device 0000:00:1c.0 to 64
PCI: Setting latency timer of device 0000:00:1c.1 to 64
PCI: Setting latency timer of device 0000:00:1c.2 to 64
PCI: Setting latency timer of device 0000:00:1c.3 to 64
PCI: Setting latency timer of device 0000:00:1c.4 to 64
ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 16 (level, low) -> IRQ 16
PCI: Setting latency timer of device 0000:00:1d.0 to 64
usb usb5: root hub lost power or was reset
ACPI: PCI Interrupt 0000:00:1d.1[b] -> GSI 17 (level, low) -> IRQ 22
PCI: Setting latency timer of device 0000:00:1d.1 to 64
usb usb6: root hub lost power or was reset
ACPI: PCI Interrupt 0000:00:1d.2[C] -> GSI 18 (level, low) -> IRQ 23
PCI: Setting latency timer of device 0000:00:1d.2 to 64
usb usb7: root hub lost power or was reset
ACPI: PCI Interrupt 0000:00:1d.7[D] -> GSI 19 (level, low) -> IRQ 21
PCI: Setting latency timer of device 0000:00:1d.7 to 64
PM: Writing back config space on device 0000:00:1e.0 at offset 1 (was 100005, writing 100007)
PCI: Setting latency timer of device 0000:00:1e.0 to 64
PM: Writing back config space on device 0000:00:1f.1 at offset 1 (was 2880005, writing 2800005)
ACPI: PCI Interrupt 0000:00:1f.1[C] -> GSI 16 (level, low) -> IRQ 16
ACPI: PCI Interrupt 0000:00:1f.2[b] -> GSI 16 (level, low) -> IRQ 16
PCI: Setting latency timer of device 0000:00:1f.2 to 64
NVRM: RmPowerManagement: 4
e1000: eth1: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex, Flow Control: RX/TX
e1000: eth1: e1000_watchdog: 10/100 speed: disabling TSO
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: configured for UDMA/100
sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
ACPI: PCI Interrupt 0000:03:00.0[A] -> GSI 17 (level, low) -> IRQ 22
PCI: Setting latency timer of device 0000:03:00.0 to 64
PM: Writing back config space on device 0000:15:00.1 at offset 4 (was 0, writing f8101000)
PM: Writing back config space on device 0000:15:00.1 at offset 3 (was 800000, writing 804000)
PM: Writing back config space on device 0000:15:00.1 at offset 1 (was 2100000, writing 2100006)
ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[22] MMIO=[f8101000-f81017ff] Max Packet=[2048] IR/IT contexts=[4/4]
PM: Writing back config space on device 0000:15:00.2 at offset 4 (was 0, writing f8101800)
PM: Writing back config space on device 0000:15:00.2 at offset 3 (was 800000, writing 804000)
PM: Writing back config space on device 0000:15:00.2 at offset 1 (was 2100000, writing 2100006)
ACPI: PCI Interrupt 0000:15:00.2[C] -> GSI 18 (level, low) -> IRQ 23
hda: selected mode 0x42
sd 0:0:0:0: [sda] Starting disk
hdaps: initial mode latch is 0x05
hdaps: setting ec_rate=250, filter_order=2
hdaps: fake_data_mode set to 0
smapi smapi: set_real_thresh: set stop to 0 for bat=0
smapi smapi: set_real_thresh: set start to 0 for bat=0
smapi smapi: set_real_thresh: set stop to 0 for bat=1
smapi smapi: set_real_thresh: set start to 0 for bat=1
usb_endpoint usbdev2.3_ep83: PM: resume from 0, parent 2-5:1.0 still 2
Restarting tasks ... <6>usb 2-5: USB disconnect, address 3
done.
usb 2-5: new high speed USB device using ehci_hcd and address 4
usb 2-5: configuration #1 chosen from 1 choice

-------------------------------------

Thanks!

[zander]

Is the CPU speed the same before/after the power management cycle? Also, does the problem persist if you unload/reload the NVIDIA kernel module after the system has resumed?

[ryanschultz]

CPU speed remains the same; as I said, actual system performance is unchanged, only the video drawing speed in X changes. For example, text apps perform as they should over an SSH connection, but just trying to run top in konsole will slow the system to a crawl in X locally after a suspend.

Restarting X fixes the problem after suspend -- there is no need to reload or unload the module, though doing so and then restarting X does not affect the appearance of the behavior on the next suspend to RAM. Unfortunately having to reload X basically defeats the purpose of suspending :- /

Although I don't know much about the nvidia driver, it's like it's going into some kind of low power state during the suspend and then not coming out of it on resume, and the X reset fixes that. Thinking about CPU frequencies, I also checked the GPU frequencies with coolbits, and they also remain correct after the suspend.

Thank you for your response! Let me know if there is additional data or logs that would be helpful. This is the latest release of X, but I can build X from development sources if that would help eliminate sources of problems.

[ryanschultz]

The 'PerfLevelSrc=0x2222' trick doesn't seem to have any real effect either; I was hoping it would prevent the slowdown. It did seem to sometimes cause the slowdown to be less intense, however, but I can't confirm that it was this option or just some random luck. I couldn't get this to be repeatable because it also often caused my R61 to not recover from the suspend.

[d13f00l]

This might be related to the issue I'm having http://www.nvnews.net/vbulletin/showthread.php?t=94480

Turning off renderaccel so far seems to have worked, and it seemed to be caused by suspending, or switching to compiz than back to metacity...but it's hard to tell. It definitely does slow to a crawl though.

I have a Thinkpad t61.

It really is bad, though. It got to the point where I was watching text being drawn on the screen, from top to bottom.

[d13f00l]

Well, I've been running ever since with renderaccel disabled, it doesn't slow down anymore, but I still get the lockups that can be fixed by ctrl-alt to console and back to X...

Is there going to be a fix for the slowdowns or nvrm xid issue w/ this GPU?

[zander]

@d13f00l: I'm aware of one power management problem that's related and may be responsible for the slowdown you're seeing; this problem should be resolved in future NVIDIA Linux graphics driver releases, but I can't guarantee that it will fix your problem.

[ryanschultz]

Disabling RenderAccel had no effect for me, unfortunately.

[d13f00l]

Originally Posted by ryanschultz

Disabling RenderAccel had no effect for me, unfortunately.

Oops, you're right....maybe it was my imagination that it was gradually slowing down...i just did a suspend and restored, it slowed down even with renderaccell off.

[ryanschultz]

I just got an email from NVIDIA that said they had duplicated the problem and that it has had an internal bug report filed!

Go NVIDIA, please fix this!

[zander]

The fix I referred to earlier was confirmed to resolve this problem. It should be included in the next driver release.

[ryanschultz]

Thank you!