Re: Time in suspended mode has second resolution

Marcelo Tosatti
2007-09-11T06:52:32Z

On suspend, timekeeping_suspend() saves the current time from RTC,
and restores that on resume. Since it truncates the time to second
resolution, and the TSC has just been zeroed on poweroff, the following
can happen:

last_jiffies_update = second.nanosec;
timekeeping_suspend_time = get_rtc_time();
suspend
resume
xtime.tv_sec = timekeeping_suspend_time;

So the system might end up with the current time set with a
value lower than last_jiffies_update, causing "delta" from
tick_do_update_jiffies64() to be negative. The end result is that the
system spends more time than necessary in cpu_idle(), until "delta"
becomes positive (which can take hundreds of ms).

The proposed fix is to zero last_jiffies_update on resume. Note: if
cpu_idle() is invoked before timekeeping_resume has had a chance to run,
a negative delta on tick_do_update_jiffies64() will be seen, so a proper
fix would be to zero it in early_resume.

Are there any side effects of zeroing last_jiffies_update like this?

TIA

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 52db9e3..28b678f 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -33,7 +33,7 @@ static DEFINE_PER_CPU(struct tick_sched,
/*
* The time, when the last jiffy update happened. Protected by xtime_lock.
*/
-static ktime_t last_jiffies_update;
+ktime_t last_jiffies_update;

struct tick_sched *tick_get_tick_sched(int cpu)
{
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 3d1042f..ac22ae2 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -260,6 +260,7 @@ static int timekeeping_suspended;
/* time in seconds when suspend began */
static unsigned long timekeeping_suspend_time;

+extern ktime_t last_jiffies_update;
/**
* timekeeping_resume - Resumes the generic timekeeping subsystem.
* @dev: unused
@@ -293,6 +294,8 @@ static int timekeeping_resume(struct sys

clockevents_notify(CLOCK_EVT_NOTIFY_RESUME, NULL);

+ last_jiffies_update = ktime_set(0, 0);
+
/* Resume hrtimers */
hres_timers_resume();

On Mon, Sep 10, 2007 at 08:55:47PM -0400, Marcelo Tosatti wrote:
>
> I suppose that saving the current nanosecond time from xtime on suspend
> and then restoring it _right after resume_ can fix this.

Bullshit.

> On Mon, Sep 10, 2007 at 04:09:07PM -0400, Marcelo Tosatti wrote:
> > Hi folks,
> >
> > So I tracked down the problem where time is being spent in cpu_idle()
> > for way more than necessary on resume (thanks Jordan!).
> >
> > What happens is that "last_jiffies_update" has a higher value than "now"
> > in tick_do_update_jiffies64(), therefore "delta" becomes negative.
> >
> > The reason for this is that timekeeping_suspend uses the RTC with second
> > resolution to save the time of suspend, thus indirectly truncating the
> > value restored on resume.
> >
> > So the following gets rid of the problem
> >
> > diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> > index 3d1042f..06a7040 100644
> > --- a/kernel/time/timekeeping.c
> > +++ b/kernel/time/timekeeping.c
> > @@ -280,7 +280,7 @@ static int timekeeping_resume(struct sys
> > if (now && (now > timekeeping_suspend_time)) {
> > unsigned long sleep_length = now - timekeeping_suspend_time;
> >
> > - xtime.tv_sec += sleep_length;
> > + xtime.tv_sec += sleep_length + 1;
> > wall_to_monotonic.tv_sec -= sleep_length;
> > }
> > /* re-base the last cycle value */
> >
> > But it erroneously affects the internal clock.
> >
> > By the way, talking about "internal clock", the fact that xtime is
> > truncated during resume can result in wrong clock time, right? Even more
> > if you do it often.
> >
> >
> > Below you can see the problem in action.
> >
> > [ 0.040888] rtc_cmos rtc_cmos: EARLY resume
> > [ 0.040972] platform powerbutton: EARLY resume
> > [ 0.041050] platform lid: EARLY resume
> > [ 0.041123] pci 0000:00:01.0: EARLY resume
> > [ 0.041202] lxfb 0000:00:01.1: EARLY resume
> > [ 0.041281] Geode LX AES 0000:00:01.2: EARLY resume
> > [ 0.041366] CAFÉ NAND 0000:00:0c.0: EARLY resume
> > [ 0.041450] sdhci 0000:00:0c.1: EARLY resume
> > [ 0.041530] cafe1000-ccic 0000:00:0c.2: EARLY resume
> > [ 0.041616] pci 0000:00:0f.0: EARLY resume
> > [ 0.041694] cs5535audio 0000:00:0f.3: EARLY resume
> > [ 0.041779] ohci_hcd 0000:00:0f.4: EARLY resume
> > [ 0.041861] ehci_hcd 0000:00:0f.5: EARLY resume
> > [ 0.041953] serial8250 serial8250.0: EARLY resume
> > [ 0.042034] platform pcspkr: EARLY resume
> > [ 0.042111] platform vesafb.0: EARLY resume
> > [ 0.042259] serial8250 serial8250: EARLY resume
> > [ 0.042354] i8042 i8042: EARLY resume
> > [ 0.042430] platform dcon: EARLY resume
> > [ 0.042525] platform olpc-battery.0: EARLY resume
> > [ 0.042658] tick_do_update_jiffies64: now=50081263258 last_jiffies_update=50523000000
> > [ 0.042773] tick_do_update_jiffies64: delta=[-1,558263258]
> > [ 0.042866] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.042970] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.043065] tick_do_update_jiffies64: now=[50,81263258]
> > [ 0.043829] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.045982] olpm-pm: SCI 0x0 received
> > [ 0.046075] PM: Finishing wakeup.
> > [ 0.046172] rtc_cmos rtc_cmos: resuming
> > [ 0.046254] platform powerbutton: resuming
> > [ 0.046335] platform lid: resuming
> > [ 0.046419] pci 0000:00:01.0: resuming
> > [ 0.046627] lxfb 0000:00:01.1: resuming
> > [ 0.046887] Geode LX AES 0000:00:01.2: resuming
> > [ 0.047128] CAFÉ NAND 0000:00:0c.0: resuming
> > [ 0.047217] sdhci 0000:00:0c.1: resuming
> > [ 0.047447] PM: Writing back config space on device 0000:00:0c.1 at offset f (was 8080100, writing 808010b)
> > [ 0.047719] PM: Writing back config space on device 0000:00:0c.1 at offset 3 (was 800000, writing 802000)
> > [ 0.047884] PM: Writing back config space on device 0000:00:0c.1 at offset 1 (was 2b00002, writing 2b00006)
> > [ 0.048228] mmc_detect_change: sleeping for 1 msecs
> > [ 0.048310] mmc_schedule_delayed_work, delay=1
> > [ 0.048401] internal_add_timer, expires=fffc317c now=fffc317b
> > [ 0.048503] cafe1000-ccic 0000:00:0c.2: resuming
> > [ 0.048674] PM: Writing back config space on device 0000:00:0c.2 at offset f (was 8080100, writing 808010b)
> > [ 0.048946] PM: Writing back config space on device 0000:00:0c.2 at offset 3 (was 800000, writing 802000)
> > [ 0.049111] PM: Writing back config space on device 0000:00:0c.2 at offset 1 (was 2b00002, writing 2b00006)
> > [ 0.054417] pci 0000:00:0f.0: resuming
> > [ 0.054648] cs5535audio 0000:00:0f.3: resuming
> > [ 0.054917] PCI: Setting latency timer of device 0000:00:0f.3 to 64
> > [ 0.059360] __wake_up: caller0=d099ceaa caller1=c052e4d7
> > [ 0.059459] ohci_hcd 0000:00:0f.4: resuming
> > [ 0.059569] ohci_hcd 0000:00:0f.4: PCI D0, from previous PCI D3
> > [ 0.059833] PCI: Setting latency timer of device 0000:00:0f.4 to 64
> > [ 0.060100] ohci_hcd 0000:00:0f.4: powerup ports
> > [ 0.060195] internal_add_timer, expires=fffc3190 now=fffc317b
> > [ 0.060326] no need resched!
> > [ 0.070678] tick_do_update_jiffies64: now=50109289623 last_jiffies_update=50523000000
> > [ 0.070793] tick_do_update_jiffies64: delta=[-1,586289623]
> > [ 0.070886] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.070990] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.071085] tick_do_update_jiffies64: now=[50,109289623]
> > [ 0.071226] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.071353] no need resched!
> > [ 0.098686] tick_do_update_jiffies64: now=50137300251 last_jiffies_update=50523000000
> > [ 0.098801] tick_do_update_jiffies64: delta=[-1,614300251]
> > [ 0.098894] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.098998] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.099092] tick_do_update_jiffies64: now=[50,137300251]
> > [ 0.099230] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.099356] no need resched!
> > [ 0.126691] tick_do_update_jiffies64: now=50165307741 last_jiffies_update=50523000000
> > [ 0.126806] tick_do_update_jiffies64: delta=[-1,642307741]
> > [ 0.126899] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.127003] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.127097] tick_do_update_jiffies64: now=[50,165307741]
> > [ 0.127235] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.127360] no need resched!
> > [ 0.154695] tick_do_update_jiffies64: now=50193314933 last_jiffies_update=50523000000
> > [ 0.154811] tick_do_update_jiffies64: delta=[-1,670314933]
> > [ 0.154903] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.155007] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.155102] tick_do_update_jiffies64: now=[50,193314933]
> > [ 0.155240] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.155365] no need resched!
> > [ 0.182700] tick_do_update_jiffies64: now=50221322406 last_jiffies_update=50523000000
> > [ 0.182815] tick_do_update_jiffies64: delta=[-1,698322406]
> > [ 0.182908] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.183013] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.183107] tick_do_update_jiffies64: now=[50,221322406]
> > [ 0.183245] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.183370] no need resched!
> > [ 0.210705] tick_do_update_jiffies64: now=50249329404 last_jiffies_update=50523000000
> > [ 0.210820] tick_do_update_jiffies64: delta=[-1,726329404]
> > [ 0.210913] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.211017] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.211111] tick_do_update_jiffies64: now=[50,249329404]
> > [ 0.211249] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.211374] no need resched!
> > [ 0.462743] tick_do_update_jiffies64: now=50501390710 last_jiffies_update=50523000000
> > ...
> > [ 0.462858] tick_do_update_jiffies64: delta=[-1,978390710]
> > [ 0.462951] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.463055] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.463150] tick_do_update_jiffies64: now=[50,501390710]
> > [ 0.463287] run_timer_softirq: jiffies=fffc317b, base->timer_jiffies=fffc317c
> > [ 0.463413] no need resched!
> > [ 0.485374] tick_do_update_jiffies64: now=50524024023 last_jiffies_update=50523000000
> > [ 0.485488] tick_do_update_jiffies64: delta=[0,1024023]
> > [ 0.485578] tick_do_update_jiffies64: last_jiffies_update=[50,523000000]
> > [ 0.485683] tick_do_update_jiffies64: tick_period=[0,1000000]
> > [ 0.485777] tick_do_update_jiffies64: now=[50,524024023]
> >
> > Then things proceed normally.
> >
> >
> >