Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754009AbYLQRer (ORCPT ); Wed, 17 Dec 2008 12:34:47 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751493AbYLQReW (ORCPT ); Wed, 17 Dec 2008 12:34:22 -0500 Received: from plexity.net ([206.123.115.38]:53079 "EHLO plexity.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751298AbYLQReU (ORCPT ); Wed, 17 Dec 2008 12:34:20 -0500 X-Greylist: delayed 380 seconds by postgrey-1.27 at vger.kernel.org; Wed, 17 Dec 2008 12:34:19 EST Date: Wed, 17 Dec 2008 09:27:58 -0800 From: Deepak Saxena To: Ingo Molnar , Thomas Gleixner , Steven Rostedt Cc: linux-kernel@vger.kernel.org Subject: TSC not updating after resume: Bug or Feature? Message-ID: <20081217172758.GA6010@trantor.hsd1.or.comcast.net> Reply-To: dsaxena@plexity.net MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Organization: Plexity Networks User-Agent: Mutt/1.5.18 (2008-05-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.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 -0 [00] 154.925216: _spin_unlock_irq <-finish_task_switch -0 [00] 154.925216: tick_nohz_stop_sched_tick <-cpu_idle -0 [00] 154.925216: ktime_get <-tick_nohz_stop_sched_tick -0 [00] 154.925216: ktime_get_ts <-ktime_get -0 [00] 154.925216: getnstimeofday <-ktime_get_ts -0 [00] 154.925216: set_normalized_timespec <-ktime_get_ts -0 [00] 154.925216: get_next_timer_interrupt <-tick_nohz_stop_sched_tick -0 [00] 154.925216: _spin_lock <-get_next_timer_interrupt -0 [00] 154.925216: _spin_unlock <-get_next_timer_interrupt -0 [00] 154.925216: hrtimer_get_next_event <-get_next_timer_interrupt -0 [00] 154.925216: _spin_lock_irqsave <-hrtimer_get_next_event -0 [00] 154.925216: _spin_unlock_irqrestore <-hrtimer_get_next_event -0 [00] 154.925216: rcu_needs_cpu <-tick_nohz_stop_sched_tick -0 [00] 154.925216: rcu_pending <-rcu_needs_cpu -0 [00] 154.925216: __rcu_pending <-rcu_pending -0 [00] 154.925216: __rcu_pending <-rcu_pending -0 [00] 154.925216: rcu_pending <-cpu_idle -0 [00] 154.925216: __rcu_pending <-rcu_pending -0 [00] 154.925216: __rcu_pending <-rcu_pending -0 [00] 154.925216: default_idle <-cpu_idle -0 [00] 154.925216: do_IRQ <-common_interrupt -0 [00] 154.925216: irq_enter <-do_IRQ -0 [00] 154.925216: tick_nohz_stop_idle <-irq_enter -0 [00] 154.925216: ktime_get <-tick_nohz_stop_idle -0 [00] 154.925216: ktime_get_ts <-ktime_get -0 [00] 154.925216: getnstimeofday <-ktime_get_ts -0 [00] 154.925216: set_normalized_timespec <-ktime_get_ts -0 [00] 154.925216: ktime_get <-sched_clock_tick -0 [00] 154.925216: ktime_get_ts <-ktime_get -0 [00] 154.925216: getnstimeofday <-ktime_get_ts -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? -0 [00] 154.929837: touch_softlockup_watchdog <-sched_clock_idle_wakeup_event -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_/_ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -- 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/