TSC not updating after resume: Bug or Feature?

TSC not updating after resume: Bug or Feature?

[Deepak Saxena]

Hi,

I am using ftrace to get a detailed timing analysis of the resume process 
on the OLPC XO laptop and am seeing that when we start running again, the
system timestamep is not being updated for several (hundreds of) thousands 
of cycles (~2000 ftrace entries). From following the ftrace, what is 
happening is that the clocksource is not updated until we run the cpu_idle() 
thread due to an explicit scheduling operation in the resume path that occurs 
via call to msleep from pci_set_power_state().  As I'm still fully groking the 
timekeeping code, the question(s) I have is whether this is expected behaviour 
and I should not assume valid timestamp data in the initial bits of the suspend path, 
whether this is an OLPC-specific bug, or whether I've uncovered a generic bug in 
the timekeeping implementation.  This is on 2.6.27.7 as I've not gotten 28-rc 
up and running on the XO but can move that up in priority if this behaviour
is different in newer kernels.

Thanks,
~Deepak

# dsaxena: Return from firmware
 do_suspend_trac-1267  [00]   154.925216: restore_processor_state <-ret_point
 do_suspend_trac-1267  [00]   154.925216: enable_sep_cpu <-restore_processor_state
 do_suspend_trac-1267  [00]   154.925216: olpc_fixup_wakeup <-olpc_pm_enter
 do_suspend_trac-1267  [00]   154.925216: geode_get_dev_base <-olpc_fixup_wakeup
 do_suspend_trac-1267  [00]   154.925216: olpc_ec_cmd <-olpc_fixup_wakeup
 do_suspend_trac-1267  [00]   154.925216: _spin_lock_irqsave <-olpc_ec_cmd
 do_suspend_trac-1267  [00]   154.925216: __wait_on_ibf <-olpc_ec_cmd
 do_suspend_trac-1267  [00]   154.925216: printk <-olpc_ec_cmd
 do_suspend_trac-1267  [00]   154.925216: vprintk <-printk
 do_suspend_trac-1267  [00]   154.925216: _spin_lock <-vprintk
 do_suspend_trac-1267  [00]   154.925216: emit_log_char <-vprintk
 do_suspend_trac-1267  [00]   154.925216: emit_log_char <-vprintk
....
# pci_set_power_state() calls msleep(10) as per PCI spec
 do_suspend_trac-1267  [00]   154.925216: msleep <-pci_set_power_state
 do_suspend_trac-1267  [00]   154.925216: msecs_to_jiffies <-msleep
 do_suspend_trac-1267  [00]   154.925216: schedule_timeout_uninterruptible <-msleep
 do_suspend_trac-1267  [00]   154.925216: schedule_timeout <-schedule_timeout_uninterruptible
 do_suspend_trac-1267  [00]   154.925216: init_timer_on_stack <-schedule_timeout
 do_suspend_trac-1267  [00]   154.925216: __init_timer <-init_timer_on_stack
 do_suspend_trac-1267  [00]   154.925216: __mod_timer <-schedule_timeout
 do_suspend_trac-1267  [00]   154.925216: __timer_stats_timer_set_start_info <-__mod_timer
 do_suspend_trac-1267  [00]   154.925216: lock_timer_base <-__mod_timer
 do_suspend_trac-1267  [00]   154.925216: _spin_lock_irqsave <-lock_timer_base
 do_suspend_trac-1267  [00]   154.925216: internal_add_timer <-__mod_timer
 do_suspend_trac-1267  [00]   154.925216: _spin_unlock_irqrestore <-__mod_timer
 do_suspend_trac-1267  [00]   154.925216: _spin_lock <-schedule
 do_suspend_trac-1267  [00]   154.925216: marker_probe_cb <-schedule
 do_suspend_trac-1267  [00]   154.925216: _spin_unlock <-tracing_record_cmdline
 do_suspend_trac-1267  [00]   154.925216: __switch_to <-schedule
          <idle>-0     [00]   154.925216: _spin_unlock_irq <-finish_task_switch
          <idle>-0     [00]   154.925216: tick_nohz_stop_sched_tick <-cpu_idle
          <idle>-0     [00]   154.925216: ktime_get <-tick_nohz_stop_sched_tick
          <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
          <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
          <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00]   154.925216: get_next_timer_interrupt <-tick_nohz_stop_sched_tick
          <idle>-0     [00]   154.925216: _spin_lock <-get_next_timer_interrupt
          <idle>-0     [00]   154.925216: _spin_unlock <-get_next_timer_interrupt
          <idle>-0     [00]   154.925216: hrtimer_get_next_event <-get_next_timer_interrupt
          <idle>-0     [00]   154.925216: _spin_lock_irqsave <-hrtimer_get_next_event
          <idle>-0     [00]   154.925216: _spin_unlock_irqrestore <-hrtimer_get_next_event
          <idle>-0     [00]   154.925216: rcu_needs_cpu <-tick_nohz_stop_sched_tick
          <idle>-0     [00]   154.925216: rcu_pending <-rcu_needs_cpu
          <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
          <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
          <idle>-0     [00]   154.925216: rcu_pending <-cpu_idle
          <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
          <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
          <idle>-0     [00]   154.925216: default_idle <-cpu_idle
          <idle>-0     [00]   154.925216: do_IRQ <-common_interrupt
          <idle>-0     [00]   154.925216: irq_enter <-do_IRQ
          <idle>-0     [00]   154.925216: tick_nohz_stop_idle <-irq_enter
          <idle>-0     [00]   154.925216: ktime_get <-tick_nohz_stop_idle
          <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
          <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
          <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
          <idle>-0     [00]   154.925216: ktime_get <-sched_clock_tick
          <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
          <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
          <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
# ktime_get_ts() calls getnstimeofday() which ends up calling clocksource_read()
# thus updating the kernel timestamp. note that we call getnstimeofday()
# twice above but for some reason they do not impact the time stamp...
# There is an IRQ in here, possibly an HRT-driven IRQ and I'm wondering
# if that is kicking the TSC into ticking?
          <idle>-0     [00]   154.929837: touch_softlockup_watchdog <-sched_clock_idle_wakeup_event
          <idle>-0     [00]   154.929839: tick_nohz_update_jiffies <-irq_enter


~Deepak

-- 
 Deepak Saxena  http://www.greenbasement.info
   _____   __o  Kernel Hacker, One Laptop Per Child  (o>
------    -\<,  Give One Laptop, Get One Laptop      //\
 ----- ( )/ ( ) http://www.amazon.com/xo             V_/_
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

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

[Steven Rostedt]

I added Peter Zijlstra too, since he works on the cpu clock as well.

-- Steve


On Wed, 2008-12-17 at 09:27 -0800, Deepak Saxena wrote:
> Hi,
> 
> I am using ftrace to get a detailed timing analysis of the resume process 
> on the OLPC XO laptop and am seeing that when we start running again, the
> system timestamep is not being updated for several (hundreds of) thousands 
> of cycles (~2000 ftrace entries). From following the ftrace, what is 
> happening is that the clocksource is not updated until we run the cpu_idle() 
> thread due to an explicit scheduling operation in the resume path that occurs 
> via call to msleep from pci_set_power_state().  As I'm still fully groking the 
> timekeeping code, the question(s) I have is whether this is expected behaviour 
> and I should not assume valid timestamp data in the initial bits of the suspend path, 
> whether this is an OLPC-specific bug, or whether I've uncovered a generic bug in 
> the timekeeping implementation.  This is on 2.6.27.7 as I've not gotten 28-rc 
> up and running on the XO but can move that up in priority if this behaviour
> is different in newer kernels.
> 
> Thanks,
> ~Deepak
> 
> # dsaxena: Return from firmware
>  do_suspend_trac-1267  [00]   154.925216: restore_processor_state <-ret_point
>  do_suspend_trac-1267  [00]   154.925216: enable_sep_cpu <-restore_processor_state
>  do_suspend_trac-1267  [00]   154.925216: olpc_fixup_wakeup <-olpc_pm_enter
>  do_suspend_trac-1267  [00]   154.925216: geode_get_dev_base <-olpc_fixup_wakeup
>  do_suspend_trac-1267  [00]   154.925216: olpc_ec_cmd <-olpc_fixup_wakeup
>  do_suspend_trac-1267  [00]   154.925216: _spin_lock_irqsave <-olpc_ec_cmd
>  do_suspend_trac-1267  [00]   154.925216: __wait_on_ibf <-olpc_ec_cmd
>  do_suspend_trac-1267  [00]   154.925216: printk <-olpc_ec_cmd
>  do_suspend_trac-1267  [00]   154.925216: vprintk <-printk
>  do_suspend_trac-1267  [00]   154.925216: _spin_lock <-vprintk
>  do_suspend_trac-1267  [00]   154.925216: emit_log_char <-vprintk
>  do_suspend_trac-1267  [00]   154.925216: emit_log_char <-vprintk
> ....
> # pci_set_power_state() calls msleep(10) as per PCI spec
>  do_suspend_trac-1267  [00]   154.925216: msleep <-pci_set_power_state
>  do_suspend_trac-1267  [00]   154.925216: msecs_to_jiffies <-msleep
>  do_suspend_trac-1267  [00]   154.925216: schedule_timeout_uninterruptible <-msleep
>  do_suspend_trac-1267  [00]   154.925216: schedule_timeout <-schedule_timeout_uninterruptible
>  do_suspend_trac-1267  [00]   154.925216: init_timer_on_stack <-schedule_timeout
>  do_suspend_trac-1267  [00]   154.925216: __init_timer <-init_timer_on_stack
>  do_suspend_trac-1267  [00]   154.925216: __mod_timer <-schedule_timeout
>  do_suspend_trac-1267  [00]   154.925216: __timer_stats_timer_set_start_info <-__mod_timer
>  do_suspend_trac-1267  [00]   154.925216: lock_timer_base <-__mod_timer
>  do_suspend_trac-1267  [00]   154.925216: _spin_lock_irqsave <-lock_timer_base
>  do_suspend_trac-1267  [00]   154.925216: internal_add_timer <-__mod_timer
>  do_suspend_trac-1267  [00]   154.925216: _spin_unlock_irqrestore <-__mod_timer
>  do_suspend_trac-1267  [00]   154.925216: _spin_lock <-schedule
>  do_suspend_trac-1267  [00]   154.925216: marker_probe_cb <-schedule
>  do_suspend_trac-1267  [00]   154.925216: _spin_unlock <-tracing_record_cmdline
>  do_suspend_trac-1267  [00]   154.925216: __switch_to <-schedule
>           <idle>-0     [00]   154.925216: _spin_unlock_irq <-finish_task_switch
>           <idle>-0     [00]   154.925216: tick_nohz_stop_sched_tick <-cpu_idle
>           <idle>-0     [00]   154.925216: ktime_get <-tick_nohz_stop_sched_tick
>           <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
>           <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
>           <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
>           <idle>-0     [00]   154.925216: get_next_timer_interrupt <-tick_nohz_stop_sched_tick
>           <idle>-0     [00]   154.925216: _spin_lock <-get_next_timer_interrupt
>           <idle>-0     [00]   154.925216: _spin_unlock <-get_next_timer_interrupt
>           <idle>-0     [00]   154.925216: hrtimer_get_next_event <-get_next_timer_interrupt
>           <idle>-0     [00]   154.925216: _spin_lock_irqsave <-hrtimer_get_next_event
>           <idle>-0     [00]   154.925216: _spin_unlock_irqrestore <-hrtimer_get_next_event
>           <idle>-0     [00]   154.925216: rcu_needs_cpu <-tick_nohz_stop_sched_tick
>           <idle>-0     [00]   154.925216: rcu_pending <-rcu_needs_cpu
>           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
>           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
>           <idle>-0     [00]   154.925216: rcu_pending <-cpu_idle
>           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
>           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
>           <idle>-0     [00]   154.925216: default_idle <-cpu_idle
>           <idle>-0     [00]   154.925216: do_IRQ <-common_interrupt
>           <idle>-0     [00]   154.925216: irq_enter <-do_IRQ
>           <idle>-0     [00]   154.925216: tick_nohz_stop_idle <-irq_enter
>           <idle>-0     [00]   154.925216: ktime_get <-tick_nohz_stop_idle
>           <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
>           <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
>           <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
>           <idle>-0     [00]   154.925216: ktime_get <-sched_clock_tick
>           <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
>           <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
>           <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
> # ktime_get_ts() calls getnstimeofday() which ends up calling clocksource_read()
> # thus updating the kernel timestamp. note that we call getnstimeofday()
> # twice above but for some reason they do not impact the time stamp...
> # There is an IRQ in here, possibly an HRT-driven IRQ and I'm wondering
> # if that is kicking the TSC into ticking?
>           <idle>-0     [00]   154.929837: touch_softlockup_watchdog <-sched_clock_idle_wakeup_event
>           <idle>-0     [00]   154.929839: tick_nohz_update_jiffies <-irq_enter
> 
> 
> ~Deepak
> 

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

[Peter Zijlstra]

On Wed, 2008-12-17 at 12:50 -0500, Steven Rostedt wrote:
> I added Peter Zijlstra too, since he works on the cpu clock as well.

Thanks Steve..

> On Wed, 2008-12-17 at 09:27 -0800, Deepak Saxena wrote:
> > Hi,
> > 
> > I am using ftrace to get a detailed timing analysis of the resume process 
> > on the OLPC XO laptop and am seeing that when we start running again, the
> > system timestamep is not being updated for several (hundreds of) thousands 
> > of cycles (~2000 ftrace entries). From following the ftrace, what is 
> > happening is that the clocksource is not updated until we run the cpu_idle() 
> > thread due to an explicit scheduling operation in the resume path that occurs 
> > via call to msleep from pci_set_power_state().  As I'm still fully groking the 
> > timekeeping code, the question(s) I have is whether this is expected behaviour 
> > and I should not assume valid timestamp data in the initial bits of the suspend path, 
> > whether this is an OLPC-specific bug, or whether I've uncovered a generic bug in 
> > the timekeeping implementation.  This is on 2.6.27.7 as I've not gotten 28-rc 
> > up and running on the XO but can move that up in priority if this behaviour
> > is different in newer kernels.

Right, so cpu_clock() relies on gtod and tsc to generate a timestamp. We
use a tick_raw (tsc) and tick_gtod, we then use tick_raw to compute a
delta in tsc and add that to tick_gtod and clip the stuff to a jiffy
window and filter backward motion.

On resume I imagine the TSC has a totally unrelated value to the TSC
before suspend, this would mean the clock would quickly end up either at
whatever place the backward motion filter saw last (new TSC < old TSC)
or at the jiffy window clip (new TSC > old TSC).

Time will only start running correctly again once the jiffy tick starts.

Then there is the acpi idle code and NOHZ stuff, that call the
sched_clock_tick() by hand in order to re-sync time (because an unknown
quantity of time passed and gtod has all the machinery of figuring that
out).

So yes, this is expected behaviour,.. OTOH I really didn't think much
about code relying on this timesource _that_ early and such.

Rafael, would something like this explain why we had to revert Shaggy's
patch? His patch fixes the backward motion filter and I'm at an utter
loss why that would break suspend.

> > 
> > # dsaxena: Return from firmware
> >  do_suspend_trac-1267  [00]   154.925216: restore_processor_state <-ret_point
> >  do_suspend_trac-1267  [00]   154.925216: enable_sep_cpu <-restore_processor_state
> >  do_suspend_trac-1267  [00]   154.925216: olpc_fixup_wakeup <-olpc_pm_enter
> >  do_suspend_trac-1267  [00]   154.925216: geode_get_dev_base <-olpc_fixup_wakeup
> >  do_suspend_trac-1267  [00]   154.925216: olpc_ec_cmd <-olpc_fixup_wakeup
> >  do_suspend_trac-1267  [00]   154.925216: _spin_lock_irqsave <-olpc_ec_cmd
> >  do_suspend_trac-1267  [00]   154.925216: __wait_on_ibf <-olpc_ec_cmd
> >  do_suspend_trac-1267  [00]   154.925216: printk <-olpc_ec_cmd
> >  do_suspend_trac-1267  [00]   154.925216: vprintk <-printk
> >  do_suspend_trac-1267  [00]   154.925216: _spin_lock <-vprintk
> >  do_suspend_trac-1267  [00]   154.925216: emit_log_char <-vprintk
> >  do_suspend_trac-1267  [00]   154.925216: emit_log_char <-vprintk
> > ....
> > # pci_set_power_state() calls msleep(10) as per PCI spec
> >  do_suspend_trac-1267  [00]   154.925216: msleep <-pci_set_power_state
> >  do_suspend_trac-1267  [00]   154.925216: msecs_to_jiffies <-msleep
> >  do_suspend_trac-1267  [00]   154.925216: schedule_timeout_uninterruptible <-msleep
> >  do_suspend_trac-1267  [00]   154.925216: schedule_timeout <-schedule_timeout_uninterruptible
> >  do_suspend_trac-1267  [00]   154.925216: init_timer_on_stack <-schedule_timeout
> >  do_suspend_trac-1267  [00]   154.925216: __init_timer <-init_timer_on_stack
> >  do_suspend_trac-1267  [00]   154.925216: __mod_timer <-schedule_timeout
> >  do_suspend_trac-1267  [00]   154.925216: __timer_stats_timer_set_start_info <-__mod_timer
> >  do_suspend_trac-1267  [00]   154.925216: lock_timer_base <-__mod_timer
> >  do_suspend_trac-1267  [00]   154.925216: _spin_lock_irqsave <-lock_timer_base
> >  do_suspend_trac-1267  [00]   154.925216: internal_add_timer <-__mod_timer
> >  do_suspend_trac-1267  [00]   154.925216: _spin_unlock_irqrestore <-__mod_timer
> >  do_suspend_trac-1267  [00]   154.925216: _spin_lock <-schedule
> >  do_suspend_trac-1267  [00]   154.925216: marker_probe_cb <-schedule
> >  do_suspend_trac-1267  [00]   154.925216: _spin_unlock <-tracing_record_cmdline
> >  do_suspend_trac-1267  [00]   154.925216: __switch_to <-schedule
> >           <idle>-0     [00]   154.925216: _spin_unlock_irq <-finish_task_switch
> >           <idle>-0     [00]   154.925216: tick_nohz_stop_sched_tick <-cpu_idle
> >           <idle>-0     [00]   154.925216: ktime_get <-tick_nohz_stop_sched_tick
> >           <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
> >           <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
> >           <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
> >           <idle>-0     [00]   154.925216: get_next_timer_interrupt <-tick_nohz_stop_sched_tick
> >           <idle>-0     [00]   154.925216: _spin_lock <-get_next_timer_interrupt
> >           <idle>-0     [00]   154.925216: _spin_unlock <-get_next_timer_interrupt
> >           <idle>-0     [00]   154.925216: hrtimer_get_next_event <-get_next_timer_interrupt
> >           <idle>-0     [00]   154.925216: _spin_lock_irqsave <-hrtimer_get_next_event
> >           <idle>-0     [00]   154.925216: _spin_unlock_irqrestore <-hrtimer_get_next_event
> >           <idle>-0     [00]   154.925216: rcu_needs_cpu <-tick_nohz_stop_sched_tick
> >           <idle>-0     [00]   154.925216: rcu_pending <-rcu_needs_cpu
> >           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
> >           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
> >           <idle>-0     [00]   154.925216: rcu_pending <-cpu_idle
> >           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
> >           <idle>-0     [00]   154.925216: __rcu_pending <-rcu_pending
> >           <idle>-0     [00]   154.925216: default_idle <-cpu_idle
> >           <idle>-0     [00]   154.925216: do_IRQ <-common_interrupt
> >           <idle>-0     [00]   154.925216: irq_enter <-do_IRQ
> >           <idle>-0     [00]   154.925216: tick_nohz_stop_idle <-irq_enter
> >           <idle>-0     [00]   154.925216: ktime_get <-tick_nohz_stop_idle
> >           <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
> >           <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
> >           <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
> >           <idle>-0     [00]   154.925216: ktime_get <-sched_clock_tick
> >           <idle>-0     [00]   154.925216: ktime_get_ts <-ktime_get
> >           <idle>-0     [00]   154.925216: getnstimeofday <-ktime_get_ts
> >           <idle>-0     [00]   154.925216: set_normalized_timespec <-ktime_get_ts
> > # ktime_get_ts() calls getnstimeofday() which ends up calling clocksource_read()
> > # thus updating the kernel timestamp. note that we call getnstimeofday()
> > # twice above but for some reason they do not impact the time stamp...
> > # There is an IRQ in here, possibly an HRT-driven IRQ and I'm wondering
> > # if that is kicking the TSC into ticking?
> >           <idle>-0     [00]   154.929837: touch_softlockup_watchdog <-sched_clock_idle_wakeup_event
> >           <idle>-0     [00]   154.929839: tick_nohz_update_jiffies <-irq_enter

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

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> Rafael, would something like this explain why we had to revert Shaggy's 
> patch? His patch fixes the backward motion filter and I'm at an utter 
> loss why that would break suspend.

yes, i'd love to have this commit reinstated:

 5b7dba4: sched_clock: prevent scd->clock from moving backwards

and the bug triggered by hibernation fixed instead.

	Ingo

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

[Rafael J. Wysocki]

On Thursday, 18 of December 2008, Ingo Molnar wrote:
> 
> * Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > Rafael, would something like this explain why we had to revert Shaggy's 
> > patch?

Well, I have yet to understand what the suspend-resume of the timekeeping code
actually does.

The original description sounds worrisome to me, it looks like we've overlooked
something at least.

> > His patch fixes the backward motion filter and I'm at an utter  
> > loss why that would break suspend.
> 
> yes, i'd love to have this commit reinstated:
> 
>  5b7dba4: sched_clock: prevent scd->clock from moving backwards
> 
> and the bug triggered by hibernation fixed instead.

Shaggy said he had an idea of what was wrong, so I expect an updated version
of the patch to appear.

Thanks,
Rafael

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

[Dave Kleikamp]

On Thu, 2008-12-18 at 23:19 +0100, Rafael J. Wysocki wrote:
> On Thursday, 18 of December 2008, Ingo Molnar wrote:
> > 
> > * Peter Zijlstra <peterz@infradead.org> wrote:
> > 
> > > Rafael, would something like this explain why we had to revert Shaggy's 
> > > patch?
> 
> Well, I have yet to understand what the suspend-resume of the timekeeping code
> actually does.
> 
> The original description sounds worrisome to me, it looks like we've overlooked
> something at least.
> 
> > > His patch fixes the backward motion filter and I'm at an utter  
> > > loss why that would break suspend.
> > 
> > yes, i'd love to have this commit reinstated:
> > 
> >  5b7dba4: sched_clock: prevent scd->clock from moving backwards
> > 
> > and the bug triggered by hibernation fixed instead.
> 
> Shaggy said he had an idea of what was wrong, so I expect an updated version
> of the patch to appear.

Not really.  I said I'd look at it, but all I know is that it looks like
something clock-related isn't initialized correctly after resume.  I
don't know enough to have any idea how to fix it.

> Thanks,
> Rafael
-- 
David Kleikamp
IBM Linux Technology Center

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

[Rafael J. Wysocki]

On Thursday, 18 of December 2008, Dave Kleikamp wrote:
> On Thu, 2008-12-18 at 23:19 +0100, Rafael J. Wysocki wrote:
> > On Thursday, 18 of December 2008, Ingo Molnar wrote:
> > > 
> > > * Peter Zijlstra <peterz@infradead.org> wrote:
> > > 
> > > > Rafael, would something like this explain why we had to revert Shaggy's 
> > > > patch?
> > 
> > Well, I have yet to understand what the suspend-resume of the timekeeping code
> > actually does.
> > 
> > The original description sounds worrisome to me, it looks like we've overlooked
> > something at least.
> > 
> > > > His patch fixes the backward motion filter and I'm at an utter  
> > > > loss why that would break suspend.
> > > 
> > > yes, i'd love to have this commit reinstated:
> > > 
> > >  5b7dba4: sched_clock: prevent scd->clock from moving backwards
> > > 
> > > and the bug triggered by hibernation fixed instead.
> > 
> > Shaggy said he had an idea of what was wrong, so I expect an updated version
> > of the patch to appear.
> 
> Not really.  I said I'd look at it, but all I know is that it looks like
> something clock-related isn't initialized correctly after resume.  I
> don't know enough to have any idea how to fix it.

Well, thanks for the update.

I'm going to have a look at the thing tomorrow, but I'm not sure I'll be able
to fix it.

Thanks,
Rafael

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

[Thomas Gleixner]

On Thu, 18 Dec 2008, Rafael J. Wysocki wrote:

> On Thursday, 18 of December 2008, Ingo Molnar wrote:
> > 
> > * Peter Zijlstra <peterz@infradead.org> wrote:
> > 
> > > Rafael, would something like this explain why we had to revert Shaggy's 
> > > patch?
> 
> Well, I have yet to understand what the suspend-resume of the timekeeping code
> actually does.

Thats rather simple:

suspend() saves the current time of the persistent clock (if
available), forwards the timekeeping variables so they can be reused
on resume, disables timekeeping activities and shuts down the clock
events layer.
 
resume() estimates the suspend time via persistent clock (if
available) and update xtime with the sleep length. After that it
reactivates timekeeping and resumes clock events and high resolution
timers.

So the sole purpose is:
   - dis/enable timekeeping and clock event devices.
   - keep track of the suspend time (if a persistent clock is available)

We reactivate clock event devices and hrtimers from timekeeping_resume
because clock events depend on functional timekeeping.

> The original description sounds worrisome to me, it looks like we've overlooked
> something at least.

Care to explain ?

> > > His patch fixes the backward motion filter and I'm at an utter  
> > > loss why that would break suspend.
> > 
> > yes, i'd love to have this commit reinstated:
> > 
> >  5b7dba4: sched_clock: prevent scd->clock from moving backwards
> > 
> > and the bug triggered by hibernation fixed instead.

Hmm. Depending on the hibernation sleep time we can end up with a
pretty long delta between the pre suspend and the post resume call to
__update_sched_clock().

I have the feeling that sched_clock looks into stale values after
resume and the first call to __update_sched_clock() trips over the
stale scd->clock value. Shaggy's patch brings scd->clock into the mix
and that might cause the whole machinery to blow up on resume.

Also we need to investigate whether sched_clock is referencing gtod
values _before_ timekeeping is resume.

Thanks,

	tglx

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

[Thomas Gleixner]

On Sun, 21 Dec 2008, Thomas Gleixner wrote:
> On Thu, 18 Dec 2008, Rafael J. Wysocki wrote:
> > >  5b7dba4: sched_clock: prevent scd->clock from moving backwards
> > > 
> > > and the bug triggered by hibernation fixed instead.
> 
> Hmm. Depending on the hibernation sleep time we can end up with a
> pretty long delta between the pre suspend and the post resume call to
> __update_sched_clock().
> 
> I have the feeling that sched_clock looks into stale values after
> resume and the first call to __update_sched_clock() trips over the
> stale scd->clock value. Shaggy's patch brings scd->clock into the mix
> and that might cause the whole machinery to blow up on resume.
> 
> Also we need to investigate whether sched_clock is referencing gtod
> values _before_ timekeeping is resume.

I checked the two bugzillas (12149 & 12155) and both reporters have
hpet=force on the command line.

One of the reporters said: "If I de-select CONFIG_HPET_TIMER then the
issue went away ..."

It looks like this was not further investigated. Is this problem
reproducible on other systems as well ?

Thanks,

	tglx

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

[Fabio Comolli]

Hi Thomas.

On Sun, Dec 21, 2008 at 8:43 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Sun, 21 Dec 2008, Thomas Gleixner wrote:
>> On Thu, 18 Dec 2008, Rafael J. Wysocki wrote:
>> > >  5b7dba4: sched_clock: prevent scd->clock from moving backwards
>> > >
>> > > and the bug triggered by hibernation fixed instead.
>>
>> Hmm. Depending on the hibernation sleep time we can end up with a
>> pretty long delta between the pre suspend and the post resume call to
>> __update_sched_clock().
>>
>> I have the feeling that sched_clock looks into stale values after
>> resume and the first call to __update_sched_clock() trips over the
>> stale scd->clock value. Shaggy's patch brings scd->clock into the mix
>> and that might cause the whole machinery to blow up on resume.
>>
>> Also we need to investigate whether sched_clock is referencing gtod
>> values _before_ timekeeping is resume.
>
> I checked the two bugzillas (12149 & 12155) and both reporters have
> hpet=force on the command line.

Well, I'm the submitter of bug 12155 and I never had hpet=force on my
command line. I don't know where you found it.
Actually my command line is:

-------------------------------------------------------------------------------------------------------------------------
fcomolli@hawking:~> cat /proc/cmdline
root=/dev/sda2 resume=/dev/sda3 i8042.nomux=1 pciehp.pciehp_force=1
quiet splash=silent vga=791
-------------------------------------------------------------------------------------------------------------------------

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.

>
> One of the reporters said: "If I de-select CONFIG_HPET_TIMER then the
> issue went away ..."
>
> It looks like this was not further investigated. Is this problem
> reproducible on other systems as well ?
>
> Thanks,
>
>        tglx
> --

Regards,
Fabio


> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>

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

[Thomas Gleixner]

Fabio,

On Sun, 21 Dec 2008, Fabio Comolli wrote:
> Well, I'm the submitter of bug 12155 and I never had hpet=force on my
> command line. I don't know where you found it.
> Actually my command line is:

My bad. I confused it with the HPET force enable. (Your BIOS does not
advertise HPET).
 
> 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 ?

Thanks,

	tglx
-----
diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index e8ab096..c18a6dd 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
  */
@@ -118,13 +126,13 @@ static u64 __update_sched_clock(struct sched_clock_data *scd, u64 now)
 
 	/*
 	 * scd->clock = clamp(scd->tick_gtod + delta,
-	 * 		      max(scd->tick_gtod, scd->clock),
-	 * 		      scd->tick_gtod + TICK_NSEC);
+	 *		      max(scd->tick_gtod, scd->clock),
+	 *		      max(scd->clock, scd->tick_gtod + TICK_NSEC));
 	 */
 
 	clock = scd->tick_gtod + delta;
 	min_clock = wrap_max(scd->tick_gtod, scd->clock);
-	max_clock = scd->tick_gtod + TICK_NSEC;
+	max_clock = wrap_max(scd->clock, scd->tick_gtod + TICK_NSEC);
 
 	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;

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

[Ingo Molnar]

* 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?

	Ingo

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

[Thomas Gleixner]

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;

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

[Thomas Gleixner]

On Mon, 22 Dec 2008, Thomas Gleixner wrote:
> 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.

Seems I'm talking to myself, but I think I finally decoded the
mystery:

resume()
  cpufreq_resume()
    tsc:time_cpufreq_notifier()
      set_cyc2ns_scale()
        sched_clock_idle_sleep_event()
          sched_clock_tick()
            ktime_get()
              hpet_read()

This happens _BEFORE_ timekeeping has resumed, so hpet_read() returns
nonsense and the timekeeping code uses the stale pre suspend
xtime/clocksource reference values to calculate the time. So the gtod
reference in sched_clock can result in total crap depending on the
time when the suspend happened.

Shaggys patch clamps sched_clock to the stale scd->clock value which
might explain the further wreckage.

The above sequence happens only for CPUs with a CPU frequency coupled
TSC, so on newer machines with CPU frequency invariant TSC this does
not happen.

/me stomps off to find a box to confirm that.

Thanks,

	tglx

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

[Fabio Comolli]

Hi Thomas.

On Mon, Dec 22, 2008 at 9:36 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Mon, 22 Dec 2008, Thomas Gleixner wrote:
>> 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.
>
> Seems I'm talking to myself, but I think I finally decoded the
> mystery:
>
> resume()
>  cpufreq_resume()
>    tsc:time_cpufreq_notifier()
>      set_cyc2ns_scale()
>        sched_clock_idle_sleep_event()
>          sched_clock_tick()
>            ktime_get()
>              hpet_read()
>
> This happens _BEFORE_ timekeeping has resumed, so hpet_read() returns
> nonsense and the timekeeping code uses the stale pre suspend
> xtime/clocksource reference values to calculate the time. So the gtod
> reference in sched_clock can result in total crap depending on the
> time when the suspend happened.
>
> Shaggys patch clamps sched_clock to the stale scd->clock value which
> might explain the further wreckage.
>
> The above sequence happens only for CPUs with a CPU frequency coupled
> TSC, so on newer machines with CPU frequency invariant TSC this does
> not happen.
>
> /me stomps off to find a box to confirm that.
>

Ok, just for reference here is my

fcomolli@hawking:~> cat /proc/cpuinfo
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 13
model name	: Intel(R) Pentium(R) M processor 1.73GHz
stepping	: 8
cpu MHz		: 800.000
cache size	: 2048 KB
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 2
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov
pat clflush dts acpi mmx fxsr sse sse2 ss tm pbe nx up bts est tm2
bogomips	: 1596.95
clflush size	: 64
power management:



Regards,
Fabio
> Thanks,
>
>        tglx
>

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

[Thomas Gleixner]

Fabio,

On Mon, 22 Dec 2008, Fabio Comolli wrote:
> Hi Thomas.
> 
> On Mon, Dec 22, 2008 at 9:36 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> > On Mon, 22 Dec 2008, Thomas Gleixner wrote:
> >> 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.
> >
> > Seems I'm talking to myself, but I think I finally decoded the
> > mystery:
> >
> > resume()
> >  cpufreq_resume()
> >    tsc:time_cpufreq_notifier()
> >      set_cyc2ns_scale()
> >        sched_clock_idle_sleep_event()
> >          sched_clock_tick()
> >            ktime_get()
> >              hpet_read()
> >
> > This happens _BEFORE_ timekeeping has resumed, so hpet_read() returns
> > nonsense and the timekeeping code uses the stale pre suspend
> > xtime/clocksource reference values to calculate the time. So the gtod
> > reference in sched_clock can result in total crap depending on the
> > time when the suspend happened.
> >
> > Shaggys patch clamps sched_clock to the stale scd->clock value which
> > might explain the further wreckage.
> >
> > The above sequence happens only for CPUs with a CPU frequency coupled
> > TSC, so on newer machines with CPU frequency invariant TSC this does
> > not happen.
> >
> > /me stomps off to find a box to confirm that.
> >
> 
> Ok, just for reference here is my
> 
> fcomolli@hawking:~> cat /proc/cpuinfo
> processor	: 0
> vendor_id	: GenuineIntel
> cpu family	: 6
> model		: 13
> model name	: Intel(R) Pentium(R) M processor 1.73GHz
> stepping	: 8
> cpu MHz		: 800.000
> cache size	: 2048 KB
> fdiv_bug	: no
> hlt_bug		: no
> f00f_bug	: no
> coma_bug	: no
> fpu		: yes
> fpu_exception	: yes
> cpuid level	: 2
> wp		: yes
> flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov
> pat clflush dts acpi mmx fxsr sse sse2 ss tm pbe nx up bts est tm2
> bogomips	: 1596.95
> clflush size	: 64
> power management:

Can please you revert the last patch and apply the following ? Does
the WARN_ON trigger ?

Thanks,

	tglx
---
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index fa05e88..0d1526d 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -46,6 +46,9 @@ struct timespec xtime __attribute__ ((aligned (16)));
 struct timespec wall_to_monotonic __attribute__ ((aligned (16)));
 static unsigned long total_sleep_time;		/* seconds */
 
+/* flag for if timekeeping is suspended */
+static int timekeeping_suspended;
+
 static struct timespec xtime_cache __attribute__ ((aligned (16)));
 void update_xtime_cache(u64 nsec)
 {
@@ -92,6 +95,8 @@ void getnstimeofday(struct timespec *ts)
 	unsigned long seq;
 	s64 nsecs;
 
+	WARN_ON(timekeeping_suspended);
+
 	do {
 		seq = read_seqbegin(&xtime_lock);
 
@@ -299,8 +304,6 @@ void __init timekeeping_init(void)
 	write_sequnlock_irqrestore(&xtime_lock, flags);
 }
 
-/* flag for if timekeeping is suspended */
-static int timekeeping_suspended;
 /* time in seconds when suspend began */
 static unsigned long timekeeping_suspend_time;
 

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

[Fabio Comolli]

Hi Thomas.

On Mon, Dec 22, 2008 at 10:13 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> Fabio,
>
> On Mon, 22 Dec 2008, Fabio Comolli wrote:
>> Hi Thomas.
>>
>> On Mon, Dec 22, 2008 at 9:36 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
>> > On Mon, 22 Dec 2008, Thomas Gleixner wrote:
>> >> 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.
>> >
>> > Seems I'm talking to myself, but I think I finally decoded the
>> > mystery:
>> >
>> > resume()
>> >  cpufreq_resume()
>> >    tsc:time_cpufreq_notifier()
>> >      set_cyc2ns_scale()
>> >        sched_clock_idle_sleep_event()
>> >          sched_clock_tick()
>> >            ktime_get()
>> >              hpet_read()
>> >
>> > This happens _BEFORE_ timekeeping has resumed, so hpet_read() returns
>> > nonsense and the timekeeping code uses the stale pre suspend
>> > xtime/clocksource reference values to calculate the time. So the gtod
>> > reference in sched_clock can result in total crap depending on the
>> > time when the suspend happened.
>> >
>> > Shaggys patch clamps sched_clock to the stale scd->clock value which
>> > might explain the further wreckage.
>> >
>> > The above sequence happens only for CPUs with a CPU frequency coupled
>> > TSC, so on newer machines with CPU frequency invariant TSC this does
>> > not happen.
>> >
>> > /me stomps off to find a box to confirm that.
>> >
>>
>> Ok, just for reference here is my
>>
>> fcomolli@hawking:~> cat /proc/cpuinfo
>> processor     : 0
>> vendor_id     : GenuineIntel
>> cpu family    : 6
>> model         : 13
>> model name    : Intel(R) Pentium(R) M processor 1.73GHz
>> stepping      : 8
>> cpu MHz               : 800.000
>> cache size    : 2048 KB
>> fdiv_bug      : no
>> hlt_bug               : no
>> f00f_bug      : no
>> coma_bug      : no
>> fpu           : yes
>> fpu_exception : yes
>> cpuid level   : 2
>> wp            : yes
>> flags         : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov
>> pat clflush dts acpi mmx fxsr sse sse2 ss tm pbe nx up bts est tm2
>> bogomips      : 1596.95
>> clflush size  : 64
>> power management:
>
> Can please you revert the last patch and apply the following ? Does
> the WARN_ON trigger ?
>
> Thanks,
>
>        tglx
> ---
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index fa05e88..0d1526d 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -46,6 +46,9 @@ struct timespec xtime __attribute__ ((aligned (16)));
>  struct timespec wall_to_monotonic __attribute__ ((aligned (16)));
>  static unsigned long total_sleep_time;         /* seconds */
>
> +/* flag for if timekeeping is suspended */
> +static int timekeeping_suspended;
> +
>  static struct timespec xtime_cache __attribute__ ((aligned (16)));
>  void update_xtime_cache(u64 nsec)
>  {
> @@ -92,6 +95,8 @@ void getnstimeofday(struct timespec *ts)
>        unsigned long seq;
>        s64 nsecs;
>
> +       WARN_ON(timekeeping_suspended);
> +
>        do {
>                seq = read_seqbegin(&xtime_lock);
>
> @@ -299,8 +304,6 @@ void __init timekeeping_init(void)
>        write_sequnlock_irqrestore(&xtime_lock, flags);
>  }
>
> -/* flag for if timekeeping is suspended */
> -static int timekeeping_suspended;
>  /* time in seconds when suspend began */
>  static unsigned long timekeeping_suspend_time;
>
>

Yes, it does:

[  159.487588] Syncing filesystems ... done.
[  159.488523] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  159.489763] Freezing remaining freezable tasks ... (elapsed 0.00
seconds) done.
[  159.491144] PM: Shrinking memory... done (0 pages freed)
[  159.556730] PM: Freed 0 kbytes in 0.06 seconds (0.00 MB/s)
[  159.556752] Suspending console(s) (use no_console_suspend to debug)
[  159.557328] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  159.621764] pciehp 0000:00:1c.0:pcie02: pciehp_suspend ENTRY
[  159.621989] ACPI handle has no context!
[  159.621999] tifm_7xx1 0000:06:06.3: PCI INT A disabled
[  159.622008] ACPI handle has no context!
[  159.636240] ACPI handle has no context!
[  159.652272] eth1: Going into suspend...
[  159.655644] ipw2200 0000:06:05.0: PCI INT A disabled
[  159.655652] ACPI handle has no context!
[  159.668043] [fglrx] Power down the ASIC .
[  159.764052] fglrx_pci 0000:01:00.0: PCI INT A disabled
[  159.764175] ata2: port disabled. ignoring.
[  159.764232] ata_piix 0000:00:1f.1: PCI INT A disabled
[  159.764507] Intel ICH 0000:00:1e.2: PCI INT A disabled
[  159.764646] ehci_hcd 0000:00:1d.7: PCI INT A disabled
[  159.764686] uhci_hcd 0000:00:1d.3: PCI INT D disabled
[  159.764725] uhci_hcd 0000:00:1d.2: PCI INT C disabled
[  159.764764] uhci_hcd 0000:00:1d.1: PCI INT B disabled
[  159.764803] uhci_hcd 0000:00:1d.0: PCI INT A disabled
[  159.764808] pciehp 0000:00:1c.0:pcie02: pciehp_suspend ENTRY
[  159.765572] ACPI: Preparing to enter system sleep state S4
[  159.766924] Disabling non-boot CPUs ...
[  159.767100] PM: Creating hibernation image:
[  159.768005] PM: Need to copy 178481 pages
[  159.768005] Intel machine check architecture supported.
[  159.768005] Intel machine check reporting enabled on CPU#0.
[  159.768005] ------------[ cut here ]------------
[  159.768005] WARNING: at kernel/time/timekeeping.c:98
getnstimeofday+0x21/0xcd()
[  159.768005] Modules linked in: cisco_ipsec(P) fglrx(P)
[  159.768005] Pid: 5883, comm: s2disk Tainted: P
2.6.28-rc9-00050-gf8fd8a7 #9
[  159.768005] Call Trace:
[  159.768005]  [<c0122ef8>] warn_on_slowpath+0x40/0x61
[  159.768005]  [<c024ddec>] acpi_ex_insert_into_field+0x2cf/0x2ef
[  159.768005]  [<c0154c53>] __rmqueue_smallest+0xbe/0x133
[  159.768005]  [<c01389a2>] getnstimeofday+0x21/0xcd
[  159.768005]  [<c0135e26>] ktime_get_ts+0x1d/0x3f
[  159.768005]  [<c0135e57>] ktime_get+0xf/0x2b
[  159.768005]  [<c013736b>] sched_clock_tick+0x46/0x83
[  159.768005]  [<c01373ad>] sched_clock_idle_wakeup_event+0x5/0xa
[  159.768005]  [<c0108670>] set_cyc2ns_scale+0x3f/0x5e
[  159.768005]  [<c01088af>] time_cpufreq_notifier+0xf9/0x103
[  159.768005]  [<c0136782>] notifier_call_chain+0x2a/0x52
[  159.768005]  [<c0136866>] __srcu_notifier_call_chain+0x35/0x4a
[  159.768005]  [<c0136884>] srcu_notifier_call_chain+0x9/0xc
[  159.768005]  [<c031cbca>] cpufreq_resume+0xf3/0x112
[  159.768005]  [<c028c3f3>] __sysdev_resume+0x24/0x34
[  159.768005]  [<c028c421>] sysdev_resume+0x1e/0x50
[  159.768005]  [<c0290637>] device_power_up+0x8/0x10
[  159.768005]  [<c0149478>] create_image+0x8f/0x9f
[  159.768005]  [<c01494ed>] hibernation_snapshot+0x65/0xce
[  159.768005]  [<c014bddc>] snapshot_ioctl+0x208/0x47d
[  159.768005]  [<c014bbd4>] snapshot_ioctl+0x0/0x47d
[  159.768005]  [<c017a279>] vfs_ioctl+0x1c/0x5f
[  159.768005]  [<c017a785>] do_vfs_ioctl+0x167/0x172
[  159.768005]  [<c017a7bc>] sys_ioctl+0x2c/0x42
[  159.768005]  [<c01038cd>] sysenter_do_call+0x12/0x35
[  159.768005] ---[ end trace 828aa214905e8df0 ]---
[  313.187879] Force enabled HPET at resume
[  159.771124] ACPI: Waking up from system sleep state S4
[  159.792183] ACPI: EC: non-query interrupt received, switching to
interrupt mode
[  159.855414] pcieport-driver 0000:00:01.0: setting latency timer to 64
[  159.855497] pcieport-driver 0000:00:1c.0: setting latency timer to 64
[  159.855502] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY
[  160.856182] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  160.856190] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[  160.856237] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[  160.856244] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[  160.856291] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[  160.856297] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[  160.856343] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16
[  160.856350] uhci_hcd 0000:00:1d.3: setting latency timer to 64
[  160.856396] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  160.856404] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[  160.856521] pci 0000:00:1e.0: setting latency timer to 64
[  160.856569] Intel ICH 0000:00:1e.2: PCI INT A -> GSI 17 (level,
low) -> IRQ 17
[  160.856576] Intel ICH 0000:00:1e.2: setting latency timer to 64
[  161.870198] ata_piix 0000:00:1f.1: restoring config space at offset
0x1 (was 0x2880001, writing 0x2880005)
[  161.870211] ata_piix 0000:00:1f.1: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[  161.870216] ata_piix 0000:00:1f.1: setting latency timer to 64
[  161.870669] fglrx_pci 0000:01:00.0: power state changed by ACPI to D0
[  161.870679] fglrx_pci 0000:01:00.0: PCI INT A -> GSI 16 (level,
low) -> IRQ 16
[  161.870684] fglrx_pci 0000:01:00.0: setting latency timer to 64
[  161.883293] ata2: port disabled. ignoring.
[  161.884515] [fglrx] Power up the ASIC
[  161.884554] eth1: Coming out of suspend...
[  161.900173] ipw2200 0000:06:05.0: enabling device (0000 -> 0002)
[  161.900181] ipw2200 0000:06:05.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[  161.900196] ipw2200 0000:06:05.0: restoring config space at offset
0xf (was 0x18030100, writing 0x1803010b)
[  161.900226] ipw2200 0000:06:05.0: restoring config space at offset
0x4 (was 0x0, writing 0xc8206000)
[  161.900234] ipw2200 0000:06:05.0: restoring config space at offset
0x3 (was 0x0, writing 0x8008)
[  161.900243] ipw2200 0000:06:05.0: restoring config space at offset
0x1 (was 0x2900002, writing 0x2900116)
[  162.072723] ata1.01: ACPI cmd ef/03:0c:00:00:00:b0 filtered out
[  162.072726] ata1.01: ACPI cmd ef/03:22:00:00:00:b0 filtered out
[  162.080461] ata1.00: ACPI cmd ef/03:0c:00:00:00:a0 filtered out
[  162.080463] ata1.00: ACPI cmd ef/03:45:00:00:00:a0 filtered out
[  162.096951] ata1.00: configured for UDMA/100
[  162.128666] ata1.01: configured for MWDMA2
[  162.129488] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors:
(80.0 GB/74.5 GiB)
[  162.129519] sd 0:0:0:0: [sda] Write Protect is off
[  162.129521] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  162.129569] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  162.129621] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors:
(80.0 GB/74.5 GiB)
[  162.129648] sd 0:0:0:0: [sda] Write Protect is off
[  162.129650] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  162.129696] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  162.168175] firewire_ohci 0000:06:06.2: restoring config space at
offset 0xf (was 0x4020300, writing 0x402030b)
[  162.168203] firewire_ohci 0000:06:06.2: restoring config space at
offset 0x5 (was 0x0, writing 0xc8200000)
[  162.168211] firewire_ohci 0000:06:06.2: restoring config space at
offset 0x4 (was 0x0, writing 0xc8208000)
[  162.168218] firewire_ohci 0000:06:06.2: restoring config space at
offset 0x3 (was 0x800000, writing 0x808008)
[  162.168228] firewire_ohci 0000:06:06.2: restoring config space at
offset 0x1 (was 0x2100000, writing 0x2100116)
[  162.256038] tifm_7xx1 0000:06:06.3: restoring config space at
offset 0xf (was 0x40701ff, writing 0x407010a)
[  162.256067] tifm_7xx1 0000:06:06.3: restoring config space at
offset 0x4 (was 0x0, writing 0xc8204000)
[  162.256075] tifm_7xx1 0000:06:06.3: restoring config space at
offset 0x3 (was 0x800000, writing 0x808008)
[  162.256085] tifm_7xx1 0000:06:06.3: restoring config space at
offset 0x1 (was 0x2100000, writing 0x2100106)
[  162.256107] tifm_7xx1 0000:06:06.3: PCI INT A -> GSI 22 (level,
low) -> IRQ 22
[  162.256283] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY
[  163.260341] sd 0:0:0:0: [sda] Starting disk
[  163.800031] usb 3-1: reset full speed USB device using uhci_hcd and address 2
[  164.014985] Restarting tasks ... done.

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

[Thomas Gleixner]

Fabio,

On Mon, 22 Dec 2008, Fabio Comolli wrote:
> On Mon, Dec 22, 2008 at 10:13 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> >
> > Can please you revert the last patch and apply the following ? Does
> > the WARN_ON trigger ?
> >

> Yes, it does:
 
> [  159.768005]  [<c01389a2>] getnstimeofday+0x21/0xcd
> [  159.768005]  [<c0135e26>] ktime_get_ts+0x1d/0x3f
> [  159.768005]  [<c0135e57>] ktime_get+0xf/0x2b
> [  159.768005]  [<c013736b>] sched_clock_tick+0x46/0x83
> [  159.768005]  [<c01373ad>] sched_clock_idle_wakeup_event+0x5/0xa
> [  159.768005]  [<c0108670>] set_cyc2ns_scale+0x3f/0x5e
> [  159.768005]  [<c01088af>] time_cpufreq_notifier+0xf9/0x103
> [  159.768005]  [<c0136782>] notifier_call_chain+0x2a/0x52
> [  159.768005]  [<c0136866>] __srcu_notifier_call_chain+0x35/0x4a
> [  159.768005]  [<c0136884>] srcu_notifier_call_chain+0x9/0xc
> [  159.768005]  [<c031cbca>] cpufreq_resume+0xf3/0x112
> [  159.768005]  [<c028c3f3>] __sysdev_resume+0x24/0x34
> [  159.768005]  [<c028c421>] sysdev_resume+0x1e/0x50

Thanks for testing. It's exaclty the code path I described :)

So my code analysis holds and your test confirms my suspicion that
Shaggy's patch just unearthed some other weirdness in the
suspend/resume code.

Can you please apply the following hack^Wpatch and retest ? It
restores Shaggys patch, but prevents the sched_clock_tick() call when
timekeeping is not resumed. The WARN_ON should not longer trigger
except there is some other code path which fiddles with that as well.

If I'm not completely nuts then this should solve your suspend/resume
problem really instead of papering over the root cause.

The patch should work on top of 2.6.27.10 as well, so whatever is
easier to verify for you is fine.

Thanks,

	tglx
---
diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index e8ab096..dd97801 100644
--- a/kernel/sched_clock.c
+++ b/kernel/sched_clock.c
@@ -124,7 +124,7 @@ 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;
+	max_clock = wrap_max(scd->clock, scd->tick_gtod + TICK_NSEC);
 
 	clock = wrap_max(clock, min_clock);
 	clock = wrap_min(clock, max_clock);
@@ -222,11 +222,16 @@ void sched_clock_idle_sleep_event(void)
 }
 EXPORT_SYMBOL_GPL(sched_clock_idle_sleep_event);
 
+extern int timekeeping_suspended;
+
 /*
  * We just idled delta nanoseconds (called with irqs disabled):
  */
 void sched_clock_idle_wakeup_event(u64 delta_ns)
 {
+	if (timekeeping_suspended)
+		return;
+
 	sched_clock_tick();
 	touch_softlockup_watchdog();
 }
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index fa05e88..50ba3d0 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -46,6 +46,9 @@ struct timespec xtime __attribute__ ((aligned (16)));
 struct timespec wall_to_monotonic __attribute__ ((aligned (16)));
 static unsigned long total_sleep_time;		/* seconds */
 
+/* flag for if timekeeping is suspended */
+int timekeeping_suspended;
+
 static struct timespec xtime_cache __attribute__ ((aligned (16)));
 void update_xtime_cache(u64 nsec)
 {
@@ -92,6 +95,8 @@ void getnstimeofday(struct timespec *ts)
 	unsigned long seq;
 	s64 nsecs;
 
+	WARN_ON(timekeeping_suspended);
+
 	do {
 		seq = read_seqbegin(&xtime_lock);
 
@@ -299,8 +304,6 @@ void __init timekeeping_init(void)
 	write_sequnlock_irqrestore(&xtime_lock, flags);
 }
 
-/* flag for if timekeeping is suspended */
-static int timekeeping_suspended;
 /* time in seconds when suspend began */
 static unsigned long timekeeping_suspend_time;
 

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

[Fabio Comolli]

Won't apply:

fcomolli@hawking:~/software/GIT-TREES/linux-2.6> patch -p1 --dry-run <
/home/fcomolli/0009c-tglx-debug.patch
patching file kernel/sched_clock.c
patching file kernel/time/timekeeping.c
Hunk #1 succeeded at 49 with fuzz 2 (offset 3 lines).
Hunk #2 succeeded at 100 with fuzz 2 (offset 5 lines).
Hunk #3 FAILED at 309.
1 out of 3 hunks FAILED -- saving rejects to file kernel/time/timekeeping.c.rej

Should I revert you previous one?

Regards,
Fabio



On Mon, Dec 22, 2008 at 11:05 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> Fabio,
>
> On Mon, 22 Dec 2008, Fabio Comolli wrote:
>> On Mon, Dec 22, 2008 at 10:13 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
>> >
>> > Can please you revert the last patch and apply the following ? Does
>> > the WARN_ON trigger ?
>> >
>
>> Yes, it does:
>
>> [  159.768005]  [<c01389a2>] getnstimeofday+0x21/0xcd
>> [  159.768005]  [<c0135e26>] ktime_get_ts+0x1d/0x3f
>> [  159.768005]  [<c0135e57>] ktime_get+0xf/0x2b
>> [  159.768005]  [<c013736b>] sched_clock_tick+0x46/0x83
>> [  159.768005]  [<c01373ad>] sched_clock_idle_wakeup_event+0x5/0xa
>> [  159.768005]  [<c0108670>] set_cyc2ns_scale+0x3f/0x5e
>> [  159.768005]  [<c01088af>] time_cpufreq_notifier+0xf9/0x103
>> [  159.768005]  [<c0136782>] notifier_call_chain+0x2a/0x52
>> [  159.768005]  [<c0136866>] __srcu_notifier_call_chain+0x35/0x4a
>> [  159.768005]  [<c0136884>] srcu_notifier_call_chain+0x9/0xc
>> [  159.768005]  [<c031cbca>] cpufreq_resume+0xf3/0x112
>> [  159.768005]  [<c028c3f3>] __sysdev_resume+0x24/0x34
>> [  159.768005]  [<c028c421>] sysdev_resume+0x1e/0x50
>
> Thanks for testing. It's exaclty the code path I described :)
>
> So my code analysis holds and your test confirms my suspicion that
> Shaggy's patch just unearthed some other weirdness in the
> suspend/resume code.
>
> Can you please apply the following hack^Wpatch and retest ? It
> restores Shaggys patch, but prevents the sched_clock_tick() call when
> timekeeping is not resumed. The WARN_ON should not longer trigger
> except there is some other code path which fiddles with that as well.
>
> If I'm not completely nuts then this should solve your suspend/resume
> problem really instead of papering over the root cause.
>
> The patch should work on top of 2.6.27.10 as well, so whatever is
> easier to verify for you is fine.
>
> Thanks,
>
>        tglx
> ---
> diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> index e8ab096..dd97801 100644
> --- a/kernel/sched_clock.c
> +++ b/kernel/sched_clock.c
> @@ -124,7 +124,7 @@ 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;
> +       max_clock = wrap_max(scd->clock, scd->tick_gtod + TICK_NSEC);
>
>        clock = wrap_max(clock, min_clock);
>        clock = wrap_min(clock, max_clock);
> @@ -222,11 +222,16 @@ void sched_clock_idle_sleep_event(void)
>  }
>  EXPORT_SYMBOL_GPL(sched_clock_idle_sleep_event);
>
> +extern int timekeeping_suspended;
> +
>  /*
>  * We just idled delta nanoseconds (called with irqs disabled):
>  */
>  void sched_clock_idle_wakeup_event(u64 delta_ns)
>  {
> +       if (timekeeping_suspended)
> +               return;
> +
>        sched_clock_tick();
>        touch_softlockup_watchdog();
>  }
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index fa05e88..50ba3d0 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -46,6 +46,9 @@ struct timespec xtime __attribute__ ((aligned (16)));
>  struct timespec wall_to_monotonic __attribute__ ((aligned (16)));
>  static unsigned long total_sleep_time;         /* seconds */
>
> +/* flag for if timekeeping is suspended */
> +int timekeeping_suspended;
> +
>  static struct timespec xtime_cache __attribute__ ((aligned (16)));
>  void update_xtime_cache(u64 nsec)
>  {
> @@ -92,6 +95,8 @@ void getnstimeofday(struct timespec *ts)
>        unsigned long seq;
>        s64 nsecs;
>
> +       WARN_ON(timekeeping_suspended);
> +
>        do {
>                seq = read_seqbegin(&xtime_lock);
>
> @@ -299,8 +304,6 @@ void __init timekeeping_init(void)
>        write_sequnlock_irqrestore(&xtime_lock, flags);
>  }
>
> -/* flag for if timekeeping is suspended */
> -static int timekeeping_suspended;
>  /* time in seconds when suspend began */
>  static unsigned long timekeeping_suspend_time;
>
>

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

[Thomas Gleixner]

On Mon, 22 Dec 2008, Fabio Comolli wrote:

> Won't apply:
> 
> fcomolli@hawking:~/software/GIT-TREES/linux-2.6> patch -p1 --dry-run <
> /home/fcomolli/0009c-tglx-debug.patch
> patching file kernel/sched_clock.c
> patching file kernel/time/timekeeping.c
> Hunk #1 succeeded at 49 with fuzz 2 (offset 3 lines).
> Hunk #2 succeeded at 100 with fuzz 2 (offset 5 lines).
> Hunk #3 FAILED at 309.
> 1 out of 3 hunks FAILED -- saving rejects to file kernel/time/timekeeping.c.rej
> 
> Should I revert you previous one?

Oops, yes.
 
Thanks,

	tglx

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

[Fabio Comolli]

OK, it seems that you got it.

The system survived two hibernation / resume cycles without triggering
the warning and, probably the most important part, the dmesg does not
have any "jumps" before the "Force enable HPET on resume" line as
before:

[  275.647704] PM: Creating hibernation image:
[  275.648005] PM: Need to copy 177844 pages
[  275.648005] Intel machine check architecture supported.
[  275.648005] Intel machine check reporting enabled on CPU#0.
[  275.648005] Force enabled HPET at resume
[  275.648005] ACPI: Waking up from system sleep state S4
[  275.669038] ACPI: EC: non-query interrupt received, switching to
interrupt mode
[  275.740697] pcieport-driver 0000:00:01.0: setting latency timer to 64
[  275.740781] pcieport-driver 0000:00:1c.0: setting latency timer to 64
[  275.740786] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY

...and so on.

As i mentioned in the bug report, to be sure that the bug doesn't
trigger I have to wait at least on day and > 10 hibernation / resumee
cycles.

But with your first patch the bug triggered at the second cycle, so
I'm optimist :-)

I'll keep you informed. Many thanks in advance,
Fabio




On Mon, Dec 22, 2008 at 11:16 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
>
> On Mon, 22 Dec 2008, Fabio Comolli wrote:
>
>> Won't apply:
>>
>> fcomolli@hawking:~/software/GIT-TREES/linux-2.6> patch -p1 --dry-run <
>> /home/fcomolli/0009c-tglx-debug.patch
>> patching file kernel/sched_clock.c
>> patching file kernel/time/timekeeping.c
>> Hunk #1 succeeded at 49 with fuzz 2 (offset 3 lines).
>> Hunk #2 succeeded at 100 with fuzz 2 (offset 5 lines).
>> Hunk #3 FAILED at 309.
>> 1 out of 3 hunks FAILED -- saving rejects to file kernel/time/timekeeping.c.rej
>>
>> Should I revert you previous one?
>
> Oops, yes.
>
> Thanks,
>
>        tglx
>

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

[Thomas Gleixner]

Fabio,

On Mon, 22 Dec 2008, Fabio Comolli wrote:

> OK, it seems that you got it.
> 
> The system survived two hibernation / resume cycles without triggering
> the warning and, probably the most important part, the dmesg does not
> have any "jumps" before the "Force enable HPET on resume" line as
> before:
> 
> [  275.647704] PM: Creating hibernation image:
> [  275.648005] PM: Need to copy 177844 pages
> [  275.648005] Intel machine check architecture supported.
> [  275.648005] Intel machine check reporting enabled on CPU#0.
> [  275.648005] Force enabled HPET at resume
> [  275.648005] ACPI: Waking up from system sleep state S4
> [  275.669038] ACPI: EC: non-query interrupt received, switching to
> interrupt mode
> [  275.740697] pcieport-driver 0000:00:01.0: setting latency timer to 64
> [  275.740781] pcieport-driver 0000:00:1c.0: setting latency timer to 64
> [  275.740786] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY
> 
> ...and so on.
> 
> As i mentioned in the bug report, to be sure that the bug doesn't
> trigger I have to wait at least on day and > 10 hibernation / resumee
> cycles.

Sure.
 
> But with your first patch the bug triggered at the second cycle, so
> I'm optimist :-)
> 
> I'll keep you informed. Many thanks in advance,

Many thanks to you for following up on this.

     tglx

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

[Rafael J. Wysocki]

On Monday, 22 of December 2008, Thomas Gleixner wrote:
> Fabio,
> 
> On Mon, 22 Dec 2008, Fabio Comolli wrote:
> 
> > OK, it seems that you got it.
> > 
> > The system survived two hibernation / resume cycles without triggering
> > the warning and, probably the most important part, the dmesg does not
> > have any "jumps" before the "Force enable HPET on resume" line as
> > before:
> > 
> > [  275.647704] PM: Creating hibernation image:
> > [  275.648005] PM: Need to copy 177844 pages
> > [  275.648005] Intel machine check architecture supported.
> > [  275.648005] Intel machine check reporting enabled on CPU#0.
> > [  275.648005] Force enabled HPET at resume
> > [  275.648005] ACPI: Waking up from system sleep state S4
> > [  275.669038] ACPI: EC: non-query interrupt received, switching to
> > interrupt mode
> > [  275.740697] pcieport-driver 0000:00:01.0: setting latency timer to 64
> > [  275.740781] pcieport-driver 0000:00:1c.0: setting latency timer to 64
> > [  275.740786] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY
> > 
> > ...and so on.
> > 
> > As i mentioned in the bug report, to be sure that the bug doesn't
> > trigger I have to wait at least on day and > 10 hibernation / resumee
> > cycles.
> 
> Sure.
>  
> > But with your first patch the bug triggered at the second cycle, so
> > I'm optimist :-)
> > 
> > I'll keep you informed. Many thanks in advance,
> 
> Many thanks to you for following up on this.

Well, thanks a lot to you both for debugging this and finding a fix.

Rafael

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

[Fabio Comolli]

Hi Thomas.
Everything seems to work fine after further testing.
Regards,
Fabio




On Mon, Dec 22, 2008 at 11:33 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> Fabio,
>
> On Mon, 22 Dec 2008, Fabio Comolli wrote:
>
>> OK, it seems that you got it.
>>
>> The system survived two hibernation / resume cycles without triggering
>> the warning and, probably the most important part, the dmesg does not
>> have any "jumps" before the "Force enable HPET on resume" line as
>> before:
>>
>> [  275.647704] PM: Creating hibernation image:
>> [  275.648005] PM: Need to copy 177844 pages
>> [  275.648005] Intel machine check architecture supported.
>> [  275.648005] Intel machine check reporting enabled on CPU#0.
>> [  275.648005] Force enabled HPET at resume
>> [  275.648005] ACPI: Waking up from system sleep state S4
>> [  275.669038] ACPI: EC: non-query interrupt received, switching to
>> interrupt mode
>> [  275.740697] pcieport-driver 0000:00:01.0: setting latency timer to 64
>> [  275.740781] pcieport-driver 0000:00:1c.0: setting latency timer to 64
>> [  275.740786] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY
>>
>> ...and so on.
>>
>> As i mentioned in the bug report, to be sure that the bug doesn't
>> trigger I have to wait at least on day and > 10 hibernation / resumee
>> cycles.
>
> Sure.
>
>> But with your first patch the bug triggered at the second cycle, so
>> I'm optimist :-)
>>
>> I'll keep you informed. Many thanks in advance,
>
> Many thanks to you for following up on this.
>
>     tglx
>

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

[Pavel Machek]

Hi!
> > >
> > > Can please you revert the last patch and apply the following ? Does
> > > the WARN_ON trigger ?
> > >
> 
> > Yes, it does:
>  
> > [  159.768005]  [<c01389a2>] getnstimeofday+0x21/0xcd
> > [  159.768005]  [<c0135e26>] ktime_get_ts+0x1d/0x3f
> > [  159.768005]  [<c0135e57>] ktime_get+0xf/0x2b
> > [  159.768005]  [<c013736b>] sched_clock_tick+0x46/0x83
> > [  159.768005]  [<c01373ad>] sched_clock_idle_wakeup_event+0x5/0xa
> > [  159.768005]  [<c0108670>] set_cyc2ns_scale+0x3f/0x5e
> > [  159.768005]  [<c01088af>] time_cpufreq_notifier+0xf9/0x103
> > [  159.768005]  [<c0136782>] notifier_call_chain+0x2a/0x52
> > [  159.768005]  [<c0136866>] __srcu_notifier_call_chain+0x35/0x4a
> > [  159.768005]  [<c0136884>] srcu_notifier_call_chain+0x9/0xc
> > [  159.768005]  [<c031cbca>] cpufreq_resume+0xf3/0x112
> > [  159.768005]  [<c028c3f3>] __sysdev_resume+0x24/0x34
> > [  159.768005]  [<c028c421>] sysdev_resume+0x1e/0x50
> 
> Thanks for testing. It's exaclty the code path I described :)
> 
> So my code analysis holds and your test confirms my suspicion that
> Shaggy's patch just unearthed some other weirdness in the
> suspend/resume code.
> 
> Can you please apply the following hack^Wpatch and retest ? It
> restores Shaggys patch, but prevents the sched_clock_tick() call when
> timekeeping is not resumed. The WARN_ON should not longer trigger
> except there is some other code path which fiddles with that as well.
> 
> If I'm not completely nuts then this should solve your suspend/resume
> problem really instead of papering over the root cause.

Should we move timekeeping resume before cpufreq resume, instead of this?

> The patch should work on top of 2.6.27.10 as well, so whatever is
> easier to verify for you is fine.
> 
> Thanks,
> 
> 	tglx
> ---
> diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> index e8ab096..dd97801 100644
> --- a/kernel/sched_clock.c
> +++ b/kernel/sched_clock.c
> @@ -124,7 +124,7 @@ 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;
> +	max_clock = wrap_max(scd->clock, scd->tick_gtod + TICK_NSEC);
>  
>  	clock = wrap_max(clock, min_clock);
>  	clock = wrap_min(clock, max_clock);
> @@ -222,11 +222,16 @@ void sched_clock_idle_sleep_event(void)
>  }
>  EXPORT_SYMBOL_GPL(sched_clock_idle_sleep_event);
>  
> +extern int timekeeping_suspended;
> +
>  /*
>   * We just idled delta nanoseconds (called with irqs disabled):
>   */
>  void sched_clock_idle_wakeup_event(u64 delta_ns)
>  {
> +	if (timekeeping_suspended)
> +		return;
> +
>  	sched_clock_tick();
>  	touch_softlockup_watchdog();
>  }
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index fa05e88..50ba3d0 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -46,6 +46,9 @@ struct timespec xtime __attribute__ ((aligned (16)));
>  struct timespec wall_to_monotonic __attribute__ ((aligned (16)));
>  static unsigned long total_sleep_time;		/* seconds */
>  
> +/* flag for if timekeeping is suspended */
> +int timekeeping_suspended;
> +
>  static struct timespec xtime_cache __attribute__ ((aligned (16)));
>  void update_xtime_cache(u64 nsec)
>  {
> @@ -92,6 +95,8 @@ void getnstimeofday(struct timespec *ts)
>  	unsigned long seq;
>  	s64 nsecs;
>  
> +	WARN_ON(timekeeping_suspended);
> +
>  	do {
>  		seq = read_seqbegin(&xtime_lock);
>  
> @@ -299,8 +304,6 @@ void __init timekeeping_init(void)
>  	write_sequnlock_irqrestore(&xtime_lock, flags);
>  }
>  
> -/* flag for if timekeeping is suspended */
> -static int timekeeping_suspended;
>  /* time in seconds when suspend began */
>  static unsigned long timekeeping_suspend_time;

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

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

[Peter Zijlstra]

On Wed, 2008-12-24 at 15:09 +0100, Pavel Machek wrote:
> Hi!
> > > >
> > > > Can please you revert the last patch and apply the following ? Does
> > > > the WARN_ON trigger ?
> > > >
> > 
> > > Yes, it does:
> >  
> > > [  159.768005]  [<c01389a2>] getnstimeofday+0x21/0xcd
> > > [  159.768005]  [<c0135e26>] ktime_get_ts+0x1d/0x3f
> > > [  159.768005]  [<c0135e57>] ktime_get+0xf/0x2b
> > > [  159.768005]  [<c013736b>] sched_clock_tick+0x46/0x83
> > > [  159.768005]  [<c01373ad>] sched_clock_idle_wakeup_event+0x5/0xa
> > > [  159.768005]  [<c0108670>] set_cyc2ns_scale+0x3f/0x5e
> > > [  159.768005]  [<c01088af>] time_cpufreq_notifier+0xf9/0x103
> > > [  159.768005]  [<c0136782>] notifier_call_chain+0x2a/0x52
> > > [  159.768005]  [<c0136866>] __srcu_notifier_call_chain+0x35/0x4a
> > > [  159.768005]  [<c0136884>] srcu_notifier_call_chain+0x9/0xc
> > > [  159.768005]  [<c031cbca>] cpufreq_resume+0xf3/0x112
> > > [  159.768005]  [<c028c3f3>] __sysdev_resume+0x24/0x34
> > > [  159.768005]  [<c028c421>] sysdev_resume+0x1e/0x50
> > 
> > Thanks for testing. It's exaclty the code path I described :)
> > 
> > So my code analysis holds and your test confirms my suspicion that
> > Shaggy's patch just unearthed some other weirdness in the
> > suspend/resume code.
> > 
> > Can you please apply the following hack^Wpatch and retest ? It
> > restores Shaggys patch, but prevents the sched_clock_tick() call when
> > timekeeping is not resumed. The WARN_ON should not longer trigger
> > except there is some other code path which fiddles with that as well.
> > 
> > If I'm not completely nuts then this should solve your suspend/resume
> > problem really instead of papering over the root cause.
> 
> Should we move timekeeping resume before cpufreq resume, instead of this?

That seems a sensible suggestion (but I've got no clue on how practical
that is). A quick look at the boot code suggests that regular bootups
have that sequence as well, so mirroring that in the resume code seems
like the best all-round solution.

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

[Fabio Comolli]

[-- Attachment #1: Type: text/plain, Size: 3216 bytes --]

Hi Thomas.
Please find the log attached (only one hibernate/resume cycle).

Regads,
Fabio



On Mon, Dec 22, 2008 at 3:48 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> Fabio,
>
> On Sun, 21 Dec 2008, Fabio Comolli wrote:
>> Well, I'm the submitter of bug 12155 and I never had hpet=force on my
>> command line. I don't know where you found it.
>> Actually my command line is:
>
> My bad. I confused it with the HPET force enable. (Your BIOS does not
> advertise HPET).
>
>> 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 ?
>
> Thanks,
>
>        tglx
> -----
> diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> index e8ab096..c18a6dd 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
>  */
> @@ -118,13 +126,13 @@ static u64 __update_sched_clock(struct sched_clock_data *scd, u64 now)
>
>        /*
>         * scd->clock = clamp(scd->tick_gtod + delta,
> -        *                    max(scd->tick_gtod, scd->clock),
> -        *                    scd->tick_gtod + TICK_NSEC);
> +        *                    max(scd->tick_gtod, scd->clock),
> +        *                    max(scd->clock, scd->tick_gtod + TICK_NSEC));
>         */
>
>        clock = scd->tick_gtod + delta;
>        min_clock = wrap_max(scd->tick_gtod, scd->clock);
> -       max_clock = scd->tick_gtod + TICK_NSEC;
> +       max_clock = wrap_max(scd->clock, scd->tick_gtod + TICK_NSEC);
>
>        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;
>
>

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: dmesg.log --]
[-- Type: text/x-log; name=dmesg.log, Size: 53903 bytes --]

[    0.000000] BIOS EBDA/lowmem at: 0009f800/0009f800
[    0.000000] Linux version 2.6.28-rc9-00047-gec4c265 (fcomolli@hawking) (gcc version 4.3.2 [gcc-4_3-branch revision 141291] (SUSE Linux) ) #8 SMP Mon Dec 22 21:03:51 CET 2008
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000]   AMD AuthenticAMD
[    0.000000]   NSC Geode by NSC
[    0.000000]   Cyrix CyrixInstead
[    0.000000]   Centaur CentaurHauls
[    0.000000]   Transmeta GenuineTMx86
[    0.000000]   Transmeta TransmetaCPU
[    0.000000]   UMC UMC UMC UMC
[    0.000000] BIOS-provided physical RAM map:
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
[    0.000000]  BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000dc000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 000000007fee0000 (usable)
[    0.000000]  BIOS-e820: 000000007fee0000 - 000000007feeb000 (ACPI data)
[    0.000000]  BIOS-e820: 000000007feeb000 - 000000007ff00000 (ACPI NVS)
[    0.000000]  BIOS-e820: 000000007ff00000 - 0000000080000000 (reserved)
[    0.000000]  BIOS-e820: 00000000e0000000 - 00000000f0006000 (reserved)
[    0.000000]  BIOS-e820: 00000000f0008000 - 00000000f000c000 (reserved)
[    0.000000]  BIOS-e820: 00000000fed20000 - 00000000fed90000 (reserved)
[    0.000000]  BIOS-e820: 00000000ff000000 - 0000000100000000 (reserved)
[    0.000000] DMI present.
[    0.000000] last_pfn = 0x7fee0 max_arch_pfn = 0x100000
[    0.000000] Scanning 2 areas for low memory corruption
[    0.000000] modified physical RAM map:
[    0.000000]  modified: 0000000000000000 - 0000000000002000 (usable)
[    0.000000]  modified: 0000000000002000 - 0000000000006000 (reserved)
[    0.000000]  modified: 0000000000006000 - 0000000000007000 (usable)
[    0.000000]  modified: 0000000000007000 - 0000000000010000 (reserved)
[    0.000000]  modified: 0000000000010000 - 0000000000092800 (usable)
[    0.000000]  modified: 000000000009f800 - 00000000000a0000 (reserved)
[    0.000000]  modified: 00000000000dc000 - 0000000000100000 (reserved)
[    0.000000]  modified: 0000000000100000 - 000000007fee0000 (usable)
[    0.000000]  modified: 000000007fee0000 - 000000007feeb000 (ACPI data)
[    0.000000]  modified: 000000007feeb000 - 000000007ff00000 (ACPI NVS)
[    0.000000]  modified: 000000007ff00000 - 0000000080000000 (reserved)
[    0.000000]  modified: 00000000e0000000 - 00000000f0006000 (reserved)
[    0.000000]  modified: 00000000f0008000 - 00000000f000c000 (reserved)
[    0.000000]  modified: 00000000fed20000 - 00000000fed90000 (reserved)
[    0.000000]  modified: 00000000ff000000 - 0000000100000000 (reserved)
[    0.000000] kernel direct mapping tables up to 377fe000 @ 10000-16000
[    0.000000] RAMDISK: 37b07000 - 37fef82a
[    0.000000] Allocated new RAMDISK: 00b08000 - 00ff082a
[    0.000000] Move RAMDISK from 0000000037b07000 - 0000000037fef829 to 00b08000 - 00ff0829
[    0.000000] ACPI: RSDP 000F76A0, 0014 (r0 HP    )
[    0.000000] ACPI: RSDT 7FEE5277, 0044 (r1 HP     309E      6040000  LTP        0)
[    0.000000] ACPI: FACP 7FEEAE88, 0074 (r1 HP     309E      6040000 LOHR       5F)
[    0.000000] ACPI: DSDT 7FEE5B1C, 536C (r1 HP     309E      6040000 MSFT  100000E)
[    0.000000] ACPI: FACS 7FEFBFC0, 0040
[    0.000000] ACPI: APIC 7FEEAEFC, 0068 (r1 HP     309E      6040000 LOHR       5F)
[    0.000000] ACPI: BOOT 7FEEAFD8, 0028 (r1 HP     309E      6040000  LTP        1)
[    0.000000] ACPI: MCFG 7FEEAF9C, 003C (r1 HP     309E      6040000 LOHR       5F)
[    0.000000] ACPI: SSDT 7FEE56D3, 0235 (r1 HP     309E         3000 INTL 20030224)
[    0.000000] ACPI: SSDT 7FEE54FB, 01D8 (r1 HP     309E         3001 INTL 20030224)
[    0.000000] ACPI: SSDT 7FEE53E7, 0114 (r1 HP     309E         3000 INTL 20030224)
[    0.000000] ACPI: SSDT 7FEE52BB, 012C (r1 HP     309E            1 INTL 20030224)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] 1158MB HIGHMEM available.
[    0.000000] 887MB LOWMEM available.
[    0.000000]   mapped low ram: 0 - 377fe000
[    0.000000]   low ram: 00000000 - 377fe000
[    0.000000]   bootmap 00012000 - 00018f00
[    0.000000] (9 early reservations) ==> bootmem [0000000000 - 00377fe000]
[    0.000000]   #0 [0000000000 - 0000001000]   BIOS data page ==> [0000000000 - 0000001000]
[    0.000000]   #1 [0000001000 - 0000002000]    EX TRAMPOLINE ==> [0000001000 - 0000002000]
[    0.000000]   #2 [0000006000 - 0000007000]       TRAMPOLINE ==> [0000006000 - 0000007000]
[    0.000000]   #3 [0000100000 - 0000b03a28]    TEXT DATA BSS ==> [0000100000 - 0000b03a28]
[    0.000000]   #4 [0000b04000 - 0000b08000]    INIT_PG_TABLE ==> [0000b04000 - 0000b08000]
[    0.000000]   #5 [000009f800 - 0000100000]    BIOS reserved ==> [000009f800 - 0000100000]
[    0.000000]   #6 [0000010000 - 0000012000]          PGTABLE ==> [0000010000 - 0000012000]
[    0.000000]   #7 [0000b08000 - 0000ff082a]      NEW RAMDISK ==> [0000b08000 - 0000ff082a]
[    0.000000]   #8 [0000012000 - 0000019000]          BOOTMAP ==> [0000012000 - 0000019000]
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000000 -> 0x00001000
[    0.000000]   Normal   0x00001000 -> 0x000377fe
[    0.000000]   HighMem  0x000377fe -> 0x0007fee0
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[4] active PFN ranges
[    0.000000]     0: 0x00000000 -> 0x00000002
[    0.000000]     0: 0x00000006 -> 0x00000007
[    0.000000]     0: 0x00000010 -> 0x00000092
[    0.000000]     0: 0x00000100 -> 0x0007fee0
[    0.000000] On node 0 totalpages: 523877
[    0.000000] free_area_init_node: node 0, pgdat c0573940, node_mem_map c1000000
[    0.000000]   DMA zone: 56 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 3917 pages, LIFO batch:0
[    0.000000]   Normal zone: 3052 pages used for memmap
[    0.000000]   Normal zone: 220178 pages, LIFO batch:31
[    0.000000]   HighMem zone: 4057 pages used for memmap
[    0.000000]   HighMem zone: 292617 pages, LIFO batch:31
[    0.000000]   Movable zone: 0 pages used for memmap
[    0.000000] ACPI: PM-Timer IO Port: 0x1008
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] disabled)
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
[    0.000000] ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
[    0.000000] IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] ACPI: IRQ2 used by override.
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] Enabling APIC mode:  Flat.  Using 1 I/O APICs
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] SMP: Allowing 2 CPUs, 1 hotplug CPUs
[    0.000000] PM: Registered nosave memory: 0000000000002000 - 0000000000006000
[    0.000000] PM: Registered nosave memory: 0000000000007000 - 0000000000010000
[    0.000000] PM: Registered nosave memory: 0000000000092000 - 00000000000a0000
[    0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000dc000
[    0.000000] PM: Registered nosave memory: 00000000000dc000 - 0000000000100000
[    0.000000] Allocating PCI resources starting at 88000000 (gap: 80000000:60000000)
[    0.000000] PERCPU: Allocating 1212416 bytes of per cpu data
[    0.000000] NR_CPUS: 8, nr_cpu_ids: 2, nr_node_ids 1
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 516712
[    0.000000] Kernel command line: root=/dev/sda2 resume=/dev/sda3 i8042.nomux=1 pciehp.pciehp_force=1 quiet splash=silent vga=791
[    0.000000] bootsplash: silent mode.
[    0.000000] Enabling fast FPU save and restore... done.
[    0.000000] Enabling unmasked SIMD FPU exception support... done.
[    0.000000] Initializing CPU#0
[    0.000000] PID hash table entries: 4096 (order: 12, 16384 bytes)
[    0.000000] Fast TSC calibration using PIT
[    0.000000] Detected 1729.706 MHz processor.
[    0.004000] Console: colour dummy device 80x25
[    0.004000] console [tty0] enabled
[    0.004000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.004000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.004000] ... MAX_LOCK_DEPTH:          48
[    0.004000] ... MAX_LOCKDEP_KEYS:        8191
[    0.004000] ... CLASSHASH_SIZE:          4096
[    0.004000] ... MAX_LOCKDEP_ENTRIES:     8192
[    0.004000] ... MAX_LOCKDEP_CHAINS:      16384
[    0.004000] ... CHAINHASH_SIZE:          8192
[    0.004000]  memory used by lock dependency info: 2463 kB
[    0.004000]  per task-struct memory footprint: 1920 bytes
[    0.004000] ------------------------
[    0.004000] | Locking API testsuite:
[    0.004000] ----------------------------------------------------------------------------
[    0.004000]                                  | spin |wlock |rlock |mutex | wsem | rsem |
[    0.004000]   --------------------------------------------------------------------------
[    0.004000]                      A-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                  A-B-B-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]              A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]              A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                     double unlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                   initialize held:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]                  bad unlock order:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.004000]   --------------------------------------------------------------------------
[    0.004000]               recursive read-lock:             |  ok  |             |  ok  |
[    0.004000]            recursive read-lock #2:             |  ok  |             |  ok  |
[    0.004000]             mixed read-write-lock:             |  ok  |             |  ok  |
[    0.004000]             mixed write-read-lock:             |  ok  |             |  ok  |
[    0.004000]   --------------------------------------------------------------------------
[    0.004000]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.004000]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    0.004000]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.004000]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    0.004000]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[    0.004000]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[    0.004000]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.004000]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    0.004000]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.004000]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    0.004000]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.004000]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.004000]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    0.004000]       hard-irq read-recursion/123:  ok  |
[    0.004000]       soft-irq read-recursion/123:  ok  |
[    0.004000]       hard-irq read-recursion/132:  ok  |
[    0.004000]       soft-irq read-recursion/132:  ok  |
[    0.004000]       hard-irq read-recursion/213:  ok  |
[    0.004000]       soft-irq read-recursion/213:  ok  |
[    0.004000]       hard-irq read-recursion/231:  ok  |
[    0.004000]       soft-irq read-recursion/231:  ok  |
[    0.004000]       hard-irq read-recursion/312:  ok  |
[    0.004000]       soft-irq read-recursion/312:  ok  |
[    0.004000]       hard-irq read-recursion/321:  ok  |
[    0.004000]       soft-irq read-recursion/321:  ok  |
[    0.004000] -------------------------------------------------------
[    0.004000] Good, all 218 testcases passed! |
[    0.004000] ---------------------------------
[    0.004000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.004000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.004000] Scanning for low memory corruption every 60 seconds
[    0.004000] Memory: 2047412k/2096000k available (2851k kernel code, 47292k reserved, 1830k data, 1428k init, 1186696k highmem)
[    0.004000] virtual kernel memory layout:
[    0.004000]     fixmap  : 0xfff51000 - 0xfffff000   ( 696 kB)
[    0.004000]     pkmap   : 0xff800000 - 0xffc00000   (4096 kB)
[    0.004000]     vmalloc : 0xf7ffe000 - 0xff7fe000   ( 120 MB)
[    0.004000]     lowmem  : 0xc0000000 - 0xf77fe000   ( 887 MB)
[    0.004000]       .init : 0xc059a000 - 0xc06ff000   (1428 kB)
[    0.004000]       .data : 0xc03c8d05 - 0xc0592568   (1830 kB)
[    0.004000]       .text : 0xc0100000 - 0xc03c8d05   (2851 kB)
[    0.004000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.004030] Calibrating delay loop (skipped), value calculated using timer frequency.. 3459.41 BogoMIPS (lpj=6918824)
[    0.004303] Mount-cache hash table entries: 512
[    0.005192] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.005195] CPU: L2 cache: 2048K
[    0.005199] Intel machine check architecture supported.
[    0.005203] Intel machine check reporting enabled on CPU#0.
[    0.005226] Checking 'hlt' instruction... OK.
[    0.020345] lockdep: fixing up alternatives.
[    0.020348] SMP alternatives: switching to UP code
[    0.109368] ACPI: Core revision 20080926
[    0.124698] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.166316] CPU0: Intel(R) Pentium(R) M processor 1.73GHz stepping 08
[    0.168001] Brought up 1 CPUs
[    0.168001] Total of 1 processors activated (3459.41 BogoMIPS).
[    0.168001] net_namespace: 392 bytes
[    0.168001] NET: Registered protocol family 16
[    0.168001] ACPI: bus type pci registered
[    0.168001] PCI: MCFG configuration 0: base e0000000 segment 0 buses 0 - 255
[    0.168001] PCI: MCFG area at e0000000 reserved in E820
[    0.168001] PCI: Using MMCONFIG for extended config space
[    0.168001] PCI: Using configuration type 1 for base access
[    0.193329] ACPI: EC: Look up EC in DSDT
[    0.201745] ACPI: Interpreter enabled
[    0.201751] ACPI: (supports S0 S3 S4 S5)
[    0.201815] ACPI: Using IOAPIC for interrupt routing
[    0.210298] ACPI: EC: non-query interrupt received, switching to interrupt mode
[    0.224296] ACPI: EC: GPE = 0x1b, I/O: command/status = 0x66, data = 0x62
[    0.224299] ACPI: EC: driver started in interrupt mode
[    0.224759] ACPI: No dock devices found.
[    0.224791] ACPI: PCI Root Bridge [PCI0] (0000:00)
[    0.225198] pci 0000:00:01.0: PME# supported from D0 D3hot D3cold
[    0.225204] pci 0000:00:01.0: PME# disabled
[    0.225364] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold
[    0.225371] pci 0000:00:1c.0: PME# disabled
[    0.225477] pci 0000:00:1d.0: reg 20 io port: [0x1800-0x181f]
[    0.225574] pci 0000:00:1d.1: reg 20 io port: [0x1820-0x183f]
[    0.225675] pci 0000:00:1d.2: reg 20 io port: [0x1840-0x185f]
[    0.225771] pci 0000:00:1d.3: reg 20 io port: [0x1860-0x187f]
[    0.225873] pci 0000:00:1d.7: reg 10 32bit mmio: [0xc8000000-0xc80003ff]
[    0.225940] pci 0000:00:1d.7: PME# supported from D0 D3hot D3cold
[    0.225948] pci 0000:00:1d.7: PME# disabled
[    0.226108] pci 0000:00:1e.2: reg 10 io port: [0x1c00-0x1cff]
[    0.226119] pci 0000:00:1e.2: reg 14 io port: [0x1880-0x18bf]
[    0.226130] pci 0000:00:1e.2: reg 18 32bit mmio: [0xc8000800-0xc80009ff]
[    0.226142] pci 0000:00:1e.2: reg 1c 32bit mmio: [0xc8000400-0xc80004ff]
[    0.226183] pci 0000:00:1e.2: PME# supported from D0 D3hot D3cold
[    0.226190] pci 0000:00:1e.2: PME# disabled
[    0.226253] pci 0000:00:1e.3: reg 10 io port: [0x2400-0x24ff]
[    0.226265] pci 0000:00:1e.3: reg 14 io port: [0x2000-0x207f]
[    0.226323] pci 0000:00:1e.3: PME# supported from D0 D3hot D3cold
[    0.226329] pci 0000:00:1e.3: PME# disabled
[    0.226475] pci 0000:00:1f.0: Force enabled HPET at 0xfed00000
[    0.226484] pci 0000:00:1f.0: quirk: region 1000-107f claimed by ICH6 ACPI/GPIO/TCO
[    0.226490] pci 0000:00:1f.0: quirk: region 1180-11bf claimed by ICH6 GPIO
[    0.226532] pci 0000:00:1f.1: reg 10 io port: [0x00-0x07]
[    0.226543] pci 0000:00:1f.1: reg 14 io port: [0x00-0x03]
[    0.226553] pci 0000:00:1f.1: reg 18 io port: [0x00-0x07]
[    0.226564] pci 0000:00:1f.1: reg 1c io port: [0x00-0x03]
[    0.226575] pci 0000:00:1f.1: reg 20 io port: [0x18c0-0x18cf]
[    0.226689] pci 0000:00:1f.3: reg 20 io port: [0x18e0-0x18ff]
[    0.226797] pci 0000:01:00.0: reg 10 32bit mmio: [0xd0000000-0xd7ffffff]
[    0.226806] pci 0000:01:00.0: reg 14 io port: [0x3000-0x30ff]
[    0.226815] pci 0000:01:00.0: reg 18 32bit mmio: [0xc8100000-0xc810ffff]
[    0.226843] pci 0000:01:00.0: reg 30 32bit mmio: [0x000000-0x01ffff]
[    0.226855] pci 0000:01:00.0: supports D1 D2
[    0.226940] pci 0000:00:01.0: bridge io port: [0x3000-0x3fff]
[    0.226946] pci 0000:00:01.0: bridge 32bit mmio: [0xc8100000-0xc81fffff]
[    0.226951] pci 0000:00:01.0: bridge 32bit mmio pref: [0xd0000000-0xd7ffffff]
[    0.227039] pci 0000:00:1c.0: bridge io port: [0x00-0xfff]
[    0.227045] pci 0000:00:1c.0: bridge 32bit mmio: [0x000000-0x0fffff]
[    0.227056] pci 0000:00:1c.0: bridge 64bit mmio pref: [0x000000-0x0fffff]
[    0.227153] pci 0000:06:05.0: reg 10 32bit mmio: [0xc8206000-0xc8206fff]
[    0.227239] pci 0000:06:05.0: PME# supported from D0 D3hot D3cold
[    0.227247] pci 0000:06:05.0: PME# disabled
[    0.227328] pci 0000:06:06.0: reg 10 32bit mmio: [0xc8207000-0xc8207fff]
[    0.227348] pci 0000:06:06.0: supports D1 D2
[    0.227350] pci 0000:06:06.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.227358] pci 0000:06:06.0: PME# disabled
[    0.227446] pci 0000:06:06.2: reg 10 32bit mmio: [0xc8208000-0xc82087ff]
[    0.227460] pci 0000:06:06.2: reg 14 32bit mmio: [0xc8200000-0xc8203fff]
[    0.227537] pci 0000:06:06.2: supports D1 D2
[    0.227540] pci 0000:06:06.2: PME# supported from D0 D1 D2 D3hot
[    0.227547] pci 0000:06:06.2: PME# disabled
[    0.227627] pci 0000:06:06.3: reg 10 32bit mmio: [0xc8204000-0xc8205fff]
[    0.227712] pci 0000:06:06.3: supports D1 D2
[    0.227715] pci 0000:06:06.3: PME# supported from D0 D1 D2 D3hot
[    0.227722] pci 0000:06:06.3: PME# disabled
[    0.227802] pci 0000:06:06.4: reg 10 32bit mmio: [0xc8209000-0xc82090ff]
[    0.227816] pci 0000:06:06.4: reg 14 32bit mmio: [0xc8208c00-0xc8208cff]
[    0.227829] pci 0000:06:06.4: reg 18 32bit mmio: [0xc8208800-0xc82088ff]
[    0.227892] pci 0000:06:06.4: supports D1 D2
[    0.227894] pci 0000:06:06.4: PME# supported from D0 D1 D2 D3hot
[    0.227902] pci 0000:06:06.4: PME# disabled
[    0.227995] pci 0000:06:07.0: reg 10 io port: [0x4000-0x40ff]
[    0.228017] pci 0000:06:07.0: reg 14 32bit mmio: [0xc8209400-0xc82094ff]
[    0.228092] pci 0000:06:07.0: supports D1 D2
[    0.228094] pci 0000:06:07.0: PME# supported from D1 D2 D3hot D3cold
[    0.228102] pci 0000:06:07.0: PME# disabled
[    0.228182] pci 0000:00:1e.0: transparent bridge
[    0.228188] pci 0000:00:1e.0: bridge io port: [0x4000-0x4fff]
[    0.228195] pci 0000:00:1e.0: bridge 32bit mmio: [0xc8200000-0xc82fffff]
[    0.228271] bus 00 -> node 0
[    0.228287] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[    0.229012] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEGP._PRT]
[    0.229379] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.RP01._PRT]
[    0.229767] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCIB._PRT]
[    0.240301] ACPI: PCI Interrupt Link [LNKA] (IRQs 1 3 4 5 6 7 10 12 14 15) *11
[    0.240512] ACPI: PCI Interrupt Link [LNKB] (IRQs 1 3 4 5 6 7 11 12 14 15) *10
[    0.240722] ACPI: PCI Interrupt Link [LNKC] (IRQs 1 3 4 5 6 7 *10 12 14 15)
[    0.240943] ACPI: PCI Interrupt Link [LNKD] (IRQs 1 3 4 5 6 7 11 12 14 15) *10
[    0.241165] ACPI: PCI Interrupt Link [LNKE] (IRQs 1 3 4 5 6 7 10 12 14 15) *11
[    0.241384] ACPI: PCI Interrupt Link [LNKF] (IRQs 1 3 4 5 6 7 *11 12 14 15)
[    0.241589] ACPI: PCI Interrupt Link [LNKG] (IRQs 1 3 4 5 6 7 *10 12 14 15)
[    0.241796] ACPI: PCI Interrupt Link [LNKH] (IRQs 1 3 4 5 6 7 *11 12 14 15)
[    0.243573] SCSI subsystem initialized
[    0.243674] libata version 3.00 loaded.
[    0.244254] usbcore: registered new interface driver usbfs
[    0.244402] usbcore: registered new interface driver hub
[    0.244596] usbcore: registered new device driver usb
[    0.245820] PCI: Using ACPI for IRQ routing
[    0.245828] pci 0000:00:1c.0: BAR 7: can't allocate resource
[    0.245838] pci 0000:00:1c.0: BAR 8: can't allocate resource
[    0.245843] pci 0000:00:1c.0: BAR 9: can't allocate resource
[    0.246333] hpet clockevent registered
[    0.246333] HPET: 3 timers in total, 0 timers will be used for per-cpu timer
[    0.246333] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.246333] hpet0: 3 comparators, 64-bit 14.318180 MHz counter
[    0.248272] pnp: PnP ACPI init
[    0.248272] ACPI: bus type pnp registered
[    0.253957] pnp: PnP ACPI: found 8 devices
[    0.253960] ACPI: ACPI bus type pnp unregistered
[    0.253992] system 00:04: ioport range 0x200-0x20f has been reserved
[    0.253996] system 00:04: ioport range 0x800-0x80f has been reserved
[    0.254000] system 00:04: ioport range 0x1000-0x107f has been reserved
[    0.254004] system 00:04: ioport range 0x1180-0x11bf has been reserved
[    0.254010] system 00:04: iomem range 0xe0000000-0xefffffff has been reserved
[    0.254014] system 00:04: iomem range 0xf0000000-0xf0003fff has been reserved
[    0.254018] system 00:04: iomem range 0xf0004000-0xf0004fff has been reserved
[    0.254022] system 00:04: iomem range 0xf0005000-0xf0005fff has been reserved
[    0.254027] system 00:04: iomem range 0xf0008000-0xf000bfff has been reserved
[    0.254031] system 00:04: iomem range 0xfed20000-0xfed8ffff has been reserved
[    0.290847] pci 0000:00:01.0: PCI bridge, secondary bus 0000:01
[    0.290852] pci 0000:00:01.0:   IO window: 0x3000-0x3fff
[    0.290859] pci 0000:00:01.0:   MEM window: 0xc8100000-0xc81fffff
[    0.290864] pci 0000:00:01.0:   PREFETCH window: 0x000000d0000000-0x000000d7ffffff
[    0.290872] pci 0000:00:1c.0: PCI bridge, secondary bus 0000:02
[    0.290875] pci 0000:00:1c.0:   IO window: disabled
[    0.290883] pci 0000:00:1c.0:   MEM window: disabled
[    0.290889] pci 0000:00:1c.0:   PREFETCH window: disabled
[    0.290907] pci 0000:06:06.0: CardBus bridge, secondary bus 0000:07
[    0.290910] pci 0000:06:06.0:   IO window: 0x004400-0x0044ff
[    0.290918] pci 0000:06:06.0:   IO window: 0x004800-0x0048ff
[    0.290926] pci 0000:06:06.0:   PREFETCH window: 0x88000000-0x8bffffff
[    0.290934] pci 0000:06:06.0:   MEM window: 0x8c000000-0x8fffffff
[    0.290942] pci 0000:00:1e.0: PCI bridge, secondary bus 0000:06
[    0.290946] pci 0000:00:1e.0:   IO window: 0x4000-0x4fff
[    0.290955] pci 0000:00:1e.0:   MEM window: 0xc8200000-0xc82fffff
[    0.290962] pci 0000:00:1e.0:   PREFETCH window: 0x00000088000000-0x0000008bffffff
[    0.290987] pci 0000:00:01.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    0.290993] pci 0000:00:01.0: setting latency timer to 64
[    0.291008] pci 0000:00:1c.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[    0.291016] pci 0000:00:1c.0: setting latency timer to 64
[    0.291028] pci 0000:00:1e.0: setting latency timer to 64
[    0.291045] pci 0000:06:06.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[    0.291053] pci 0000:06:06.0: setting latency timer to 64
[    0.291058] bus: 00 index 0 io port: [0x00-0xffff]
[    0.291061] bus: 00 index 1 mmio: [0x000000-0xffffffff]
[    0.291063] bus: 01 index 0 io port: [0x3000-0x3fff]
[    0.291066] bus: 01 index 1 mmio: [0xc8100000-0xc81fffff]
[    0.291068] bus: 01 index 2 mmio: [0xd0000000-0xd7ffffff]
[    0.291071] bus: 01 index 3 mmio: [0x0-0x0]
[    0.291073] bus: 02 index 0 mmio: [0x0-0xfff]
[    0.291075] bus: 02 index 1 mmio: [0x0-0xfffff]
[    0.291077] bus: 02 index 2 mmio: [0x0-0xfffff]
[    0.291079] bus: 02 index 3 mmio: [0x0-0x0]
[    0.291082] bus: 06 index 0 io port: [0x4000-0x4fff]
[    0.291084] bus: 06 index 1 mmio: [0xc8200000-0xc82fffff]
[    0.291086] bus: 06 index 2 mmio: [0x88000000-0x8bffffff]
[    0.291089] bus: 06 index 3 io port: [0x00-0xffff]
[    0.291091] bus: 06 index 4 mmio: [0x000000-0xffffffff]
[    0.291094] bus: 07 index 0 io port: [0x4400-0x44ff]
[    0.291096] bus: 07 index 1 io port: [0x4800-0x48ff]
[    0.291098] bus: 07 index 2 mmio: [0x88000000-0x8bffffff]
[    0.291101] bus: 07 index 3 mmio: [0x8c000000-0x8fffffff]
[    0.291173] NET: Registered protocol family 2
[    0.291495] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.292427] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.293616] TCP bind hash table entries: 65536 (order: 9, 2359296 bytes)
[    0.300376] TCP: Hash tables configured (established 131072 bind 65536)
[    0.300434] TCP reno registered
[    0.300837] NET: Registered protocol family 1
[    0.301789] checking if image is initramfs... it is
[    0.721728] Freeing initrd memory: 5026k freed
[    0.722125] Simple Boot Flag at 0x36 set to 0x1
[    0.724283] Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[    0.725496] highmem bounce pool size: 64 pages
[    0.726535] fuse init (API version 7.10)
[    0.726779] msgmni has been set to 1692
[    0.727185] alg: No test for cipher_null (cipher_null-generic)
[    0.727318] alg: No test for digest_null (digest_null-generic)
[    0.727381] alg: No test for compress_null (compress_null-generic)
[    0.730771] alg: No test for stdrng (krng)
[    0.730839] io scheduler noop registered
[    0.730889] io scheduler cfq registered (default)
[    0.731072] pci 0000:01:00.0: Boot video device
[    0.736856] pcieport-driver 0000:00:01.0: setting latency timer to 64
[    0.736929] pcieport-driver 0000:00:01.0: found MSI capability
[    0.736975] pcieport-driver 0000:00:01.0: irq 511 for MSI/MSI-X
[    0.736997] pci_express 0000:00:01.0:pcie00: allocate port service
[    0.737151] pci_express 0000:00:01.0:pcie03: allocate port service
[    0.737373] pcieport-driver 0000:00:1c.0: setting latency timer to 64
[    0.737443] pcieport-driver 0000:00:1c.0: found MSI capability
[    0.737492] pcieport-driver 0000:00:1c.0: irq 510 for MSI/MSI-X
[    0.737518] pci_express 0000:00:1c.0:pcie00: allocate port service
[    0.737674] pci_express 0000:00:1c.0:pcie02: allocate port service
[    0.737817] pci_express 0000:00:1c.0:pcie03: allocate port service
[    0.738309] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.738330] pciehp 0000:00:1c.0:pcie02: Bypassing BIOS check for pciehp use on 0000:00:1c.0
[    0.738437] pciehp 0000:00:1c.0:pcie02: HPC vendor_id 8086 device_id 2660 ss_vid 0 ss_did 0
[    0.738841] pciehp 0000:00:1c.0:pcie02: service driver pciehp loaded
[    0.738963] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.740331] vesafb: framebuffer at 0xd0000000, mapped to 0xf8500000, using 6144k, total 16384k
[    0.740334] vesafb: mode is 1024x768x16, linelength=2048, pages=9
[    0.740337] vesafb: protected mode interface info at c000:aeb4
[    0.740340] vesafb: pmi: set display start = c00caf42, set palette = c00caf82
[    0.740342] vesafb: scrolling: redraw
[    0.740345] vesafb: Truecolor: size=0:5:6:5, shift=0:11:5:0
[    0.740957] bootsplash 3.1.6-2004/03/31: looking for picture...<7>Switched to high resolution mode on CPU 0
[    0.757848]  silentjpeg size 100719 bytes,<6>...found (1024x768, 38691 bytes, v3).
[    0.841638] Console: switching to colour frame buffer device 124x44
[    0.922375] fb0: VESA VGA frame buffer device
[    0.924647] ACPI: AC Adapter [AC] (on-line)
[    0.972484] ACPI: Battery Slot [BAT0] (battery present)
[    0.972996] input: Power Button (FF) as /class/input/input0
[    0.973036] ACPI: Power Button (FF) [PWRF]
[    0.973332] input: Lid Switch as /class/input/input1
[    0.974814] ACPI: Lid Switch [LID0]
[    0.975078] input: Sleep Button (CM) as /class/input/input2
[    0.975083] ACPI: Sleep Button (CM) [SLPB]
[    0.975348] input: Power Button (CM) as /class/input/input3
[    0.975352] ACPI: Power Button (CM) [PWB]
[    0.976653] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3] C4[C3])
[    0.976918] processor ACPI_CPU:00: registered as cooling_device0
[    0.990918] thermal LNXTHERM:01: registered as thermal_zone0
[    0.996589] ACPI: Thermal Zone [THR0] (87 C)
[    1.005800] thermal LNXTHERM:02: registered as thermal_zone1
[    1.011525] ACPI: Thermal Zone [THR1] (66 C)
[    1.022680] Linux agpgart interface v0.103
[    1.022889] Serial: 8250/16550 driver4 ports, IRQ sharing disabled
[    1.024494] serial 0000:00:1e.3: PCI INT B -> GSI 20 (level, low) -> IRQ 20
[    1.024504] serial 0000:00:1e.3: PCI INT B disabled
[    1.030552] brd: module loaded
[    1.033336] loop: module loaded
[    1.033720] tifm_7xx1 0000:06:06.3: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[    1.034219] PPP generic driver version 2.4.2
[    1.034525] PPP Deflate Compression module registered
[    1.039713] PPP MPPE Compression module registered
[    1.039718] NET: Registered protocol family 24
[    1.039782] 8139too Fast Ethernet driver 0.9.28
[    1.039814] 8139too 0000:06:07.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[    1.041366] eth0: RealTek RTL8139 at 0xf803e400, 00:0a:e4:dd:8b:30, IRQ 20
[    1.041369] eth0:  Identified 8139 chip type 'RTL-8100B/8139D'
[    1.041634] usbcore: registered new interface driver cdc_ether
[    1.041766] usbcore: registered new interface driver rndis_host
[    1.041781] ipw2200: Intel(R) PRO/Wireless 2200/2915 Network Driver, 1.2.2kmr
[    1.041783] ipw2200: Copyright(c) 2003-2006 Intel Corporation
[    1.042095] ipw2200 0000:06:05.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[    1.042175] ipw2200: Detected Intel PRO/Wireless 2200BG Network Connection
[    1.042353] ipw2200 0000:06:05.0: firmware: using built-in firmware ipw2200-bss.fw
[    1.194313] ipw2200: Detected geography ZZR (14 802.11bg channels, 0 802.11a channels)
[    1.194634] Driver 'sd' needs updating - please use bus_type methods
[    1.194760] Driver 'sr' needs updating - please use bus_type methods
[    1.195121] ata_piix 0000:00:1f.1: version 2.12
[    1.195145] ata_piix 0000:00:1f.1: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[    1.195348] ata_piix 0000:00:1f.1: setting latency timer to 64
[    1.195511] scsi0 : ata_piix
[    1.195938] scsi1 : ata_piix
[    1.197465] ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0x18c0 irq 14
[    1.197469] ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x18c8 irq 15
[    1.384719] ata1.00: ATA-6: HTS721080G9AT00, MC4OA51A, max UDMA/100
[    1.384722] ata1.00: 156301488 sectors, multi 16: LBA48 
[    1.384763] ata1.01: ATAPI: TSSTcorpCD/DVDW TS-L532M, HR08, max MWDMA2
[    1.400660] ata1.00: configured for UDMA/100
[    1.432503] ata1.01: configured for MWDMA2
[    1.433405] ata2: port disabled. ignoring.
[    1.434001] scsi 0:0:0:0: Direct-Access     ATA      HTS721080G9AT00  MC4O PQ: 0 ANSI: 5
[    1.434790] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors: (80.0 GB/74.5 GiB)
[    1.434831] sd 0:0:0:0: [sda] Write Protect is off
[    1.434834] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.434905] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.435357] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors: (80.0 GB/74.5 GiB)
[    1.435397] sd 0:0:0:0: [sda] Write Protect is off
[    1.435399] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.435470] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.435488]  sda: sda1 sda2 sda3 sda4
[    1.452897] sd 0:0:0:0: [sda] Attached SCSI disk
[    1.453666] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.460480] scsi 0:0:1:0: CD-ROM            TSSTcorp CD/DVDW TS-L532M HR08 PQ: 0 ANSI: 5
[    1.470185] sr0: scsi3-mmc drive: 24x/24x writer cd/rw xa/form2 cdda tray
[    1.470189] Uniform CD-ROM driver Revision: 3.20
[    1.470748] sr 0:0:1:0: Attached scsi CD-ROM sr0
[    1.471082] sr 0:0:1:0: Attached scsi generic sg1 type 5
[    1.471488] firewire_ohci 0000:06:06.2: PCI INT C -> GSI 21 (level, low) -> IRQ 21
[    1.540013] firewire_ohci: Added fw-ohci device 0000:06:06.2, OHCI version 1.10
[    1.540576] yenta_cardbus 0000:06:06.0: CardBus bridge found [103c:309d]
[    1.540608] yenta_cardbus 0000:06:06.0: Enabling burst memory read transactions
[    1.540616] yenta_cardbus 0000:06:06.0: Using CSCINT to route CSC interrupts to PCI
[    1.540619] yenta_cardbus 0000:06:06.0: Routing CardBus interrupts to PCI
[    1.540628] yenta_cardbus 0000:06:06.0: TI: mfunc 0x01aa1b02, devctl 0x64
[    1.773299] yenta_cardbus 0000:06:06.0: ISA IRQ mask 0x0cf8, PCI irq 22
[    1.773304] yenta_cardbus 0000:06:06.0: Socket status: 30000006
[    1.773308] pci_bus 0000:06: Raising subordinate bus# of parent bus (#06) from #07 to #0a
[    1.773336] yenta_cardbus 0000:06:06.0: pcmcia: parent PCI bridge I/O window: 0x4000 - 0x4fff
[    1.773361] pcmcia_socket pcmcia_socket0: cs: IO port probe 0x4000-0x4fff: clean.
[    1.774585] yenta_cardbus 0000:06:06.0: pcmcia: parent PCI bridge Memory window: 0xc8200000 - 0xc82fffff
[    1.774589] yenta_cardbus 0000:06:06.0: pcmcia: parent PCI bridge Memory window: 0x88000000 - 0x8bffffff
[    2.028272] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    2.028317] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[    2.028340] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[    2.028345] ehci_hcd 0000:00:1d.7: EHCI Host Controller
[    2.029156] ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1
[    2.033121] ehci_hcd 0000:00:1d.7: debug port 1
[    2.033130] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[    2.033165] ehci_hcd 0000:00:1d.7: irq 23, io mem 0xc8000000
[    2.040509] firewire_core: created device fw0: GUID 05e40a003c175052, S400
[    2.048014] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00
[    2.048490] usb usb1: configuration #1 chosen from 1 choice
[    2.048777] hub 1-0:1.0: USB hub found
[    2.048827] hub 1-0:1.0: 8 ports detected
[    2.049844] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.049847] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.049850] usb usb1: Product: EHCI Host Controller
[    2.049852] usb usb1: Manufacturer: Linux 2.6.28-rc9-00047-gec4c265 ehci_hcd
[    2.049855] usb usb1: SerialNumber: 0000:00:1d.7
[    2.050011] uhci_hcd: USB Universal Host Controller Interface driver
[    2.050062] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[    2.050075] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[    2.050080] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[    2.050255] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    2.050296] uhci_hcd 0000:00:1d.0: irq 23, io base 0x00001800
[    2.050646] usb usb2: configuration #1 chosen from 1 choice
[    2.050843] hub 2-0:1.0: USB hub found
[    2.050897] hub 2-0:1.0: 2 ports detected
[    2.051388] usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
[    2.051391] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.051393] usb usb2: Product: UHCI Host Controller
[    2.051396] usb usb2: Manufacturer: Linux 2.6.28-rc9-00047-gec4c265 uhci_hcd
[    2.051398] usb usb2: SerialNumber: 0000:00:1d.0
[    2.051439] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[    2.051461] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[    2.051466] uhci_hcd 0000:00:1d.1: UHCI Host Controller
[    2.051646] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
[    2.051720] uhci_hcd 0000:00:1d.1: irq 19, io base 0x00001820
[    2.052108] usb usb3: configuration #1 chosen from 1 choice
[    2.052301] hub 3-0:1.0: USB hub found
[    2.052319] hub 3-0:1.0: 2 ports detected
[    2.052778] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
[    2.052781] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.052784] usb usb3: Product: UHCI Host Controller
[    2.052786] usb usb3: Manufacturer: Linux 2.6.28-rc9-00047-gec4c265 uhci_hcd
[    2.052789] usb usb3: SerialNumber: 0000:00:1d.1
[    2.052824] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[    2.052837] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[    2.052841] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[    2.053013] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
[    2.053077] uhci_hcd 0000:00:1d.2: irq 18, io base 0x00001840
[    2.053444] usb usb4: configuration #1 chosen from 1 choice
[    2.053634] hub 4-0:1.0: USB hub found
[    2.053669] hub 4-0:1.0: 2 ports detected
[    2.054125] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
[    2.054128] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.054130] usb usb4: Product: UHCI Host Controller
[    2.054132] usb usb4: Manufacturer: Linux 2.6.28-rc9-00047-gec4c265 uhci_hcd
[    2.054135] usb usb4: SerialNumber: 0000:00:1d.2
[    2.054172] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16
[    2.054184] uhci_hcd 0000:00:1d.3: setting latency timer to 64
[    2.054189] uhci_hcd 0000:00:1d.3: UHCI Host Controller
[    2.054363] uhci_hcd 0000:00:1d.3: new USB bus registered, assigned bus number 5
[    2.054433] uhci_hcd 0000:00:1d.3: irq 16, io base 0x00001860
[    2.054788] usb usb5: configuration #1 chosen from 1 choice
[    2.054988] hub 5-0:1.0: USB hub found
[    2.055004] hub 5-0:1.0: 2 ports detected
[    2.055465] usb usb5: New USB device found, idVendor=1d6b, idProduct=0001
[    2.055468] usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.055471] usb usb5: Product: UHCI Host Controller
[    2.055473] usb usb5: Manufacturer: Linux 2.6.28-rc9-00047-gec4c265 uhci_hcd
[    2.055475] usb usb5: SerialNumber: 0000:00:1d.3
[    2.055791] usbcore: registered new interface driver usblp
[    2.055797] Initializing USB Mass Storage driver...
[    2.055966] usbcore: registered new interface driver usb-storage
[    2.055972] USB Mass Storage support registered.
[    2.056302] usbcore: registered new interface driver usbserial
[    2.056430] USB Serial support registered for generic
[    2.056582] usbcore: registered new interface driver usbserial_generic
[    2.056584] usbserial: USB Serial Driver core
[    2.056712] USB Serial support registered for PocketPC PDA
[    2.056892] usbcore: registered new interface driver ipaq
[    2.056894] ipaq: v0.5:USB PocketPC PDA driver
[    2.057021] USB Serial support registered for pl2303
[    2.057181] usbcore: registered new interface driver pl2303
[    2.057184] pl2303: Prolific PL2303 USB to serial adaptor driver
[    2.057484] PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
[    2.063186] serio: i8042 KBD port at 0x60,0x64 irq 1
[    2.063215] serio: i8042 AUX port at 0x60,0x64 irq 12
[    2.063590] mice: PS/2 mouse device common for all mice
[    2.065349] rtc_cmos 00:05: RTC can wake from S4
[    2.065639] rtc_cmos 00:05: rtc core: registered rtc_cmos as rtc0
[    2.065681] rtc0: alarms up to one month, y3k, 242 bytes nvram, hpet irqs
[    2.065804] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.04
[    2.066145] iTCO_wdt: Found a ICH6-M TCO device (Version=2, TCOBASE=0x1060)
[    2.066482] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
[    2.066770] device-mapper: ioctl: 4.14.0-ioctl (2008-04-23) initialised: dm-devel@redhat.com
[    2.067542] cpuidle: using governor ladder
[    2.068838] cpuidle: using governor menu
[    2.069915] Advanced Linux Sound Architecture Driver Version 1.0.18rc3.
[    2.076290] Intel ICH 0000:00:1e.2: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[    2.076346] Intel ICH 0000:00:1e.2: setting latency timer to 64
[    2.076950] Marking TSC unstable due to TSC halts in idle
[    2.077641] input: AT Translated Set 2 keyboard as /class/input/input4
[    2.244022] Clocksource tsc unstable (delta = -179548942 ns)
[    2.346055] input: PS/2 Mouse as /class/input/input5
[    2.362911] input: AlpsPS/2 ALPS GlidePoint as /class/input/input6
[    2.624035] usb 3-1: new full speed USB device using uhci_hcd and address 2
[    2.794365] usb 3-1: configuration #1 chosen from 1 choice
[    2.799555] usb 3-1: New USB device found, idVendor=03f0, idProduct=171d
[    2.799558] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    2.799561] usb 3-1: Product: HP Integrated Module
[    2.799563] usb 3-1: Manufacturer: Broadcom Corp
[    2.976034] intel8x0_measure_ac97_clock: measured 55906 usecs
[    2.976036] intel8x0: measured clock 196 rejected
[    2.976038] intel8x0: clocking to 48000
[    2.979108] ALSA device list:
[    2.979111]   #0: Intel ICH6 with AD1981B at irq 17
[    2.980390] TCP cubic registered
[    2.980393] Initializing XFRM netlink socket
[    2.980430] NET: Registered protocol family 17
[    2.980470] NET: Registered protocol family 15
[    2.980480] ieee80211: 802.11 data/management/control stack, git-1.1.13
[    2.980482] ieee80211: Copyright (C) 2004-2005 Intel Corporation <jketreno@linux.intel.com>
[    2.980497] ieee80211_crypt: registered algorithm 'NULL'
[    2.980500] ieee80211_crypt: registered algorithm 'WEP'
[    2.980503] ieee80211_crypt: registered algorithm 'CCMP'
[    2.980506] ieee80211_crypt: registered algorithm 'TKIP'
[    2.981700] Using IPI No-Shortcut mode
[    2.992277] rtc_cmos 00:05: setting system clock to 2008-12-22 21:06:41 UTC (1229980001)
[    2.993337] Freeing unused kernel memory: 1428k freed
[    3.060386] udevd version 128 started
[    4.070049] PM: Starting manual resume from disk
[    4.466212] kjournald starting.  Commit interval 5 seconds
[    4.466634] EXT3 FS on sda2, internal journal
[    4.466865] EXT3-fs: mounted filesystem with ordered data mode.
[    7.281789] udevd version 128 started
[    8.904110] pcmcia_socket pcmcia_socket0: cs: IO port probe 0x100-0x3af: clean.
[    8.906203] pcmcia_socket pcmcia_socket0: cs: IO port probe 0x3e0-0x4ff: excluding 0x4d0-0x4d7
[    8.907149] pcmcia_socket pcmcia_socket0: cs: IO port probe 0x820-0x8ff: clean.
[    8.907937] pcmcia_socket pcmcia_socket0: cs: IO port probe 0xc00-0xcf7: clean.
[    8.909157] pcmcia_socket pcmcia_socket0: cs: IO port probe 0xa00-0xaff: clean.
[    9.301869] Adding 2104504k swap on /dev/sda3.  Priority:-1 extents:1 across:2104504k
[   11.650969] kjournald starting.  Commit interval 5 seconds
[   11.651302] EXT3 FS on sda4, internal journal
[   11.651314] EXT3-fs: mounted filesystem with ordered data mode.
[   14.332857] ACPI: 'LID0' and 'PS2M' have the same GPE, can't disable/enable one seperately
[   14.340603] ACPI: 'PS2K' and 'PS2M' have the same GPE, can't disable/enable one seperately
[   51.799842] fglrx: module license 'Proprietary. (C) 2002 - ATI Technologies, Starnberg, GERMANY' taints kernel.
[   51.849549] [fglrx] Maximum main memory to use for locked dma buffers: 1879 MBytes.
[   51.850740] [fglrx]   vendor: 1002 device: 5653 count: 1
[   51.853474] [fglrx] ioport: bar 1, base 0x3000, size: 0x100
[   51.853598] pci 0000:01:00.0: power state changed by ACPI to D0
[   51.853608] pci 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[   51.853614] pci 0000:01:00.0: setting latency timer to 64
[   51.854778] [fglrx] Driver built-in PAT support is enabled successfully
[   51.854866] [fglrx] module loaded - fglrx 8.56.4 [Dec  1 2008] with 1 minors
[   54.240633] Cisco Systems VPN Client Version 4.8.02 (0030) kernel module loaded
[   56.086306] bootsplash: status on console 0 changed to on
[   56.389881] [fglrx] Gart USWC size:192 M.
[   56.389888] [fglrx] Gart cacheable size:60 M.
[   56.389904] [fglrx] Reserved FB block: Shared offset:0, size:40000 
[   56.389910] [fglrx] Reserved FB block: Unshared offset:7fb6000, size:45000 
[   56.389917] [fglrx] Reserved FB block: Unshared offset:7ffb000, size:5000 
[  558.508796] [fglrx] It's not necessary to adjust system aperture on this ASIC 
[  559.400095] Syncing filesystems ... done.
[  559.400809] Freezing user space processes ... (elapsed 0.00 seconds) done.
[  559.402028] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[  559.403405] PM: Shrinking memory...  \b-\bdone (0 pages freed)
[  559.464816] PM: Freed 0 kbytes in 0.06 seconds (0.00 MB/s)
[  559.464839] Suspending console(s) (use no_console_suspend to debug)
[  559.465415] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  559.516188] pciehp 0000:00:1c.0:pcie02: pciehp_suspend ENTRY
[  559.516413] ACPI handle has no context!
[  559.516423] tifm_7xx1 0000:06:06.3: PCI INT A disabled
[  559.516431] ACPI handle has no context!
[  559.532243] ACPI handle has no context!
[  559.548271] eth1: Going into suspend...
[  559.551176] ipw2200 0000:06:05.0: PCI INT A disabled
[  559.551184] ACPI handle has no context!
[  559.564043] [fglrx] Power down the ASIC .
[  559.660052] fglrx_pci 0000:01:00.0: PCI INT A disabled
[  559.660174] ata2: port disabled. ignoring.
[  559.660231] ata_piix 0000:00:1f.1: PCI INT A disabled
[  559.660505] Intel ICH 0000:00:1e.2: PCI INT A disabled
[  559.660643] ehci_hcd 0000:00:1d.7: PCI INT A disabled
[  559.660683] uhci_hcd 0000:00:1d.3: PCI INT D disabled
[  559.660722] uhci_hcd 0000:00:1d.2: PCI INT C disabled
[  559.660761] uhci_hcd 0000:00:1d.1: PCI INT B disabled
[  559.660800] uhci_hcd 0000:00:1d.0: PCI INT A disabled
[  559.660806] pciehp 0000:00:1c.0:pcie02: pciehp_suspend ENTRY
[  559.661568] ACPI: Preparing to enter system sleep state S4
[  559.663113] Disabling non-boot CPUs ...
[  559.663192] SCD raw 81220634864 gtod 559660004903 clock 559663113457 now 81223820545
[  559.663293] PM: Creating hibernation image: 
[  559.664005] PM: Need to copy 176823 pages
[  559.664005] Intel machine check architecture supported.
[  559.664005] Intel machine check reporting enabled on CPU#0.
[  612.929722] Force enabled HPET at resume
[  612.929731] SCD raw 36410541237 gtod 612929432462 clock 612929722283 now 36410836846
[  612.929857] ACPI: Waking up from system sleep state S4
[  612.929857] ACPI: EC: non-query interrupt received, switching to interrupt mode
[  612.929857] pcieport-driver 0000:00:01.0: setting latency timer to 64
[  612.929857] pcieport-driver 0000:00:1c.0: setting latency timer to 64
[  612.929857] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY
[  612.929857] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  612.929857] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[  612.929857] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[  612.929857] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[  612.929857] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[  612.929857] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[  612.929857] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16
[  612.929857] uhci_hcd 0000:00:1d.3: setting latency timer to 64
[  612.929857] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[  612.929857] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[  612.929857] pci 0000:00:1e.0: setting latency timer to 64
[  612.929857] Intel ICH 0000:00:1e.2: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[  612.929857] Intel ICH 0000:00:1e.2: setting latency timer to 64
[  612.929857] ata_piix 0000:00:1f.1: restoring config space at offset 0x1 (was 0x2880001, writing 0x2880005)
[  612.929857] ata_piix 0000:00:1f.1: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[  612.929857] ata_piix 0000:00:1f.1: setting latency timer to 64
[  612.929857] ata2: port disabled. ignoring.
[  612.929857] fglrx_pci 0000:01:00.0: power state changed by ACPI to D0
[  612.929857] fglrx_pci 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[  612.929857] fglrx_pci 0000:01:00.0: setting latency timer to 64
[  612.929857] [fglrx] Power up the ASIC
[  612.929857] eth1: Coming out of suspend...
[  612.929857] ipw2200 0000:06:05.0: enabling device (0000 -> 0002)
[  612.929857] ipw2200 0000:06:05.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[  612.929857] ipw2200 0000:06:05.0: restoring config space at offset 0xf (was 0x18030100, writing 0x1803010b)
[  612.929857] ipw2200 0000:06:05.0: restoring config space at offset 0x4 (was 0x0, writing 0xc8206000)
[  612.929857] ipw2200 0000:06:05.0: restoring config space at offset 0x3 (was 0x0, writing 0x8008)
[  612.929857] ipw2200 0000:06:05.0: restoring config space at offset 0x1 (was 0x2900002, writing 0x2900116)
[  612.929857] ata1.01: ACPI cmd ef/03:0c:00:00:00:b0 filtered out
[  612.929857] ata1.01: ACPI cmd ef/03:22:00:00:00:b0 filtered out
[  612.929857] ata1.00: ACPI cmd ef/03:0c:00:00:00:a0 filtered out
[  612.929857] ata1.00: ACPI cmd ef/03:45:00:00:00:a0 filtered out
[  612.929857] ata1.00: configured for UDMA/100
[  612.929857] ata1.01: configured for MWDMA2
[  612.929857] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors: (80.0 GB/74.5 GiB)
[  612.929857] sd 0:0:0:0: [sda] Write Protect is off
[  612.929857] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  612.929857] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  612.929857] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors: (80.0 GB/74.5 GiB)
[  612.929857] sd 0:0:0:0: [sda] Write Protect is off
[  612.929857] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  612.929857] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  612.929857] firewire_ohci 0000:06:06.2: restoring config space at offset 0xf (was 0x4020300, writing 0x402030b)
[  612.929857] firewire_ohci 0000:06:06.2: restoring config space at offset 0x5 (was 0x0, writing 0xc8200000)
[  612.929857] firewire_ohci 0000:06:06.2: restoring config space at offset 0x4 (was 0x0, writing 0xc8208000)
[  612.929857] firewire_ohci 0000:06:06.2: restoring config space at offset 0x3 (was 0x800000, writing 0x808008)
[  612.929857] firewire_ohci 0000:06:06.2: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100116)
[  612.929857] tifm_7xx1 0000:06:06.3: restoring config space at offset 0xf (was 0x40701ff, writing 0x407010a)
[  612.929857] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x4 (was 0x0, writing 0xc8204000)
[  612.929857] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x3 (was 0x800000, writing 0x808008)
[  612.929857] tifm_7xx1 0000:06:06.3: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106)
[  612.929857] tifm_7xx1 0000:06:06.3: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[  612.929857] pciehp 0000:00:1c.0:pcie02: pciehp_resume ENTRY
[  612.929857] sd 0:0:0:0: [sda] Starting disk
[  612.929857] usb 3-1: reset full speed USB device using uhci_hcd and address 2
[  612.929857] Restarting tasks ... done.
[  612.929857] [fglrx] It's not necessary to adjust system aperture on this ASIC 

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

[Thomas Gleixner]

On Sun, 21 Dec 2008, Thomas Gleixner wrote:
> On Thu, 18 Dec 2008, Rafael J. Wysocki wrote:
> Also we need to investigate whether sched_clock is referencing gtod
> values _before_ timekeeping is resume.

It does. I added a check into __update_sched_clock() and it triggers
on every resume:

WARNING: at /home/tglx/work/kernel/git/linux-2.6/kernel/sched_clock.c:117 __update_sched_clock+0x31/0xad()
Modules linked in: fuse i915 drm bridge stp bnep sco l2cap bluetooth coretemp sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq freq_table dm_mirror dm_region_hash dm_log dm_multipath uinput joydev thinkpad_acpi hwmon snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device pcspkr i2c_i801 snd_pcm_oss firewire_ohci i2c_core firewire_core yenta_socket iwlagn iTCO_wdt snd_mixer_oss rsrc_nonstatic crc_itu_t iTCO_vendor_support snd_pcm iwlcore snd_timer snd_page_alloc snd_hwdep rfkill snd soundcore e1000e wmi video output battery ac [last unloaded: microcode]
Pid: 3212, comm: pm-hibernate Not tainted 2.6.28-rc9 #80
Call Trace:
 [<ffffffff8103ef04>] warn_on_slowpath+0x5d/0x82
 [<ffffffff8117becf>] ? vsnprintf+0x669/0x6ba
 [<ffffffff81099c38>] ? __mod_zone_page_state+0x9/0x5a
 [<ffffffff810900b7>] ? __rmqueue+0x24/0x1fa
 [<ffffffff81057689>] __update_sched_clock+0x31/0xad
 [<ffffffff81090004>] ? __rmqueue_smallest+0xb7/0x146
 [<ffffffff81057809>] sched_clock_cpu+0x104/0x120
 [<ffffffff811b5030>] ? acpi_ns_search_one_scope+0xc/0x4b
 [<ffffffff81367d14>] ? _spin_lock+0xe/0x11
 [<ffffffff81038e17>] try_to_wake_up+0xff/0x1b1
 [<ffffffff8128e4ca>] ? cpufreq_debug_printk+0x17/0x124
 [<ffffffff81038ed6>] default_wake_function+0xd/0xf
 [<ffffffff81052d94>] autoremove_wake_function+0x16/0x3d
 [<ffffffff8103262f>] __wake_up_common+0x46/0x75
 [<ffffffff81032c7c>] __wake_up+0x38/0x50
 [<ffffffff8104f378>] insert_work+0x68/0x70
 [<ffffffff8104fb94>] __queue_work+0x2f/0x42
 [<ffffffff8104fc2f>] queue_work_on+0x47/0x50
 [<ffffffff8104fdc1>] queue_work+0x1f/0x21
 [<ffffffff8104fdde>] schedule_work+0x1b/0x1d
 [<ffffffff8128f0c8>] cpufreq_resume+0x157/0x16c
 [<ffffffff811fe436>] __sysdev_resume+0x3d/0x55
 [<ffffffff811fe484>] sysdev_resume+0x36/0x77
 [<ffffffff81203e28>] device_power_up+0x15/0x20
 [<ffffffff810670c9>] hibernation_snapshot+0x181/0x210
 [<ffffffff81067220>] hibernate+0xc8/0x1a6
 [<ffffffff81065f75>] state_store+0x5e/0xdd
 [<ffffffff81176f83>] kobj_attr_store+0x17/0x19
 [<ffffffff811106db>] sysfs_write_file+0xe4/0x119
 [<ffffffff810c1856>] vfs_write+0xb0/0x10a
 [<ffffffff810c197e>] sys_write+0x4c/0x74
 [<ffffffff8100c1fa>] system_call_fastpath+0x16/0x1b

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

[Rafael J. Wysocki]

On Sunday, 21 of December 2008, Thomas Gleixner wrote:
> On Thu, 18 Dec 2008, Rafael J. Wysocki wrote:
> 
> > On Thursday, 18 of December 2008, Ingo Molnar wrote:
> > > 
> > > * Peter Zijlstra <peterz@infradead.org> wrote:
> > > 
> > > > Rafael, would something like this explain why we had to revert Shaggy's 
> > > > patch?
> > 
> > Well, I have yet to understand what the suspend-resume of the timekeeping code
> > actually does.
> 
> Thats rather simple:
> 
> suspend() saves the current time of the persistent clock (if
> available), forwards the timekeeping variables so they can be reused
> on resume, disables timekeeping activities and shuts down the clock
> events layer.
>  
> resume() estimates the suspend time via persistent clock (if
> available) and update xtime with the sleep length. After that it
> reactivates timekeeping and resumes clock events and high resolution
> timers.
> 
> So the sole purpose is:
>    - dis/enable timekeeping and clock event devices.
>    - keep track of the suspend time (if a persistent clock is available)
> 
> We reactivate clock event devices and hrtimers from timekeeping_resume
> because clock events depend on functional timekeeping.

Thanks for the explanation.  In fact, the reactivation of clock event devices
and hrtimers is the part I'm not familiar with.

> > The original description sounds worrisome to me, it looks like we've overlooked
> > something at least.
> 
> Care to explain ?

Well, the fact that in the resume code path the clocksource is only updated as
a result of executing pci_set_power_state() is worrisome.  I would be more
reliable to update it directly at one point.

Thanks,
Rafael

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

[Thomas Gleixner]

On Tue, 23 Dec 2008, Rafael J. Wysocki wrote:
> > Care to explain ?
> 
> Well, the fact that in the resume code path the clocksource is only updated as
> a result of executing pci_set_power_state() is worrisome.  I would be more
> reliable to update it directly at one point.

Hmm. We reactivate the clock sources from timekeeping resume():

     clocksource_resume();

How is this related to pci_set_power_state() ?

Thanks,

	tglx

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

[Rafael J. Wysocki]

On Tuesday, 23 of December 2008, Thomas Gleixner wrote:
> On Tue, 23 Dec 2008, Rafael J. Wysocki wrote:
> > > Care to explain ?
> > 
> > Well, the fact that in the resume code path the clocksource is only updated as
> > a result of executing pci_set_power_state() is worrisome.  I would be more
> > reliable to update it directly at one point.
> 
> Hmm. We reactivate the clock sources from timekeeping resume():
> 
>      clocksource_resume();
> 
> How is this related to pci_set_power_state() ?

>From the original report:

"I am using ftrace to get a detailed timing analysis of the resume process 
on the OLPC XO laptop and am seeing that when we start running again, the
system timestamep is not being updated for several (hundreds of) thousands 
of cycles (~2000 ftrace entries). From following the ftrace, what is 
happening is that the clocksource is not updated until we run the cpu_idle() 
thread due to an explicit scheduling operation in the resume path that occurs 
via call to msleep from pci_set_power_state()."

That's what I was referring to.

Thanks,
Rafael

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

[Thomas Gleixner]

Deepak,

On Wed, 17 Dec 2008, Deepak Saxena wrote:
> 
> Hi,
> 
> I am using ftrace to get a detailed timing analysis of the resume process 
> on the OLPC XO laptop and am seeing that when we start running again, the
> system timestamep is not being updated for several (hundreds of) thousands 
> of cycles (~2000 ftrace entries). From following the ftrace, what is 
> happening is that the clocksource is not updated until we run the cpu_idle() 
> thread due to an explicit scheduling operation in the resume path that occurs 
> via call to msleep from pci_set_power_state().  As I'm still fully groking the 
> timekeeping code, the question(s) I have is whether this is expected behaviour 
> and I should not assume valid timestamp data in the initial bits of the suspend path, 
> whether this is an OLPC-specific bug, or whether I've uncovered a generic bug in 
> the timekeeping implementation.  This is on 2.6.27.7 as I've not gotten 28-rc 
> up and running on the XO but can move that up in priority if this behaviour
> is different in newer kernels.

Can you please upload the full trace somewhere ? 

Thanks,

	tglx

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

[Deepak Saxena]

On Sun, Dec 21, 2008 at 10:19:12PM +0100, Thomas Gleixner wrote:
> > of cycles (~2000 ftrace entries). From following the ftrace, what is 
> > happening is that the clocksource is not updated until we run the cpu_idle() 
> > thread due to an explicit scheduling operation in the resume path that occurs 
> > via call to msleep from pci_set_power_state().  As I'm still fully groking the 
> > timekeeping code, the question(s) I have is whether this is expected behaviour 
> > and I should not assume valid timestamp data in the initial bits of the suspend path, 
> > whether this is an OLPC-specific bug, or whether I've uncovered a generic bug in 
> > the timekeeping implementation.  This is on 2.6.27.7 as I've not gotten 28-rc 
> > up and running on the XO but can move that up in priority if this behaviour
> > is different in newer kernels.
> 
> Can you please upload the full trace somewhere ? 
> 
> Thanks,

Thomas,

Sorry for the delayed response...travelling and have very limited
connectivity. I will read the thread in detail when back online in a
few days.

http://dev.laptop.org/~dsaxena/suspend-trace-1267

~Deepak