Dirty pages underflow on 3.14.23

Dirty pages underflow on 3.14.23

[Mikulas Patocka]

Hi

I would like to report a memory management bug where the dirty pages count 
underflowed.

It happened after some time that the Dirty pages count underflowed, as can 
be seen in /proc/meminfo. The underflow condition was persistent, 
/proc/meminfo was showing the big value even when the system was 
completely idle. The counter never returned to zero.

The system didn't crash, but it became very slow - because of the big 
value in the "Dirty" field, lazy writing was not working anymore, any 
process that created a dirty page triggered immediate writeback, which 
slowed down the system very much. The only fix was to reboot the machine.

The kernel version where this happened is 3.14.23. The kernel is compiled 
without SMP and with peemption. The system is single-core 32-bit x86.

The bug probably happened during git pull or apt-get update, though one 
can't be sure that these commands caused it.

I see that 3.14.24 containes some fix for underflow (commit 
6619741f17f541113a02c30f22a9ca22e32c9546, upstream commit 
abe5f972912d086c080be4bde67750630b6fb38b), but it doesn't seem that that 
commit fixes this condition. If you have a commit that could fix this, say 
it.

Mikulas


MemTotal:         253504 kB
MemFree:            6128 kB
MemAvailable:      54956 kB
Buffers:            1376 kB
Cached:            45284 kB
SwapCached:        40432 kB
Active:           105596 kB
Inactive:         111672 kB
Active(anon):      82772 kB
Inactive(anon):    88604 kB
Active(file):      22824 kB
Inactive(file):    23068 kB
Unevictable:           4 kB
Mlocked:               4 kB
SwapTotal:       4242896 kB
SwapFree:        4144248 kB
Dirty:          4294944344 kB
Writeback:             8 kB
AnonPages:        167484 kB
Mapped:             7808 kB
Shmem:               768 kB
Slab:              19072 kB
SReclaimable:      10448 kB
SUnreclaim:         8624 kB
KernelStack:        1136 kB
PageTables:         2032 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:     4369648 kB
Committed_AS:     398032 kB
VmallocTotal:     778184 kB
VmallocUsed:       38316 kB
VmallocChunk:     707540 kB
AnonHugePages:         0 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       4096 kB
DirectMap4k:       20416 kB
DirectMap4M:      241664 kB

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

Re: Dirty pages underflow on 3.14.23

[Johannes Weiner]

On Mon, Jan 05, 2015 at 06:05:59PM -0500, Mikulas Patocka wrote:
> Hi
> 
> I would like to report a memory management bug where the dirty pages count 
> underflowed.
> 
> It happened after some time that the Dirty pages count underflowed, as can 
> be seen in /proc/meminfo. The underflow condition was persistent, 
> /proc/meminfo was showing the big value even when the system was 
> completely idle. The counter never returned to zero.
> 
> The system didn't crash, but it became very slow - because of the big 
> value in the "Dirty" field, lazy writing was not working anymore, any 
> process that created a dirty page triggered immediate writeback, which 
> slowed down the system very much. The only fix was to reboot the machine.
> 
> The kernel version where this happened is 3.14.23. The kernel is compiled 
> without SMP and with peemption. The system is single-core 32-bit x86.
> 
> The bug probably happened during git pull or apt-get update, though one 
> can't be sure that these commands caused it.
> 
> I see that 3.14.24 containes some fix for underflow (commit 
> 6619741f17f541113a02c30f22a9ca22e32c9546, upstream commit 
> abe5f972912d086c080be4bde67750630b6fb38b), but it doesn't seem that that 
> commit fixes this condition. If you have a commit that could fix this, say 
> it.

That's an unrelated counter, but there is a known dirty underflow
problem that was addressed in 87a7e00b206a ("mm: protect
set_page_dirty() from ongoing truncation").  It should make it into
the stable kernels in the near future.  Can you reproduce this issue?

Thanks,
Johannes

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

Re: Dirty pages underflow on 3.14.23

[Mikulas Patocka]

On Tue, 6 Jan 2015, Johannes Weiner wrote:

> > The bug probably happened during git pull or apt-get update, though one 
> > can't be sure that these commands caused it.
> > 
> > I see that 3.14.24 containes some fix for underflow (commit 
> > 6619741f17f541113a02c30f22a9ca22e32c9546, upstream commit 
> > abe5f972912d086c080be4bde67750630b6fb38b), but it doesn't seem that that 
> > commit fixes this condition. If you have a commit that could fix this, say 
> > it.
> 
> That's an unrelated counter, but there is a known dirty underflow
> problem that was addressed in 87a7e00b206a ("mm: protect
> set_page_dirty() from ongoing truncation").  It should make it into
> the stable kernels in the near future.  Can you reproduce this issue?
> 
> Thanks,
> Johannes

I can't reprodce it. It happened just once.

That patch is supposed to fix an occasional underflow by a single page - 
while my meminfo showed underflow by 22952KiB (5738 pages).

Mikulas

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

Re: Dirty pages underflow on 3.14.23

[Simon Kirby]

On Mon, Jan 05, 2015 at 06:05:59PM -0500, Mikulas Patocka wrote:

> Hi
> 
> I would like to report a memory management bug where the dirty pages count 
> underflowed.

Hello!

I've been hitting this problem for a while now. I've seen it on:

3.12.9
3.14.4
3.16
3.16.6

When it occurs, /proc/vmstat shows nr_dirty values such as:

nr_dirty 4294967031 (3.12.9)
nr_dirty 4294967251 (3.16.6)

No other counters appear to be negative or have wrapped in 32 bits, and
/proc/meminfo is similar as with your report. See proc file copies and
.config here: http://0x.ca/sim/ref/3.16.6-blue/ (hosting box is this one)

> It happened after some time that the Dirty pages count underflowed, as can 
> be seen in /proc/meminfo. The underflow condition was persistent, 
> /proc/meminfo was showing the big value even when the system was 
> completely idle. The counter never returned to zero.
> 
> The system didn't crash, but it became very slow - because of the big 
> value in the "Dirty" field, lazy writing was not working anymore, any 
> process that created a dirty page triggered immediate writeback, which 
> slowed down the system very much. The only fix was to reboot the machine.

This is also the case with me, although each time it occurs it seems to
be when I'm running apt-get upgrade to apply updates. Today, it occurred
on 3.16.6 as I started an "apt-get update". It is still possible to dirty
new pages and make some progress, but it becomes unusably slow. It ends
up writing the same blocks forever (from blktrace | grep D);

 33,0    0     2776     1.220890482 20335  D   W 43765671 + 8 [kworker/u2:0]
 33,0    0     2783     1.221073198 20335  D   W 7439223 + 8 [kworker/u2:0]
 33,0    0     2791     1.224824452 20335  D   W 43765671 + 8 [kworker/u2:0]
 33,0    0     2800     1.232559686 20335  D   W 7439223 + 8 [kworker/u2:0]

> The kernel version where this happened is 3.14.23. The kernel is compiled 
> without SMP and with peemption. The system is single-core 32-bit x86.

Same. The only other oddity to note is that the IDE driver is still
enabled in my case; root is on /dev/md6 which is a RAID 1 of hde1, hdg1.

> I see that 3.14.24 containes some fix for underflow (commit 
> 6619741f17f541113a02c30f22a9ca22e32c9546, upstream commit 
> abe5f972912d086c080be4bde67750630b6fb38b), but it doesn't seem that that 
> commit fixes this condition. If you have a commit that could fix this, say 
> it.

That doesn't seem to have made it to 3.16.6, but it sounds like a
fairness thing more than a race fix. Vlastimil pointed at this as
possibly useful:

http://ozlabs.org/~akpm/mmots/broken-out/mm-protect-set_page_dirty-from-ongoing-truncation.patch

...but I can't reproduce this immediately. So far, I have to
forget about it for a while, then do an apt-get upgrade.

> MemTotal:         253504 kB

MemTotal:         639396 kB

640MB should be enough for anybody. :)

Hmm, just tried to shut it down as cleanly as possible with sysrq-s,
sysrq-u, and got:

SysRq : Emergency Sync
Emergency Sync complete
SysRq : Emergency Remount R/O
------------[ cut here ]------------
WARNING: CPU: 0 PID: 24535 at fs/ext3/inode.c:1590 ext3_ordered_writepage+0x7c/0x240()
Modules linked in: xt_recent ts_kmp xt_string nfnetlink_log e100 xt_hashlimit xt_state xt_REDIRECT nf_conntrack_ftp iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack [last unloaded: xt_recent]
CPU: 0 PID: 24535 Comm: kworker/u2:0 Not tainted 3.16.6-blue #51
Hardware name: MICRO-STAR INTERNATIONAL CO., LTD MS-6330/MS-6330, BIOS 6.00 PG 06/15/2001
Workqueue: writeback bdi_writeback_workfn (flush-9:6)
 00000000 00000000 dd3f5c70 c16091f1 dd3f5ca0 c103231b c17bf9ac 00000000
 00005fd7 c17e8a3b 00000636 c115db7c c115db7c e7c3d140 00000000 e4d673d0
 dd3f5cb0 c103235d 00000009 00000000 dd3f5cd8 c115db7c dd3f5cc8 c10fe13c
Call Trace:
 [<c16091f1>] dump_stack+0x16/0x18
 [<c103231b>] warn_slowpath_common+0x7b/0xa0
 [<c115db7c>] ? ext3_ordered_writepage+0x7c/0x240
 [<c115db7c>] ? ext3_ordered_writepage+0x7c/0x240
 [<c103235d>] warn_slowpath_null+0x1d/0x20
 [<c115db7c>] ext3_ordered_writepage+0x7c/0x240
 [<c10fe13c>] ? __set_page_dirty_buffers+0xc/0x90
 [<c10ad18b>] __writepage+0xb/0x30
 [<c10ad180>] ? mapping_tagged+0x10/0x10
 [<c10ad981>] write_cache_pages+0x161/0x3a0
 [<c12ef76d>] ? blk_finish_plug+0xd/0x30
 [<c10ad180>] ? mapping_tagged+0x10/0x10
 [<c10adbef>] generic_writepages+0x2f/0x60
 [<c10aef65>] do_writepages+0x35/0x40
 [<c10f7f6b>] __writeback_single_inode+0x3b/0x1e0
 [<c10f8860>] writeback_sb_inodes+0x160/0x2e0
 [<c10f8a4c>] __writeback_inodes_wb+0x6c/0xa0
 [<c10f8f22>] wb_writeback+0x1a2/0x240
 [<c10f93a9>] bdi_writeback_workfn+0x149/0x370
 [<c1045e1f>] process_one_work+0xef/0x310
 [<c1046718>] worker_thread+0xe8/0x410
 [<c1046630>] ? mod_delayed_work_on+0x60/0x60
 [<c1046630>] ? mod_delayed_work_on+0x60/0x60
 [<c104ab45>] kthread+0x95/0xb0
 [<c160cec0>] ret_from_kernel_thread+0x20/0x30
 [<c104aab0>] ? __kthread_parkme+0x60/0x60
---[ end trace ca1dc42be1a0b8e5 ]---
EXT4-fs (md7): re-mounted. Opts: (null)
EXT4-fs (md2): re-mounted. Opts: (null)
Emergency Remount complete
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs (md2): ext4_writepages: jbd2_start: 1024 pages, ino 9438915; err -30
EXT4-fs: 1219 callbacks suppressed

#define EROFS           30      /* Read-only file system */

Simon-

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

Re: Dirty pages underflow on 3.14.23

[Holger Hoffstätte]

On Tue, 06 Jan 2015 12:54:43 -0500, Mikulas Patocka wrote:

> On Tue, 6 Jan 2015, Johannes Weiner wrote:
> 
>> > The bug probably happened during git pull or apt-get update, though
>> > one can't be sure that these commands caused it.
>> > 
>> > I see that 3.14.24 containes some fix for underflow (commit
>> > 6619741f17f541113a02c30f22a9ca22e32c9546, upstream commit
>> > abe5f972912d086c080be4bde67750630b6fb38b), but it doesn't seem that
>> > that commit fixes this condition. If you have a commit that could fix
>> > this, say it.
>> 
>> That's an unrelated counter, but there is a known dirty underflow
>> problem that was addressed in 87a7e00b206a ("mm: protect
>> set_page_dirty() from ongoing truncation").  It should make it into the
>> stable kernels in the near future.  Can you reproduce this issue?
>> 
>> Thanks,
>> Johannes
> 
> I can't reprodce it. It happened just once.
> 
> That patch is supposed to fix an occasional underflow by a single page -
> while my meminfo showed underflow by 22952KiB (5738 pages).

You are probably looking for:
commit 835f252c6debd204fcd607c79975089b1ecd3472
"aio: fix uncorrent dirty pages accouting when truncating AIO ring buffer"

It definitely went into 3.14.26, don't know about 3.16.x.

-h

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

Re: Dirty pages underflow on 3.14.23

[Simon Kirby]

On Wed, Jan 07, 2015 at 10:57:46AM +0000, Holger Hoffst?tte wrote:

> On Tue, 06 Jan 2015 12:54:43 -0500, Mikulas Patocka wrote:
> 
> > I can't reprodce it. It happened just once.
> > 
> > That patch is supposed to fix an occasional underflow by a single page -
> > while my meminfo showed underflow by 22952KiB (5738 pages).
> 
> You are probably looking for:
> commit 835f252c6debd204fcd607c79975089b1ecd3472
> "aio: fix uncorrent dirty pages accouting when truncating AIO ring buffer"
> 
> It definitely went into 3.14.26, don't know about 3.16.x.

I can confirm that a MySQL shutdown/restart triggers it for me, even
immediately following a fresh boot:

# uname -a ; grep '^nr_dirty ' /proc/vmstat; /etc/init.d/mysql restart; \
             grep '^nr_dirty ' /proc/vmstat
Linux blue 3.16.6-blue #51 Mon Oct 20 14:00:47 PDT 2014 i686 GNU/Linux
nr_dirty 13
[ ok ] Stopping MySQL database server: mysqld.
[ ok ] Starting MySQL database server: mysqld . ..
[info] Checking for tables which need an upgrade, are corrupt or were not closed cleanly..
nr_dirty 4294967245

Hmm...A possibly-related issue...Before trying this, after a fresh boot,
/proc/vmstat showed:

nr_alloc_batch 4294541205

and after the restart, it shows:

nr_alloc_batch 161

...anyway, git cherry-pick ce4b66be6cd964e84363afd4a603633dd061b3b8 on
3.16.6 tree does seem to fix nr_dirty from underflowing...Yay!

Still, nr_alloc_batch reads as 4294254379 after MySQL restart, and now
seems to stay up there.

Simon-

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

Re: Dirty pages underflow on 3.14.23

[Vlastimil Babka]

On 01/07/2015 10:28 PM, Simon Kirby wrote:
> On Wed, Jan 07, 2015 at 10:57:46AM +0000, Holger Hoffst?tte wrote:
> 
>> On Tue, 06 Jan 2015 12:54:43 -0500, Mikulas Patocka wrote:
>> 
>> > I can't reprodce it. It happened just once.
>> > 
>> > That patch is supposed to fix an occasional underflow by a single page -
>> > while my meminfo showed underflow by 22952KiB (5738 pages).
>> 
>> You are probably looking for:
>> commit 835f252c6debd204fcd607c79975089b1ecd3472
>> "aio: fix uncorrent dirty pages accouting when truncating AIO ring buffer"
>> 
>> It definitely went into 3.14.26, don't know about 3.16.x.
> 
> I can confirm that a MySQL shutdown/restart triggers it for me, even
> immediately following a fresh boot:
> 
> # uname -a ; grep '^nr_dirty ' /proc/vmstat; /etc/init.d/mysql restart; \
>              grep '^nr_dirty ' /proc/vmstat
> Linux blue 3.16.6-blue #51 Mon Oct 20 14:00:47 PDT 2014 i686 GNU/Linux
> nr_dirty 13
> [ ok ] Stopping MySQL database server: mysqld.
> [ ok ] Starting MySQL database server: mysqld . ..
> [info] Checking for tables which need an upgrade, are corrupt or were not closed cleanly..
> nr_dirty 4294967245
> 
> Hmm...A possibly-related issue...Before trying this, after a fresh boot,
> /proc/vmstat showed:
> 
> nr_alloc_batch 4294541205

This can happen, and not be a problem in general. However, there was a fix
abe5f972912d086c080be4bde67750630b6fb38b in 3.17 for a potential performance
issue if this counter overflows on single processor configuration. It was marked
stable, but the 3.16 series was discontinued before the fix could be backported.
So if you are on single-core, you might hit the performance issue.

> and after the restart, it shows:
> 
> nr_alloc_batch 161
> 
> ...anyway, git cherry-pick ce4b66be6cd964e84363afd4a603633dd061b3b8 on
> 3.16.6 tree does seem to fix nr_dirty from underflowing...Yay!

Great!

> Still, nr_alloc_batch reads as 4294254379 after MySQL restart, and now
> seems to stay up there.

Hm if it stays there, then you are probably hitting the performance issue. Look
at /proc/zoneinfo, which zone has the underflow. It means this zone will get
unfair amount of allocations, while others may contain stale data and would be
better candidates.

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

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

Re: Dirty pages underflow on 3.14.23

[Simon Kirby]

On Wed, Jan 07, 2015 at 10:48:10PM +0100, Vlastimil Babka wrote:

> On 01/07/2015 10:28 PM, Simon Kirby wrote:
>
> > Hmm...A possibly-related issue...Before trying this, after a fresh boot,
> > /proc/vmstat showed:
> > 
> > nr_alloc_batch 4294541205
> 
> This can happen, and not be a problem in general. However, there was a fix
> abe5f972912d086c080be4bde67750630b6fb38b in 3.17 for a potential performance
> issue if this counter overflows on single processor configuration. It was marked
> stable, but the 3.16 series was discontinued before the fix could be backported.
> So if you are on single-core, you might hit the performance issue.

That particular commit seems to just change the code path in that case,
but should it be underflowing at all on UP?

> > Still, nr_alloc_batch reads as 4294254379 after MySQL restart, and now
> > seems to stay up there.
> 
> Hm if it stays there, then you are probably hitting the performance issue. Look
> at /proc/zoneinfo, which zone has the underflow. It means this zone will get
> unfair amount of allocations, while others may contain stale data and would be
> better candidates.

In this case, it has only 640MB, and there's only DMA and Normal. This is
affecting Normal, and DMA is so small that it probably doesn't matter.

Simon-

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

Re: Dirty pages underflow on 3.14.23

[Vlastimil Babka]

On 01/08/2015 02:04 AM, Simon Kirby wrote:
> On Wed, Jan 07, 2015 at 10:48:10PM +0100, Vlastimil Babka wrote:
> 
>> On 01/07/2015 10:28 PM, Simon Kirby wrote:
>>
>> > Hmm...A possibly-related issue...Before trying this, after a fresh boot,
>> > /proc/vmstat showed:
>> > 
>> > nr_alloc_batch 4294541205
>> 
>> This can happen, and not be a problem in general. However, there was a fix
>> abe5f972912d086c080be4bde67750630b6fb38b in 3.17 for a potential performance
>> issue if this counter overflows on single processor configuration. It was marked
>> stable, but the 3.16 series was discontinued before the fix could be backported.
>> So if you are on single-core, you might hit the performance issue.
> 
> That particular commit seems to just change the code path in that case,
> but should it be underflowing at all on UP?

Yes, the code using this counter is either treating it as signed, or includes a
<0 tests. It's just the /proc output might be confusing here...

>> > Still, nr_alloc_batch reads as 4294254379 after MySQL restart, and now
>> > seems to stay up there.
>> 
>> Hm if it stays there, then you are probably hitting the performance issue. Look
>> at /proc/zoneinfo, which zone has the underflow. It means this zone will get
>> unfair amount of allocations, while others may contain stale data and would be
>> better candidates.
> 
> In this case, it has only 640MB, and there's only DMA and Normal. This is
> affecting Normal, and DMA is so small that it probably doesn't matter.
> 
> Simon-
> 
> --
> To unsubscribe, send a message with 'unsubscribe linux-mm' in
> the body to majordomo@kvack.org.  For more info on Linux MM,
> see: http://www.linux-mm.org/ .
> Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
> 

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