| Message ID | 20220721022959.4189726-1-bxue@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [v1] generic/476: requires 27GB scratch size | expand |
on 2022/07/21 10:29, bxue@redhat.com wrote: > From: Boyang Xue <bxue@redhat.com> > > The test requires larger scratch dev size when running on top of NFS other > than ext4 and xfs. It requires at least 27GB in my test. Without this > requirement, the test run never finishes on NFS, leaving 100% scratch disk > space use. > > Signed-off-by: Boyang Xue <bxue@redhat.com> > --- > Hi, > > I find generic/476 easily goes into an infinite run on top of NFS. When it > happens, the common pattern is 100% disk space use of SCRATCH_MNT, and > `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large > enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size > requirement. > > Please help review this patch. Thanks! > > -Boyang > > tests/generic/476 | 1 + > 1 file changed, 1 insertion(+) > > diff --git a/tests/generic/476 b/tests/generic/476 > index 212373d1..dcc7c3da 100755 > --- a/tests/generic/476 > +++ b/tests/generic/476 > @@ -24,6 +24,7 @@ _cleanup() > _supported_fs generic > > _require_scratch > +_require_scratch_size $((27 * 1024 * 1024)) # 27GB If NFS needs this requirement, why do you require all filesystem meet this? It will break test when using local filesystem ie xfs,ext4(as README says the minimum requiremount is 10G). I often use 20G as test device and scratch device. Also, I think you should figure out why NFS 100% use space. Use a large device size only hides a bug. Best Regards Yang Xu > _require_command "$KILLALL_PROG" "killall" > > echo "Silence is golden."
On Thu, Jul 21, 2022 at 10:29:59AM +0800, bxue@redhat.com wrote: > From: Boyang Xue <bxue@redhat.com> > > The test requires larger scratch dev size when running on top of NFS other > than ext4 and xfs. It requires at least 27GB in my test. Without this > requirement, the test run never finishes on NFS, leaving 100% scratch disk > space use. > Signed-off-by: Boyang Xue <bxue@redhat.com> > --- > Hi, > > I find generic/476 easily goes into an infinite run on top of NFS. When it Infinite? It's only supposed to start 25000*nr_cpus*TIME_FACTOR operations, so it /should/ conclude eventually. That includes driving the filesystem completel out of space, but there ought to be enough unlink/rmdir/truncate calls to free up space every now and then... > happens, the common pattern is 100% disk space use of SCRATCH_MNT, and > `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large > enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size > requirement. > > Please help review this patch. Thanks! > > -Boyang > > tests/generic/476 | 1 + > 1 file changed, 1 insertion(+) > > diff --git a/tests/generic/476 b/tests/generic/476 > index 212373d1..dcc7c3da 100755 > --- a/tests/generic/476 > +++ b/tests/generic/476 > @@ -24,6 +24,7 @@ _cleanup() > _supported_fs generic > > _require_scratch > +_require_scratch_size $((27 * 1024 * 1024)) # 27GB ...so IDGI, this test works as intended. Are you saying that NFS command overhead is so high that this test takes too long? --D > _require_command "$KILLALL_PROG" "killall" > > echo "Silence is golden." > -- > 2.27.0 >
On Thu, Jul 21, 2022 at 10:50 AM xuyang2018.jy@fujitsu.com <xuyang2018.jy@fujitsu.com> wrote: > > on 2022/07/21 10:29, bxue@redhat.com wrote: > > From: Boyang Xue <bxue@redhat.com> > > > > The test requires larger scratch dev size when running on top of NFS other > > than ext4 and xfs. It requires at least 27GB in my test. Without this > > requirement, the test run never finishes on NFS, leaving 100% scratch disk > > space use. > > > > Signed-off-by: Boyang Xue <bxue@redhat.com> > > --- > > Hi, > > > > I find generic/476 easily goes into an infinite run on top of NFS. When it > > happens, the common pattern is 100% disk space use of SCRATCH_MNT, and > > `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large > > enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size > > requirement. > > > > Please help review this patch. Thanks! > > > > -Boyang > > > > tests/generic/476 | 1 + > > 1 file changed, 1 insertion(+) > > > > diff --git a/tests/generic/476 b/tests/generic/476 > > index 212373d1..dcc7c3da 100755 > > --- a/tests/generic/476 > > +++ b/tests/generic/476 > > @@ -24,6 +24,7 @@ _cleanup() > > _supported_fs generic > > > > _require_scratch > > +_require_scratch_size $((27 * 1024 * 1024)) # 27GB > > If NFS needs this requirement, why do you require all filesystem meet this? I can fix this by requiring the 27GB only when the target is NFS in the next version of the patch. > > It will break test when using local filesystem ie xfs,ext4(as README > says the minimum requiremount is 10G). I often use 20G as test device > and scratch device. > > Also, I think you should figure out why NFS 100% use space. Use a large > device size only hides a bug. I think the test use 100% space just because the scratch device in test is too small for the full operations of the test, and I guess the test requires a so large device for NFS from day1 of the test. Thanks, Boyang > > Best Regards > Yang Xu > > _require_command "$KILLALL_PROG" "killall" > > > > echo "Silence is golden."
On Thu, Jul 21, 2022 at 12:40 PM Darrick J. Wong <djwong@kernel.org> wrote: > > On Thu, Jul 21, 2022 at 10:29:59AM +0800, bxue@redhat.com wrote: > > From: Boyang Xue <bxue@redhat.com> > > > > The test requires larger scratch dev size when running on top of NFS other > > than ext4 and xfs. It requires at least 27GB in my test. Without this > > requirement, the test run never finishes on NFS, leaving 100% scratch disk > > space use. > > > Signed-off-by: Boyang Xue <bxue@redhat.com> > > --- > > Hi, > > > > I find generic/476 easily goes into an infinite run on top of NFS. When it > > Infinite? It's only supposed to start 25000*nr_cpus*TIME_FACTOR > operations, so it /should/ conclude eventually. That includes driving > the filesystem completel out of space, but there ought to be enough > unlink/rmdir/truncate calls to free up space every now and then... Yes. I'm not sure the calculations inside, but when the size of the scratch device < 27GB (can be 26GB when the backing storage is ext4 rather than xfs), the test runs infinitely. I'm aware that the test should be slow, especially on NFS, but I see the test never finishes after multi-days. This problem happens in both localhost exported NFS and remote exported NFS configurations. > > > happens, the common pattern is 100% disk space use of SCRATCH_MNT, and > > `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large > > enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size > > requirement. > > > > Please help review this patch. Thanks! > > > > -Boyang > > > > tests/generic/476 | 1 + > > 1 file changed, 1 insertion(+) > > > > diff --git a/tests/generic/476 b/tests/generic/476 > > index 212373d1..dcc7c3da 100755 > > --- a/tests/generic/476 > > +++ b/tests/generic/476 > > @@ -24,6 +24,7 @@ _cleanup() > > _supported_fs generic > > > > _require_scratch > > +_require_scratch_size $((27 * 1024 * 1024)) # 27GB > > ...so IDGI, this test works as intended. Are you saying that NFS > command overhead is so high that this test takes too long? > > --D > > > _require_command "$KILLALL_PROG" "killall" > > > > echo "Silence is golden." > > -- > > 2.27.0 > > >
On Thu, Jul 21, 2022 at 03:26:05PM +0800, Boyang Xue wrote: > > > I find generic/476 easily goes into an infinite run on top of NFS. When it > > > > Infinite? It's only supposed to start 25000*nr_cpus*TIME_FACTOR > > operations, so it /should/ conclude eventually. That includes driving > > the filesystem completel out of space, but there ought to be enough > > unlink/rmdir/truncate calls to free up space every now and then... > > Yes. I'm not sure the calculations inside, but when the size of the > scratch device < 27GB (can be 26GB when the backing storage is ext4 > rather than xfs), the test runs infinitely. I'm aware that the test > should be slow, especially on NFS, but I see the test never finishes > after multi-days. This problem happens in both localhost exported NFS > and remote exported NFS configurations. I can partially confirm this. I had noted a few weeks ago that I needed to exclude generic/476 or the test VM would hang for over 24 hours, a which point I lost patience and terminated the VM. I had gotten as far as gce-xfstests -c nfs -g auto -X generic/476 (which is a loopback config) using 5.19-rc4 in order to get a test run to complete. Note: this was also triggering failures of generic/426 and generic/551, which I also haven't had time to investigate, not being an NFS developer. :-) I wasn't sure whether generic/476 never terminating was caused by a loopback-triggered deadlock, or something else. But it sounds like you've isolated it to the scratch device *too* small, and since that the failure occurred even on a configuration where the client and server were on different machines/VM's, correct? > > > _require_scratch > > > +_require_scratch_size $((27 * 1024 * 1024)) # 27GB > > > > ...so IDGI, this test works as intended. Are you saying that NFS > > command overhead is so high that this test takes too long? I interpreted this as "if the drive is too small, we're hitting some kind of problem". This *could* be some kind of problem which triggers on ENOSPC; perhaps it's just much more likely on a smaller device? So it's possible this is not a test bug, but an NFS problem. Perhaps we should forward this off to the NFS folks first? - Ted
Following up, using NFS loopback with a 5GB scratch device on a Google
Compute Engine VM, generic/476 passes using a 4.14 LTS, 4.19 LTS, and
5.4 LTS kernel. So this looks like it's a regression which is in 5.10
LTS and newer kernels, and so instead of patching it out of the test,
I think the right thing to do is to add it to a kernel
version-specific exclude file and then filing a bug with the NFS
folks.
KERNEL: kernel 4.14.284-xfstests #8 SMP Tue Jul 5 08:21:37 EDT 2022 x86_64
CMDLINE: -c nfs/default generic/476
CPUS: 2
MEM: 7680
nfs/loopback: 1 tests, 597 seconds
generic/476 Pass 595s
Totals: 1 tests, 0 skipped, 0 failures, 0 errors, 595s
---
KERNEL: kernel 4.19.248-xfstests #4 SMP Sat Jun 25 10:43:45 EDT 2022 x86_64
CMDLINE: -c nfs/default generic/476
CPUS: 2
MEM: 7680
nfs/loopback: 1 tests, 407 seconds
generic/476 Pass 407s
Totals: 1 tests, 0 skipped, 0 failures, 0 errors, 407s
----
KERNEL: kernel 5.4.199-xfstests #21 SMP Sun Jul 3 12:15:15 EDT 2022 x86_64
CMDLINE: -c nfs/default generic/476
CPUS: 2
MEM: 7680
nfs/loopback: 1 tests, 404 seconds
generic/476 Pass 404s
Totals: 1 tests, 0 skipped, 0 failures, 0 errors, 404s
See below for what I'm checking into xfstests-bld for
{kvm,gce}-xfstests. I don't believe we should be changing xfstests's
generic/476, since it *does* pass with a smaller scratch device on
older kernels, and presumably, RHEL customers would be cranky if this
issue resulted in their production systems to lock up, and so it
should be considered a kernel bug as opposed to a test bug.
- Ted
commit 4a33b6721d5db9c07f295a10a8ad65d2a0021406
Author: Theodore Ts'o <tytso@mit.edu>
Date: Thu Jul 21 09:54:50 2022 -0400
test-appliance: add an nfs test exclusions for kernels newer than 5.4
This is apparently an NFS bug which is visible in 5.10 LTS and newer
kernels, and likely appeared sometime after 5.4. Since it causes the
test VM to spin forever (or at least for days), let's exclude it for
now.
Link: https://lore.kernel.org/all/CAHLe9YaAVyBmmM8T27dudvoeAxbJ_JMQmkz7tdM1ZLnpeQW4UQ@mail.gmail.com/
Signed-off-by: Theodore Ts'o <tytso@mit.edu>
diff --git a/test-appliance/files/root/fs/nfs/exclude b/test-appliance/files/root/fs/nfs/exclude
index 184750fb..ef4b19bc 100644
--- a/test-appliance/files/root/fs/nfs/exclude
+++ b/test-appliance/files/root/fs/nfs/exclude
@@ -10,3 +10,14 @@ generic/477
// failing in the expected output of the linux-nfs Wiki page. So we'll
// suppress this failure for now.
generic/294
+
+#if LINUX_VERSION_CODE > KERNEL_VERSION(5,4,0)
+// There appears to be a regression that shows up sometime after 5.4.
+// LTS kernels for 4.14, 4.19, and 5.4 will terminate successfully,
+// but newer kernels will spin forever in some kind of deadlock or livelock
+// This apparently does not happen if the scratch device is > 27GB, so it
+// may be some kind of ENOSPC-related bug.
+// For more information see the e-mail thread starting at:
+// https://lore.kernel.org/r/CAHLe9YaAVyBmmM8T27dudvoeAxbJ_JMQmkz7tdM1ZLnpeQW4UQ@mail.gmail.com/
+generic/476
+#endif
> On Jul 21, 2022, at 10:03 AM, Theodore Ts'o <tytso@mit.edu> wrote: > > Following up, using NFS loopback with a 5GB scratch device on a Google > Compute Engine VM, generic/476 passes using a 4.14 LTS, 4.19 LTS, and > 5.4 LTS kernel. So this looks like it's a regression which is in 5.10 > LTS and newer kernels, and so instead of patching it out of the test, > I think the right thing to do is to add it to a kernel > version-specific exclude file and then filing a bug with the NFS > folks. Quite apart from the question of whether to exclude that test rather than troubleshoot, I would like to state that testing NFS in loopback, while possibly convenient for Q/A, is pretty fraught. - Loopback means the client and server are part of the direct reclaim path on the same system, which makes livelock or deadlock much more likely. Given that these test systems are typically small, that pushes the stack even further into this territory. - Loopback means there's often no way to know which part of the stack (client or server) is the problem. Any NFS test needs to have no less than two test systems, otherwise what you're really testing is how the system handles memory exhaustion. An important test, no doubt, but it doesn't paint a full picture. -- Chuck Lever
> On Jul 21, 2022, at 11:12 AM, Chuck Lever III <chuck.lever@oracle.com> wrote: > > > >> On Jul 21, 2022, at 10:03 AM, Theodore Ts'o <tytso@mit.edu> wrote: >> >> Following up, using NFS loopback with a 5GB scratch device on a Google >> Compute Engine VM, generic/476 passes using a 4.14 LTS, 4.19 LTS, and >> 5.4 LTS kernel. So this looks like it's a regression which is in 5.10 >> LTS and newer kernels, and so instead of patching it out of the test, >> I think the right thing to do is to add it to a kernel >> version-specific exclude file and then filing a bug with the NFS >> folks. > > Quite apart from the question of whether to exclude that test > rather than troubleshoot, I would like to state that testing NFS > in loopback, while possibly convenient for Q/A, is pretty fraught. > > - Loopback means the client and server are part of the direct > reclaim path on the same system, which makes livelock or deadlock > much more likely. Given that these test systems are typically > small, that pushes the stack even further into this territory. > > - Loopback means there's often no way to know which part of > the stack (client or server) is the problem. And by the way, it's even worse if that single system acts as both the NFS server scratch device and the server under test. > Any NFS test needs to have no less than two test systems, > otherwise what you're really testing is how the system handles > memory exhaustion. An important test, no doubt, but it doesn't > paint a full picture. > > > -- > Chuck Lever > > > -- Chuck Lever
On Thu, Jul 21, 2022 at 10:29:59AM +0800, bxue@redhat.com wrote: > From: Boyang Xue <bxue@redhat.com> > > The test requires larger scratch dev size when running on top of NFS other > than ext4 and xfs. It requires at least 27GB in my test. Without this > requirement, the test run never finishes on NFS, leaving 100% scratch disk > space use. > > Signed-off-by: Boyang Xue <bxue@redhat.com> > --- > Hi, > > I find generic/476 easily goes into an infinite run on top of NFS. When it > happens, the common pattern is 100% disk space use of SCRATCH_MNT, and > `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large > enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size > requirement. > > Please help review this patch. Thanks! > > -Boyang > > tests/generic/476 | 1 + > 1 file changed, 1 insertion(+) > > diff --git a/tests/generic/476 b/tests/generic/476 > index 212373d1..dcc7c3da 100755 > --- a/tests/generic/476 > +++ b/tests/generic/476 > @@ -24,6 +24,7 @@ _cleanup() > _supported_fs generic > > _require_scratch > +_require_scratch_size $((27 * 1024 * 1024)) # 27GB At first, most of other filesystems don't need this requirement, that will reduce test coverage of other fs suddently. Second, there's not a clear reason to prove NFS (or others) need a 27+GB device to run this test. Due to the generic/476 does nothing special, except random I/Os, even running with ENOSPC... So one difference of running with small device or large enough device is the chance to run with ENOSPC. I think the device size isn't the root cause of nfs hang you hit, I doubt if it's a NFS bug with ENOSPC, or something else bug which is triggered by someone random I/O operation. We'd better not to skip a known generic test (from upstream fstests directly) if without a clear reason. That might cause we miss bugs or test coverage, better to make sure if it's a real bug at first. Then think about if we need to improve the case or fix a bug. Thanks, Zorro > _require_command "$KILLALL_PROG" "killall" > > echo "Silence is golden." > -- > 2.27.0 >
> On Jul 21, 2022, at 11:29 AM, Zorro Lang <zlang@redhat.com> wrote: > > On Thu, Jul 21, 2022 at 10:29:59AM +0800, bxue@redhat.com wrote: >> From: Boyang Xue <bxue@redhat.com> >> >> The test requires larger scratch dev size when running on top of NFS other >> than ext4 and xfs. It requires at least 27GB in my test. Without this >> requirement, the test run never finishes on NFS, leaving 100% scratch disk >> space use. >> >> Signed-off-by: Boyang Xue <bxue@redhat.com> >> --- >> Hi, >> >> I find generic/476 easily goes into an infinite run on top of NFS. When it >> happens, the common pattern is 100% disk space use of SCRATCH_MNT, and >> `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large >> enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size >> requirement. >> >> Please help review this patch. Thanks! >> >> -Boyang >> >> tests/generic/476 | 1 + >> 1 file changed, 1 insertion(+) >> >> diff --git a/tests/generic/476 b/tests/generic/476 >> index 212373d1..dcc7c3da 100755 >> --- a/tests/generic/476 >> +++ b/tests/generic/476 >> @@ -24,6 +24,7 @@ _cleanup() >> _supported_fs generic >> >> _require_scratch >> +_require_scratch_size $((27 * 1024 * 1024)) # 27GB > > At first, most of other filesystems don't need this requirement, that will > reduce test coverage of other fs suddently. Second, there's not a clear > reason to prove NFS (or others) need a 27+GB device to run this test. Due to > the generic/476 does nothing special, except random I/Os, even running with > ENOSPC... > > So one difference of running with small device or large enough device is the > chance to run with ENOSPC. I think the device size isn't the root cause of > nfs hang you hit, I doubt if it's a NFS bug with ENOSPC, or something else > bug which is triggered by someone random I/O operation. > > We'd better not to skip a known generic test (from upstream fstests directly) > if without a clear reason. That might cause we miss bugs or test coverage, > better to make sure if it's a real bug at first. Then think about if we need > to improve the case or fix a bug. +1 I can help troubleshoot the NFS-related aspects of this further, if needed. > Thanks, > Zorro > >> _require_command "$KILLALL_PROG" "killall" >> >> echo "Silence is golden." >> -- >> 2.27.0 >> > -- Chuck Lever
On Thu, Jul 21, 2022 at 03:32:49PM +0000, Chuck Lever III wrote: > > > > On Jul 21, 2022, at 11:29 AM, Zorro Lang <zlang@redhat.com> wrote: > > > > On Thu, Jul 21, 2022 at 10:29:59AM +0800, bxue@redhat.com wrote: > >> From: Boyang Xue <bxue@redhat.com> > >> > >> The test requires larger scratch dev size when running on top of NFS other > >> than ext4 and xfs. It requires at least 27GB in my test. Without this > >> requirement, the test run never finishes on NFS, leaving 100% scratch disk > >> space use. > >> > >> Signed-off-by: Boyang Xue <bxue@redhat.com> > >> --- > >> Hi, > >> > >> I find generic/476 easily goes into an infinite run on top of NFS. When it > >> happens, the common pattern is 100% disk space use of SCRATCH_MNT, and > >> `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large > >> enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size > >> requirement. > >> > >> Please help review this patch. Thanks! > >> > >> -Boyang > >> > >> tests/generic/476 | 1 + > >> 1 file changed, 1 insertion(+) > >> > >> diff --git a/tests/generic/476 b/tests/generic/476 > >> index 212373d1..dcc7c3da 100755 > >> --- a/tests/generic/476 > >> +++ b/tests/generic/476 > >> @@ -24,6 +24,7 @@ _cleanup() > >> _supported_fs generic > >> > >> _require_scratch > >> +_require_scratch_size $((27 * 1024 * 1024)) # 27GB > > > > At first, most of other filesystems don't need this requirement, that will > > reduce test coverage of other fs suddently. Second, there's not a clear > > reason to prove NFS (or others) need a 27+GB device to run this test. Due to > > the generic/476 does nothing special, except random I/Os, even running with > > ENOSPC... > > > > So one difference of running with small device or large enough device is the > > chance to run with ENOSPC. I think the device size isn't the root cause of > > nfs hang you hit, I doubt if it's a NFS bug with ENOSPC, or something else > > bug which is triggered by someone random I/O operation. > > > > We'd better not to skip a known generic test (from upstream fstests directly) > > if without a clear reason. That might cause we miss bugs or test coverage, > > better to make sure if it's a real bug at first. Then think about if we need > > to improve the case or fix a bug. > > +1 > > I can help troubleshoot the NFS-related aspects of this further, if needed. Thanks Chuck, I think we'd better to cc linux-nfs list. I can reproduce generic/476 hang on nfs[0] too, with real disk or Virtio disk, it's not a loop device related issue. And sometimes it test passed[1], even with a 10G loop device[2] (which I/O speed is very fast). If you or nfs forks need full console log, I can provide. But I think it's easy to reproduce this bug by running generic/476 on a general nfs v4.2. Thanks, Zorro [0] [173303.753434] sysrq: Show Memory [173303.764679] Mem-Info: [173303.765683] active_anon:1872 inactive_anon:22756 isolated_anon:0 [173303.765683] active_file:47360 inactive_file:1230085 isolated_file:0 [173303.765683] unevictable:0 dirty:3 writeback:0 [173303.765683] slab_reclaimable:108117 slab_unreclaimable:100595 [173303.765683] mapped:11734 shmem:7363 pagetables:544 bounce:0 [173303.765683] kernel_misc_reclaimable:0 [173303.765683] free:49561 free_pcp:5112 free_cma:0 [173303.780542] Node 0 active_anon:7488kB inactive_anon:91024kB active_file:189440kB inactive_file:4920340kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:46936kB dirty:12kB writeback:0kB shmem:29452kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 18432kB writeback_tmp:0kB kernel_stack:5920kB pagetables:2176kB all_unreclaimable? no [173303.790519] Node 0 DMA free:14336kB boost:0kB min:160kB low:200kB high:240kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB [173303.799060] lowmem_reserve[]: 0 2659 6183 6183 6183 [173303.800781] Node 0 DMA32 free:123700kB boost:0kB min:28992kB low:36240kB high:43488kB reserved_highatomic:0KB active_anon:12kB inactive_anon:1452kB active_file:61020kB inactive_file:2279284kB unevictable:0kB writepending:8kB present:3129308kB managed:2801628kB mlocked:0kB bounce:0kB free_pcp:3508kB local_pcp:768kB free_cma:0kB [173303.810096] lowmem_reserve[]: 0 0 3524 3524 3524 [173303.812131] Node 0 Normal free:60208kB boost:0kB min:38424kB low:48028kB high:57632kB reserved_highatomic:2048KB active_anon:7476kB inactive_anon:89572kB active_file:128420kB inactive_file:2641056kB unevictable:0kB writepending:4kB present:5242880kB managed:3618860kB mlocked:0kB bounce:0kB free_pcp:16240kB local_pcp:4196kB free_cma:0kB [173303.822880] lowmem_reserve[]: 0 0 0 0 0 [173303.824683] Node 0 DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB (M) 3*4096kB (M) = 14336kB [173303.829410] Node 0 DMA32: 1385*4kB (UME) 1254*8kB (UME) 368*16kB (UME) 317*32kB (UME) 121*64kB (UM) 105*128kB (UME) 99*256kB (UM) 63*512kB (UME) 13*1024kB (UME) 0*2048kB 0*4096kB = 123700kB [173303.836654] Node 0 Normal: 1056*4kB (UMEH) 1027*8kB (UMEH) 400*16kB (UMEH) 287*32kB (UMEH) 105*64kB (UMEH) 71*128kB (UM) 42*256kB (M) 10*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 59704kB [173303.843268] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [173303.846232] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [173303.849541] 1284815 total pagecache pages [173303.851713] 7 pages in swap cache [173303.853033] Swap cache stats: add 24, delete 17, find 0/1 [173303.874135] Free swap = 8257760kB [173303.875679] Total swap = 8258556kB [173303.877210] 2097045 pages RAM [173303.878574] 0 pages HighMem/MovableOnly [173303.880204] 488083 pages reserved [173303.881721] 0 pages cma reserved [173303.883181] 0 pages hwpoisoned [173311.514201] sysrq: Show State [173311.531486] task:systemd state:S stack:23208 pid: 1 ppid: 0 flags:0x00000002 [173311.535523] Call Trace: [173311.536988] <TASK> [173311.537992] __schedule+0x673/0x1540 [173311.539782] ? io_schedule_timeout+0x160/0x160 [173311.541842] schedule+0xe0/0x200 [173311.543466] schedule_hrtimeout_range_clock+0x2c0/0x310 [173311.545632] ? hrtimer_nanosleep_restart+0x170/0x170 [173311.547948] ? lock_downgrade+0x130/0x130 [173311.549585] ? lockdep_hardirqs_on_prepare.part.0+0x18c/0x370 [173311.551686] ep_poll+0x7db/0xa80 [173311.552999] ? ep_send_events+0x9f0/0x9f0 [173311.555015] ? pick_next_task_stop+0x250/0x250 [173311.574734] ? prepare_to_wait_exclusive+0x2c0/0x2c0 [173311.576518] ? __lock_release+0x4c1/0xa00 [173311.579162] do_epoll_wait+0x12f/0x160 [173311.580973] __x64_sys_epoll_wait+0x12e/0x250 [173311.582599] ? __x64_sys_epoll_pwait2+0x240/0x240 [173311.584769] ? lockdep_hardirqs_on_prepare.part.0+0x18c/0x370 [173311.587348] do_syscall_64+0x5c/0x90 [173311.589335] ? do_syscall_64+0x69/0x90 [173311.591128] ? lockdep_hardirqs_on+0x79/0x100 [173311.593125] ? do_syscall_64+0x69/0x90 [173311.594805] ? lockdep_hardirqs_on+0x79/0x100 [173311.596598] entry_SYSCALL_64_after_hwframe+0x63/0xcd [173311.598376] RIP: 0033:0x7f0a5834e7de [173311.599836] RSP: 002b:00007ffcee99d180 EFLAGS: 00000293 ORIG_RAX: 00000000000000e8 [173311.603432] RAX: ffffffffffffffda RBX: 000056269d7b5b80 RCX: 00007f0a5834e7de [173311.605924] RDX: 00000000000000a6 RSI: 000056269da4f0d0 RDI: 0000000000000004 [173311.608922] RBP: 000056269d7b5d10 R08: 0000000000000000 R09: 000000000000000d [173311.611243] R10: 00000000ffffffff R11: 0000000000000293 R12: 0000000000000226 [173311.613741] R13: 000056269d7b5b80 R14: 00000000000000a6 R15: 0000000000000037 [173311.626581] </TASK> [173311.627500] task:kthreadd state:S stack:27704 pid: 2 ppid: 0 flags:0x00004000 [173311.630191] Call Trace: [173311.631013] <TASK> [173311.631872] __schedule+0x673/0x1540 [173311.633147] ? io_schedule_timeout+0x160/0x160 [173311.634725] schedule+0xe0/0x200 [173311.635884] kthreadd+0x9fb/0xd60 [173311.637204] ? kthread_is_per_cpu+0xc0/0xc0 [173311.638684] ret_from_fork+0x22/0x30 [173311.640320] </TASK> [173311.641273] task:rcu_gp state:I stack:29336 pid: 3 ppid: 2 flags:0x00004000 [173311.645006] Workqueue: 0x0 (rcu_gp) [173311.646684] Call Trace: [173311.647756] <TASK> [173311.648895] __schedule+0x673/0x1540 [173311.650435] ? io_schedule_timeout+0x160/0x160 [173311.652317] schedule+0xe0/0x200 [173311.653732] rescuer_thread+0x662/0xb80 [173311.656494] ? _raw_spin_unlock_irqrestore+0x59/0x70 [173311.658779] ? worker_thread+0xed0/0xed0 [173311.660381] ? __kthread_parkme+0xcc/0x200 [173311.662276] ? worker_thread+0xed0/0xed0 [173311.664182] kthread+0x2a7/0x350 [173311.665725] ? kthread_complete_and_exit+0x20/0x20 [173311.667519] ret_from_fork+0x22/0x30 [173311.669222] </TASK> [173311.670098] task:rcu_par_gp state:I stack:30888 pid: 4 ppid: 2 flags:0x00004000 [173311.673101] Call Trace: [173311.673976] <TASK> [173311.674868] __schedule+0x673/0x1540 [173311.676197] ? io_schedule_timeout+0x160/0x160 [173311.677805] schedule+0xe0/0x200 [173311.678991] rescuer_thread+0x662/0xb80 [173311.680502] ? _raw_spin_unlock_irqrestore+0x59/0x70 [173311.682222] ? worker_thread+0xed0/0xed0 ... (too many lines) ... [173319.787263] Showing all locks held in the system: [173319.788884] no locks held by systemd-journal/517. [173319.789881] 1 lock held by fsstress/663798: [173319.790895] #0: ffff888130b68488 (sb_writers#16){.+.+}-{0:0}, at: ksys_write+0xf9/0x1d0 [173319.792551] 3 locks held by kworker/u8:2/666396: [173319.794275] #0: ffff8881e4602f58 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x30/0x120 [173319.795933] #1: ffff8881e4e02f58 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x30/0x120 [173319.797605] #2: ffff8881009bc4f0 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0xb3/0xdd0 [173319.799126] 3 locks held by 20_sysinfo/666628: [173319.799995] #0: ffff88810c362488 (sb_writers#3){.+.+}-{0:0}, at: ksys_write+0xf9/0x1d0 [173319.801695] #1: ffffffff860e6dc0 (rcu_read_lock){....}-{1:2}, at: __handle_sysrq+0x4a/0xe0 [173319.803276] #2: ffffffff860e6dc0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire.constprop.0+0x0/0x30 [173319.804988] [173319.805319] ============================================= [173319.805319] [173319.806614] Showing busy workqueues and worker pools: [173319.807587] workqueue events_highpri: flags=0x10 [173319.808538] pwq 5: cpus=2 node=0 flags=0x0 nice=-20 active=1/256 refcnt=2 [173319.808581] pending: mix_interrupt_randomness [173328.255900] sysrq: Show Blocked State [173328.276745] task:fsstress state:D stack:23416 pid:663798 ppid:663797 flags:0x00004002 [173328.279713] Call Trace: [173328.280646] <TASK> [173328.281768] __schedule+0x673/0x1540 [173328.283583] ? io_schedule_timeout+0x160/0x160 [173328.285898] ? pick_next_task_stop+0x250/0x250 [173328.288286] schedule+0xe0/0x200 [173328.289932] schedule_timeout+0x19e/0x250 [173328.291845] ? usleep_range_state+0x190/0x190 [173328.293563] ? mark_held_locks+0xa5/0xf0 [173328.295072] ? lockdep_hardirqs_on_prepare.part.0+0x18c/0x370 [173328.297228] ? _raw_spin_unlock_irq+0x24/0x50 [173328.299148] __wait_for_common+0x381/0x540 [173328.301081] ? usleep_range_state+0x190/0x190 [173328.303037] ? out_of_line_wait_on_bit_timeout+0x170/0x170 [173328.304937] ? up_write+0x20/0x20 [173328.306118] ? nfs_file_direct_write+0xaef/0x1050 [nfs] [173328.308327] wait_for_completion_killable+0x20/0x40 [173328.310146] nfs_file_direct_write+0xb2c/0x1050 [nfs] [173328.312009] ? nfs_file_direct_read+0xaa0/0xaa0 [nfs] [173328.313878] ? nfs_key_timeout_notify+0x3a/0x90 [nfs] [173328.315651] ? __lock_acquire+0xb72/0x1870 [173328.317032] ? nfs_file_write+0xed/0x8c0 [nfs] [173328.318716] new_sync_write+0x2ef/0x540 [173328.320059] ? new_sync_read+0x530/0x530 [173328.321447] ? lock_acquire+0x1d8/0x620 [173328.322839] ? rcu_read_unlock+0x40/0x40 [173328.324309] vfs_write+0x62a/0x920 [173328.325592] ksys_write+0xf9/0x1d0 [173328.327621] ? __ia32_sys_read+0xa0/0xa0 [173328.328996] ? ktime_get_coarse_real_ts64+0x130/0x170 [173328.330746] do_syscall_64+0x5c/0x90 [173328.331998] ? do_syscall_64+0x69/0x90 [173328.333303] ? lockdep_hardirqs_on+0x79/0x100 [173328.335143] ? do_syscall_64+0x69/0x90 [173328.336483] ? do_syscall_64+0x69/0x90 [173328.338093] ? lockdep_hardirqs_on+0x79/0x100 [173328.340276] ? do_syscall_64+0x69/0x90 [173328.341683] ? asm_sysvec_apic_timer_interrupt+0x16/0x20 [173328.343466] ? lockdep_hardirqs_on+0x79/0x100 [173328.344989] entry_SYSCALL_64_after_hwframe+0x63/0xcd [173328.346646] RIP: 0033:0x7f16be13e8c7 [173328.347857] RSP: 002b:00007ffea1b02798 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 [173328.350228] RAX: ffffffffffffffda RBX: 0000000000100000 RCX: 00007f16be13e8c7 [173328.352485] RDX: 0000000000100000 RSI: 0000000001c00000 RDI: 0000000000000003 [173328.354769] RBP: 0000000000000003 R08: 0000000001d00000 R09: 0000000000000000 [173328.357318] R10: 0000000000000100 R11: 0000000000000246 R12: 0000000000017de1 [173328.359664] R13: 0000000000000000 R14: 0000000001c00000 R15: 0000000000000000 [173328.362074] </TASK> Stopping /usr/bin/bash -c …j; exec ./tests/generic/476 ... [1] [ 9746.410677] run fstests generic/476 at 2022-07-16 15:42:38 [ 9803.017543] restraintd[2193]: *** Current Time: Sat Jul 16 15:43:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [ 9863.016020] restraintd[2193]: *** Current Time: Sat Jul 16 15:44:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [-- MARK -- Sat Jul 16 19:45:00 2022] [ 9923.014409] restraintd[2193]: *** Current Time: Sat Jul 16 15:45:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [ 9983.016088] restraintd[2193]: *** Current Time: Sat Jul 16 15:46:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10043.014435] restraintd[2193]: *** Current Time: Sat Jul 16 15:47:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10103.017105] restraintd[2193]: *** Current Time: Sat Jul 16 15:48:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10163.057993] restraintd[2193]: *** Current Time: Sat Jul 16 15:49:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [-- MARK -- Sat Jul 16 19:50:00 2022] [10223.018212] restraintd[2193]: *** Current Time: Sat Jul 16 15:50:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10283.015296] restraintd[2193]: *** Current Time: Sat Jul 16 15:51:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10343.014956] restraintd[2193]: *** Current Time: Sat Jul 16 15:52:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10403.014340] restraintd[2193]: *** Current Time: Sat Jul 16 15:53:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10463.016180] restraintd[2193]: *** Current Time: Sat Jul 16 15:54:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [-- MARK -- Sat Jul 16 19:55:00 2022] [10523.017423] restraintd[2193]: *** Current Time: Sat Jul 16 15:55:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10583.015557] restraintd[2193]: *** Current Time: Sat Jul 16 15:56:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10643.014811] restraintd[2193]: *** Current Time: Sat Jul 16 15:57:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10703.009075] restraintd[2193]: *** Current Time: Sat Jul 16 15:58:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 [10752.278563] run fstests generic/477 at 2022-07-16 15:59:23 ... [2] The 1st layer fs: xfs - SCRATCH_DEV=/dev/loop1, SCRATCH_MNT=/mnt/fstests/SCRATCH_DIR meta-data=/dev/loop1 isize=512 agcount=4, agsize=655360 blks = sectsz=512 attr=2, projid32bit=1 = crc=1 finobt=1, sparse=1, rmapbt=0 = reflink=1 bigtime=1 inobtcount=1 nrext64=0 data = bsize=4096 blocks=2621440, imaxpct=25 = sunit=0 swidth=0 blks naming =version 2 bsize=4096 ascii-ci=0, ftype=1 log =internal log bsize=4096 blocks=16384, version=2 = sectsz=512 sunit=0 blks, lazy-count=1 realtime =none extsz=4096 blocks=0, rtextents=0 Discarding blocks...Done. The 2nd layer fs: nfs - SCRATCH_DEV=s390x-kvm-xxx.xxx.xxx.xxxx.redhat.com:/mnt/fstests/SCRATCH_DIR/nfs-server, SCRATCH_MNT=/mnt/fstests/SCRATCH_DIR/nfs-client > > > > Thanks, > > Zorro > > > >> _require_command "$KILLALL_PROG" "killall" > >> > >> echo "Silence is golden." > >> -- > >> 2.27.0 > >> > > > > -- > Chuck Lever > > >
On Thu, Jul 21, 2022 at 03:14:30PM +0000, Chuck Lever III wrote: > > - Loopback means there's often no way to know which part of > > the stack (client or server) is the problem. > > And by the way, it's even worse if that single system acts as > both the NFS server scratch device and the server under test. > I believe Boyang has stated that this has been seen both in loopback and in an externally mounted configuration. Boyang, in your external exported configuration, was the lockup happening on the client or server system? - Ted P.S. I just don't have the capability of testing NFS on separate VM's for the client and server using gce-xfstests. It's on my list of things to implement someday, but I just don't have time at the moment. Maybe a GSOC project someday... Or if someone has time, patches or pull requests to https://github.com/tytso/xfstests-bld are gratefully accepted. :-)
> On Jul 21, 2022, at 2:04 PM, Theodore Ts'o <tytso@mit.edu> wrote: > > On Thu, Jul 21, 2022 at 03:14:30PM +0000, Chuck Lever III wrote: >>> - Loopback means there's often no way to know which part of >>> the stack (client or server) is the problem. >> >> And by the way, it's even worse if that single system acts as >> both the NFS server scratch device and the server under test. >> > > I believe Boyang has stated that this has been seen both in loopback > and in an externally mounted configuration. > > Boyang, in your external exported configuration, was the lockup > happening on the client or server system? > > - Ted > > P.S. I just don't have the capability of testing NFS on separate VM's > for the client and server using gce-xfstests. It's on my list of > things to implement someday, but I just don't have time at the moment. > Maybe a GSOC project someday... Or if someone has time, patches or > pull requests to https://github.com/tytso/xfstests-bld are gratefully > accepted. :-) I agree that Q/A and dev testing needs are distinct, so a dev might have a simpler series of tests to run and fewer resources to run them in. That said, I've had it on my to-do list for some time to find an easy way to run automated multi-host tests, and I've been told it should be straight-forward, but I've been swamped lately. Many of us in the NFS community actually don't run the tests that require a scratch dev, because many of them don't seem relevant to NFS, or they take a long time to run. Someday we should sort through all that :-) For the particular issue with generic/476, I would like to see if there's a reason that test takes a long time and fails with a small scratch dev before agreeing that excluding it is the proper response. -- Chuck Lever
On Fri, 2022-07-22 at 00:30 +0800, Zorro Lang wrote: > On Thu, Jul 21, 2022 at 03:32:49PM +0000, Chuck Lever III wrote: > > > > > > > On Jul 21, 2022, at 11:29 AM, Zorro Lang <zlang@redhat.com> wrote: > > > > > > On Thu, Jul 21, 2022 at 10:29:59AM +0800, bxue@redhat.com wrote: > > > > From: Boyang Xue <bxue@redhat.com> > > > > > > > > The test requires larger scratch dev size when running on top of NFS other > > > > than ext4 and xfs. It requires at least 27GB in my test. Without this > > > > requirement, the test run never finishes on NFS, leaving 100% scratch disk > > > > space use. > > > > > > > > Signed-off-by: Boyang Xue <bxue@redhat.com> > > > > --- > > > > Hi, > > > > > > > > I find generic/476 easily goes into an infinite run on top of NFS. When it > > > > happens, the common pattern is 100% disk space use of SCRATCH_MNT, and > > > > `nfsiostat` shows 50% write error on SCRATCH_MNT. When I run it with a large > > > > enough SCRATCH_MNT, the problem disappears. So I post this patch to add the size > > > > requirement. > > > > > > > > Please help review this patch. Thanks! > > > > > > > > -Boyang > > > > > > > > tests/generic/476 | 1 + > > > > 1 file changed, 1 insertion(+) > > > > > > > > diff --git a/tests/generic/476 b/tests/generic/476 > > > > index 212373d1..dcc7c3da 100755 > > > > --- a/tests/generic/476 > > > > +++ b/tests/generic/476 > > > > @@ -24,6 +24,7 @@ _cleanup() > > > > _supported_fs generic > > > > > > > > _require_scratch > > > > +_require_scratch_size $((27 * 1024 * 1024)) # 27GB > > > > > > At first, most of other filesystems don't need this requirement, that will > > > reduce test coverage of other fs suddently. Second, there's not a clear > > > reason to prove NFS (or others) need a 27+GB device to run this test. Due to > > > the generic/476 does nothing special, except random I/Os, even running with > > > ENOSPC... > > > > > > So one difference of running with small device or large enough device is the > > > chance to run with ENOSPC. I think the device size isn't the root cause of > > > nfs hang you hit, I doubt if it's a NFS bug with ENOSPC, or something else > > > bug which is triggered by someone random I/O operation. > > > > > > We'd better not to skip a known generic test (from upstream fstests directly) > > > if without a clear reason. That might cause we miss bugs or test coverage, > > > better to make sure if it's a real bug at first. Then think about if we need > > > to improve the case or fix a bug. > > > > +1 > > > > I can help troubleshoot the NFS-related aspects of this further, if needed. > > Thanks Chuck, I think we'd better to cc linux-nfs list. > > I can reproduce generic/476 hang on nfs[0] too, with real disk or Virtio disk, > it's not a loop device related issue. And sometimes it test passed[1], even with > a 10G loop device[2] (which I/O speed is very fast). If you or nfs forks need > full console log, I can provide. But I think it's easy to reproduce this bug > by running generic/476 on a general nfs v4.2. > > Thanks, > Zorro > > [0] > [173303.753434] sysrq: Show Memory > [173303.764679] Mem-Info: > [173303.765683] active_anon:1872 inactive_anon:22756 isolated_anon:0 > [173303.765683] active_file:47360 inactive_file:1230085 isolated_file:0 > [173303.765683] unevictable:0 dirty:3 writeback:0 > [173303.765683] slab_reclaimable:108117 slab_unreclaimable:100595 > [173303.765683] mapped:11734 shmem:7363 pagetables:544 bounce:0 > [173303.765683] kernel_misc_reclaimable:0 > [173303.765683] free:49561 free_pcp:5112 free_cma:0 > [173303.780542] Node 0 active_anon:7488kB inactive_anon:91024kB active_file:189440kB inactive_file:4920340kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:46936kB dirty:12kB writeback:0kB shmem:29452kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 18432kB writeback_tmp:0kB kernel_stack:5920kB pagetables:2176kB all_unreclaimable? no > [173303.790519] Node 0 DMA free:14336kB boost:0kB min:160kB low:200kB high:240kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB > [173303.799060] lowmem_reserve[]: 0 2659 6183 6183 6183 > [173303.800781] Node 0 DMA32 free:123700kB boost:0kB min:28992kB low:36240kB high:43488kB reserved_highatomic:0KB active_anon:12kB inactive_anon:1452kB active_file:61020kB inactive_file:2279284kB unevictable:0kB writepending:8kB present:3129308kB managed:2801628kB mlocked:0kB bounce:0kB free_pcp:3508kB local_pcp:768kB free_cma:0kB > [173303.810096] lowmem_reserve[]: 0 0 3524 3524 3524 > [173303.812131] Node 0 Normal free:60208kB boost:0kB min:38424kB low:48028kB high:57632kB reserved_highatomic:2048KB active_anon:7476kB inactive_anon:89572kB active_file:128420kB inactive_file:2641056kB unevictable:0kB writepending:4kB present:5242880kB managed:3618860kB mlocked:0kB bounce:0kB free_pcp:16240kB local_pcp:4196kB free_cma:0kB > [173303.822880] lowmem_reserve[]: 0 0 0 0 0 > [173303.824683] Node 0 DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB (M) 3*4096kB (M) = 14336kB > [173303.829410] Node 0 DMA32: 1385*4kB (UME) 1254*8kB (UME) 368*16kB (UME) 317*32kB (UME) 121*64kB (UM) 105*128kB (UME) 99*256kB (UM) 63*512kB (UME) 13*1024kB (UME) 0*2048kB 0*4096kB = 123700kB > [173303.836654] Node 0 Normal: 1056*4kB (UMEH) 1027*8kB (UMEH) 400*16kB (UMEH) 287*32kB (UMEH) 105*64kB (UMEH) 71*128kB (UM) 42*256kB (M) 10*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 59704kB > [173303.843268] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB > [173303.846232] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB > [173303.849541] 1284815 total pagecache pages > [173303.851713] 7 pages in swap cache > [173303.853033] Swap cache stats: add 24, delete 17, find 0/1 > [173303.874135] Free swap = 8257760kB > [173303.875679] Total swap = 8258556kB > [173303.877210] 2097045 pages RAM > [173303.878574] 0 pages HighMem/MovableOnly > [173303.880204] 488083 pages reserved > [173303.881721] 0 pages cma reserved > [173303.883181] 0 pages hwpoisoned > [173311.514201] sysrq: Show State > [173311.531486] task:systemd state:S stack:23208 pid: 1 ppid: 0 flags:0x00000002 > [173311.535523] Call Trace: > [173311.536988] <TASK> > [173311.537992] __schedule+0x673/0x1540 > [173311.539782] ? io_schedule_timeout+0x160/0x160 > [173311.541842] schedule+0xe0/0x200 > [173311.543466] schedule_hrtimeout_range_clock+0x2c0/0x310 > [173311.545632] ? hrtimer_nanosleep_restart+0x170/0x170 > [173311.547948] ? lock_downgrade+0x130/0x130 > [173311.549585] ? lockdep_hardirqs_on_prepare.part.0+0x18c/0x370 > [173311.551686] ep_poll+0x7db/0xa80 > [173311.552999] ? ep_send_events+0x9f0/0x9f0 > [173311.555015] ? pick_next_task_stop+0x250/0x250 > [173311.574734] ? prepare_to_wait_exclusive+0x2c0/0x2c0 > [173311.576518] ? __lock_release+0x4c1/0xa00 > [173311.579162] do_epoll_wait+0x12f/0x160 > [173311.580973] __x64_sys_epoll_wait+0x12e/0x250 > [173311.582599] ? __x64_sys_epoll_pwait2+0x240/0x240 > [173311.584769] ? lockdep_hardirqs_on_prepare.part.0+0x18c/0x370 > [173311.587348] do_syscall_64+0x5c/0x90 > [173311.589335] ? do_syscall_64+0x69/0x90 > [173311.591128] ? lockdep_hardirqs_on+0x79/0x100 > [173311.593125] ? do_syscall_64+0x69/0x90 > [173311.594805] ? lockdep_hardirqs_on+0x79/0x100 > [173311.596598] entry_SYSCALL_64_after_hwframe+0x63/0xcd > [173311.598376] RIP: 0033:0x7f0a5834e7de > [173311.599836] RSP: 002b:00007ffcee99d180 EFLAGS: 00000293 ORIG_RAX: 00000000000000e8 > [173311.603432] RAX: ffffffffffffffda RBX: 000056269d7b5b80 RCX: 00007f0a5834e7de > [173311.605924] RDX: 00000000000000a6 RSI: 000056269da4f0d0 RDI: 0000000000000004 > [173311.608922] RBP: 000056269d7b5d10 R08: 0000000000000000 R09: 000000000000000d > [173311.611243] R10: 00000000ffffffff R11: 0000000000000293 R12: 0000000000000226 > [173311.613741] R13: 000056269d7b5b80 R14: 00000000000000a6 R15: 0000000000000037 > [173311.626581] </TASK> > [173311.627500] task:kthreadd state:S stack:27704 pid: 2 ppid: 0 flags:0x00004000 > [173311.630191] Call Trace: > [173311.631013] <TASK> > [173311.631872] __schedule+0x673/0x1540 > [173311.633147] ? io_schedule_timeout+0x160/0x160 > [173311.634725] schedule+0xe0/0x200 > [173311.635884] kthreadd+0x9fb/0xd60 > [173311.637204] ? kthread_is_per_cpu+0xc0/0xc0 > [173311.638684] ret_from_fork+0x22/0x30 > [173311.640320] </TASK> > [173311.641273] task:rcu_gp state:I stack:29336 pid: 3 ppid: 2 flags:0x00004000 > [173311.645006] Workqueue: 0x0 (rcu_gp) > [173311.646684] Call Trace: > [173311.647756] <TASK> > [173311.648895] __schedule+0x673/0x1540 > [173311.650435] ? io_schedule_timeout+0x160/0x160 > [173311.652317] schedule+0xe0/0x200 > [173311.653732] rescuer_thread+0x662/0xb80 > [173311.656494] ? _raw_spin_unlock_irqrestore+0x59/0x70 > [173311.658779] ? worker_thread+0xed0/0xed0 > [173311.660381] ? __kthread_parkme+0xcc/0x200 > [173311.662276] ? worker_thread+0xed0/0xed0 > [173311.664182] kthread+0x2a7/0x350 > [173311.665725] ? kthread_complete_and_exit+0x20/0x20 > [173311.667519] ret_from_fork+0x22/0x30 > [173311.669222] </TASK> > [173311.670098] task:rcu_par_gp state:I stack:30888 pid: 4 ppid: 2 flags:0x00004000 > [173311.673101] Call Trace: > [173311.673976] <TASK> > [173311.674868] __schedule+0x673/0x1540 > [173311.676197] ? io_schedule_timeout+0x160/0x160 > [173311.677805] schedule+0xe0/0x200 > [173311.678991] rescuer_thread+0x662/0xb80 > [173311.680502] ? _raw_spin_unlock_irqrestore+0x59/0x70 > [173311.682222] ? worker_thread+0xed0/0xed0 > ... > (too many lines) > ... > [173319.787263] Showing all locks held in the system: > [173319.788884] no locks held by systemd-journal/517. > [173319.789881] 1 lock held by fsstress/663798: > [173319.790895] #0: ffff888130b68488 (sb_writers#16){.+.+}-{0:0}, at: ksys_write+0xf9/0x1d0 > [173319.792551] 3 locks held by kworker/u8:2/666396: > [173319.794275] #0: ffff8881e4602f58 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x30/0x120 > [173319.795933] #1: ffff8881e4e02f58 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x30/0x120 > [173319.797605] #2: ffff8881009bc4f0 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0xb3/0xdd0 > [173319.799126] 3 locks held by 20_sysinfo/666628: > [173319.799995] #0: ffff88810c362488 (sb_writers#3){.+.+}-{0:0}, at: ksys_write+0xf9/0x1d0 > [173319.801695] #1: ffffffff860e6dc0 (rcu_read_lock){....}-{1:2}, at: __handle_sysrq+0x4a/0xe0 > [173319.803276] #2: ffffffff860e6dc0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire.constprop.0+0x0/0x30 > [173319.804988] > [173319.805319] ============================================= > [173319.805319] > [173319.806614] Showing busy workqueues and worker pools: > [173319.807587] workqueue events_highpri: flags=0x10 > [173319.808538] pwq 5: cpus=2 node=0 flags=0x0 nice=-20 active=1/256 refcnt=2 > [173319.808581] pending: mix_interrupt_randomness > [173328.255900] sysrq: Show Blocked State > [173328.276745] task:fsstress state:D stack:23416 pid:663798 ppid:663797 flags:0x00004002 > [173328.279713] Call Trace: > [173328.280646] <TASK> > [173328.281768] __schedule+0x673/0x1540 > [173328.283583] ? io_schedule_timeout+0x160/0x160 > [173328.285898] ? pick_next_task_stop+0x250/0x250 > [173328.288286] schedule+0xe0/0x200 > [173328.289932] schedule_timeout+0x19e/0x250 > [173328.291845] ? usleep_range_state+0x190/0x190 > [173328.293563] ? mark_held_locks+0xa5/0xf0 > [173328.295072] ? lockdep_hardirqs_on_prepare.part.0+0x18c/0x370 > [173328.297228] ? _raw_spin_unlock_irq+0x24/0x50 > [173328.299148] __wait_for_common+0x381/0x540 > [173328.301081] ? usleep_range_state+0x190/0x190 > [173328.303037] ? out_of_line_wait_on_bit_timeout+0x170/0x170 > [173328.304937] ? up_write+0x20/0x20 > [173328.306118] ? nfs_file_direct_write+0xaef/0x1050 [nfs] > [173328.308327] wait_for_completion_killable+0x20/0x40 > [173328.310146] nfs_file_direct_write+0xb2c/0x1050 [nfs] > [173328.312009] ? nfs_file_direct_read+0xaa0/0xaa0 [nfs] > [173328.313878] ? nfs_key_timeout_notify+0x3a/0x90 [nfs] > [173328.315651] ? __lock_acquire+0xb72/0x1870 > [173328.317032] ? nfs_file_write+0xed/0x8c0 [nfs] > [173328.318716] new_sync_write+0x2ef/0x540 > [173328.320059] ? new_sync_read+0x530/0x530 > [173328.321447] ? lock_acquire+0x1d8/0x620 > [173328.322839] ? rcu_read_unlock+0x40/0x40 > [173328.324309] vfs_write+0x62a/0x920 > [173328.325592] ksys_write+0xf9/0x1d0 > [173328.327621] ? __ia32_sys_read+0xa0/0xa0 > [173328.328996] ? ktime_get_coarse_real_ts64+0x130/0x170 > [173328.330746] do_syscall_64+0x5c/0x90 > [173328.331998] ? do_syscall_64+0x69/0x90 > [173328.333303] ? lockdep_hardirqs_on+0x79/0x100 > [173328.335143] ? do_syscall_64+0x69/0x90 > [173328.336483] ? do_syscall_64+0x69/0x90 > [173328.338093] ? lockdep_hardirqs_on+0x79/0x100 > [173328.340276] ? do_syscall_64+0x69/0x90 > [173328.341683] ? asm_sysvec_apic_timer_interrupt+0x16/0x20 > [173328.343466] ? lockdep_hardirqs_on+0x79/0x100 > [173328.344989] entry_SYSCALL_64_after_hwframe+0x63/0xcd > [173328.346646] RIP: 0033:0x7f16be13e8c7 > [173328.347857] RSP: 002b:00007ffea1b02798 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 > [173328.350228] RAX: ffffffffffffffda RBX: 0000000000100000 RCX: 00007f16be13e8c7 > [173328.352485] RDX: 0000000000100000 RSI: 0000000001c00000 RDI: 0000000000000003 > [173328.354769] RBP: 0000000000000003 R08: 0000000001d00000 R09: 0000000000000000 > [173328.357318] R10: 0000000000000100 R11: 0000000000000246 R12: 0000000000017de1 > [173328.359664] R13: 0000000000000000 R14: 0000000001c00000 R15: 0000000000000000 > [173328.362074] </TASK> > Stopping > /usr/bin/bash -c …j; exec ./tests/generic/476 > ... > > [1] > [ 9746.410677] run fstests generic/476 at 2022-07-16 15:42:38 > [ 9803.017543] restraintd[2193]: *** Current Time: Sat Jul 16 15:43:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [ 9863.016020] restraintd[2193]: *** Current Time: Sat Jul 16 15:44:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [-- MARK -- Sat Jul 16 19:45:00 2022] > [ 9923.014409] restraintd[2193]: *** Current Time: Sat Jul 16 15:45:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [ 9983.016088] restraintd[2193]: *** Current Time: Sat Jul 16 15:46:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10043.014435] restraintd[2193]: *** Current Time: Sat Jul 16 15:47:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10103.017105] restraintd[2193]: *** Current Time: Sat Jul 16 15:48:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10163.057993] restraintd[2193]: *** Current Time: Sat Jul 16 15:49:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [-- MARK -- Sat Jul 16 19:50:00 2022] > [10223.018212] restraintd[2193]: *** Current Time: Sat Jul 16 15:50:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10283.015296] restraintd[2193]: *** Current Time: Sat Jul 16 15:51:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10343.014956] restraintd[2193]: *** Current Time: Sat Jul 16 15:52:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10403.014340] restraintd[2193]: *** Current Time: Sat Jul 16 15:53:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10463.016180] restraintd[2193]: *** Current Time: Sat Jul 16 15:54:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [-- MARK -- Sat Jul 16 19:55:00 2022] > [10523.017423] restraintd[2193]: *** Current Time: Sat Jul 16 15:55:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10583.015557] restraintd[2193]: *** Current Time: Sat Jul 16 15:56:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10643.014811] restraintd[2193]: *** Current Time: Sat Jul 16 15:57:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10703.009075] restraintd[2193]: *** Current Time: Sat Jul 16 15:58:33 2022 Localwatchdog at: Mon Jul 18 13:01:33 2022 > [10752.278563] run fstests generic/477 at 2022-07-16 15:59:23 > ... > > [2] > The 1st layer fs: xfs - SCRATCH_DEV=/dev/loop1, SCRATCH_MNT=/mnt/fstests/SCRATCH_DIR > meta-data=/dev/loop1 isize=512 agcount=4, agsize=655360 blks > = sectsz=512 attr=2, projid32bit=1 > = crc=1 finobt=1, sparse=1, rmapbt=0 > = reflink=1 bigtime=1 inobtcount=1 nrext64=0 > data = bsize=4096 blocks=2621440, imaxpct=25 > = sunit=0 swidth=0 blks > naming =version 2 bsize=4096 ascii-ci=0, ftype=1 > log =internal log bsize=4096 blocks=16384, version=2 > = sectsz=512 sunit=0 blks, lazy-count=1 > realtime =none extsz=4096 blocks=0, rtextents=0 > Discarding blocks...Done. > The 2nd layer fs: nfs - SCRATCH_DEV=s390x-kvm-xxx.xxx.xxx.xxxx.redhat.com:/mnt/fstests/SCRATCH_DIR/nfs-server, SCRATCH_MNT=/mnt/fstests/SCRATCH_DIR/nfs-client > > > > Thanks Zorro. I'm having a look at this now: https://bugzilla.redhat.com/show_bug.cgi?id=2028370 I'm pretty sure this is a client error handling bug of some sort. It looks like the server is doing the right thing, but the client keeps trying to reissue the same write over and over.
On Thu, Jul 21, 2022 at 06:13:48PM +0000, Chuck Lever III wrote: > > I agree that Q/A and dev testing needs are distinct, so a dev might > have a simpler series of tests to run and fewer resources to run them > in. > > That said, I've had it on my to-do list for some time to find an easy > way to run automated multi-host tests, and I've been told it should be > straight-forward, but I've been swamped lately. Yeah, in a cloud or VM environment it shouldn't be *that* hard. Especially for cloud setup, it's just a matter of launching another cloud VM with a metadata flag that says, "please provide an NFS server using the specified file system as the backing store", noting the IP address, and then passing it to the client VM. The only slightly tricky part is that monitoring and saving the serial console of the server as a test artifact in case of an oops or triggers a BUG or WARN_ON. Unfortunately, like you, I've been swamped lately. :-/ > Many of us in the NFS community actually don't run the tests that > require a scratch dev, because many of them don't seem relevant to > NFS, or they take a long time to run. Someday we should sort through > all that :-) It doesn't take *that* long. In loopback mode, as well as using the GCE Filestore Basic product as the remote NFS server, it takes between 2.5 and 3 hours to run the auto group with the test and scratch device sized to 5GB: nfs/filestore: 785 tests, 3 failures, 323 skipped, 9922 seconds Failures: generic/258 generic/444 generic/551 nfs/loopback: 814 tests, 2 failures, 342 skipped, 9364 seconds Failures: generic/426 generic/551 That's the same order of magnitude for ext4 or xfs running -g auto, and at least for me "gce-xfsetsts -c nfs/default -g auto" is fire and forget kind of thing. 2-3 hours later, the results show up in my inbox. It's actually *analyzing* the test failures which takes time and NFS expertise, both of which I don't have a lot of at the moment. > For the particular issue with generic/476, I would like to see if > there's a reason that test takes a long time and fails with a small > scratch dev before agreeing that excluding it is the proper response. At the moment, my test runner setup assumes that if a single test takes more than hour, the system under test is hung and should be killed. So if generic/476 is taking ~400 seconds for pre-5.10 LTS kernels, and over 24 hours if the watchdog safety timer isn't in use for 5.10+ kernels, I need to exclude it in my test runner, at least for now. Once it's fixed, I can use a linux versioned #ifdef to only exclude the test if the fix is not present. (Also on my todo wishlist is to have some way to automatically exclude a test if a specified fix commit isn't present on the tested kernel, but to run it automatically once the fix commit is present. Unfortunately, I don't have the time or the business case to put someone on it as a work project...) - Ted
Thank you everyone for the review and suggestions! Yes it's a real bug rather than a test flaw, so we should fix the kernel code instead. Jeff has posted a patchset to linux-nfs@ , and I have done testing against the patchset. The results are all good. generic/476 would complete within 30 mins typically in both localhost and multi-host configurations. Please check out the link for the patchset: https://www.spinics.net/lists/linux-nfs/msg92009.html Thanks, Boyang On Fri, Jul 22, 2022 at 10:19 AM Theodore Ts'o <tytso@mit.edu> wrote: > > On Thu, Jul 21, 2022 at 06:13:48PM +0000, Chuck Lever III wrote: > > > > I agree that Q/A and dev testing needs are distinct, so a dev might > > have a simpler series of tests to run and fewer resources to run them > > in. > > > > That said, I've had it on my to-do list for some time to find an easy > > way to run automated multi-host tests, and I've been told it should be > > straight-forward, but I've been swamped lately. > > Yeah, in a cloud or VM environment it shouldn't be *that* hard. > Especially for cloud setup, it's just a matter of launching another > cloud VM with a metadata flag that says, "please provide an NFS server > using the specified file system as the backing store", noting the IP > address, and then passing it to the client VM. The only slightly > tricky part is that monitoring and saving the serial console of the > server as a test artifact in case of an oops or triggers a BUG or > WARN_ON. > > Unfortunately, like you, I've been swamped lately. :-/ > > > Many of us in the NFS community actually don't run the tests that > > require a scratch dev, because many of them don't seem relevant to > > NFS, or they take a long time to run. Someday we should sort through > > all that :-) > > It doesn't take *that* long. In loopback mode, as well as using the > GCE Filestore Basic product as the remote NFS server, it takes between > 2.5 and 3 hours to run the auto group with the test and scratch device > sized to 5GB: > > nfs/filestore: 785 tests, 3 failures, 323 skipped, 9922 seconds > Failures: generic/258 generic/444 generic/551 > nfs/loopback: 814 tests, 2 failures, 342 skipped, 9364 seconds > Failures: generic/426 generic/551 > > That's the same order of magnitude for ext4 or xfs running -g auto, > and at least for me "gce-xfsetsts -c nfs/default -g auto" is fire and > forget kind of thing. 2-3 hours later, the results show up in my > inbox. It's actually *analyzing* the test failures which takes time > and NFS expertise, both of which I don't have a lot of at the moment. > > > For the particular issue with generic/476, I would like to see if > > there's a reason that test takes a long time and fails with a small > > scratch dev before agreeing that excluding it is the proper response. > > At the moment, my test runner setup assumes that if a single test > takes more than hour, the system under test is hung and should be > killed. So if generic/476 is taking ~400 seconds for pre-5.10 LTS > kernels, and over 24 hours if the watchdog safety timer isn't in use > for 5.10+ kernels, I need to exclude it in my test runner, at least > for now. > > Once it's fixed, I can use a linux versioned #ifdef to only exclude > the test if the fix is not present. > > (Also on my todo wishlist is to have some way to automatically exclude > a test if a specified fix commit isn't present on the tested kernel, > but to run it automatically once the fix commit is present. > Unfortunately, I don't have the time or the business case to put > someone on it as a work project...) > > - Ted >
diff --git a/tests/generic/476 b/tests/generic/476 index 212373d1..dcc7c3da 100755 --- a/tests/generic/476 +++ b/tests/generic/476 @@ -24,6 +24,7 @@ _cleanup() _supported_fs generic _require_scratch +_require_scratch_size $((27 * 1024 * 1024)) # 27GB _require_command "$KILLALL_PROG" "killall" echo "Silence is golden."