* Ingo Molnar <mingo@xxxxxxx> wrote: > so here's an UP suspend+resume trace i did: > > http://redhat.com/~mingo/latency-tracing-patches/misc/trace-suspend-long.txt.bz2 > > tons of detail - which might be interesting to other folks as well. > Fact is, our suspend-to-RAM+resume cycle is very, very slow, even on > fast hardware - and this trace shows all the reasons why. > > This was a fully cached system - i.e. i've done a suspend+resume > before to warm up the caches. (not that suspend+resume does much IO > normally.) > > The trace shows that a suspend+resume cycle is 7.95 seconds long > (without counting the time the box spent suspended) - ouch! This was a > T60 with Core2Duo 1.83GHz. and the amount of time spent executing on the CPU was only 70 msecs! So we spent 99% of that 7.9 seconds with just waiting around. Here are the top 10 sleep reasons: 864 schedule()<-schedule_timeout()<-ps2_sendbyte()<-ps2_command() 183 schedule()<-vt_waitactive()<-vt_ioctl()<-tty_ioctl() 164 schedule()<-schedule_timeout()<-acpi_ec_wait()<-acpi_ec_transaction() 157 schedule()<-refrigerator()<-get_signal_to_deliver()<-do_notify_resume() 118 schedule()<-worker_thread()<-kthread()<-kernel_thread_helper() 80 schedule()<-do_msleep()<-msleep()<-sata_link_debounce() 64 schedule()<-schedule_timeout()<-inet_csk_accept()<-inet_accept() 37 schedule()<-__mutex_lock_slowpath()<-mutex_lock()<-acpi_ec_transaction() 20 schedule()<-schedule_timeout()<-do_select()<-core_sys_select() 20 schedule()<-io_schedule()<-sync_buffer()<-__wait_on_bit() what's weird are all those ps2 related sleeps - they make up for much of the delay. This how such a sleep point looks like: bash 3500 0D... 8641415us : schedule()<-schedule_timeout()<-ps2_sendbyte()<-ps2_command() bash 3500 0D... 8641417us : psmouse_sliced_command()<-synaptics_pt_write()<-ps2_sendbyte()<-ps2_command() it starts somewhere here: bash 3500 0.... 5302376us : serio_reconnect_driver (serio_resume) and ends: kseriod 208 0D... 9182560us : synaptics_query_hardware()<-synaptics_reconnect()<-psmouse_reconnect()<-serio_reconnect_driver() so this section (serio_resume()) took almost 4 seconds. the main delay seems to be dpm_resume(): bash 3500 0.N.. 3061040us : dpm_resume (device_resume) ... bash 3500 0.... 9105017us : mutex_unlock (dpm_resume) bash 3500 0.... 9105018us : mutex_unlock (device_resume) 6.1 seconds! Ingo _______________________________________________ linux-pm mailing list linux-pm@xxxxxxxxxxxxxxxxxxxxxxxxxx https://lists.linux-foundation.org/mailman/listinfo/linux-pm
