Re: Fixed at last!

Milan Oravec <[email protected]> Wed, 06 Jun 2012 11:18:22 +0200
Newsgroups gmane.linux.swsusp.devel
Organization CIKT UKF Nitra
Message-ID <[email protected]>
Hi Nigel, it is still the same problem. I have set: echo "10" > 
/sys/power/tuxonice/image_size_limit

First time (fresh booted system, no apps running) hibernation suspends 
(after some memory seeking) and resumes OK.
I've run firefox with 10 tabs and try to suspend again with no success:

....

PM: restore of devices complete after 852.021 msecs
Restarting tasks ... Restarting kernel threads ... done.
done.
TuxOnIce debugging info:
- TuxOnIce core  : 3.2.1
- Kernel Version : 3.4.0+
- Compiler vers. : 4.6
- Attempt number : 1
- Parameters     : 0 667656 0 1 10 0
- Overall expected compression percentage: 0.
- Compressor is 'lzo'.
   Compressed 666112000 bytes into 230715040 (65 percent compression).
- Block I/O active.
   Used 56822 pages from swap on /dev/sda1.
- Max outstanding reads 1. Max writes 0.
   Memory_needed: 1024 x (4096 + 232 + 72) = 4505600 bytes.
   Free mem throttle point reached 0.
- Swap Allocator enabled.
   Swap available for image: 975939 pages.
- I/O speed: Write 38 MB/s, Read 97 MB/s.
- Extra pages    : 45 used/2000.
- Result         : Succeeded.
sky2: driver version 1.30
sky2 0000:07:00.0: Yukon-2 FE chip revision 1
sky2 0000:07:00.0: irq 45 for MSI/MSI-X
sky2 0000:07:00.0: eth0: addr 00:13:a9:40:ba:61
sky2 0000:07:00.0: eth0: enabling interface
Bluetooth: HIDP (Human Interface Emulation) ver 1.2
sky2 0000:07:00.0: eth0: Link is up at 100 Mbps, full duplex, flow control
rx
sky2 0000:07:00.0: eth0: disabling interface
TuxOnIce 3.2.1, with support for usm, compression, block i/o, swap
storage, userui.
Initiating a hibernation cycle.
Starting other threads.Freezing user space processes ... (elapsed 0.02
seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Restarting kernel threads ... done.
Asked shrink_all_memory for 210924 low pages & 0 pages from anywhere, got
0.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Restarting kernel threads ... done.
Freezing remaining freezable tasks ...
Freezing of tasks failed after 20.00 seconds (1 tasks refusing to freeze,
wq_busy=0):
flush-8:0       R running      0   267      2 0x00000000
  029bc9e9 03018798 00000041 03018798 00000041 00000003 03346198 00000041
  00000046 f4efa000 00000092 00000000 00000006 f4efb93c 00000000 00000000
  00000040 c1777140 f4efb9c0 c10bad69 f4efb9b0 00000040 ffffffff 00000001
Call Trace:
  [<c10c2fb6>] ? try_to_free_pages+0x76/0x80
  [<c1046760>] ? add_wait_queue+0x50/0x50
  [<c10bb498>] ? __alloc_pages_nodemask+0x548/0x6f0
  [<c10b4c23>] ? find_or_create_page+0x43/0x90
  [<c1197c9e>] ? ext4_mb_init_group+0x5e/0x170
  [<c1197e68>] ? ext4_mb_good_group+0xb8/0x110
  [<c1199d72>] ? ext4_mb_regular_allocator+0x162/0x3d0
  [<c1195542>] ? ext4_mb_use_preallocated+0xd2/0x2b0
  [<c119b7ca>] ? ext4_mb_new_blocks+0x36a/0x480
  [<c118e9f5>] ? ext4_ext_find_goal+0xa5/0xb0
  [<c1191ea4>] ? ext4_ext_map_blocks+0xb54/0x19a0
  [<c12e2863>] ? drive_stat_acct+0xb3/0x180
  [<c12e551f>] ? blk_queue_bio+0xdf/0x2e0
  [<c12e4923>] ? generic_make_request+0x93/0xc0
  [<c117e159>] ? ext4_io_submit+0x29/0x50
  [<c1179f64>] ? mpage_da_submit_io+0x344/0x540
  [<c117846b>] ? ext4_map_blocks+0x1cb/0x380
  [<c10b4d44>] ? find_get_pages_tag+0xd4/0x180
  [<c117c1be>] ? mpage_da_map_and_submit+0xae/0x620
  [<c117c92d>] ? write_cache_pages_da+0x10d/0x3e0
  [<c117cec1>] ? ext4_da_writepages+0x2c1/0x490
  [<c10bd44d>] ? do_writepages+0x1d/0x30
  [<c111558b>] ? writeback_single_inode+0xcb/0x250
  [<c110acdf>] ? iput+0x2f/0x1c0
  [<c1115866>] ? writeback_sb_inodes+0x156/0x1f0
  [<c111597c>] ? __writeback_inodes_wb+0x7c/0xb0
  [<c1115cf9>] ? wb_writeback+0x1a9/0x1b0
  [<c10bc55c>] ? global_dirty_limits+0x2c/0xd0
  [<c1116290>] ? wb_do_writeback+0x120/0x1b0
  [<c1116371>] ? bdi_writeback_thread+0x51/0x100
  [<c1116320>] ? wb_do_writeback+0x1b0/0x1b0
  [<c1045fed>] ? kthread+0x6d/0x80
  [<c1045f80>] ? kthread_freezable_should_stop+0x50/0x50
  [<c15b14fe>] ? kernel_thread_helper+0x6/0xd

Restarting kernel threads ... done.
Restarting tasks ... Restarting kernel threads ... done.
done.
sky2: driver version 1.30
sky2 0000:07:00.0: Yukon-2 FE chip revision 1
sky2 0000:07:00.0: irq 45 for MSI/MSI-X
sky2 0000:07:00.0: eth0: addr 00:13:a9:40:ba:61
sky2 0000:07:00.0: eth0: enabling interface
sky2 0000:07:00.0: eth0: Link is up at 100 Mbps, full duplex, flow control
rx
sky2 0000:07:00.0: eth0: disabling interface
TuxOnIce 3.2.1, with support for usm, compression, block i/o, swap
storage, userui.
Initiating a hibernation cycle.
Starting other threads.Freezing user space processes ... (elapsed 0.01
seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Restarting kernel threads ... done.
Asked shrink_all_memory for 205307 low pages & 0 pages from anywhere, got
0.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Restarting kernel threads ... done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Restarting kernel threads ... done.
Asked shrink_all_memory for 205307 low pages & 0 pages from anywhere, got
0.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Restarting kernel threads ... done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Failed to allocate a page buffer for TuxOnIce compression driver.
Failed to initialise compression algorithm.
Continuing without compressing the image.
Waited for i/o due to synchronous I/O 4 times.
Restarting tasks ... Restarting kernel threads ... done.
done.
sky2: driver version 1.30
sky2 0000:07:00.0: Yukon-2 FE chip revision 1
sky2 0000:07:00.0: irq 45 for MSI/MSI-X
sky2 0000:07:00.0: eth0: addr 00:13:a9:40:ba:61
sky2 0000:07:00.0: eth0: enabling interface
sky2 0000:07:00.0: eth0: Link is up at 100 Mbps, full duplex, flow control
rx
root@migo-laptop:/home/migo#

....

I've tried to reproduce this with success:

I fresh booted the system, set image size again and run firefox, than 
run hibernate command form shell.

TOI_userui_text shows: Failed to initialise the allocator. (Press ...)



Is it helpful for debugging?

Many thanx for your great work!

Greetings from Slovakia,

Milan




S pozdravom

Milan Oravec

CIKT UKF Nitra
Mobil: +421907670270
email: [email protected]

On 06/05/2012 12:17 PM, Nigel Cunningham wrote:
> Hi.
>
> On 05/06/12 17:30, Milan Oravec wrote:
>> Hi Harald, I'll look for those steps, but I don't have any experience
>> with code bisecting.
>>
>> I thing problematic commit was introduced later (not 3.2-rc6 and
>> 3.2-rc8), somewhere in 3.3 development phase, because all 3.2.xx
>> kernel are working fine.
>>
>> - TuxOnIce core : 3.2.1
>> - Kernel Version : 3.2.10-05355-gf5dcb59
>> - Compiler vers. : 4.4
>> - Attempt number : 63
>> - Parameters : 0 667648 0 0 -2 5
>> - Overall expected compression percentage: 0.
>> - Compressor is 'lzo'.
>> Compressed 2506092544 bytes into 775863186 (69 percent compression).
>> - Block I/O active.
>> Used 192288 pages from swap on /dev/sda3.
>> - Max outstanding reads 3284. Max writes 1797.
>> Memory_needed: 1024 x (4096 + 368 + 112) = 4685824 bytes.
>> Free mem throttle point reached 0.
>> - Swap Allocator enabled.
>> Swap available for image: 776990 pages.
>> - I/O speed: Write 211 MB/s, Read 302 MB/s.
>> - Extra pages : 42 used/2000.
>> - Result : Succeeded.
>>
>> 09:23:11 up 83 days, 20:12, 15 users, load average: 2.35, 0.82, 0.39
>>
>>
> This is the problem you reported on 21 May? If I set the image size
> limit to (say) 10MB, would that be enough to reproduce it?
>
> Regards,
>
> Nigel
>
>