[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20071116124319.GA21978@elte.hu>
Date: Fri, 16 Nov 2007 13:43:19 +0100
From: Ingo Molnar <mingo@...e.hu>
To: Mark Lord <lkml@....ca>
Cc: Pavel Machek <pavel@....cz>, Mark Lord <liml@....ca>,
Thomas Gleixner <tglx@...utronix.de>, len.brown@...el.com,
Andrew Morton <akpm@...ux-foundation.org>,
linux-kernel@...r.kernel.org, linux-pm@...ts.linux-foundation.org,
rjw@...k.pl, Len Brown <lenb@...nel.org>
Subject: Re: [BUG] Strange 1-second pauses during Resume-from-RAM
* Ingo Molnar <mingo@...e.hu> 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
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists