[PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Vyacheslav Dubeyko]

From: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
Subject: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

Many NILFS2 users were reported about strange file system corruption (for example):

[129306.872119] NILFS: bad btree node (blocknr=185027): level = 0, flags = 0x0, nchildren = 768
[129306.872127] NILFS error (device sda4): nilfs_bmap_last_key: broken bmap (inode number=11540)

But such error messages are consequence of file system's issue that takes place
more earlier. Fortunately, Jerome Poulin <jeromepoulin-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> and
Anton Eliasson <devel-17Olwe7vw2dLC78zk6coLg@public.gmane.org> were reported about another issue
not so recently. These reports describe the issue with segctor thread's crash:

[1677.310656] BUG: unable to handle kernel paging request at 0000000000004c83
[1677.310683] IP: [<ffffffffa024d0f2>] nilfs_end_page_io+0x12/0xd0 [nilfs2]

[1677.311562] Call Trace:
[1677.311575]  [<ffffffffa024e4c5>] nilfs_segctor_do_construct+0xf25/0x1b20 [nilfs2]
[1677.311596]  [<ffffffff81019d09>] ? sched_clock+0x9/0x10
[1677.311614]  [<ffffffffa024f3ab>] nilfs_segctor_construct+0x17b/0x290 [nilfs2]
[1677.311636]  [<ffffffffa024f5e2>] nilfs_segctor_thread+0x122/0x3b0 [nilfs2]
[1677.311657]  [<ffffffffa024f4c0>] ?nilfs_segctor_construct+0x290/0x290 [nilfs2]
[1677.311677]  [<ffffffff8107cae0>] kthread+0xc0/0xd0
[1677.311690]  [<ffffffff8107ca20>] ? kthread_create_on_node+0x120/0x120
[1677.311709]  [<ffffffff816dd16c>] ret_from_fork+0x7c/0xb0
[1677.311724]  [<ffffffff8107ca20>] ? kthread_create_on_node+0x120/0x120

These two issues have one reason. This reason can raise third issue too.
Third issue results in hanging of segctor thread with eating of 100% CPU.

REPRODUCING PATH:
One of the possible way or the issue reproducing was described by
Jérôme Poulin <jeromepoulin-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org>:

1. init S to get to single user mode.
2. sysrq+E to make sure only my shell is running
3. start network-manager to get my wifi connection up
4. login as root and launch "screen"
5. cd /boot/log/nilfs which is a ext3 mount point and can log when NILFS dies.
6. lscp | xz -9e > lscp.txt.xz
7. mount my snapshot using mount -o cp=3360839,ro /dev/vgUbuntu/root /mnt/nilfs
8. start a screen to dump /proc/kmsg to text file since rsyslog is killed
9. start a screen and launch strace -f -o find-cat.log -t find
/mnt/nilfs -type f -exec cat {} > /dev/null \;
10. start a screen and launch strace -f -o apt-get.log -t apt-get update
11. launch the last command again as it did not crash the first time
12. apt-get crashes
13. ps aux > ps-aux-crashed.log
13. sysrq+W
14. sysrq+E  wait for everything to terminate
15. sysrq+SUSB

Simplified way of the issue reproducing is starting kernel compilation task
and "apt-get update" in parallel.

REPRODUCIBILITY:
The issue is reproduced not stable [60% - 80%]. It is very important to have
proper environment for the issue reproducing. The critical conditions for
successful reproducing:
(1) It should have big modified file by mmap() way.
(2) This file should have the count of dirty blocks are greater that several
segments in size (for example, two or three) from time to time during
processing.
(3) It should be intensive background activity of files modification in
another thread.

INVESTIGATION:
First of all, it is possible to see that the reason of crash is not valid
page address:

[291.101244] NILFS [nilfs_segctor_complete_write]:2100 bh->b_count 0, bh->b_blocknr 13895680, bh->b_size 13897727, bh->b_page 0000000000001a82
[291.101249] NILFS [nilfs_segctor_complete_write]:2101 segbuf->sb_segnum 6783

Moreover, value of b_page (0x1a82) is 6786. This value looks like segment
number. And b_blocknr with b_size values look like block numbers. So,
buffer_head's pointer points on not proper address value.

Detailed investigation of the issue is discovered such picture:

[-----------------------------SEGMENT 6783-------------------------------]
[290.886448] NILFS [nilfs_segctor_do_construct]:2310 nilfs_segctor_begin_construction
[290.886460] NILFS [nilfs_segctor_do_construct]:2321 nilfs_segctor_collect
[290.886578] NILFS [nilfs_segctor_do_construct]:2336 nilfs_segctor_assign
[290.886601] NILFS [nilfs_segctor_do_construct]:2367 nilfs_segctor_update_segusage
[290.886608] NILFS [nilfs_segctor_do_construct]:2371 nilfs_segctor_prepare_write
[290.886631] NILFS [nilfs_segctor_do_construct]:2376 nilfs_add_checksums_on_logs
[290.886663] NILFS [nilfs_segctor_do_construct]:2381 nilfs_segctor_write
[290.886697] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111149024, segbuf->sb_segnum 6783

[-----------------------------SEGMENT 6784-------------------------------]
[290.886755] NILFS [nilfs_segctor_do_construct]:2310 nilfs_segctor_begin_construction
[290.886765] NILFS [nilfs_segctor_do_construct]:2321 nilfs_segctor_collect
[290.952406] NILFS [nilfs_lookup_dirty_data_buffers]:782 bh->b_count 1, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
[290.952411] NILFS [nilfs_lookup_dirty_data_buffers]:783 bh->b_assoc_buffers.next ffff8802174a6798, bh->b_assoc_buffers.prev ffff880221cffee8
[290.919399] NILFS [nilfs_segctor_do_construct]:2336 nilfs_segctor_assign
[290.932458] NILFS [nilfs_segctor_do_construct]:2367 nilfs_segctor_update_segusage
[290.933098] NILFS [nilfs_segctor_do_construct]:2371 nilfs_segctor_prepare_write
[290.939184] NILFS [nilfs_segctor_do_construct]:2376 nilfs_add_checksums_on_logs
[290.951133] NILFS [nilfs_segctor_do_construct]:2381 nilfs_segctor_write
[290.951314] NILFS [nilfs_segbuf_submit_bh]:575 bh->b_count 1, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
[290.951321] NILFS [nilfs_segbuf_submit_bh]:576 segbuf->sb_segnum 6784
[290.951325] NILFS [nilfs_segbuf_submit_bh]:577 bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880218bcdf50
[290.951534] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111150080, segbuf->sb_segnum 6784, segbuf->sb_nbio 0
[----------] ditto
[290.952308] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111164416, segbuf->sb_segnum 6784, segbuf->sb_nbio 15

[-----------------------------SEGMENT 6785-------------------------------]
[290.952340] NILFS [nilfs_segctor_do_construct]:2310 nilfs_segctor_begin_construction
[290.952364] NILFS [nilfs_segctor_do_construct]:2321 nilfs_segctor_collect
[290.952406] NILFS [nilfs_lookup_dirty_data_buffers]:782 bh->b_count 2, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
[290.952411] NILFS [nilfs_lookup_dirty_data_buffers]:783 bh->b_assoc_buffers.next ffff880219277e80, bh->b_assoc_buffers.prev ffff880221cffc88
[290.990248] NILFS [nilfs_segctor_do_construct]:2367 nilfs_segctor_update_segusage
[290.990265] NILFS [nilfs_segctor_do_construct]:2371 nilfs_segctor_prepare_write
[291.008348] NILFS [nilfs_segctor_do_construct]:2376 nilfs_add_checksums_on_logs
[291.018110] NILFS [nilfs_segctor_do_construct]:2381 nilfs_segctor_write
[291.021206] NILFS [nilfs_segbuf_submit_bh]:575 bh->b_count 2, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
[291.021210] NILFS [nilfs_segbuf_submit_bh]:576 segbuf->sb_segnum 6785
[291.021214] NILFS [nilfs_segbuf_submit_bh]:577 bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880222cc7ee8
[291.021241] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111165440, segbuf->sb_segnum 6785, segbuf->sb_nbio 0
[----------] ditto
[291.021916] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111177728, segbuf->sb_segnum 6785, segbuf->sb_nbio 12

[291.021944] NILFS [nilfs_segctor_do_construct]:2399 nilfs_segctor_wait
[291.021950] NILFS [nilfs_segbuf_wait]:676 segbuf->sb_segnum 6783
[291.021964] NILFS [nilfs_segbuf_wait]:676 segbuf->sb_segnum 6784
[291.021984] NILFS [nilfs_segbuf_wait]:676 segbuf->sb_segnum 6785

[291.071861] NILFS [nilfs_segctor_complete_write]:2100 bh->b_count 0, bh->b_blocknr 13895680, bh->b_size 13897727, bh->b_page 0000000000001a82

BUG: unable to handle kernel paging request at 0000000000001a82
IP: [<ffffffffa024d0f2>] nilfs_end_page_io+0x12/0xd0 [nilfs2]

Usually, for every segment we collect dirty files in list. Then, dirty blocks
are gathered for every dirty file, prepared for write and submitted by means of
nilfs_segbuf_submit_bh() call. Finally, it takes place complete write phase
after calling nilfs_end_bio_write() on the block layer. Buffers/pages
are marked as not dirty on final phase and processed files removed from the
list of dirty files.

It is possible to see that we had three prepare_write and submit_bio phases
before segbuf_wait and complete_write phase. Moreover, segments compete
between each other for dirty blocks because on every iteration of segments
processing dirty buffer_heads are added in several lists of payload_buffers:

[SEGMENT 6784]: bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880218bcdf50
[SEGMENT 6785]: bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880222cc7ee8

The next pointer is the same but prev pointer has changed. It means that
buffer_head has next pointer from one list but prev pointer from another.
Such modification can be made several times. And, finally,
it can be resulted in various issues: (1) segctor hanging, (2) segctor
crashing, (3) file system metadata corruption.

FIX:
This patch adds:
(1) setting of BH_Async_Write flag in nilfs_segctor_prepare_write()
for every proccessed dirty block;
(2) checking of BH_Async_Write flag in nilfs_lookup_dirty_data_buffers() and
nilfs_lookup_dirty_node_buffers();
(3) clearing of BH_Async_Write flag in nilfs_segctor_complete_write(),
nilfs_abort_logs(), nilfs_forget_buffer(), nilfs_clear_dirty_page().

Reported-by: Jerome Poulin <jeromepoulin-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org>
Reported-by: Anton Eliasson <devel-17Olwe7vw2dLC78zk6coLg@public.gmane.org>
CC: Paul Fertser <fercerpav-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org>
CC: ARAI Shun-ichi <hermes-akuOmOme3sQYOdUovKs6ag@public.gmane.org>
CC: Piotr Szymaniak <szarpaj-TbOm9Ca2r9GrDJvtcaxF/A@public.gmane.org>
CC: Juan Barry Manuel Canham <Linux-pOR+BrglI3BO41XttqYhMtHuzzzSOjJt@public.gmane.org>
CC: Zahid Chowdhury <zahid.chowdhury-VJizFkI/10gAspv4Qr0y0gC/G2K4zDHf@public.gmane.org>
CC: Elmer Zhang <freeboy6716-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org>
CC: Kenneth Langga <klangga-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org>
Signed-off-by: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
CC: Ryusuke Konishi <konishi.ryusuke-Zyj7fXuS5i5L9jVzuh4AOg@public.gmane.org>
---
 fs/nilfs2/page.c    |    2 ++
 fs/nilfs2/segment.c |   11 +++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)

diff --git a/fs/nilfs2/page.c b/fs/nilfs2/page.c
index 0ba6798..da27664 100644
--- a/fs/nilfs2/page.c
+++ b/fs/nilfs2/page.c
@@ -94,6 +94,7 @@ void nilfs_forget_buffer(struct buffer_head *bh)
 	clear_buffer_nilfs_volatile(bh);
 	clear_buffer_nilfs_checked(bh);
 	clear_buffer_nilfs_redirected(bh);
+	clear_buffer_async_write(bh);
 	clear_buffer_dirty(bh);
 	if (nilfs_page_buffers_clean(page))
 		__nilfs_clear_page_dirty(page);
@@ -429,6 +430,7 @@ void nilfs_clear_dirty_page(struct page *page, bool silent)
 					"discard block %llu, size %zu",
 					(u64)bh->b_blocknr, bh->b_size);
 			}
+			clear_buffer_async_write(bh);
 			clear_buffer_dirty(bh);
 			clear_buffer_nilfs_volatile(bh);
 			clear_buffer_nilfs_checked(bh);
diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c
index bd88a74..9f6b486 100644
--- a/fs/nilfs2/segment.c
+++ b/fs/nilfs2/segment.c
@@ -665,7 +665,7 @@ static size_t nilfs_lookup_dirty_data_buffers(struct inode *inode,
 
 		bh = head = page_buffers(page);
 		do {
-			if (!buffer_dirty(bh))
+			if (!buffer_dirty(bh) || buffer_async_write(bh))
 				continue;
 			get_bh(bh);
 			list_add_tail(&bh->b_assoc_buffers, listp);
@@ -699,7 +699,8 @@ static void nilfs_lookup_dirty_node_buffers(struct inode *inode,
 		for (i = 0; i < pagevec_count(&pvec); i++) {
 			bh = head = page_buffers(pvec.pages[i]);
 			do {
-				if (buffer_dirty(bh)) {
+				if (buffer_dirty(bh) &&
+						!buffer_async_write(bh)) {
 					get_bh(bh);
 					list_add_tail(&bh->b_assoc_buffers,
 						      listp);
@@ -1579,6 +1580,7 @@ static void nilfs_segctor_prepare_write(struct nilfs_sc_info *sci)
 
 		list_for_each_entry(bh, &segbuf->sb_segsum_buffers,
 				    b_assoc_buffers) {
+			set_buffer_async_write(bh);
 			if (bh->b_page != bd_page) {
 				if (bd_page) {
 					lock_page(bd_page);
@@ -1592,6 +1594,7 @@ static void nilfs_segctor_prepare_write(struct nilfs_sc_info *sci)
 
 		list_for_each_entry(bh, &segbuf->sb_payload_buffers,
 				    b_assoc_buffers) {
+			set_buffer_async_write(bh);
 			if (bh == segbuf->sb_super_root) {
 				if (bh->b_page != bd_page) {
 					lock_page(bd_page);
@@ -1677,6 +1680,7 @@ static void nilfs_abort_logs(struct list_head *logs, int err)
 	list_for_each_entry(segbuf, logs, sb_list) {
 		list_for_each_entry(bh, &segbuf->sb_segsum_buffers,
 				    b_assoc_buffers) {
+			clear_buffer_async_write(bh);
 			if (bh->b_page != bd_page) {
 				if (bd_page)
 					end_page_writeback(bd_page);
@@ -1686,6 +1690,7 @@ static void nilfs_abort_logs(struct list_head *logs, int err)
 
 		list_for_each_entry(bh, &segbuf->sb_payload_buffers,
 				    b_assoc_buffers) {
+			clear_buffer_async_write(bh);
 			if (bh == segbuf->sb_super_root) {
 				if (bh->b_page != bd_page) {
 					end_page_writeback(bd_page);
@@ -1755,6 +1760,7 @@ static void nilfs_segctor_complete_write(struct nilfs_sc_info *sci)
 				    b_assoc_buffers) {
 			set_buffer_uptodate(bh);
 			clear_buffer_dirty(bh);
+			clear_buffer_async_write(bh);
 			if (bh->b_page != bd_page) {
 				if (bd_page)
 					end_page_writeback(bd_page);
@@ -1776,6 +1782,7 @@ static void nilfs_segctor_complete_write(struct nilfs_sc_info *sci)
 				    b_assoc_buffers) {
 			set_buffer_uptodate(bh);
 			clear_buffer_dirty(bh);
+			clear_buffer_async_write(bh);
 			clear_buffer_delay(bh);
 			clear_buffer_nilfs_volatile(bh);
 			clear_buffer_nilfs_redirected(bh);
-- 
1.7.9.5



--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Ryusuke Konishi]

On Mon, 02 Sep 2013 17:27:44 +0400, Vyacheslav Dubeyko wrote:
> From: Vyacheslav Dubeyko <slava@dubeyko.com>
> Subject: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

Before considering to apply this patch, please confirm that the
suspected issue, "dirty buffer_heads are added in several lists of
payload_buffers" you pointed out, is actually happening.

The easiest way for this is testing the following patch:

diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c
index bd88a74..cab38db 100644
--- a/fs/nilfs2/segment.c
+++ b/fs/nilfs2/segment.c
@@ -668,6 +668,7 @@ static size_t nilfs_lookup_dirty_data_buffers(struct inode *inode,
 			if (!buffer_dirty(bh))
 				continue;
 			get_bh(bh);
+			BUG_ON(!list_empty(&bh->b_assoc_buffers));
 			list_add_tail(&bh->b_assoc_buffers, listp);
 			ndirties++;
 			if (unlikely(ndirties >= nlimit)) {
@@ -701,6 +702,7 @@ static void nilfs_lookup_dirty_node_buffers(struct inode *inode,
 			do {
 				if (buffer_dirty(bh)) {
 					get_bh(bh);
+					BUG_ON(!list_empty(&bh->b_assoc_buffers));
 					list_add_tail(&bh->b_assoc_buffers,
 						      listp);
 				}

You can rewrite the above BUG_ON() check with the following debug code
if you want to get detail information on the buffer:

  if (!list_empty(&bh->b_assoc_buffers)) {
     /* dump information on bh */
  }

As a workaround, we can avoid double registration to different payload
lists with list_empty(&bh->b_assoc_buffers) instead of adding
BH_async_write flag.

However, I think we should first narrow down the root cause of why the
issue "dirty buffer_heads are added in several lists of
payload_buffers" happens.

We designed the log writer so that the same buffer is not registered
to two different payload buffer lists at the same time.  If it is not
satisfied, it's a bug.

What is the root cause of the "double registration" of a buffer head,
do you think?


Regards,
Ryusuke Konishi


> Many NILFS2 users were reported about strange file system corruption (for example):
> 
> [129306.872119] NILFS: bad btree node (blocknr=185027): level = 0, flags = 0x0, nchildren = 768
> [129306.872127] NILFS error (device sda4): nilfs_bmap_last_key: broken bmap (inode number=11540)
> 
> But such error messages are consequence of file system's issue that takes place
> more earlier. Fortunately, Jerome Poulin <jeromepoulin@gmail.com> and
> Anton Eliasson <devel@antoneliasson.se> were reported about another issue
> not so recently. These reports describe the issue with segctor thread's crash:
> 
> [1677.310656] BUG: unable to handle kernel paging request at 0000000000004c83
> [1677.310683] IP: [<ffffffffa024d0f2>] nilfs_end_page_io+0x12/0xd0 [nilfs2]
> 
> [1677.311562] Call Trace:
> [1677.311575]  [<ffffffffa024e4c5>] nilfs_segctor_do_construct+0xf25/0x1b20 [nilfs2]
> [1677.311596]  [<ffffffff81019d09>] ? sched_clock+0x9/0x10
> [1677.311614]  [<ffffffffa024f3ab>] nilfs_segctor_construct+0x17b/0x290 [nilfs2]
> [1677.311636]  [<ffffffffa024f5e2>] nilfs_segctor_thread+0x122/0x3b0 [nilfs2]
> [1677.311657]  [<ffffffffa024f4c0>] ?nilfs_segctor_construct+0x290/0x290 [nilfs2]
> [1677.311677]  [<ffffffff8107cae0>] kthread+0xc0/0xd0
> [1677.311690]  [<ffffffff8107ca20>] ? kthread_create_on_node+0x120/0x120
> [1677.311709]  [<ffffffff816dd16c>] ret_from_fork+0x7c/0xb0
> [1677.311724]  [<ffffffff8107ca20>] ? kthread_create_on_node+0x120/0x120
> 
> These two issues have one reason. This reason can raise third issue too.
> Third issue results in hanging of segctor thread with eating of 100% CPU.
> 
> REPRODUCING PATH:
> One of the possible way or the issue reproducing was described by
> Jérôme Poulin <jeromepoulin@gmail.com>:
> 
> 1. init S to get to single user mode.
> 2. sysrq+E to make sure only my shell is running
> 3. start network-manager to get my wifi connection up
> 4. login as root and launch "screen"
> 5. cd /boot/log/nilfs which is a ext3 mount point and can log when NILFS dies.
> 6. lscp | xz -9e > lscp.txt.xz
> 7. mount my snapshot using mount -o cp=3360839,ro /dev/vgUbuntu/root /mnt/nilfs
> 8. start a screen to dump /proc/kmsg to text file since rsyslog is killed
> 9. start a screen and launch strace -f -o find-cat.log -t find
> /mnt/nilfs -type f -exec cat {} > /dev/null \;
> 10. start a screen and launch strace -f -o apt-get.log -t apt-get update
> 11. launch the last command again as it did not crash the first time
> 12. apt-get crashes
> 13. ps aux > ps-aux-crashed.log
> 13. sysrq+W
> 14. sysrq+E  wait for everything to terminate
> 15. sysrq+SUSB
> 
> Simplified way of the issue reproducing is starting kernel compilation task
> and "apt-get update" in parallel.
> 
> REPRODUCIBILITY:
> The issue is reproduced not stable [60% - 80%]. It is very important to have
> proper environment for the issue reproducing. The critical conditions for
> successful reproducing:
> (1) It should have big modified file by mmap() way.
> (2) This file should have the count of dirty blocks are greater that several
> segments in size (for example, two or three) from time to time during
> processing.
> (3) It should be intensive background activity of files modification in
> another thread.
> 
> INVESTIGATION:
> First of all, it is possible to see that the reason of crash is not valid
> page address:
> 
> [291.101244] NILFS [nilfs_segctor_complete_write]:2100 bh->b_count 0, bh->b_blocknr 13895680, bh->b_size 13897727, bh->b_page 0000000000001a82
> [291.101249] NILFS [nilfs_segctor_complete_write]:2101 segbuf->sb_segnum 6783
> 
> Moreover, value of b_page (0x1a82) is 6786. This value looks like segment
> number. And b_blocknr with b_size values look like block numbers. So,
> buffer_head's pointer points on not proper address value.
> 
> Detailed investigation of the issue is discovered such picture:
> 
> [-----------------------------SEGMENT 6783-------------------------------]
> [290.886448] NILFS [nilfs_segctor_do_construct]:2310 nilfs_segctor_begin_construction
> [290.886460] NILFS [nilfs_segctor_do_construct]:2321 nilfs_segctor_collect
> [290.886578] NILFS [nilfs_segctor_do_construct]:2336 nilfs_segctor_assign
> [290.886601] NILFS [nilfs_segctor_do_construct]:2367 nilfs_segctor_update_segusage
> [290.886608] NILFS [nilfs_segctor_do_construct]:2371 nilfs_segctor_prepare_write
> [290.886631] NILFS [nilfs_segctor_do_construct]:2376 nilfs_add_checksums_on_logs
> [290.886663] NILFS [nilfs_segctor_do_construct]:2381 nilfs_segctor_write
> [290.886697] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111149024, segbuf->sb_segnum 6783
> 
> [-----------------------------SEGMENT 6784-------------------------------]
> [290.886755] NILFS [nilfs_segctor_do_construct]:2310 nilfs_segctor_begin_construction
> [290.886765] NILFS [nilfs_segctor_do_construct]:2321 nilfs_segctor_collect
> [290.952406] NILFS [nilfs_lookup_dirty_data_buffers]:782 bh->b_count 1, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
> [290.952411] NILFS [nilfs_lookup_dirty_data_buffers]:783 bh->b_assoc_buffers.next ffff8802174a6798, bh->b_assoc_buffers.prev ffff880221cffee8
> [290.919399] NILFS [nilfs_segctor_do_construct]:2336 nilfs_segctor_assign
> [290.932458] NILFS [nilfs_segctor_do_construct]:2367 nilfs_segctor_update_segusage
> [290.933098] NILFS [nilfs_segctor_do_construct]:2371 nilfs_segctor_prepare_write
> [290.939184] NILFS [nilfs_segctor_do_construct]:2376 nilfs_add_checksums_on_logs
> [290.951133] NILFS [nilfs_segctor_do_construct]:2381 nilfs_segctor_write
> [290.951314] NILFS [nilfs_segbuf_submit_bh]:575 bh->b_count 1, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
> [290.951321] NILFS [nilfs_segbuf_submit_bh]:576 segbuf->sb_segnum 6784
> [290.951325] NILFS [nilfs_segbuf_submit_bh]:577 bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880218bcdf50
> [290.951534] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111150080, segbuf->sb_segnum 6784, segbuf->sb_nbio 0
> [----------] ditto
> [290.952308] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111164416, segbuf->sb_segnum 6784, segbuf->sb_nbio 15
> 
> [-----------------------------SEGMENT 6785-------------------------------]
> [290.952340] NILFS [nilfs_segctor_do_construct]:2310 nilfs_segctor_begin_construction
> [290.952364] NILFS [nilfs_segctor_do_construct]:2321 nilfs_segctor_collect
> [290.952406] NILFS [nilfs_lookup_dirty_data_buffers]:782 bh->b_count 2, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
> [290.952411] NILFS [nilfs_lookup_dirty_data_buffers]:783 bh->b_assoc_buffers.next ffff880219277e80, bh->b_assoc_buffers.prev ffff880221cffc88
> [290.990248] NILFS [nilfs_segctor_do_construct]:2367 nilfs_segctor_update_segusage
> [290.990265] NILFS [nilfs_segctor_do_construct]:2371 nilfs_segctor_prepare_write
> [291.008348] NILFS [nilfs_segctor_do_construct]:2376 nilfs_add_checksums_on_logs
> [291.018110] NILFS [nilfs_segctor_do_construct]:2381 nilfs_segctor_write
> [291.021206] NILFS [nilfs_segbuf_submit_bh]:575 bh->b_count 2, bh->b_page ffffea000709b000, page->index 0, i_ino 1033103, i_size 25165824
> [291.021210] NILFS [nilfs_segbuf_submit_bh]:576 segbuf->sb_segnum 6785
> [291.021214] NILFS [nilfs_segbuf_submit_bh]:577 bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880222cc7ee8
> [291.021241] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111165440, segbuf->sb_segnum 6785, segbuf->sb_nbio 0
> [----------] ditto
> [291.021916] NILFS [nilfs_segbuf_submit_bio]:464 bio->bi_sector 111177728, segbuf->sb_segnum 6785, segbuf->sb_nbio 12
> 
> [291.021944] NILFS [nilfs_segctor_do_construct]:2399 nilfs_segctor_wait
> [291.021950] NILFS [nilfs_segbuf_wait]:676 segbuf->sb_segnum 6783
> [291.021964] NILFS [nilfs_segbuf_wait]:676 segbuf->sb_segnum 6784
> [291.021984] NILFS [nilfs_segbuf_wait]:676 segbuf->sb_segnum 6785
> 
> [291.071861] NILFS [nilfs_segctor_complete_write]:2100 bh->b_count 0, bh->b_blocknr 13895680, bh->b_size 13897727, bh->b_page 0000000000001a82
> 
> BUG: unable to handle kernel paging request at 0000000000001a82
> IP: [<ffffffffa024d0f2>] nilfs_end_page_io+0x12/0xd0 [nilfs2]
> 
> Usually, for every segment we collect dirty files in list. Then, dirty blocks
> are gathered for every dirty file, prepared for write and submitted by means of
> nilfs_segbuf_submit_bh() call. Finally, it takes place complete write phase
> after calling nilfs_end_bio_write() on the block layer. Buffers/pages
> are marked as not dirty on final phase and processed files removed from the
> list of dirty files.
> 
> It is possible to see that we had three prepare_write and submit_bio phases
> before segbuf_wait and complete_write phase. Moreover, segments compete
> between each other for dirty blocks because on every iteration of segments
> processing dirty buffer_heads are added in several lists of payload_buffers:
> 
> [SEGMENT 6784]: bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880218bcdf50
> [SEGMENT 6785]: bh->b_assoc_buffers.next ffff880218a0d5f8, bh->b_assoc_buffers.prev ffff880222cc7ee8
> 
> The next pointer is the same but prev pointer has changed. It means that
> buffer_head has next pointer from one list but prev pointer from another.
> Such modification can be made several times. And, finally,
> it can be resulted in various issues: (1) segctor hanging, (2) segctor
> crashing, (3) file system metadata corruption.
> 
> FIX:
> This patch adds:
> (1) setting of BH_Async_Write flag in nilfs_segctor_prepare_write()
> for every proccessed dirty block;
> (2) checking of BH_Async_Write flag in nilfs_lookup_dirty_data_buffers() and
> nilfs_lookup_dirty_node_buffers();
> (3) clearing of BH_Async_Write flag in nilfs_segctor_complete_write(),
> nilfs_abort_logs(), nilfs_forget_buffer(), nilfs_clear_dirty_page().
> 
> Reported-by: Jerome Poulin <jeromepoulin@gmail.com>
> Reported-by: Anton Eliasson <devel@antoneliasson.se>
> CC: Paul Fertser <fercerpav@gmail.com>
> CC: ARAI Shun-ichi <hermes@ceres.dti.ne.jp>
> CC: Piotr Szymaniak <szarpaj@grubelek.pl>
> CC: Juan Barry Manuel Canham <Linux@riotingpacifist.net>
> CC: Zahid Chowdhury <zahid.chowdhury@starsolutions.com>
> CC: Elmer Zhang <freeboy6716@gmail.com>
> CC: Kenneth Langga <klangga@gmail.com>
> Signed-off-by: Vyacheslav Dubeyko <slava@dubeyko.com>
> CC: Ryusuke Konishi <konishi.ryusuke@lab.ntt.co.jp>
> ---
>  fs/nilfs2/page.c    |    2 ++
>  fs/nilfs2/segment.c |   11 +++++++++--
>  2 files changed, 11 insertions(+), 2 deletions(-)
> 
> diff --git a/fs/nilfs2/page.c b/fs/nilfs2/page.c
> index 0ba6798..da27664 100644
> --- a/fs/nilfs2/page.c
> +++ b/fs/nilfs2/page.c
> @@ -94,6 +94,7 @@ void nilfs_forget_buffer(struct buffer_head *bh)
>  	clear_buffer_nilfs_volatile(bh);
>  	clear_buffer_nilfs_checked(bh);
>  	clear_buffer_nilfs_redirected(bh);
> +	clear_buffer_async_write(bh);
>  	clear_buffer_dirty(bh);
>  	if (nilfs_page_buffers_clean(page))
>  		__nilfs_clear_page_dirty(page);
> @@ -429,6 +430,7 @@ void nilfs_clear_dirty_page(struct page *page, bool silent)
>  					"discard block %llu, size %zu",
>  					(u64)bh->b_blocknr, bh->b_size);
>  			}
> +			clear_buffer_async_write(bh);
>  			clear_buffer_dirty(bh);
>  			clear_buffer_nilfs_volatile(bh);
>  			clear_buffer_nilfs_checked(bh);
> diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c
> index bd88a74..9f6b486 100644
> --- a/fs/nilfs2/segment.c
> +++ b/fs/nilfs2/segment.c
> @@ -665,7 +665,7 @@ static size_t nilfs_lookup_dirty_data_buffers(struct inode *inode,
>  
>  		bh = head = page_buffers(page);
>  		do {
> -			if (!buffer_dirty(bh))
> +			if (!buffer_dirty(bh) || buffer_async_write(bh))
>  				continue;
>  			get_bh(bh);
>  			list_add_tail(&bh->b_assoc_buffers, listp);
> @@ -699,7 +699,8 @@ static void nilfs_lookup_dirty_node_buffers(struct inode *inode,
>  		for (i = 0; i < pagevec_count(&pvec); i++) {
>  			bh = head = page_buffers(pvec.pages[i]);
>  			do {
> -				if (buffer_dirty(bh)) {
> +				if (buffer_dirty(bh) &&
> +						!buffer_async_write(bh)) {
>  					get_bh(bh);
>  					list_add_tail(&bh->b_assoc_buffers,
>  						      listp);
> @@ -1579,6 +1580,7 @@ static void nilfs_segctor_prepare_write(struct nilfs_sc_info *sci)
>  
>  		list_for_each_entry(bh, &segbuf->sb_segsum_buffers,
>  				    b_assoc_buffers) {
> +			set_buffer_async_write(bh);
>  			if (bh->b_page != bd_page) {
>  				if (bd_page) {
>  					lock_page(bd_page);
> @@ -1592,6 +1594,7 @@ static void nilfs_segctor_prepare_write(struct nilfs_sc_info *sci)
>  
>  		list_for_each_entry(bh, &segbuf->sb_payload_buffers,
>  				    b_assoc_buffers) {
> +			set_buffer_async_write(bh);
>  			if (bh == segbuf->sb_super_root) {
>  				if (bh->b_page != bd_page) {
>  					lock_page(bd_page);
> @@ -1677,6 +1680,7 @@ static void nilfs_abort_logs(struct list_head *logs, int err)
>  	list_for_each_entry(segbuf, logs, sb_list) {
>  		list_for_each_entry(bh, &segbuf->sb_segsum_buffers,
>  				    b_assoc_buffers) {
> +			clear_buffer_async_write(bh);
>  			if (bh->b_page != bd_page) {
>  				if (bd_page)
>  					end_page_writeback(bd_page);
> @@ -1686,6 +1690,7 @@ static void nilfs_abort_logs(struct list_head *logs, int err)
>  
>  		list_for_each_entry(bh, &segbuf->sb_payload_buffers,
>  				    b_assoc_buffers) {
> +			clear_buffer_async_write(bh);
>  			if (bh == segbuf->sb_super_root) {
>  				if (bh->b_page != bd_page) {
>  					end_page_writeback(bd_page);
> @@ -1755,6 +1760,7 @@ static void nilfs_segctor_complete_write(struct nilfs_sc_info *sci)
>  				    b_assoc_buffers) {
>  			set_buffer_uptodate(bh);
>  			clear_buffer_dirty(bh);
> +			clear_buffer_async_write(bh);
>  			if (bh->b_page != bd_page) {
>  				if (bd_page)
>  					end_page_writeback(bd_page);
> @@ -1776,6 +1782,7 @@ static void nilfs_segctor_complete_write(struct nilfs_sc_info *sci)
>  				    b_assoc_buffers) {
>  			set_buffer_uptodate(bh);
>  			clear_buffer_dirty(bh);
> +			clear_buffer_async_write(bh);
>  			clear_buffer_delay(bh);
>  			clear_buffer_nilfs_volatile(bh);
>  			clear_buffer_nilfs_redirected(bh);
> -- 
> 1.7.9.5
> 
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Vyacheslav Dubeyko]

Hi Ryusuke,

On Tue, 2013-09-03 at 03:13 +0900, Ryusuke Konishi wrote:
> On Mon, 02 Sep 2013 17:27:44 +0400, Vyacheslav Dubeyko wrote:
> > From: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
> > Subject: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks
> 
> Before considering to apply this patch, please confirm that the
> suspected issue, "dirty buffer_heads are added in several lists of
> payload_buffers" you pointed out, is actually happening.
> 
> The easiest way for this is testing the following patch:
> 
> diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c
> index bd88a74..cab38db 100644
> --- a/fs/nilfs2/segment.c
> +++ b/fs/nilfs2/segment.c
> @@ -668,6 +668,7 @@ static size_t nilfs_lookup_dirty_data_buffers(struct inode *inode,
>  			if (!buffer_dirty(bh))
>  				continue;
>  			get_bh(bh);
> +			BUG_ON(!list_empty(&bh->b_assoc_buffers));
>  			list_add_tail(&bh->b_assoc_buffers, listp);
>  			ndirties++;
>  			if (unlikely(ndirties >= nlimit)) {
> @@ -701,6 +702,7 @@ static void nilfs_lookup_dirty_node_buffers(struct inode *inode,
>  			do {
>  				if (buffer_dirty(bh)) {
>  					get_bh(bh);
> +					BUG_ON(!list_empty(&bh->b_assoc_buffers));
>  					list_add_tail(&bh->b_assoc_buffers,
>  						      listp);
>  				}
> 

Yes, I can confirm the issue. I have applied your patch. And I have such
output in my syslog after reproducing of the issue:

[  424.605561] ------------[ cut here ]------------
[  424.605576] kernel BUG at fs/nilfs2/segment.c:672!
[  424.605581] invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC
[  424.605589] Modules linked in: rfcomm bnep bluetooth parport_pc ppdev snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_intel snd_hda_codec snd_hwdep snd_pcm xfs snd_seq_midi kvm_amd snd_rawmidi kvm snd_seq_midi_event snd_seq r8712u(C) snd_timer snd_seq_device snd sp5100_tco microcode soundcore k10temp i2c_piix4 lp snd_page_alloc parport mac_hid video ext2 sky2 btrfs raid6_pq xor zlib_deflate libcrc32c
[  424.605650] CPU: 0 PID: 358 Comm: segctord Tainted: G         C   3.10.0-rc5+ #116
[  424.605654] Hardware name:    /EDGE-FT1M1 E450, BIOS 4.6.4 11/15/2011
[  424.605660] task: ffff880208ad22a0 ti: ffff8802085e0000 task.ti: ffff8802085e0000
[  424.605663] RIP: 0010:[<ffffffff812bff53>]  [<ffffffff812bff53>] nilfs_lookup_dirty_data_buffers.isra.22+0x203/0x270
[  424.605678] RSP: 0000:ffff8802085e1b08  EFLAGS: 00010293
[  424.605682] RAX: ffff880219589618 RBX: ffff8802085e1c08 RCX: ffff88022dfb6000
[  424.605685] RDX: ffff880219589660 RSI: ffff880219589618 RDI: ffff88022dff8aa8
[  424.605689] RBP: ffff8802085e1be8 R08: 4600000000000000 R09: a8001c7123000000
[  424.605692] R10: 57ffcd8ee41c48c0 R11: 0000000000000000 R12: 0000000000000000
[  424.605695] R13: ffffea00071c48c0 R14: 0000000000000000 R15: 0000000000000800
[  424.605699] FS:  00002aaaaaae3780(0000) GS:ffff880225a00000(0000) knlGS:0000000000000000
[  424.605703] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  424.605706] CR2: 00007fff2945bff8 CR3: 00000002186f9000 CR4: 00000000000007f0
[  424.605710] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  424.605713] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  424.605716] Stack:
[  424.605719]  ffff8802085e1b78 ffff880219177508 ffff8802191773cc ffffffffffffffff
[  424.605728]  ffff88021a637958 000000000000000e 0000000000000000 ffffea00071c48c0
[  424.605735]  ffffea00071c4880 ffffea00071c4840 ffffea00071c4800 ffffea00071dd7c0
[  424.605742] Call Trace:
[  424.605753]  [<ffffffff812c0050>] nilfs_segctor_scan_file+0x90/0x190
[  424.605760]  [<ffffffff812c0736>] nilfs_segctor_do_construct+0x596/0x1ba0
[  424.605767]  [<ffffffff812c2053>] nilfs_segctor_construct+0x183/0x2a0
[  424.605774]  [<ffffffff812c22b6>] nilfs_segctor_thread+0x146/0x370
[  424.605781]  [<ffffffff812c2170>] ? nilfs_segctor_construct+0x2a0/0x2a0
[  424.605788]  [<ffffffff8106bc9d>] kthread+0xed/0x100
[  424.605794]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190
[  424.605802]  [<ffffffff816ef2dc>] ret_from_fork+0x7c/0xb0
[  424.605808]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190
[  424.605811] Code: ef 8b 08 d3 e6 48 63 f6 e8 2b 3d ef ff e9 19 ff ff ff 85 c0 74 ac 66 90 eb 9c 8b 95 48 ff ff ff 85 d2 75 09 e8 6f 48 42 00 eb ad <0f> 0b 48 8d bd 48 ff ff ff e8 1f 29 e7 ff e8 5a 48 42 00 eb 98 
[  424.605886] RIP  [<ffffffff812bff53>] nilfs_lookup_dirty_data_buffers.isra.22+0x203/0x270
[  424.605893]  RSP <ffff8802085e1b08>
[  424.605900] ---[ end trace 0061903595fb4cff ]---

> You can rewrite the above BUG_ON() check with the following debug code
> if you want to get detail information on the buffer:
> 
>   if (!list_empty(&bh->b_assoc_buffers)) {
>      /* dump information on bh */
>   }
> 
> As a workaround, we can avoid double registration to different payload
> lists with list_empty(&bh->b_assoc_buffers) instead of adding
> BH_async_write flag.
> 

Ok. I agree that we need to elaborate another fix if you think that my
approach is not clear enough.

> However, I think we should first narrow down the root cause of why the
> issue "dirty buffer_heads are added in several lists of
> payload_buffers" happens.
> 
> We designed the log writer so that the same buffer is not registered
> to two different payload buffer lists at the same time.  If it is not
> satisfied, it's a bug.
> 
> What is the root cause of the "double registration" of a buffer head,
> do you think?
> 

I have such understanding of the issue's reason.

First of all, I am talking about full segments case but not about
partial segments. As I see, all works fine for partial segments case
because processing of partial segments of one full segment is located
inside of one iteration of cycle in nilfs_segctor_do_construct() method.

So, if we have a file with dirty blocks count is greater than full
segment size then such dirty file will be processed by means of several
iterations of cycle in nilfs_segctor_do_construct() method. Also it
needs to take into account the asynchronous nature of processing of
submitted bio requests on block layer. The searching of dirty blocks is
made in nilfs_lookup_dirty_data_buffers() and
nilfs_lookup_dirty_node_buffers() on the basis of lookup of dirty memory
pages in pagecache and selecting found dirty buffers. Found dirty blocks
are added in current segbuf. Then it makes preparation of dirty blocks
for write operation and submission write requests on block layer. When
block layer ends processing of some bio then it calls
nilfs_end_bio_write(). The segctor thread can complete write request in
nilfs_segctor_complete_write() only after nilfs_end_bio_write() call.
Processed buffers are made as clean namely in
nilfs_segctor_complete_write() method. But if we submitted dirty blocks
of file A in previous iteration and try to process dirty blocks of file
A in next iteration again without
nilfs_end_bio_write()/nilfs_segctor_complete_write() pair for previous
iteration then we will have the issue of "double registration" of a
buffer head (because we find pages under asynchronous write as dirty
again).

Maybe I don't clear understand a condition of this issue or NILFS2
driver's architecture but I can't see another solution for this issue
yet. I suppose that we need to talk over the issue in more details. What
do you think?

You said that the log writer design should prevent from registering of
buffer in several payload buffer lists. Could you describe this in more
details?

With the best regards,
Vyacheslav Dubeyko.


--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Ryusuke Konishi]

On Tue, 03 Sep 2013 19:18:04 +0400, Vyacheslav Dubeyko wrote:
> Hi Ryusuke,
> 
> On Tue, 2013-09-03 at 03:13 +0900, Ryusuke Konishi wrote:
>> On Mon, 02 Sep 2013 17:27:44 +0400, Vyacheslav Dubeyko wrote:
>> > From: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
>> > Subject: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks
>> 
>> Before considering to apply this patch, please confirm that the
>> suspected issue, "dirty buffer_heads are added in several lists of
>> payload_buffers" you pointed out, is actually happening.
>> 
>> The easiest way for this is testing the following patch:
>> 
>> diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c
>> index bd88a74..cab38db 100644
>> --- a/fs/nilfs2/segment.c
>> +++ b/fs/nilfs2/segment.c
>> @@ -668,6 +668,7 @@ static size_t nilfs_lookup_dirty_data_buffers(struct inode *inode,
>>  			if (!buffer_dirty(bh))
>>  				continue;
>>  			get_bh(bh);
>> +			BUG_ON(!list_empty(&bh->b_assoc_buffers));
>>  			list_add_tail(&bh->b_assoc_buffers, listp);
>>  			ndirties++;
>>  			if (unlikely(ndirties >= nlimit)) {
>> @@ -701,6 +702,7 @@ static void nilfs_lookup_dirty_node_buffers(struct inode *inode,
>>  			do {
>>  				if (buffer_dirty(bh)) {
>>  					get_bh(bh);
>> +					BUG_ON(!list_empty(&bh->b_assoc_buffers));
>>  					list_add_tail(&bh->b_assoc_buffers,
>>  						      listp);
>>  				}
>> 
> 
> Yes, I can confirm the issue. I have applied your patch. And I have such
> output in my syslog after reproducing of the issue:
> 
> [  424.605561] ------------[ cut here ]------------
> [  424.605576] kernel BUG at fs/nilfs2/segment.c:672!
> [  424.605581] invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC
> [  424.605589] Modules linked in: rfcomm bnep bluetooth parport_pc ppdev snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_intel snd_hda_codec snd_hwdep snd_pcm xfs snd_seq_midi kvm_amd snd_rawmidi kvm snd_seq_midi_event snd_seq r8712u(C) snd_timer snd_seq_device snd sp5100_tco microcode soundcore k10temp i2c_piix4 lp snd_page_alloc parport mac_hid video ext2 sky2 btrfs raid6_pq xor zlib_deflate libcrc32c
> [  424.605650] CPU: 0 PID: 358 Comm: segctord Tainted: G         C   3.10.0-rc5+ #116
> [  424.605654] Hardware name:    /EDGE-FT1M1 E450, BIOS 4.6.4 11/15/2011
> [  424.605660] task: ffff880208ad22a0 ti: ffff8802085e0000 task.ti: ffff8802085e0000
> [  424.605663] RIP: 0010:[<ffffffff812bff53>]  [<ffffffff812bff53>] nilfs_lookup_dirty_data_buffers.isra.22+0x203/0x270
> [  424.605678] RSP: 0000:ffff8802085e1b08  EFLAGS: 00010293
> [  424.605682] RAX: ffff880219589618 RBX: ffff8802085e1c08 RCX: ffff88022dfb6000
> [  424.605685] RDX: ffff880219589660 RSI: ffff880219589618 RDI: ffff88022dff8aa8
> [  424.605689] RBP: ffff8802085e1be8 R08: 4600000000000000 R09: a8001c7123000000
> [  424.605692] R10: 57ffcd8ee41c48c0 R11: 0000000000000000 R12: 0000000000000000
> [  424.605695] R13: ffffea00071c48c0 R14: 0000000000000000 R15: 0000000000000800
> [  424.605699] FS:  00002aaaaaae3780(0000) GS:ffff880225a00000(0000) knlGS:0000000000000000
> [  424.605703] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [  424.605706] CR2: 00007fff2945bff8 CR3: 00000002186f9000 CR4: 00000000000007f0
> [  424.605710] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [  424.605713] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [  424.605716] Stack:
> [  424.605719]  ffff8802085e1b78 ffff880219177508 ffff8802191773cc ffffffffffffffff
> [  424.605728]  ffff88021a637958 000000000000000e 0000000000000000 ffffea00071c48c0
> [  424.605735]  ffffea00071c4880 ffffea00071c4840 ffffea00071c4800 ffffea00071dd7c0
> [  424.605742] Call Trace:
> [  424.605753]  [<ffffffff812c0050>] nilfs_segctor_scan_file+0x90/0x190
> [  424.605760]  [<ffffffff812c0736>] nilfs_segctor_do_construct+0x596/0x1ba0
> [  424.605767]  [<ffffffff812c2053>] nilfs_segctor_construct+0x183/0x2a0
> [  424.605774]  [<ffffffff812c22b6>] nilfs_segctor_thread+0x146/0x370
> [  424.605781]  [<ffffffff812c2170>] ? nilfs_segctor_construct+0x2a0/0x2a0
> [  424.605788]  [<ffffffff8106bc9d>] kthread+0xed/0x100
> [  424.605794]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190
> [  424.605802]  [<ffffffff816ef2dc>] ret_from_fork+0x7c/0xb0
> [  424.605808]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190
> [  424.605811] Code: ef 8b 08 d3 e6 48 63 f6 e8 2b 3d ef ff e9 19 ff ff ff 85 c0 74 ac 66 90 eb 9c 8b 95 48 ff ff ff 85 d2 75 09 e8 6f 48 42 00 eb ad <0f> 0b 48 8d bd 48 ff ff ff e8 1f 29 e7 ff e8 5a 48 42 00 eb 98 
> [  424.605886] RIP  [<ffffffff812bff53>] nilfs_lookup_dirty_data_buffers.isra.22+0x203/0x270
> [  424.605893]  RSP <ffff8802085e1b08>
> [  424.605900] ---[ end trace 0061903595fb4cff ]---

Thank you for testing the patch.
Ok, let's narrow down the root cause of this issue.

>> You can rewrite the above BUG_ON() check with the following debug code
>> if you want to get detail information on the buffer:
>> 
>>   if (!list_empty(&bh->b_assoc_buffers)) {
>>      /* dump information on bh */
>>   }
>> 
>> As a workaround, we can avoid double registration to different payload
>> lists with list_empty(&bh->b_assoc_buffers) instead of adding
>> BH_async_write flag.
>> 
> 
> Ok. I agree that we need to elaborate another fix if you think that my
> approach is not clear enough.
> 
>> However, I think we should first narrow down the root cause of why the
>> issue "dirty buffer_heads are added in several lists of
>> payload_buffers" happens.
>> 
>> We designed the log writer so that the same buffer is not registered
>> to two different payload buffer lists at the same time.  If it is not
>> satisfied, it's a bug.
>> 
>> What is the root cause of the "double registration" of a buffer head,
>> do you think?
>> 
> 
> I have such understanding of the issue's reason.
> 
> First of all, I am talking about full segments case but not about
> partial segments. As I see, all works fine for partial segments case
> because processing of partial segments of one full segment is located
> inside of one iteration of cycle in nilfs_segctor_do_construct() method.
> 
> So, if we have a file with dirty blocks count is greater than full
> segment size then such dirty file will be processed by means of several
> iterations of cycle in nilfs_segctor_do_construct() method. Also it
> needs to take into account the asynchronous nature of processing of
> submitted bio requests on block layer. The searching of dirty blocks is
> made in nilfs_lookup_dirty_data_buffers() and
> nilfs_lookup_dirty_node_buffers() on the basis of lookup of dirty memory
> pages in pagecache and selecting found dirty buffers. Found dirty blocks
> are added in current segbuf. Then it makes preparation of dirty blocks
> for write operation and submission write requests on block layer. When
> block layer ends processing of some bio then it calls
> nilfs_end_bio_write(). The segctor thread can complete write request in
> nilfs_segctor_complete_write() only after nilfs_end_bio_write() call.
> Processed buffers are made as clean namely in
> nilfs_segctor_complete_write() method. But if we submitted dirty blocks
> of file A in previous iteration and try to process dirty blocks of file
> A in next iteration again without
> nilfs_end_bio_write()/nilfs_segctor_complete_write() pair for previous
> iteration then we will have the issue of "double registration" of a
> buffer head (because we find pages under asynchronous write as dirty
> again).

Usually pages in nilfs are not marked dirty while the log writer is
writing.  ns_segctor_sem is used for this exclusion control.

But, we have an exception -- nilfs_set_page_dirty().

I now suspect the root cause is that nilfs_set_page_dirty() can
asynchronously mark pages dirty on mmapped files.

Can you confirm this assumption by comparing addresses of the
following two page structures ?

1. Address of page structures passed to nilfs_set_page_dirty().
2. bh->b_page of the buffer head captured by the above BUG_ON checks.


Regards,
Ryusuke Konishi


> Maybe I don't clear understand a condition of this issue or NILFS2
> driver's architecture but I can't see another solution for this issue
> yet. I suppose that we need to talk over the issue in more details. What
> do you think?
> 
> You said that the log writer design should prevent from registering of
> buffer in several payload buffer lists. Could you describe this in more
> details?
> 
> With the best regards,
> Vyacheslav Dubeyko.
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Vyacheslav Dubeyko]

On Thu, 2013-09-05 at 05:35 +0900, Ryusuke Konishi wrote:

> Usually pages in nilfs are not marked dirty while the log writer is
> writing.  ns_segctor_sem is used for this exclusion control.
> 
> But, we have an exception -- nilfs_set_page_dirty().
> 
> I now suspect the root cause is that nilfs_set_page_dirty() can
> asynchronously mark pages dirty on mmapped files.
> 
> Can you confirm this assumption by comparing addresses of the
> following two page structures ?
> 
> 1. Address of page structures passed to nilfs_set_page_dirty().
> 2. bh->b_page of the buffer head captured by the above BUG_ON checks.
> 

So, I have such output in my syslog:

[  257.825054] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
[  257.825072] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
[  257.855659] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
[  258.115918] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
[  258.622433] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
[  258.622433] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
[  258.643247] NILFS [nilfs_lookup_dirty_data_buffers]:673 bh->b_page ffffea000687d680, bh->b_blocknr 0
[  258.643290] ------------[ cut here ]------------
[  258.643294] kernel BUG at fs/nilfs2/segment.c:676!

And I can see such call trace for the case of nilfs_set_page_dirty()
call:

[  441.538563] Call Trace:
[  441.538568]  [<ffffffff816df345>] dump_stack+0x19/0x1b
[  441.538574]  [<ffffffff812ae1cc>] nilfs_set_page_dirty+0x1c/0xa0
[  441.538579]  [<ffffffff8112e75e>] set_page_dirty+0x3e/0x60
[  441.538584]  [<ffffffff8112e838>] clear_page_dirty_for_io+0xb8/0xc0
[  441.538589]  [<ffffffff812c01d9>] nilfs_begin_page_io.part.24+0x29/0x50
[  441.538595]  [<ffffffff812c0e6c>] nilfs_segctor_do_construct+0xc6c/0x1ba0
[  441.538601]  [<ffffffff812c20b3>] nilfs_segctor_construct+0x183/0x2a0
[  441.538607]  [<ffffffff812c2316>] nilfs_segctor_thread+0x146/0x370
[  441.538613]  [<ffffffff812c21d0>] ? nilfs_segctor_construct+0x2a0/0x2a0
[  441.538617]  [<ffffffff8106bc9d>] kthread+0xed/0x100
[  441.538623]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190
[  441.538628]  [<ffffffff816ef35c>] ret_from_fork+0x7c/0xb0
[  441.538633]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190

So, as I understand, segctor thread calls nilfs_set_page_dirty() on the
segment construction phase by itself.

Today I haven't more time for analyzing it in details. I hope that this
output will be useful for you. I'll analyze it more deeply tomorrow. And
if you need in additional details, please, feel free to ask me.

With the best regards,
Vyacheslav Dubeyko.

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Ryusuke Konishi]

Hi Vyacheslav,
On Thu, 05 Sep 2013 19:42:58 +0400, Vyacheslav Dubeyko wrote:
> On Thu, 2013-09-05 at 05:35 +0900, Ryusuke Konishi wrote:
> 
>> Usually pages in nilfs are not marked dirty while the log writer is
>> writing.  ns_segctor_sem is used for this exclusion control.
>> 
>> But, we have an exception -- nilfs_set_page_dirty().
>> 
>> I now suspect the root cause is that nilfs_set_page_dirty() can
>> asynchronously mark pages dirty on mmapped files.
>> 
>> Can you confirm this assumption by comparing addresses of the
>> following two page structures ?
>> 
>> 1. Address of page structures passed to nilfs_set_page_dirty().
>> 2. bh->b_page of the buffer head captured by the above BUG_ON checks.
>> 
> 
> So, I have such output in my syslog:
> 
> [  257.825054] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
> [  257.825072] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
> [  257.855659] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
> [  258.115918] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
> [  258.622433] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
> [  258.622433] NILFS [nilfs_set_page_dirty]:225 page ffffea000687d680
> [  258.643247] NILFS [nilfs_lookup_dirty_data_buffers]:673 bh->b_page ffffea000687d680, bh->b_blocknr 0
> [  258.643290] ------------[ cut here ]------------
> [  258.643294] kernel BUG at fs/nilfs2/segment.c:676!
> 
> And I can see such call trace for the case of nilfs_set_page_dirty()
> call:
> 
> [  441.538563] Call Trace:
> [  441.538568]  [<ffffffff816df345>] dump_stack+0x19/0x1b
> [  441.538574]  [<ffffffff812ae1cc>] nilfs_set_page_dirty+0x1c/0xa0
> [  441.538579]  [<ffffffff8112e75e>] set_page_dirty+0x3e/0x60
> [  441.538584]  [<ffffffff8112e838>] clear_page_dirty_for_io+0xb8/0xc0
> [  441.538589]  [<ffffffff812c01d9>] nilfs_begin_page_io.part.24+0x29/0x50
> [  441.538595]  [<ffffffff812c0e6c>] nilfs_segctor_do_construct+0xc6c/0x1ba0
> [  441.538601]  [<ffffffff812c20b3>] nilfs_segctor_construct+0x183/0x2a0
> [  441.538607]  [<ffffffff812c2316>] nilfs_segctor_thread+0x146/0x370
> [  441.538613]  [<ffffffff812c21d0>] ? nilfs_segctor_construct+0x2a0/0x2a0
> [  441.538617]  [<ffffffff8106bc9d>] kthread+0xed/0x100
> [  441.538623]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190
> [  441.538628]  [<ffffffff816ef35c>] ret_from_fork+0x7c/0xb0
> [  441.538633]  [<ffffffff8106bbb0>] ? flush_kthread_worker+0x190/0x190
> 
> So, as I understand, segctor thread calls nilfs_set_page_dirty() on the
> segment construction phase by itself.

So, nilfs_set_page_dirty() turned out to make some buffers dirty
asynchronously and cause the issue as I predicted.

I looked again at nilfs_set_page_dirty().  This function implements
aops->set_page_dirty(), and is called from several callers.

When this function is called, the page is locked, but it is not
guaranteed that ns_segctor_sem is locked, and this restriction is
unavoidable.  If all callers wait on page writeback flag just before
calling aops->set_page_dirty, the problem doesn't arise, but this is
not satisfied, either.

We can change nilfs_set_page_dirty() not to make the given page dirty
if its page writeback flag is set.  But this approach doesn't work
properly when a page has multiple buffers and was partially dirtied.

So, I reached a conclusion that simply skipping reentry of buffer
heads to the payload list of log writer is better approach at present.
Your patch looks proper from this standpoint.


Acked-by: Ryusuke Konishi <konishi.ryusuke@lab.ntt.co.jp>


Vyacheslav, could you please test your patch for 1KB-block format to
make sure ?


Thanks,
Ryusuke Konishi

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Vyacheslav Dubeyko]

Hi Ryusuke,

On Thu, 2013-09-19 at 03:09 +0900, Ryusuke Konishi wrote:

[snip]
> 
> Vyacheslav, could you please test your patch for 1KB-block format to
> make sure ?
> 

Yes, sure. I need to prepare rootfs with 1 KB block size. So, I will
spend some time for preparation, reproducing of the issue and patch
testing.

I will share results of testing.

With the best regards,
Vyacheslav Dubeyko.

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Vyacheslav Dubeyko]

Hi Ryusuke,

> On Thu, 2013-09-19 at 03:09 +0900, Ryusuke Konishi wrote:
> 
> [snip]
> > 
> > Vyacheslav, could you please test your patch for 1KB-block format to
> > make sure ?
> > 

I have prepared NILFS2 rootfs with 1 KB block size and I tried to
reproduce the issue as for 1 KB block size as for 4 KB block size. So, I
can see such situation. I reproduce the issue for 4 KB block size,
easily. But I can't reproduce the issue for the rootfs with 1 KB block
size.

I tried to reproduce the issue several times. And every time I reproduce
the issue for 4 KB block size and I don't reproduce the issue for 1 KB
block size.

With the best regards,
Vyacheslav Dubeyko.


--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] [CRITICAL] nilfs2: fix issue with race condition of competition between segments for dirty blocks

[Ryusuke Konishi]

On Wed, 25 Sep 2013 16:22:43 +0400, Vyacheslav Dubeyko wrote:
> Hi Ryusuke,
> 
>> On Thu, 2013-09-19 at 03:09 +0900, Ryusuke Konishi wrote:
>> 
>> [snip]
>> > 
>> > Vyacheslav, could you please test your patch for 1KB-block format to
>> > make sure ?
>> > 
> 
> I have prepared NILFS2 rootfs with 1 KB block size and I tried to
> reproduce the issue as for 1 KB block size as for 4 KB block size. So, I
> can see such situation. I reproduce the issue for 4 KB block size,
> easily. But I can't reproduce the issue for the rootfs with 1 KB block
> size.
> 
> I tried to reproduce the issue several times. And every time I reproduce
> the issue for 4 KB block size and I don't reproduce the issue for 1 KB
> block size.

Ok, thank you for your effort trying to reproduce the issue.

Andrew, please send this patch to the upstream.


Thanks,
Ryusuke Konishi
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html