Re: tsc breaks atkbd suspend

[Pavel Machek]

On Mon 2008-02-18 16:12:40, Thomas Gleixner wrote:
> On Mon, 18 Feb 2008, Pavel Machek wrote:
> > > I do not understand, what you mean. When exactly is "sleeppy test"
> > > running ?
> > 
> > from late_initcall().
> 
> Has the system already switched to highres/nohz mode at this point ?

I guess so, as nohz=off makes the problem go away.

> > > Also the TSC unstable detection is in a 500ms timeframe, so you should
> > > never get a 10s delay.
> > 
> > I'd not expect TSC instability detection to be ran while system is
> > suspending
> 
> There is nothing which switches it off, except right at the point
> where the machine is shutdown. It's definitely active during the
> freeze period.
> 
> > , plus "wrong for 500msec" is still wrong.
> 
> To be wrong for 500ms, the TSC must freeze completely.

...which is still very possible with C3, and being wrong for <500msec
is still wrong.

> > > > I believe fix is very simple:
> > > 
> > > NAK. 
> > > 
> > > This kills TSC on machines which have a working TSC and never go into
> > > suspend.
> > 
> > Apart from OLPC, which machines have working TSC?
> > 
> > Anything that has cpufreq does not.
> 
> Wrong. Newer CPUs have TSCs which are not affected by cpu frequency.

Ok, so whitelist the newer CPUs.

> > Anything that enters C2 does not.
> 
> Wrong. C3 stops the TSC everywhere. C2 should not, but it does
> unfortunately due to stupid BIOS implementations and on a lot of AMD
> CPUs.

Hmm, and C3 is rather common, right?

> > Anything that is SMP does not.
> 
> Wrong. I'm writing this mail from a SMP machine with perfectly
> sychronized TSCs.

While I'm writing this from thinkpad X60:

checking TSC synchronization [CPU#0 -> CPU#1]:
Measured 580063 cycles TSC warp between CPUs, turning off TSC clock.
Marking TSC unstable due to: check_tsc_sync_source failed.

> > So, how many machines do you have with working TSC?
> 
> At least 5.

Out of?

I do not see what we are arguing about. TSC was not originally
designed to provide time, and it does not provide time at least on
machines with C3. We are using it by default, which is just wrong.

If it works for some systems, they should be whitelisted.

> One sensible solution would be to force TSC unstable before we
> suspend, but I'd like to know why that 10sec delay happens at all.
> 
> Can you please provide a dmesg log ?

(Detailed log in attachment).

...
PM: Adding info for No Bus:cpu_dma_latency
PM: Adding info for No Bus:network_latency
PM: Adding info for No Bus:network_throughput
PM: test RTC wakeup from 'mem' suspend
PM: Syncing filesystems ... done.
PM: Preparing system for mem sleep
Freezing user space processes ... (elapsed 0.00 seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
PM: Entering mem sleep
ACPI: Preparing to enter system sleep state S3
coretemp coretemp.0: suspend
serio serio1: suspend
serio_suspend: starting
serio_suspend: done
atkbd serio0: suspend
serio_suspend: starting
ps2_command enter
ps2_command get mutex
ps2_command pause rx
ps2_command synaptics
ps2_command sending bytes
ps2_command waiting event: 1000
wait_event returned: 998
ps2_command adjust timeout: 25
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
# here it hangs, for ~30 seconds, while it should be sleeping for 100msec.
#
ps2_command receiving
ps2_command mostly done
serio_suspend: done
i8042 i8042: suspend
i8042_suspend: starting
i8042_suspend: done
sd 0:0:0:0: suspend
sd 0:0:0:0: [sda] Synchronizing SCSI cache
sd 0:0:0:0: [sda] Stopping disk
sd 0:0:0:0: suspended
ahci: autosuspend disabled

Here's what I used to get those debug prints:

diff --git a/drivers/input/serio/i8042.c b/drivers/input/serio/i8042.c
index 2763394..8115893 100644
--- a/drivers/input/serio/i8042.c
+++ b/drivers/input/serio/i8042.c
@@ -895,12 +895,14 @@ #ifdef CONFIG_PM
 
 static int i8042_suspend(struct platform_device *dev, pm_message_t state)
 {
+	printk("i8042_suspend: starting\n");
 	if (dev->dev.power.power_state.event != state.event) {
 		if (state.event == PM_EVENT_SUSPEND)
 			i8042_controller_reset();
 
 		dev->dev.power.power_state = state;
 	}
+	printk("i8042_suspend: done\n");
 
 	return 0;
 }
diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
index b819239..81bd843 100644
--- a/drivers/input/serio/libps2.c
+++ b/drivers/input/serio/libps2.c
@@ -178,6 +178,7 @@ int ps2_command(struct ps2dev *ps2dev, u
 	int rc = -1;
 	int i;
 
+	printk("ps2_command enter\n");
 	if (receive > sizeof(ps2dev->cmdbuf)) {
 		WARN_ON(1);
 		return -1;
@@ -188,8 +189,10 @@ int ps2_command(struct ps2dev *ps2dev, u
 		return -1;
 	}
 
+	printk("ps2_command get mutex\n");
 	mutex_lock(&ps2dev->cmd_mutex);
 
+	printk("ps2_command pause rx\n");
 	serio_pause_rx(ps2dev->serio);
 	ps2dev->flags = command == PS2_CMD_GETID ? PS2_FLAG_WAITID : 0;
 	ps2dev->cmdcnt = receive;
@@ -198,6 +201,7 @@ int ps2_command(struct ps2dev *ps2dev, u
 			ps2dev->cmdbuf[(receive - 1) - i] = param[i];
 	serio_continue_rx(ps2dev->serio);
 
+	printk("ps2_command synaptics\n");
 	/*
 	 * Some devices (Synaptics) peform the reset before
 	 * ACKing the reset command, and so it can take a long
@@ -207,29 +211,51 @@ int ps2_command(struct ps2dev *ps2dev, u
 			 command == PS2_CMD_RESET_BAT ? 1000 : 200))
 		goto out;
 
+	printk("ps2_command sending bytes\n");
 	for (i = 0; i < send; i++)
 		if (ps2_sendbyte(ps2dev, param[i], 200))
 			goto out;
 
+
 	/*
 	 * The reset command takes a long time to execute.
 	 */
 	timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
 
+#if 0
+	printk("ps2: testing timeouts\n");
+	timeout = wait_event_timeout(ps2dev->wait, 0, 10);
+	printk("ps2: testing timeouts\n");
+	timeout = wait_event_timeout(ps2dev->wait, 0, 10);
+	printk("ps2: testing timeouts\n");
+	timeout = wait_event_timeout(ps2dev->wait, 0, 10);
+	printk("ps2: testing timeouts\n");
+	timeout = wait_event_timeout(ps2dev->wait, 0, 10);
+	printk("ps2: testing timeouts\n");
+	timeout = wait_event_timeout(ps2dev->wait, 0, 10);
+	printk("ps2: timeouts ok?\n");
+#endif
+	printk("ps2_command waiting event: %d\n", timeout);
 	timeout = wait_event_timeout(ps2dev->wait,
 				     !(ps2dev->flags & PS2_FLAG_CMD1), timeout);
 
 	if (ps2dev->cmdcnt && timeout > 0) {
+		printk("wait_event returned: %d\n", timeout);
 
 		timeout = ps2_adjust_timeout(ps2dev, command, timeout);
+
+		printk("ps2_command adjust timeout: %d\n", timeout);
 		wait_event_timeout(ps2dev->wait,
 				   !(ps2dev->flags & PS2_FLAG_CMD), timeout);
 	}
 
+	printk("ps2_command receiving\n");
 	if (param)
 		for (i = 0; i < receive; i++)
 			param[i] = ps2dev->cmdbuf[(receive - 1) - i];
 
+	printk("ps2_command mostly done\n");
+
 	if (ps2dev->cmdcnt && (command != PS2_CMD_RESET_BAT || ps2dev->cmdcnt != 1))
 		goto out;
 
diff --git a/drivers/input/serio/serio.c b/drivers/input/serio/serio.c
index 7f52938..cd320b1 100644
--- a/drivers/input/serio/serio.c
+++ b/drivers/input/serio/serio.c
@@ -912,12 +912,14 @@ #endif /* CONFIG_HOTPLUG */
 #ifdef CONFIG_PM
 static int serio_suspend(struct device *dev, pm_message_t state)
 {
+	printk("serio_suspend: starting\n");
 	if (dev->power.power_state.event != state.event) {
 		if (state.event == PM_EVENT_SUSPEND)
 			serio_cleanup(to_serio_port(dev));
 
 		dev->power.power_state = state;
 	}
+	printk("serio_suspend: done\n");
 
 	return 0;
 }

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Attachment: hz.bug.gz
Description: Binary data