New: [bisected] s2disk / hibernate blocks on "Saving 506031 image data pages () ..."

Bug 75101 Andrew Morton 4 participants 4 messages Apr 29, 2014 – May 5, 2014 1 message not in the archive Memory management

lore

Share & tools

lore

Andrew Morton

author maintainer

2014-04-29 22:24 UTC #1 lore raw

In reply to a message not in the archive

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Quoted 19 lines · On Tue, 29 Apr 2014 20:13:44 +0000 [email protected] wrote:

https://bugzilla.kernel.org/show_bug.cgi?id=75101
Bug ID: 75101
Summary: [bisected] s2disk / hibernate blocks on "Saving 506031
image data pages () ..."
Product: Memory Management
Version: 2.5
Kernel Version: v3.14
Hardware: All
OS: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: Other
Assignee: [email protected]
Reporter: [email protected]
Regression: No

Quoted 6 lines

Created attachment 134271
--> https://bugzilla.kernel.org/attachment.cgi?id=134271&action=edit
Full console trace with various SysRq outputs
Since v3.14 under normal desktop usage my s2disk/hibernate often blocks on the saving of the image data ("Saving 506031 image data pages () ...").

A means to reproduce as well as a bisection result. Nice! Thanks.

Johannes, could you please take a look?

Quoted 37 lines

With following test I can reproduce the problem reliably:
---
0) Boot
1) Fill ram with 2GiB (+50% in my case)
mount -t tmpfs tmpfs /media/test/
dd if=/dev/zero of=/media/test/test0.bin bs=1k count=$[1024*1024] dd if=/dev/zero of=/media/test/test1.bin bs=1k count=$[1024*1024]
2) Do s2disk
s2disk
---
s2disk: Unable to switch virtual terminals, using the current console.
s2disk: Snapshotting system
s2disk: System snapshot ready. Preparing to write
s2disk: Image size: 2024124 kilobytes
s2disk: Free swap: 3791208 kilobytes
s2disk: Saving 506031 image data pages (press backspace to abort) ... 0%
#Problem>: ... there is stays and blocks. SysRq still responds, so that I could trigger various debug outputs.
---
I've bisected this to following commit:
---
commit a1c3bfb2f67ef766de03f1f56bdfff9c8595ab14 (HEAD, refs/bisect/bad)
Author: Johannes Weiner <[email protected]>
Date:   Wed Jan 29 14:05:41 2014 -0800
mm/page-writeback.c: do not count anon pages as dirtyable memory
[...]
---

Quoted 8 lines

Reverting a1c3bfb2 fixes s2disk for me again - so basically I'm ok ;). But maybe there is still another better solution.
Attached is a full console trace with various SysRq outputs, possibly useful for analyzing.
BR, Oliver

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Johannes Weiner

2014-05-05 15:35 UTC #2 lore raw

Hi,

Quoted 29 lines · Andrew Morton

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).
Quoted 23 lines · On Tue, 29 Apr 2014 20:13:44 +0000 [email protected] wrote:
https://bugzilla.kernel.org/show_bug.cgi?id=75101
Bug ID: 75101
Summary: [bisected] s2disk / hibernate blocks on "Saving 506031
image data pages () ..."
Product: Memory Management
Version: 2.5
Kernel Version: v3.14
Hardware: All
OS: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: Other
Assignee: [email protected]
Reporter: [email protected]
Regression: No
Created attachment 134271
--> https://bugzilla.kernel.org/attachment.cgi?id=134271&action=edit
Full console trace with various SysRq outputs

Quoted 31 lines

Quoted 2 lines
Since v3.14 under normal desktop usage my s2disk/hibernate often blocks on the saving of the image data ("Saving 506031 image data pages () ...").
A means to reproduce as well as a bisection result. Nice! Thanks.
Johannes, could you please take a look?
Quoted 24 lines
With following test I can reproduce the problem reliably:
---
0) Boot
1) Fill ram with 2GiB (+50% in my case)
mount -t tmpfs tmpfs /media/test/
dd if=/dev/zero of=/media/test/test0.bin bs=1k count=$[1024*1024] dd if=/dev/zero of=/media/test/test1.bin bs=1k count=$[1024*1024]
2) Do s2disk
s2disk
---
s2disk: Unable to switch virtual terminals, using the current console.
s2disk: Snapshotting system
s2disk: System snapshot ready. Preparing to write
s2disk: Image size: 2024124 kilobytes
s2disk: Free swap: 3791208 kilobytes
s2disk: Saving 506031 image data pages (press backspace to abort) ... 0%
#Problem>: ... there is stays and blocks. SysRq still responds, so that I could trigger various debug outputs.

According to your dmesg s2disk is stuck in balance_dirty_pages():

[  215.645240] s2disk          D ffff88011fd93100     0  3323   3261 0x00000000
[  215.645240]  ffff8801196d4110 0000000000000082 0000000000013100 ffff8801196d4110
[  215.645240]  ffff8800365cdfd8 ffff880119ed9190 00000000ffffc16c ffff8800365cdbe8
[  215.645240]  0000000000000032 0000000000000032 ffff8801196d4110 0000000000000000
[  215.645240] Call Trace:
[  215.645240]  [<ffffffff8162fdce>] ? schedule_timeout+0xde/0xff
[  215.645240]  [<ffffffff81041be1>] ? ftrace_raw_output_tick_stop+0x55/0x55
[  215.645240]  [<ffffffff81630987>] ? io_schedule_timeout+0x5d/0x7e
[  215.645240]  [<ffffffff810cb035>] ? balance_dirty_pages_ratelimited+0x588/0x747
[  215.645240]  [<ffffffff812d0795>] ? radix_tree_tag_set+0x69/0xc4
[  215.645240]  [<ffffffff810c244e>] ? generic_file_buffered_write+0x1a8/0x21c
[  215.645240]  [<ffffffff810c351e>] ? __generic_file_aio_write+0x1c7/0x1fe
[  215.645240]  [<ffffffff81134ab5>] ? blkdev_aio_write+0x44/0x79
[  215.645240]  [<ffffffff8110c02a>] ? do_sync_write+0x56/0x76
[  215.645240]  [<ffffffff8110c33c>] ? vfs_write+0xa1/0xfb
[  215.645240]  [<ffffffff8110ca08>] ? SyS_write+0x41/0x74
[  215.645240]  [<ffffffff81637622>] ? system_call_fastpath+0x16/0x1b

but I don't see a flusher thread anywhere.

What the bisected change does is allow the effective dirty threshold to drop fairly low, because anonymous pages are no longer considered dirtyable, and your usecase has particularly low free + cache pages:

[  196.375988] active_anon:328150 inactive_anon:118571 isolated_anon:0
[  196.375988]  active_file:1658 inactive_file:1823 isolated_file:0
[  196.375988]  unevictable:867 dirty:616 writeback:0 unstable:0
[  196.375988]  free:32320 slab_reclaimable:5129 slab_unreclaimable:5080
[  196.375988]  mapped:2684 shmem:424844 pagetables:1528 bounce:0
[  196.375988]  free_cma:0

Ignoring free pages due to dirty_balance_reserve, inactive+active file yields 3481 dirtyable pages, which sets the global limits to 174 pages background and 348 pages foreground with the default configuration. It's low, but not 0. So why is the dirtier throttled to starvation when the background flusher is not even running? Shouldn't they be looking at the same numbers and behave inversely?

I'll dive into the writeback and throttling code, but also Ccing Maxim, Jan, and Fengguang. Maybe they have a faster answer.

Thanks for the report!

Jan Kara

2014-05-05 16:10 UTC #3 lore raw

Hello,

Quoted 94 lines · Johannes Weiner

Quoted 28 lines · Andrew Morton
(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).
Quoted 23 lines · On Tue, 29 Apr 2014 20:13:44 +0000 [email protected] wrote:
https://bugzilla.kernel.org/show_bug.cgi?id=75101
Bug ID: 75101
Summary: [bisected] s2disk / hibernate blocks on "Saving 506031
image data pages () ..."
Product: Memory Management
Version: 2.5
Kernel Version: v3.14
Hardware: All
OS: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: Other
Assignee: [email protected]
Reporter: [email protected]
Regression: No
Created attachment 134271
--> https://bugzilla.kernel.org/attachment.cgi?id=134271&action=edit
Full console trace with various SysRq outputs
Quoted 31 lines
Quoted 2 lines
Since v3.14 under normal desktop usage my s2disk/hibernate often blocks on the saving of the image data ("Saving 506031 image data pages () ...").
A means to reproduce as well as a bisection result. Nice! Thanks.
Johannes, could you please take a look?
Quoted 24 lines
With following test I can reproduce the problem reliably:
---
0) Boot
1) Fill ram with 2GiB (+50% in my case)
mount -t tmpfs tmpfs /media/test/
dd if=/dev/zero of=/media/test/test0.bin bs=1k count=$[1024*1024] dd if=/dev/zero of=/media/test/test1.bin bs=1k count=$[1024*1024]
2) Do s2disk
s2disk
---
s2disk: Unable to switch virtual terminals, using the current console.
s2disk: Snapshotting system
s2disk: System snapshot ready. Preparing to write
s2disk: Image size: 2024124 kilobytes
s2disk: Free swap: 3791208 kilobytes
s2disk: Saving 506031 image data pages (press backspace to abort) ... 0%
#Problem>: ... there is stays and blocks. SysRq still responds, so that I could trigger various debug outputs.
According to your dmesg s2disk is stuck in balance_dirty_pages():
[  215.645240] s2disk          D ffff88011fd93100     0  3323   3261 0x00000000
[  215.645240]  ffff8801196d4110 0000000000000082 0000000000013100 ffff8801196d4110
[  215.645240]  ffff8800365cdfd8 ffff880119ed9190 00000000ffffc16c ffff8800365cdbe8
[  215.645240]  0000000000000032 0000000000000032 ffff8801196d4110 0000000000000000
[  215.645240] Call Trace:
[  215.645240]  [<ffffffff8162fdce>] ? schedule_timeout+0xde/0xff
[  215.645240]  [<ffffffff81041be1>] ? ftrace_raw_output_tick_stop+0x55/0x55
[  215.645240]  [<ffffffff81630987>] ? io_schedule_timeout+0x5d/0x7e
[  215.645240]  [<ffffffff810cb035>] ? balance_dirty_pages_ratelimited+0x588/0x747
[  215.645240]  [<ffffffff812d0795>] ? radix_tree_tag_set+0x69/0xc4
[  215.645240]  [<ffffffff810c244e>] ? generic_file_buffered_write+0x1a8/0x21c
[  215.645240]  [<ffffffff810c351e>] ? __generic_file_aio_write+0x1c7/0x1fe
[  215.645240]  [<ffffffff81134ab5>] ? blkdev_aio_write+0x44/0x79
[  215.645240]  [<ffffffff8110c02a>] ? do_sync_write+0x56/0x76
[  215.645240]  [<ffffffff8110c33c>] ? vfs_write+0xa1/0xfb
[  215.645240]  [<ffffffff8110ca08>] ? SyS_write+0x41/0x74
[  215.645240]  [<ffffffff81637622>] ? system_call_fastpath+0x16/0x1b
but I don't see a flusher thread anywhere.
What the bisected change does is allow the effective dirty threshold to drop fairly low, because anonymous pages are no longer considered dirtyable, and your usecase has particularly low free + cache pages:
[  196.375988] active_anon:328150 inactive_anon:118571 isolated_anon:0
[  196.375988]  active_file:1658 inactive_file:1823 isolated_file:0
[  196.375988]  unevictable:867 dirty:616 writeback:0 unstable:0
[  196.375988]  free:32320 slab_reclaimable:5129 slab_unreclaimable:5080
[  196.375988]  mapped:2684 shmem:424844 pagetables:1528 bounce:0
[  196.375988]  free_cma:0

Quoted 4 lines

Ignoring free pages due to dirty_balance_reserve, inactive+active file yields 3481 dirtyable pages, which sets the global limits to 174 pages background and 348 pages foreground with the default configuration. It's low, but not 0.

OK, so we are over the dirty_limit.

Quoted 3 lines

So why is the dirtier throttled to starvation when the background flusher is not even running? Shouldn't they be looking at the same numbers and behave inversely?

These days there isn't a background flusher thread but a workqueue which
handles the flushing work. But still you should see that in a process list like "flush-$dev". Can you check whether balance_dirty_pages() properly calls bdi_start_background_writeback() and whether wb_do_writeback() gets to run (there are tracepoints in there)? Also can you have a look in /sys/kernel/debug/bdi/<dev>/stats? What is the estimated bandwith?

Honza

Signature · 8 lines

Jan Kara <[email protected]>
SUSE Labs, CR

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to [email protected].  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Oliver Winker

2014-05-05 21:05 UTC #4 lore raw

Hello,

1) Attached a full function-trace log + other SysRq outputs, see [1] attached.

I saw bdi_...() calls in the s2disk paths, but didn't check in detail Probably more efficient when one of you guys looks directly.

2) /sys/kernel/debug/bdi/<dev>/stats

They are also in [1] - however the major/minors of my sdbX didn't match with the /sys/.../bdi/<dev>'s. So I just displayed them all.

3) What is the estimated bandwith?

It's an Samsung SSD 840 PRO, in this system: Read: 237 MB/s, Write 265 MB/s - see [2] (the faster writing is maybe due caching?)

Just by curiosity:

Can you also reproduce it ? ... since the test is quite simple. Or is it something specific in my system here ?

BR, Oliver

---

[1] Attached session.log.s2disk.20140505_2238.bz2
- 18MiB uncompressed function-trace output + others
- The bdi outputs are also in there

[2] Rough bandwidth tests
Read:
---

gamix64:~# swapon -s 
Filename                                Type            Size    Used    Priority
/dev/sdb7                               partition       4193276 0       -1
gamix64:~# dd if=/dev/sdb7 bs=1024 count=$[1024*1024*4] |pv >/dev/null
   4GB 0:00:18 [ 226MB/s] [                                                     <=>                                                                                        ]4193280+0 records in
4193280+0 records out

4293918720 bytes (4.3 GB) copied, 18.1509 s, 237 MB/s
---

Write:
---

gamix64:~# dd if=/dev/zero bs=1024 count=$[1024*1024*4] |pv >/root/Test/test1.bin
4194304+0 records inMB/s] [                                          <=>                                                                                                   ]
4194304+0 records out
4294967296 bytes (4.3 GB) copied, 16.2039 s, 265 MB/s
   4GB 0:00:15 [ 256MB/s] [                                             <=>                                                                                                ]
---

Quoted 18 lines · On Mon, 5 May 2014 18:10:53 +0200 Jan Kara <[email protected]> wrote:

Quoted 4 lines
Ignoring free pages due to dirty_balance_reserve, inactive+active file yields 3481 dirtyable pages, which sets the global limits to 174 pages background and 348 pages foreground with the default configuration. It's low, but not 0.
OK, so we are over the dirty_limit.
Quoted 3 lines
So why is the dirtier throttled to starvation when the background flusher is not even running? Shouldn't they be looking at the same numbers and behave inversely?
These days there isn't a background flusher thread but a workqueue
which handles the flushing work. But still you should see that in a process list like "flush-$dev". Can you check whether balance_dirty_pages() properly calls bdi_start_background_writeback() and whether wb_do_writeback() gets to run (there are tracepoints in there)? Also can you have a look
in /sys/kernel/debug/bdi/<dev>/stats? What is the estimated bandwith?
Honza