sb_fdblocks inconsistency in xfs/297 test

BUG 4.10-rc7 Eryu Guan 3 participants 11 messages Feb 10, 2017 – Feb 21, 2017

Subsystems (2)

VFS Filesystem direct access (DAX)

lore

Share & tools

lore

Eryu Guan

author

2017-02-10 04:17 UTC #0 lore raw

Hi,

I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to

commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d

Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800

fs: break out of iomap_file_buffered_write on fatal signals

Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....

It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...

And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).

Thanks,
Eryu

P.S. full xfs_repair -n output

*** xfs_repair -n output ***
Phase 1 - find and verify superblock...
- reporting progress in intervals of 15 minutes
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
Phase 3 - for each AG...
- scan (but don't clear) agi unlinked lists...
- 11:37:41: scanning agi unlinked lists - 16 of 16 allocation groups done
- process known inodes and perform inode discovery...
- agno = 0
- agno = 15
- agno = 1
- agno = 2
- agno = 3
- agno = 4
- agno = 5
- agno = 6
- agno = 7
- agno = 8
- agno = 9
- agno = 10
- agno = 11
- agno = 12
- agno = 13
- agno = 14
- 11:37:42: process known inodes and inode discovery - 13760 of 13760 inodes done
- process newly discovered inodes...
- 11:37:42: process newly discovered inodes - 16 of 16 allocation groups done
Phase 4 - check for duplicate blocks...
- setting up duplicate extent list...
- 11:37:42: setting up duplicate extent list - 16 of 16 allocation groups done
- check for inodes claiming duplicate blocks...
- agno = 0
- agno = 2
- agno = 3
- agno = 1
- agno = 4
- agno = 5
- agno = 6
- agno = 7
- agno = 8
- agno = 9
- agno = 10
- agno = 11
- agno = 12
- agno = 13
- agno = 14
- agno = 15
- 11:37:42: check for inodes claiming duplicate blocks - 13760 of 13760 inodes done
No modify flag set, skipping phase 5
Phase 6 - check inode connectivity...
- traversing filesystem ...
- traversal finished ...
- moving disconnected inodes to lost+found ...
Phase 7 - verify link counts...
- 11:37:43: verify and correct link counts - 16 of 16 allocation groups done
No modify flag set, skipping filesystem flush and exiting.

Eryu Guan

author

2017-02-10 04:21 UTC #1 lore raw

Quoted 4 lines · Eryu Guan

Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6

Seems generic/269 reproduces it easily too. I also saw xfs/167 fail on ppc64 host because of this issue, but rarely.

Thanks,
Eryu

Michal Hocko

2017-02-10 07:14 UTC #2 lore raw

In reply to Eryu Guan

Quoted 27 lines · Eryu Guan

Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to
commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d
Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800
fs: break out of iomap_file_buffered_write on fatal signals
Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....
It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...

Quoted 4 lines

And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).

The patch can lead to short writes when the task is killed. Was there any OOM killer triggered during the test? If not who is killing the task? I will try to reproduce later today.

Signature · 2 lines

Michal Hocko
SUSE Labs

Michal Hocko

2017-02-10 08:02 UTC #3 lore raw

Quoted 28 lines · Michal Hocko

Quoted 27 lines · Eryu Guan
Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to
commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d
Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800
fs: break out of iomap_file_buffered_write on fatal signals
Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....
It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...

Quoted 8 lines

Quoted 4 lines
And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).
The patch can lead to short writes when the task is killed. Was there any OOM killer triggered during the test? If not who is killing the task? I will try to reproduce later today.

I have checked both tests and they are killing the test but none of them seems to be using SIGKILL. The patch should make a difference only for fatal signal (aka SIGKILL). Is there any other part that can do SIGKILL except for the OOM killer?

Signature · 2 lines

Michal Hocko
SUSE Labs

Michal Hocko

2017-02-10 09:32 UTC #4 lore raw

[CC Christoph]

Quoted 34 lines · Michal Hocko

Quoted 33 lines · Michal Hocko
Quoted 31 lines · Eryu Guan
Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to
commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d
Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800
fs: break out of iomap_file_buffered_write on fatal signals
Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....
It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...
And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).

Quoted 8 lines

Quoted 3 lines
The patch can lead to short writes when the task is killed. Was there any OOM killer triggered during the test? If not who is killing the task? I will try to reproduce later today.
I have checked both tests and they are killing the test but none of them seems to be using SIGKILL. The patch should make a difference only for fatal signal (aka SIGKILL). Is there any other part that can do SIGKILL except for the OOM killer?

I have done

fs/dax.c +1 -0

index c45598b912e1..4de00ceaf73d 100644
@@ -1032,6 +1032,7 @@ dax_iomap_actor(struct inode *inode, loff_t pos, loff_t length, void *data,
 		ssize_t map_len;
 
 		if (fatal_signal_pending(current)) {
+			WARN(1, "dax_iomap_actor\n");
 			ret = -EINTR;
 			break;
 		}

fs/iomap.c +3 -1

index a51cb4c07d4d..00019e2cdad3 100644
@@ -114,8 +114,10 @@ iomap_write_begin(struct inode *inode, loff_t pos, unsigned len, unsigned flags,
 
 	BUG_ON(pos + len > iomap->offset + iomap->length);
 
-	if (fatal_signal_pending(current))
+	if (fatal_signal_pending(current)) {
+		WARN(1, "iomap_write_begin\n");
 		return -EINTR;
+	}
 
 	page = grab_cache_page_write_begin(inode->i_mapping, index, flags);
 	if (!page)

and it triggered

[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.087297] WARNING: CPU: 1 PID: 4899 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.150542] WARNING: CPU: 2 PID: 4857 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.153653] WARNING: CPU: 3 PID: 4889 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154413] WARNING: CPU: 0 PID: 4929 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154734] WARNING: CPU: 3 PID: 4934 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.162743] WARNING: CPU: 0 PID: 4813 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163282] WARNING: CPU: 1 PID: 4891 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163820] WARNING: CPU: 0 PID: 4932 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.169112] WARNING: CPU: 0 PID: 4923 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.182816] WARNING: CPU: 0 PID: 4892 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.321991] WARNING: CPU: 3 PID: 4872 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c

always from

[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.057092] iomap_write_begin
[  135.057556] Modules linked in: xfs libcrc32c
[  135.058191] CPU: 2 PID: 4894 Comm: fsstress Tainted: G        W       4.10.0-rc6-test1-00149-gd1908f52557b-dirty #1064
[  135.060349] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1 04/01/2014
[  135.060865] Call Trace:
[  135.060865]  dump_stack+0x68/0x92
[  135.060865]  __warn+0xc2/0xdd
[  135.060865]  warn_slowpath_fmt+0x4b/0x53
[  135.060865]  iomap_write_begin+0x72/0x12c
[  135.060865]  iomap_write_actor+0x99/0x161
[  135.060865]  iomap_apply+0x9e/0xec
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  iomap_file_buffered_write+0x5b/0x7f
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  xfs_file_buffered_aio_write+0x187/0x2b4 [xfs]
[  135.060865]  xfs_file_write_iter+0x93/0x11c [xfs]
[  135.060865]  __vfs_write+0xcc/0xf5
[  135.060865]  vfs_write+0x100/0x1a9
[  135.060865]  SyS_write+0x51/0x8e

So somebody had to send SIGKILL to fsstress. Anyway, I am wondering whether this is really a regression. xfs_file_buffered_aio_write used to call generic_perform_write which does the same thing.

Signature · 2 lines

Michal Hocko
SUSE Labs

Eryu Guan

author

2017-02-11 06:02 UTC #5 lore raw

Quoted 45 lines · Michal Hocko

[CC Christoph]
Quoted 42 lines · Michal Hocko
Quoted 28 lines · Michal Hocko
Quoted 27 lines · Eryu Guan
Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to
commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d
Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800
fs: break out of iomap_file_buffered_write on fatal signals
Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....
It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...
Quoted 8 lines
Quoted 4 lines
And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).
The patch can lead to short writes when the task is killed. Was there any OOM killer triggered during the test? If not who is killing the task? I will try to reproduce later today.
I have checked both tests and they are killing the test but none of them seems to be using SIGKILL. The patch should make a difference only for fatal signal (aka SIGKILL). Is there any other part that can do SIGKILL except for the OOM killer?

No, I'm not aware of any other part in fstests harness could send SIGKILL.

I also noticed xfs/274 xfs/275 failed due to the same sb_fdblocks inconsistency (xfs_1k_rmap test config), which have no kill/killall involved at all.

BTW, I'm using latest xfsprogs for-next branch in all my testing, in case it matters.

Quoted 2 lines

I have done

Thanks for looking into this! This issue seems to cause random fstests failures on xfs.

Quoted 65 lines

fs/dax.c +1 -0

index c45598b912e1..4de00ceaf73d 100644
@@ -1032,6 +1032,7 @@ dax_iomap_actor(struct inode *inode, loff_t pos, loff_t length, void *data,
 		ssize_t map_len;
 
 		if (fatal_signal_pending(current)) {
+			WARN(1, "dax_iomap_actor\n");
 			ret = -EINTR;
 			break;
 		}

fs/iomap.c +3 -1

index a51cb4c07d4d..00019e2cdad3 100644
@@ -114,8 +114,10 @@ iomap_write_begin(struct inode *inode, loff_t pos, unsigned len, unsigned flags,
 
 	BUG_ON(pos + len > iomap->offset + iomap->length);
 
-	if (fatal_signal_pending(current))
+	if (fatal_signal_pending(current)) {
+		WARN(1, "iomap_write_begin\n");
 		return -EINTR;
+	}
 
 	page = grab_cache_page_write_begin(inode->i_mapping, index, flags);
 	if (!page)

and it triggered

[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.087297] WARNING: CPU: 1 PID: 4899 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.150542] WARNING: CPU: 2 PID: 4857 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.153653] WARNING: CPU: 3 PID: 4889 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154413] WARNING: CPU: 0 PID: 4929 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154734] WARNING: CPU: 3 PID: 4934 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.162743] WARNING: CPU: 0 PID: 4813 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163282] WARNING: CPU: 1 PID: 4891 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163820] WARNING: CPU: 0 PID: 4932 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.169112] WARNING: CPU: 0 PID: 4923 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.182816] WARNING: CPU: 0 PID: 4892 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.321991] WARNING: CPU: 3 PID: 4872 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c

always from

[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.057092] iomap_write_begin
[  135.057556] Modules linked in: xfs libcrc32c
[  135.058191] CPU: 2 PID: 4894 Comm: fsstress Tainted: G        W       4.10.0-rc6-test1-00149-gd1908f52557b-dirty #1064
[  135.060349] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1 04/01/2014
[  135.060865] Call Trace:
[  135.060865]  dump_stack+0x68/0x92
[  135.060865]  __warn+0xc2/0xdd
[  135.060865]  warn_slowpath_fmt+0x4b/0x53
[  135.060865]  iomap_write_begin+0x72/0x12c
[  135.060865]  iomap_write_actor+0x99/0x161
[  135.060865]  iomap_apply+0x9e/0xec
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  iomap_file_buffered_write+0x5b/0x7f
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  xfs_file_buffered_aio_write+0x187/0x2b4 [xfs]
[  135.060865]  xfs_file_write_iter+0x93/0x11c [xfs]
[  135.060865]  __vfs_write+0xcc/0xf5
[  135.060865]  vfs_write+0x100/0x1a9
[  135.060865]  SyS_write+0x51/0x8e

Quoted 3 lines

So somebody had to send SIGKILL to fsstress. Anyway, I am wondering whether this is really a regression. xfs_file_buffered_aio_write used to call generic_perform_write which does the same thing.

Maybe it just uncovered some existing bug? Anyway, a reliable reproduced filesystem metadata inconsistency does smell like a bug.

Thanks,
Eryu

Michal Hocko

2017-02-11 06:35 UTC #6 lore raw

Quoted 42 lines · Eryu Guan

Quoted 41 lines · Michal Hocko
[CC Christoph]
Quoted 38 lines · Michal Hocko
Quoted 36 lines · Michal Hocko
Quoted 27 lines · Eryu Guan
Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to
commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d
Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800
fs: break out of iomap_file_buffered_write on fatal signals
Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....
It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...
Quoted 4 lines
And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).
The patch can lead to short writes when the task is killed. Was there any OOM killer triggered during the test? If not who is killing the task? I will try to reproduce later today.

Quoted 7 lines

Quoted 4 lines
Quoted 4 lines
I have checked both tests and they are killing the test but none of them seems to be using SIGKILL. The patch should make a difference only for fatal signal (aka SIGKILL). Is there any other part that can do SIGKILL except for the OOM killer?
No, I'm not aware of any other part in fstests harness could send SIGKILL.

hmm, maybe this is a result of the group_exit which sends SIGKILL to other threads (zap_other_threads)

[...]

Quoted 5 lines

Quoted 3 lines
So somebody had to send SIGKILL to fsstress. Anyway, I am wondering whether this is really a regression. xfs_file_buffered_aio_write used to call generic_perform_write which does the same thing.
Maybe it just uncovered some existing bug?

maybe

Quoted 2 lines

Anyway, a reliable reproduced filesystem metadata inconsistency does smell like a bug.

definitely! Unfortunately I am going to disappear for week. Will be back on 20th. Anyway, I believe iomap_file_buffered_write and its callers _should_ be able to handle short reads. EINTR is not the only way how can this happen. ENOMEM would be another.

Signature · 2 lines

Michal Hocko
SUSE Labs

Michal Hocko

2017-02-20 14:26 UTC #7 lore raw

In reply to Michal Hocko

I have discussed that shortly with Jack and he suspects that xfs specific part of the iomap callbacks doesn't cancel reservations. Let's CC more xfs people. The thread starts
http://lkml.kernel.org/r/[email protected]

Quoted 118 lines · Michal Hocko

[CC Christoph]
Quoted 34 lines · Michal Hocko
Quoted 33 lines · Michal Hocko
Quoted 31 lines · Eryu Guan
Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to
commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d
Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800
fs: break out of iomap_file_buffered_write on fatal signals
Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....
It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...
And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).
Quoted 8 lines
Quoted 3 lines
The patch can lead to short writes when the task is killed. Was there any OOM killer triggered during the test? If not who is killing the task? I will try to reproduce later today.
I have checked both tests and they are killing the test but none of them seems to be using SIGKILL. The patch should make a difference only for fatal signal (aka SIGKILL). Is there any other part that can do SIGKILL except for the OOM killer?
I have done
fs/dax.c +1 -0
index c45598b912e1..4de00ceaf73d 100644
@@ -1032,6 +1032,7 @@ dax_iomap_actor(struct inode *inode, loff_t pos, loff_t length, void *data,
 		ssize_t map_len;
 
 		if (fatal_signal_pending(current)) {
+			WARN(1, "dax_iomap_actor\n");
 			ret = -EINTR;
 			break;
 		}
fs/iomap.c +3 -1
index a51cb4c07d4d..00019e2cdad3 100644
@@ -114,8 +114,10 @@ iomap_write_begin(struct inode *inode, loff_t pos, unsigned len, unsigned flags,
 
 	BUG_ON(pos + len > iomap->offset + iomap->length);
 
-	if (fatal_signal_pending(current))
+	if (fatal_signal_pending(current)) {
+		WARN(1, "iomap_write_begin\n");
 		return -EINTR;
+	}
 
 	page = grab_cache_page_write_begin(inode->i_mapping, index, flags);
 	if (!page)
and it triggered
[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.087297] WARNING: CPU: 1 PID: 4899 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.150542] WARNING: CPU: 2 PID: 4857 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.153653] WARNING: CPU: 3 PID: 4889 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154413] WARNING: CPU: 0 PID: 4929 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154734] WARNING: CPU: 3 PID: 4934 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.162743] WARNING: CPU: 0 PID: 4813 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163282] WARNING: CPU: 1 PID: 4891 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163820] WARNING: CPU: 0 PID: 4932 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.169112] WARNING: CPU: 0 PID: 4923 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.182816] WARNING: CPU: 0 PID: 4892 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.321991] WARNING: CPU: 3 PID: 4872 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
always from
[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.057092] iomap_write_begin
[  135.057556] Modules linked in: xfs libcrc32c
[  135.058191] CPU: 2 PID: 4894 Comm: fsstress Tainted: G        W       4.10.0-rc6-test1-00149-gd1908f52557b-dirty #1064
[  135.060349] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1 04/01/2014
[  135.060865] Call Trace:
[  135.060865]  dump_stack+0x68/0x92
[  135.060865]  __warn+0xc2/0xdd
[  135.060865]  warn_slowpath_fmt+0x4b/0x53
[  135.060865]  iomap_write_begin+0x72/0x12c
[  135.060865]  iomap_write_actor+0x99/0x161
[  135.060865]  iomap_apply+0x9e/0xec
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  iomap_file_buffered_write+0x5b/0x7f
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  xfs_file_buffered_aio_write+0x187/0x2b4 [xfs]
[  135.060865]  xfs_file_write_iter+0x93/0x11c [xfs]
[  135.060865]  __vfs_write+0xcc/0xf5
[  135.060865]  vfs_write+0x100/0x1a9
[  135.060865]  SyS_write+0x51/0x8e
So somebody had to send SIGKILL to fsstress. Anyway, I am wondering whether this is really a regression. xfs_file_buffered_aio_write used to call generic_perform_write which does the same thing.
Signature · 2 lines
Michal Hocko
SUSE Labs

Signature · 2 lines

Michal Hocko
SUSE Labs

Brian Foster

2017-02-20 14:59 UTC #8 lore raw

Quoted 5 lines · Michal Hocko

I have discussed that shortly with Jack and he suspects that xfs specific part of the iomap callbacks doesn't cancel reservations. Let's CC more xfs people. The thread starts
http://lkml.kernel.org/r/[email protected]

Have you tried commit fa7f138 ("xfs: clear delalloc and cache on buffered write failure"), currently in for-next?

Brian

Quoted 127 lines · Michal Hocko

Quoted 118 lines
[CC Christoph]
Quoted 34 lines · Michal Hocko
Quoted 33 lines · Michal Hocko
Quoted 31 lines · Eryu Guan
Hi,
I was testing 4.10-rc7 kernel and noticed that xfs_repair reported XFS corruption after fstests xfs/297 test. This didn't happen with 4.10-rc6 kernel, and git bisect pointed the first bad commit to
commit d1908f52557b3230fbd63c0429f3b4b748bf2b6d
Author: Michal Hocko <[email protected]>
Date:   Fri Feb 3 13:13:26 2017 -0800
fs: break out of iomap_file_buffered_write on fatal signals
Tetsuo has noticed that an OOM stress test which performs large write requests can cause the full memory reserves depletion. He has tracked this down to the following path
....
It's the sb_fdblocks field reports inconsistency:
...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
sb_fdblocks 3367765, counted 3367863
- 11:37:41: scanning filesystem freespace - 16 of 16 allocation groups done
- found root inode chunk
...
And it can be reproduced almost 100% with all XFS test configurations (e.g. xfs_4k xfs_2k_reflink), on all test hosts I tried (so I didn't bother pasting my detailed test and host configs, if more info is needed please let me know).
Quoted 8 lines
Quoted 3 lines
The patch can lead to short writes when the task is killed. Was there any OOM killer triggered during the test? If not who is killing the task? I will try to reproduce later today.
I have checked both tests and they are killing the test but none of them seems to be using SIGKILL. The patch should make a difference only for fatal signal (aka SIGKILL). Is there any other part that can do SIGKILL except for the OOM killer?
I have done
fs/dax.c +1 -0
index c45598b912e1..4de00ceaf73d 100644
@@ -1032,6 +1032,7 @@ dax_iomap_actor(struct inode *inode, loff_t pos, loff_t length, void *data,
 		ssize_t map_len;
 
 		if (fatal_signal_pending(current)) {
+			WARN(1, "dax_iomap_actor\n");
 			ret = -EINTR;
 			break;
 		}
fs/iomap.c +3 -1
index a51cb4c07d4d..00019e2cdad3 100644
@@ -114,8 +114,10 @@ iomap_write_begin(struct inode *inode, loff_t pos, unsigned len, unsigned flags,
 
 	BUG_ON(pos + len > iomap->offset + iomap->length);
 
-	if (fatal_signal_pending(current))
+	if (fatal_signal_pending(current)) {
+		WARN(1, "iomap_write_begin\n");
 		return -EINTR;
+	}
 
 	page = grab_cache_page_write_begin(inode->i_mapping, index, flags);
 	if (!page)
and it triggered
[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.087297] WARNING: CPU: 1 PID: 4899 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.150542] WARNING: CPU: 2 PID: 4857 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.153653] WARNING: CPU: 3 PID: 4889 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154413] WARNING: CPU: 0 PID: 4929 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.154734] WARNING: CPU: 3 PID: 4934 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.162743] WARNING: CPU: 0 PID: 4813 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163282] WARNING: CPU: 1 PID: 4891 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.163820] WARNING: CPU: 0 PID: 4932 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.169112] WARNING: CPU: 0 PID: 4923 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.182816] WARNING: CPU: 0 PID: 4892 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.321991] WARNING: CPU: 3 PID: 4872 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
always from
[  135.055682] WARNING: CPU: 2 PID: 4894 at fs/iomap.c:118 iomap_write_begin+0x72/0x12c
[  135.057092] iomap_write_begin
[  135.057556] Modules linked in: xfs libcrc32c
[  135.058191] CPU: 2 PID: 4894 Comm: fsstress Tainted: G        W       4.10.0-rc6-test1-00149-gd1908f52557b-dirty #1064
[  135.060349] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1 04/01/2014
[  135.060865] Call Trace:
[  135.060865]  dump_stack+0x68/0x92
[  135.060865]  __warn+0xc2/0xdd
[  135.060865]  warn_slowpath_fmt+0x4b/0x53
[  135.060865]  iomap_write_begin+0x72/0x12c
[  135.060865]  iomap_write_actor+0x99/0x161
[  135.060865]  iomap_apply+0x9e/0xec
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  iomap_file_buffered_write+0x5b/0x7f
[  135.060865]  ? iomap_write_end+0x62/0x62
[  135.060865]  xfs_file_buffered_aio_write+0x187/0x2b4 [xfs]
[  135.060865]  xfs_file_write_iter+0x93/0x11c [xfs]
[  135.060865]  __vfs_write+0xcc/0xf5
[  135.060865]  vfs_write+0x100/0x1a9
[  135.060865]  SyS_write+0x51/0x8e
So somebody had to send SIGKILL to fsstress. Anyway, I am wondering whether this is really a regression. xfs_file_buffered_aio_write used to call generic_perform_write which does the same thing.
Signature · 2 lines
Michal Hocko
SUSE Labs
Signature · 6 lines
Michal Hocko
SUSE Labs
--
To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Eryu Guan

author

2017-02-21 04:14 UTC #9 lore raw

Quoted 9 lines · Brian Foster

Quoted 5 lines · Michal Hocko
I have discussed that shortly with Jack and he suspects that xfs specific part of the iomap callbacks doesn't cancel reservations. Let's CC more xfs people. The thread starts
http://lkml.kernel.org/r/[email protected]
Have you tried commit fa7f138 ("xfs: clear delalloc and cache on buffered write failure"), currently in for-next?

I cherry-picked this commit to 4.10-rc8 tree and xfs/297 xfs/305 all passed for me without fs corruption. They used to fail for me reliably with stock 4.10-rc8 kernel. Thanks all for looking at this!

Thanks,
Eryu

Michal Hocko

2017-02-21 08:14 UTC #10 lore raw

Quoted 8 lines · Eryu Guan

Quoted 7 lines · Brian Foster
Quoted 5 lines · Michal Hocko
I have discussed that shortly with Jack and he suspects that xfs specific part of the iomap callbacks doesn't cancel reservations. Let's CC more xfs people. The thread starts
http://lkml.kernel.org/r/[email protected]

Quoted 6 lines

Quoted 2 lines
Have you tried commit fa7f138 ("xfs: clear delalloc and cache on buffered write failure"), currently in for-next?
I cherry-picked this commit to 4.10-rc8 tree and xfs/297 xfs/305 all passed for me without fs corruption. They used to fail for me reliably with stock 4.10-rc8 kernel. Thanks all for looking at this!

Brian, could you make sure that your commit gets to stable (at least) 4.8+ because that is where d1908f52557b ("fs: break out of iomap_file_buffered_write on fatal signals") will be backported to.

Signature · 2 lines

Michal Hocko
SUSE Labs