lkml.org 
[lkml]   [2008]   [Dec]   [17]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: TSC not updating after resume: Bug or Feature?
From
Date

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
>



\
 
 \ /
  Last update: 2008-12-17 18:53    [W:0.085 / U:0.400 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site