Thinkpad T23 60 second stall on resuming 8.0-RELEASE/i386

Sun Dec 13 03:36:12 PST 2009

Hi,

Precis: suspend by Fn-F4 or acpiconf -s3 works as usual.  When resuming 
by hitting Fn or raising the lid, however, the screen comes back on but 
then system freezes for pretty well exactly 60 seconds before responding 
to anything, after which it seems to be fine, although top shows running 
processes' TIME havig being reset to 00:00 (sometimes, not always)

Also, quite often (but only when verbose messages are off, it seems), I 
see "calcru: time went backwards .." for devd (if powerd is running), 
and once with X/KDE3 up I got a calcru: msg for every process running, 
including init! I have logs of that, but think it an effect, not cause.

I've spent a while exploring this over the last 10 days, and now have a 
solid pointer to the problem by comparing suspend/resume messages with 
what happens on 7.0-R, which exhibits no such problem (nor did 6.1-R)

Here's a diff of a suspend/resume cycle between 7.0R and 8.0R, with the 
problem delay messages marked <<<<<<< .. there are always 3 of these, 
sometimes with the too long/short in different order, and they appear on 
VTY0 screen while resuming every 15 seconds, with a further 15s delay 
before posting the rest of the messages, then coming back to life.

The shortest 'slept' messages I get, by resuming straight away after it 
suspends, is 00:00:04 on 7.0R and 00:01:04 on 8.0R, which makes sense as 
there's a 3 second sleep in rc.suspend.  Here I'd paused a few seconds:

--- 7.0_verb_sleep_7sec	2009-12-13 16:57:28.000000000 +1100
+++ 8.0_dmesg_sleep_01:07_delays.13Dec09	2009-12-13 17:13:56.000000000 +1100
@@ -1,34 +1,35 @@
-Trying to mount root from ufs:/dev/ad0s2a
-start_init: trying /sbin/init
-Linux ELF exec handler installed
-splash: image decoder found: green_saver
 acpi_button0: sleep button pressed
 acpi_lid0: wake_prep enabled for \\_SB_.LID_ (S3)
 acpi_button0: wake_prep enabled for \\_SB_.SLPB (S3)
 pci0:1:0:0: Transition from D0 to D3
 pci0:2:8:0: Transition from D0 to D3
+ct_to_ts([2009-12-13 17:09:32]) = 1260724172.000000000
 vga0: saving 68 bytes of video state
 ======== acpi_printcpu() debug dump ========
-gdt[0097:c0bfe5a0] idt[07ff:c0c00240] ldt[0050] tr[0048] efl[00080006]
-eax[0101e000] ebx[c215d300] ecx[00000000] edx[00000000]
-esi[00000000] edi[00080246] ebp[cc6a8bfc] esp[cc6a8bdc]
-cr0[8005003b] cr2[28207000] cr3[0101e000] cr4[00000691]
-cs[0020] ds[0028] es[0028] fs[0008] gs[003b] ss[0028]
+gdt[0097:c0dfb6a0] idt[07ff:c0e03d00] ldt[0050] tr[0048] efl[00080006]
+eax[0101e000] ebx[00000000] ecx[c101e000] edx[0101e000]
+esi[c2571900] edi[00080202] ebp[cd27cb54] esp[cd27cb34]
+cr0[8005003b] cr2[2815f930] cr3[0101e000] cr4[00000691]
+cs[0020] ds[0028] es[0028] fs[0008] gs[001b] ss[0028]
 ======== acpi_printcpu() debug dump ========
-gdt[0097:c0bfe5a0] idt[07ff:c0c00240] ldt[0050] tr[0048] efl[00000002]
-eax[c2119c01] ebx[00000001] ecx[00000001] edx[c2119c60]
-esi[00000000] edi[00080246] ebp[cc6a8bfc] esp[cc6a8bdc]
-cr0[8005003b] cr2[28207000] cr3[0101e000] cr4[00000691]
-cs[0020] ds[0028] es[0028] fs[0008] gs[003b] ss[0028]
+gdt[0097:c0dfb6a0] idt[07ff:c0e03d00] ldt[0050] tr[0048] efl[00000002]
+eax[c28e8601] ebx[00000000] ecx[00000004] edx[c28e86c0]
+esi[c2571900] edi[00080202] ebp[cd27cb54] esp[cd27cb34]
+cr0[8005003b] cr2[2815f930] cr3[0101e000] cr4[00000691]
+cs[0020] ds[0028] es[0028] fs[0008] gs[001b] ss[0028]
 acpi_lid0: run_prep cleaned up for \\_SB_.LID_
 acpi_button0: run_prep cleaned up for \\_SB_.SLPB
 pci0:1:0:0: Transition from D3 to D0
-wakeup from sleeping state (slept 00:00:07)
+t_delta 15.f9ad99f01204edd8 too short                        <<<<<<<
+t_delta 16.07bb5b66ef900000 too long                         <<<<<<<
+t_delta 15.f9ad90918acc0000 too short                        <<<<<<<
+ct_to_ts([2009-12-13 17:10:39]) = 1260724239.000000000
+wakeup from sleeping state (slept 00:01:07)
 ata0: reiniting channel ..
 ata0: reset tp1 mask=03 ostat0=50 ostat1=00
 ata0: stat0=0x50 err=0x01 lsb=0x00 msb=0x00
 ata0: stat1=0x00 err=0x01 lsb=0x00 msb=0x00
-ata0: reset tp2 stat0=50 stat1=00 devices=0x1<ATA_MASTER>
+ata0: reset tp2 stat0=50 stat1=00 devices=0x1
 ad0: setting PIO4 on ICH3 chip
 ad0: setting UDMA100 on ICH3 chip
 ata0: reinit done ..
@@ -36,7 +37,7 @@
 ata1: reset tp1 mask=03 ostat0=00 ostat1=00
 ata1: stat0=0x00 err=0x01 lsb=0x14 msb=0xeb
 ata1: stat1=0x00 err=0x00 lsb=0x00 msb=0x00
-ata1: reset tp2 stat0=00 stat1=00 devices=0x4<ATAPI_MASTER>
+ata1: reset tp2 stat0=00 stat1=00 devices=0x10000
 acd0: setting PIO4 on ICH3 chip
 acd0: setting UDMA33 on ICH3 chip
 ata1: reinit done ..

I've tested this many times without powerd (or indeed any other daemons) 
running and that makes no difference, nor does not loading acpi_ibm.  
Looking back I see these "t_delta .. time too short|long" messages were 
being logged from the first suspend after the install.

I see they're emitted by /sys/kern/kern_tc.c but I've no idea what's 
calling what during resume.  Happy to test any patches etc of course.

BIOS and EC are the latest, flashed a month or so ago, which did solve a 
whole bunch of ACPI boot messages appearing on 7.0-R.

Further information, though I think the above shows the issue best ..

http://smithi.id.au/7.0_dmesg_verbose.11Dec09
http://smithi.id.au/8.0_dmesg_verbose.13Dec09
http://smithi.id.au/7.0_verb_sleep_7sec
http://smithi.id.au/8.0_dmesg_sleep_01:07_delays.13Dec09

cheers, Ian
