profiling the resume path

[Marcelo Tosatti]

On Wed, Aug 29, 2007 at 09:25:28AM -0400, Marcelo Tosatti wrote:
> On Wed, Aug 29, 2007 at 02:07:55PM +0100, David Woodhouse wrote:
> > On Wed, 2007-08-29 at 08:31 -0400, Marcelo Tosatti wrote:
> > > What you think is the easier/proper way to postpone this console work
> > > to happen after the resume process is finished?
> > 
> > It's spending all its time waiting for characters to be sent out a
> > serial port which isn't even going to have anything attached to it?
> > 
> > Have you considered dropping 'console=ttyS0' from the kernel command
> > line? :)
> 
> That should do it, thanks :)

Note: ohci_pci_resume does msleep 20.

Resolution is second.microsecond. This was gathered using infrastructure
from the latency trace patches (thanks Arnaldo). The timing code is
similar to CONFIG_PRINTK_TIME.

[    0.040881] ohci_pci_resume+0x73/0x8a -> msleep+0xb/0x27
[    0.040881] msleep+0x16/0x27 -> msecs_to_jiffies+0x8/0x16
[    0.040883] msleep+0x21/0x27 -> schedule_timeout_uninterruptible+0x8/0x1d
[    0.040884] schedule_timeout_uninterruptible+0x1b/0x1d -> schedule_timeout+0xd/0x97
[    0.040885] schedule_timeout+0x65/0x97 -> init_timer+0x9/0x37
[    0.040886] schedule_timeout+0x71/0x97 -> __mod_timer+0xe/0xb4
[    0.040886] __mod_timer+0x20/0xb4 -> __timer_stats_timer_set_start_info+0xa/0x3e
[    0.040887] __mod_timer+0x39/0xb4 -> lock_timer_base+0xb/0x3d
[    0.040888] lock_timer_base+0x1f/0x3d -> _spin_lock_irqsave+0xd/0x2b
[    0.040889] _spin_lock_irqsave+0x24/0x2b -> _raw_spin_lock+0xe/0x10e
[    0.040890] __mod_timer+0x9f/0xb4 -> internal_add_timer+0xd/0xa4
[    0.040891] internal_add_timer+0x9d/0xa4 -> __list_add+0xd/0x6c
[    0.040892] __mod_timer+0xa9/0xb4 -> _spin_unlock_irqrestore+0xc/0x39
[    0.040893] _spin_unlock_irqrestore+0x16/0x39 -> _raw_spin_unlock+0xc/0x87
[    0.040894] schedule_timeout+0x76/0x97 -> __sched_text_start+0xe/0x82c
[    0.040895] __sched_text_start+0xc8/0x82c -> sched_clock+0xa/0x58
[    0.040896] __sched_text_start+0x149/0x82c -> _spin_lock_irq+0xc/0x25
[    0.040897] _spin_lock_irq+0x21/0x25 -> _raw_spin_lock+0xe/0x10e
[    0.040898] __sched_text_start+0x1dc/0x82c -> __deactivate_task+0xc/0x36
[    0.040898] __deactivate_task+0x2a/0x36 -> dequeue_task+0xd/0x3e
[    0.040899] dequeue_task+0x2a/0x3e -> list_del+0xc/0x69
[    0.040902] __sched_text_start+0x771/0x82c -> __switch_to+0xe/0x12c
[    0.040904] __sched_text_start+0x79c/0x82c -> _spin_unlock_irq+0xb/0x33
[    0.040905] _spin_unlock_irq+0x13/0x33 -> _raw_spin_unlock+0xc/0x87
[    0.040907] cpu_idle+0x1d/0x7c -> tick_nohz_stop_sched_tick+0xe/0x265
[    0.040909] cpu_idle+0x2e/0x7c -> check_pgt_cache+0xb/0x31
[    0.000000] check_pgt_cache+0x2f/0x31 -> quicklist_trim+0xe/0xe5
[    0.040912] cpu_idle+0x4e/0x7c -> default_idle+0x8/0x43
[    0.233593] do_IRQ+0x45/0xdb -> irq_enter+0xb/0x2d
[    0.233594] irq_enter+0x22/0x2d -> idle_cpu+0x8/0x1b
[    0.233595] irq_enter+0x2b/0x2d -> tick_nohz_update_jiffies+0xc/0x49
[    0.233596] do_IRQ+0xb0/0xdb -> handle_level_irq+0xe/0xe3
[    0.233597] handle_level_irq+0x22/0xe3 -> _spin_lock+0xc/0x24

This is with HZ=1000 and PIT (MFGPT is similar). Disabling CONFIG_NO_HZ
didnt help. Any clues?