Date: Sun, 13 Dec 2009 22:36:08 +1100 (EST) From: Ian Smith <smithi@nimnet.asn.au> To: freebsd-mobile@freebsd.org Cc: freebsd-acpi@freebsd.org Subject: Thinkpad T23 60 second stall on resuming 8.0-RELEASE/i386 Message-ID: <20091213204201.A12012@sola.nimnet.asn.au>
next in thread | raw e-mail | index | archive | help
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20091213204201.A12012>