TSC not updating after resume: Bug or Feature?

[Deepak Saxena <dsaxena@laptop.org>]

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_/_
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~