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

[Steven Rostedt <srostedt@redhat.com>]

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
>