[ltp] T61 suspend troubles

Marius Gedminas linux-thinkpad@linux-thinkpad.org
Fri, 10 Aug 2007 14:41:37 +0300


--Pd0ReVV5GZGQvF3a
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Fri, Aug 10, 2007 at 12:57:21AM +0300, Marius Gedminas wrote:
> I'm trying to get suspend to work on my T61 (model 6466-55G).  I already
> figured out that I need acpi_sleep=3Ds3_bios on the kernel command line to
> get LCD backlight back after a resume.  (This may be applicable only to
> laptops with Intel video.)  I'm fighting the kernel panic now, which
> seems to be SMP/APIC related:

The same oops occurs if I try to hibernate rather than suspend (and it
happens before the kernel starts writing pages to disk rather than on
resume).

Booting with nolapic_timer didn't help: same oops.  Booting with nolapic
didn't work: the laptop froze when I tried to log in.  I didn't try
booting with noapic or noacpi yet.  Booting with maxcpus=3D1 seems to help
somewhat, but the first resume takes a long while (~2 minutes), and
every suspend/resume after that is also very very slow.

It seems that the laptop freezes and doesn't do anything until I start
furiously tapping CapsLock to see whether it works or not, and then it
progresses a bit.  It can't be a coincidence: every time I got bored
waiting and started tapping CapsLock it woke up and started buzzing the
disk again.


First suspend: 2 seconds:

  [  138.680000] PM: Preparing system for mem sleep
  ...
  [  140.692000] PM: Entering mem sleep

First resume: ~50 seconds

    [  140.692000] Back to C!
    ...
    [  188.108000] Restarting tasks ... <6>usb 1-1: USB disconnect, address=
 3
    [  188.188000] done.

There's a 15 second delay between these two messages:

    [  140.708000] PCI: Setting latency timer of device 0000:00:1a.7 to 64
    [  155.900000] PM: Writing back config space on device 0000:00:1b.0 at =
offset 1 (was 100106, writing 100102)

then a 20 second delay between these two messages:

    [  155.900000] PCI: Setting latency timer of device 0000:00:1b.0 to 64
    [  174.876000] hda_intel: azx_get_response timeout, switching to pollin=
g mode...

and a couple more 3-5 second delays in other places.


I also see a scary disk exception:

    [  371.228000] ata1.00: exception Emask 0x2 SAct 0x7fc1f SErr 0x0 actio=
n 0x2 frozen
    [  371.228000] ata1.00: (spurious completions during NCQ issue=3D0x0 SA=
ct=3D0x7fc1f FIS=3D005040a1:00000200)
    [  371.228000] ata1.00: cmd 61/08:00:30:13:ab/00:00:02:00:00/40 tag 0 c=
db 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:08:30:13:b3/00:00:02:00:00/40 tag 1 c=
db 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:10:80:13:c3/00:00:02:00:00/40 tag 2 c=
db 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:18:48:14:cb/00:00:02:00:00/40 tag 3 c=
db 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:20:d8:14:db/00:00:02:00:00/40 tag 4 c=
db 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:50:38:16:a7/00:00:02:00:00/40 tag 10 =
cdb 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:58:38:17:a7/00:00:02:00:00/40 tag 11 =
cdb 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:60:40:17:a7/00:00:02:00:00/40 tag 12 =
cdb 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:68:20:18:a7/00:00:02:00:00/40 tag 13 =
cdb 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:70:b8:1a:a7/00:00:02:00:00/40 tag 14 =
cdb 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:78:08:1b:a7/00:00:02:00:00/40 tag 15 =
cdb 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/08:80:a8:13:ab/00:00:02:00:00/40 tag 16 =
cdb 0x0 data 4096 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/10:88:88:14:ab/00:00:02:00:00/40 tag 17 =
cdb 0x0 data 8192 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.228000] ata1.00: cmd 61/10:90:f8:14:ab/00:00:02:00:00/40 tag 18 =
cdb 0x0 data 8192 out
    [  371.228000]          res 50/00:08:d8:14:db/00:00:02:00:00/40 Emask 0=
x2 (HSM violation)
    [  371.552000] ata1: soft resetting port
    [  371.728000] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
    [  371.728000] ata1.00: configured for UDMA/100
    [  371.728000] ata1: EH complete
    [  371.728000] sd 0:0:0:0: [sda] 234441648 512-byte hardware sectors (1=
20034 MB)
    [  371.728000] sd 0:0:0:0: [sda] Write Protect is off
    [  371.728000] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
    [  371.732000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enab=
led, doesn't support DPO or FUA

It's not the first time I see it; it once happened on boot and added an ext=
ra
~30 second delay.


Second suspend: 60 seconds

    [  764.816000] PM: Preparing system for mem sleep
    ...
    [  824.408000] PM: Entering mem sleep

Longest delay:

    [  764.820000] usb_endpoint usbdev1.6_ep00: PM: suspend 0->2, parent 1-=
2 already 2
    [  822.292000] sd 0:0:0:0: [sda] Synchronizing SCSI cache

Second resume: 150 seconds

    [  824.408000] Back to C!
    ...
    [  972.864000] done.

Longest delay:

    [  836.300000] hda_intel: azx_get_response timeout, switching to single=
_cmd mode...
    [  960.704000] PM: Writing back config space on device 0000:00:1c.0 at =
offset 1 (was 100107, writing 100507)


Third suspend: 350 seconds

    [ 1055.728000] PM: Preparing system for mem sleep
    ...
    [ 1404.760000] PM: Entering mem sleep

Longest delay:

    [ 1060.596000] usb_endpoint usbdev2.1_ep00: PM: suspend 0->2, parent us=
b2 already 2
    [ 1350.764000] ACPI: PCI interrupt for device 0000:15:00.2 disabled

Third resume: 100 seconds.

    [ 1404.760000] Back to C!
    ...
    [ 1506.388000] Restarting tasks ... done.

Long delay:

    [ 1407.860000] PCI: Setting latency timer of device 0000:00:1b.0 to 64
    [ 1421.368000] PM: Writing back config space on device 0000:00:1c.0 at =
offset 1 (was 100107, writing 100507)

Longest delay:

    [ 1423.212000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enab=
led, doesn't support DPO or FUA
    [ 1503.604000] usb_endpoint usbdev6.1_ep00: PM: resume from 0, parent u=
sb6 still 2


The PCI devices mentioned in these messages are

    00:1a.7 USB Controller: Intel Corporation 82801H (ICH8 Family) USB2 EHC=
I #2 (rev 03)
    00:1b.0 Audio device: Intel Corporation 82801H (ICH8 Family) HD Audio C=
ontroller (rev 03)
    00:1c.0 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express =
Port 1 (rev 03)
    15:00.2 Generic system peripheral [0805]: Ricoh Co Ltd R5C822 SD/SDIO/M=
MC/MS/MSPro Host Adapter (rev 21)


By the way, some time after the last resume I got this error:

    [ 1739.476000] irq 23: nobody cared (try booting with the "irqpoll" opt=
ion)
    [ 1739.476000]  [<c015b4c4>] __report_bad_irq+0x24/0x80
    [ 1739.476000]  [<c015b782>] note_interrupt+0x262/0x2a0
    [ 1739.476000]  [<f88696b2>] usb_hcd_irq+0x22/0x60 [usbcore]
    [ 1739.476000]  [<c015a9e0>] handle_IRQ_event+0x30/0x60
    [ 1739.476000]  [<c015c16b>] handle_fasteoi_irq+0xbb/0xf0
    [ 1739.476000]  [<c0106b1b>] do_IRQ+0x3b/0x70
    [ 1739.476000]  [<c0105223>] common_interrupt+0x23/0x30
    [ 1739.476000]  =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D
    [ 1739.476000] handlers:
    [ 1739.476000] [<f8869690>] (usb_hcd_irq+0x0/0x60 [usbcore])
    [ 1739.476000] Disabling IRQ #23

Now the one USB port on the left side works, but the two USB ports on the r=
ight
don't.  My USB1 mouse doesn't light up.  My USB2 Nokia N800 detects the USB
cable, but the kernel doesn't see a new device.


I'm starting to think I should've bought a Dell with Ubuntu preinstalled.  =
:/

Marius Gedminas
--=20
It's not illegal to disagree with my opinions (*).
[...]
(*) Although it obviously _should_ be. Mwhaahahahahaaa... You unbelievers
will all be shot when the revolution comes!
		-- Linus Torvalds

--Pd0ReVV5GZGQvF3a
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: Digital signature
Content-Disposition: inline

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQFGvE7xkVdEXeem148RAtJ/AKCNqU43g+EEjQSIXDctJurdU93vegCfSp+E
YhHBnSyFliIuYFF5F3qbeTg=
=qQR4
-----END PGP SIGNATURE-----

--Pd0ReVV5GZGQvF3a--