Solution to various issues on resume resulting from WARN_ON in suspend_test_finish() ?

[TJ]

On Fri, 2009-02-27 at 15:19 +0100, Stefan Bader wrote:
> This is something that we should consider. It a bit of a nutshell. 5s can feel 
> long already when returning from suspend. On the other hand is this showing up 
> as a crash a bit overreacting. Do you have an overview what the most common or 
> maximum time would be? Another possible solution would be to replace that WARN 
> by a simple printk(WARN, ...).

The reason I didn't suggest a printk is the commentary in
kernel/power/main.c::suspend_test_finish():

	 * Warning on either suspend or resume also means the system
	 * has some performance issues.  The stack dump of a WARN_ON
	 * is more likely to get the right attention than a printk...
	 */

I've posted a bit of shell script to a couple of bug reports so far that
will help gather information on the typical resume times.

Maybe other dev's could use this in bug reports you are looking at to
request information so we can make a determination?

for log in /var/log/kern.log*; do CMD="cat "; echo $log; \
 [ ! ${log##*.gz} ] && CMD="zcat "; \
 $CMD $log | grep -n 'PM: \(suspend\|resume\) devices took'; done

Example output:

var/log/kern.log
/var/log/kern.log.0
3678:Feb 19 06:06:56 hephaestion kernel: [60285.296215] PM: suspend devices took 3.752 seconds
3830:Feb 19 06:06:57 hephaestion kernel: [60354.780958] PM: resume devices took 69.072 seconds
3948:Feb 19 10:19:23 hephaestion kernel: [75478.752211] PM: suspend devices took 3.752 seconds
4102:Feb 19 10:19:23 hephaestion kernel: [75488.172580] PM: resume devices took 9.024 seconds
/var/log/kern.log.1.gz
/var/log/kern.log.2.gz
/var/log/kern.log.3.gz

The resume of 69 seconds shows this system is affected by bug #331415