Re: TSC not updating after resume: Bug or Feature?

[Thomas Gleixner <tglx@linutronix.de>]

On Mon, 22 Dec 2008, Ingo Molnar wrote:
> * Thomas Gleixner <tglx@linutronix.de> wrote:
> 
> > > By the way, I don't know if it matters but the problema happened with 
> > > in-kernel hibernation and also in out-of-tree TuxOnIce hibernation. 
> > > Maybe this can help debugging the issue, I don't know.
> > 
> > Hmm, does not ring a bell here. Can you please apply the patch below to 
> > mainline and retest ?
> 
> ... and he should send a dmesg after a suspend cycle, right?

Yes :)

I digged more in the bugzillas. Toralf added some debug to
__update_sched_clock():

-       max_clock = wrap_max(scd->clock, scd->tick_gtod + TICK_NSEC);
+       max_clock = scd->tick_gtod + TICK_NSEC;
+       if (scd->clock > max_clock)
+               printk(KERN_INFO "%d %d\n", scd->clock, max_clock);

The interesting output is:

Dec 14 21:55:55 n22 Back to C!
Dec 14 21:55:55 n22 Extended CMOS year: 2000
Dec 14 21:55:55 n22 Force enabled HPET at resume
Dec 14 21:55:55 n22 212611283 77

The 77 is totaly bogus and it's likely not just a truncation of the
64bit value because (scd->clock > max_clock) evaluates to true. This
output is _AFTER_ timekeeping resume because the HPET force enable
message comes from timekeeping resume.

Toralf, can you please try the patch below on top of mainline ? Make
sure that CONFIG_PRINTK_TIME is off, otherwise the kernel
deadlocks. Please send the dmesg output from a suspend/resume cycle.

Thanks,

	tglx
----
diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index e8ab096..9c307a2 100644
--- a/kernel/sched_clock.c
+++ b/kernel/sched_clock.c
@@ -86,6 +86,14 @@ void sched_clock_init(void)
 	sched_clock_running = 1;
 }
 
+void sched_clock_debug(void)
+{
+	struct sched_clock_data *scd = this_scd();
+
+	printk(KERN_INFO "SCD raw %llu gtod %llu clock %llu now %llu\n",
+	       scd->tick_raw, scd->tick_gtod, scd->clock, sched_clock());
+}
+
 /*
  * min,max except they take wrapping into account
  */
@@ -125,6 +133,11 @@ static u64 __update_sched_clock(struct sched_clock_data *scd, u64 now)
 	clock = scd->tick_gtod + delta;
 	min_clock = wrap_max(scd->tick_gtod, scd->clock);
 	max_clock = scd->tick_gtod + TICK_NSEC;
+	if (scd->clock > max_clock) {
+		printk(KERN_INFO "SC: %llu %llu %llu %llu %llu %llu\n",
+		       scd->clock, scd->tick_raw, scd->tick_gtod, now,
+		       max_clock, clock);
+	}
 
 	clock = wrap_max(clock, min_clock);
 	clock = wrap_min(clock, max_clock);
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index fa05e88..bafbd2d 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -304,6 +304,8 @@ static int timekeeping_suspended;
 /* time in seconds when suspend began */
 static unsigned long timekeeping_suspend_time;
 
+extern void sched_clock_debug(void);
+
 /**
  * timekeeping_resume - Resumes the generic timekeeping subsystem.
  * @dev:	unused
@@ -336,6 +338,8 @@ static int timekeeping_resume(struct sys_device *dev)
 	timekeeping_suspended = 0;
 	write_sequnlock_irqrestore(&xtime_lock, flags);
 
+	sched_clock_debug();
+
 	touch_softlockup_watchdog();
 
 	clockevents_notify(CLOCK_EVT_NOTIFY_RESUME, NULL);
@@ -357,6 +361,8 @@ static int timekeeping_suspend(struct sys_device *dev, pm_message_t state)
 	timekeeping_suspended = 1;
 	write_sequnlock_irqrestore(&xtime_lock, flags);
 
+	sched_clock_debug();
+
 	clockevents_notify(CLOCK_EVT_NOTIFY_SUSPEND, NULL);
 
 	return 0;