profiling the resume path

[Marcelo Tosatti]

On Mon, Sep 03, 2007 at 12:40:43PM +0100, David Woodhouse wrote:
> On Mon, 2007-09-03 at 09:27 +0100, David Woodhouse wrote:
> > On Mon, 2007-09-03 at 04:05 -0400, Marcelo Tosatti wrote:
> > > > This interrupt scheduled for 233-40ms is what sounds wrong. It should
> > > > just continue to blaze off the EHCI resume path.
> > > 
> > > ... after 20ms have passed, not almost 200. 
> > 
> > Ah, right. Sorry, I missed the order of magnitude discrepancy. Are we
> > just miscalculating the setting of the wakeup interrupt? More debugging
> > of that calculation might be in order...
> 
> Can you comment out the 'if(tbase_get_deferrable(nte->base)) continue;'
> in __next_timer_interrupt() at about line 678 of kernel/timer.c ?

Actually with CONFIG_NO_HZ disabled what happens is:

[    0.061390] ohci_pci_resume+0x73/0x8a -> msleep+0xb/0x27
[    0.061390] msleep+0x16/0x27 -> msecs_to_jiffies+0x8/0x16
[    0.061391] msleep+0x21/0x27 -> schedule_timeout_uninterruptible+0x8/0x1d
...
[    0.000000] _spin_unlock_irq+0x13/0x33 -> _raw_spin_unlock+0xc/0x87
[    0.077128] schedule_timeout+0x80/0x97 -> del_timer+0xd/0x62 [    0.077129] mmc_go_idle+0x89/0xa0 -> mmc_set_chip_select+0xb/0x2f
[    0.077129] mmc_set_chip_select+0x2d/0x2f -> sdhci_set_ios+0xe/0xac
[    0.077130] sdhci_set_ios+0x24/0xac -> _spin_lock_irqsave+0xd/0x2b
[    0.077131] _spin_lock_irqsave+0x24/0x2b -> _raw_spin_lock+0xe/0x10e
[    0.077132] sdhci_set_ios+0x4c/0xac -> sdhci_set_clock+0xe/0xb1

Meaning that the kernel continues after 16ms (77-61) when a sdhci timer
expires. Resume time goes down from 1060ms to 815ms without dynamic
ticks.

Your suggested change did not help.. I'll RTFS, thanks.