Red Hat Bugzilla – Bug 1252549
leaf optimization cannot be enabled for a NFS file system
Last modified: 2016-06-24 09:54:17 EDT
+++ This bug was initially created as a clone of Bug #883285 +++ --- Additional comment from Dave Wysochanski on 2015-07-29 04:02:39 CEST --- This testcase fails on NFS though passes on local filesystem (ext4). The number of files matters as well, but as of yet I don't know why. I set FILE_COUNT=5000 since that seems to fail 100% of the time for me. A smaller number (500) passes the test. [root@rhel6u6-node1 01478764]# ./t1_bz883285.sh /mnt/nfs3/test Setting FIND_DIR to /mnt/nfs3/test Testing https://bugzilla.redhat.com/show_bug.cgi?id=883285 Creating files in /mnt/nfs3/test/883285 Filesystem 1K-blocks Used Available Use% Mounted on 192.168.122.37:/exports/nfs3 8910848 3300736 5610112 38% /mnt/nfs3 strace -c -o /tmp/test-883285-strace.txt find /mnt/nfs3/test -xdev -type f Found 5000 files Found 3884 fstatat calls in /tmp/test-883285-strace.txt Found 8 getdents calls in /tmp/test-883285-strace.txt Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 86.04 0.024651 6 3884 newfstatat 13.96 0.003999 500 8 getdents 0.00 0.000000 0 8 read 0.00 0.000000 0 39 write 0.00 0.000000 0 20 6 open 0.00 0.000000 0 16 close 0.00 0.000000 0 1 stat 0.00 0.000000 0 11 fstat 0.00 0.000000 0 24 mmap 0.00 0.000000 0 13 mprotect 0.00 0.000000 0 3 munmap 0.00 0.000000 0 14 brk 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 2 1 ioctl 0.00 0.000000 0 1 1 access 0.00 0.000000 0 1 execve 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 fcntl 0.00 0.000000 0 7 fchdir 0.00 0.000000 0 1 gettimeofday 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 2 statfs 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 2 1 futex 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.028650 4066 9 total TEST FAIL: on findutils-4.4.2-6.2.test.bz883285.el6_7.x86_64 - excessive newfstatat system calls found [root@rhel6u6-node1 01478764]# ./t1_bz883285.sh /tmp/test Setting FIND_DIR to /tmp/test Testing https://bugzilla.redhat.com/show_bug.cgi?id=883285 Creating files in /tmp/test/883285 Filesystem 1K-blocks Used Available Use% Mounted on /dev/mapper/VolGroup-lv_root 8649736 6977900 1225784 86% / strace -c -o /tmp/test-883285-strace.txt find /tmp/test -xdev -type f Found 5000 files Found 4 fstatat calls in /tmp/test-883285-strace.txt Found 8 getdents calls in /tmp/test-883285-strace.txt Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000024 2 16 close 0.00 0.000000 0 8 read 0.00 0.000000 0 33 write 0.00 0.000000 0 20 6 open 0.00 0.000000 0 1 stat 0.00 0.000000 0 11 fstat 0.00 0.000000 0 24 mmap 0.00 0.000000 0 13 mprotect 0.00 0.000000 0 3 munmap 0.00 0.000000 0 14 brk 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 2 1 ioctl 0.00 0.000000 0 1 1 access 0.00 0.000000 0 1 execve 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 fcntl 0.00 0.000000 0 8 getdents 0.00 0.000000 0 7 fchdir 0.00 0.000000 0 1 gettimeofday 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 2 statfs 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 2 1 futex 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 4 newfstatat 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000024 180 9 total TEST PASS: on findutils-4.4.2-6.2.test.bz883285.el6_7.x86_64 - did not find excessive newfstatat system calls --- Additional comment from Kamil Dudka on 2015-07-29 14:28:16 CEST --- Thank you for creating the test-case, Dave! I observed comparable results in my environment, too. The cause is pretty obvious IMO. readdir(3) returns d_type in the resulting 'struct dirent' object. If the field is set, fts and consequently find(1) use it to optimize out the call to stat () if only type of the file is required. However, the field is optional and each file system implementation may handle it differently. It is even correct for a file system implementation to always set the field to DT_UNKNOWN: http://marc.info/?l=netbsd-tech-kern&m=106753193617121 In this particular case, I guess, the NFS client implementation in kernel runs out of cache after a number of files and starts to return DT_UNKNOWN for the rest of them. Consequently find() has to call stat() to get that information, which causes additional round trips over the network and that is the delays. I am not sure whether the cache in kernel space is anyhow configurable. --- Additional comment from Kamil Dudka on 2015-07-29 16:06:01 CEST --- (In reply to Dave Wysochanski from comment #34) > If it's the NFS client kernel implementation, then why does 'oldfind' work > just fine, regardless of the number of files? I have been tracing oldfind with gdb and it looks like oldfind treats DT_UNKNOWN as "not a directory", which is not a safe assumption IMO (file systems in general can be implemented to use DT_UNKNOWN for everything): http://git.savannah.gnu.org/cgit/findutils.git/tree/find/find.c?id=FINDUTILS_4_4_2-1#n1164 Not sure whether we are able to find a counterexample for NFS though... --- Additional comment from Kamil Dudka on 2015-07-29 16:26:30 CEST --- It seems to be related to the following (safe?) optimization: http://git.savannah.gnu.org/cgit/findutils.git/tree/find/find.c?id=FINDUTILS_4_4_2-1#n1434 --- Additional comment from Kamil Dudka on 2015-07-30 20:10:11 CEST --- (In reply to Kamil Dudka from comment #36) > It seems to be related to the following (safe?) optimization: > > http://git.savannah.gnu.org/cgit/findutils.git/tree/find/find. > c?id=FINDUTILS_4_4_2-1#n1434 I learned myself that the above optimization is named "leaf optimization" and it is documented in find(1) man page. It can be disabled by the -noleaf option (and it indeed switches oldfind to the same "poor performance" mode). The problem is that the optimization is not implemented in RHEL-6 findutils. It is implemented in RHEL-7 and Fedora findutils: http://git.savannah.gnu.org/cgit/gnulib.git/commit/?id=97d5b665 ... however it is not enabled for NFS anyway: https://lists.gnu.org/archive/html/bug-gnulib/2009-01/msg00024.html I believe that *this* bug, as originally reported, is addressed by the proposed patch. With the patch applied, both find and oldfind now provide similar performance for the "-type f" predicate. The performance is still poor for name-only search on NFS with huge directories on RHEL-6+ but I would treat this as a separate issue. I propose to clone this bug and get the other problem fixed in upstream and Fedora first. --- Additional comment from Kamil Dudka on 2015-08-10 23:52:57 CEST --- There are two issues I would like to evaluate separately: 1) RHEL-6 find currently does not use the d_type field returned by readdir() at all. This is the bug that was originally described in comment #0, is already fixed in RHEL-7 and Fedora, and can be fixed in RHEL-6 using attachment #1056956 [details]. 2) RHEL-6 find (unlike oldfind or RHEL-5 find) does not use the above mentioned leaf optimization, which is able to skip stat() calls in additional cases. The optimization relies the link count previously returned for the directory being traversed and, if all its subdirectories were already traversed, all other files are assumed to be non-directories. The leaf optimization is useless if the '-type f' predicate needs to be evaluated (as in comment #0) because this requires stat() to be called anyway. Your test case uses name-only search where the leaf optimization applies. The problem is that issue 2) is not yet addressed in upstream findutils, at least not for NFS. That is why I would like to treat it as a separate bug. --- Additional comment from Dave Wysochanski on 2015-08-11 00:45:53 CEST --- Ah ok, thanks for the clarification. Have you opened the second bug yet? So there's actually 3 bugs here, 2 in 'find' and one in the RHEL6 kernel nfs behavior (1248140), so the whole 'find performance' can be quite confusing and easily misdiagnosed. I still am not sure what, if anything can be done for the RHEL6 kernel behavior change in bug 1248140. --- Additional comment from Kamil Dudka on 2015-08-11 10:41:17 CEST --- (In reply to Dave Wysochanski from comment #44) > Have you opened the second bug yet? Not yet. I propose to open the second bug against RHEL-7 because the optimization, as implemented, requires the FTS_CWDFD mode to be enabled: http://git.savannah.gnu.org/cgit/findutils.git/commit/?id=214320ca ... and enabling would basically require a rebase of findutils, which is unlikely to be approved for RHEL-6 so late in its life time.
Created attachment 1078398 [details] [PATCH] enable leaf optimization for NFS I have implemented the proposed fix. It enables the leaf optimization for NFS but allows to disable it by the -noleaf option of find. In the end, the patch appeared not to be necessary because the FTS_CWDFD flag did all the job. That is, I got equivalent results with/without the leaf optimization for NFS using RHEL-7 find.
Dave, are you able to reproduce the slowdown on a RHEL-7 system?
(In reply to Kamil Dudka from comment #2) > Dave, are you able to reproduce the slowdown on a RHEL-7 system? Yes, see test results here: https://bugzilla.redhat.com/show_bug.cgi?id=1248140#c20 If you have a new findutils package for RHEL7 I can try to test it with my reproducer. The reproducer is fairly stable right now but I'm still working on a few more refinements, including adding a couple similar "listing" type commands such as 'ls' and 'ls -l' since they are related and commonly used and come up on support cases a lot. I can repro on even an upstream kernel 4.2. The root of the problem seems to be that d_type in the getdents call is a real oddball. If someone does a 'stat' on a directory entry then they get the type in the 'mode' bits back, but with 'getdents' it may come back there as well. Now regardless of where the type is obtained, it seems like it should be cached somewhere, and subject to the same caching rules. I'm wondering what can be done for NFS to help the d_type situation. In the NFS client, there seems to be a disconnect between the 'readdir' implementation's caching of d_type and directory entries, and the overall attribute caching of attributes of an inode / dentry (i.e. the mode bits we get back when we service a 'stat' which results in a GETATTR). I found some unexpected behavior in RHEL6.7 kernels where an 'ls -l' would trip the readdirplus code, and hence fill in d_type = 8 for all entries. After that the test case no longer fails, since the 'd_type' field is filled in for any subsequent readdir call, and so there's no need for 'find' to issue fstatat calls anymore. See https://bugzilla.redhat.com/show_bug.cgi?id=1248140#c27
(In reply to Dave Wysochanski from comment #3) > (In reply to Kamil Dudka from comment #2) > > Dave, are you able to reproduce the slowdown on a RHEL-7 system? > > Yes, see test results here: > https://bugzilla.redhat.com/show_bug.cgi?id=1248140#c20 This differs from my results obtained from running attachment #1076695 [details] on kernel-3.10.0-326.el7.x86_64 and findutils-4.5.11-3.el7.x86_64: # ./t0_bz1248140.sh localhost Setting FIND_DIR = /mnt/bz1248140-export/test, FILE_COUNT = 5000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1248140 Error: an inet prefix is expected rather than "localhost". Thu Oct 29 11:42:06 CET 2015: Step 1. On NFS client: tcpdump -q -i -w /tmp/tcpdump-1917-1248140.pcap -s 0 port 2049 and host localhost tcpdump: -w: No such device exists (SIOCGIFHWADDR: No such device) Thu Oct 29 11:42:07 CET 2015: Step 2. On NFS client: mount -t nfs localhost:/exports/bz1248140-export /mnt/bz1248140-export Creating files in /mnt/bz1248140-export/test/1248140 Filesystem 1K-blocks Used Available Use% Mounted on localhost:/exports/bz1248140-export 126931968 63157760 57303296 53% /mnt/bz1248140-export strace -c -o /tmp/test-1248140-strace.txt find /mnt/bz1248140-export/test -name *.pdf Found 5000 files Found 4 fstatat calls in /tmp/test-1248140-strace.txt Found 4 getdents calls in /tmp/test-1248140-strace.txt Thu Oct 29 11:42:21 CET 2015: Step 8. On NFS client, kill tcpdump Thu Oct 29 11:42:21 CET 2015: Step 9. On NFS client, check tcpdump expected packets. Cannot read /tmp/tcpdump-1917-1248140.pcap! Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 78.70 0.026873 6718 4 getdents 4.79 0.001635 53 31 brk 3.37 0.001151 40 29 mmap 2.27 0.000774 41 19 6 open 1.62 0.000553 35 16 mprotect 1.56 0.000534 28 19 fcntl 1.51 0.000517 24 22 close 1.49 0.000510 34 15 fstat 1.07 0.000367 33 11 read 0.64 0.000220 110 2 openat 0.47 0.000160 32 5 munmap 0.41 0.000140 35 4 newfstatat 0.40 0.000135 135 1 1 access 0.23 0.000079 79 1 execve 0.21 0.000072 36 2 2 statfs 0.18 0.000063 32 2 1 ioctl 0.18 0.000060 30 2 rt_sigaction 0.14 0.000049 1 60 write 0.11 0.000038 38 1 rt_sigprocmask 0.10 0.000035 35 1 1 stat 0.09 0.000031 31 1 uname 0.09 0.000031 31 1 getrlimit 0.09 0.000031 31 1 futex 0.09 0.000030 30 1 arch_prctl 0.09 0.000030 30 1 set_tid_address 0.09 0.000030 30 1 set_robust_list 0.00 0.000000 0 1 fchdir ------ ----------- ----------- --------- --------- ---------------- 100.00 0.034148 254 11 total TEST PASS: on findutils-4.5.11-3.el7.x86_64 kernel-3.10.0-326.el7.x86_64 - did not find excessive newfstatat system calls > If you have a new findutils package for RHEL7 I can try to test it with my > reproducer. My patch (attachment #1078398 [details]) seems to be broken. I will try to fix it and prepare a new build of findutils for testing.
Created attachment 1087477 [details] [PATCH V2] enable leaf optimization for NFS
Kamil, Your latest code definitely fixes the problem for the testcase I have. The latest test case I have divides the creation of the files into a separate 'prep' step, then a second 'run' script runs the actual find command. I did this to separate any effect of the creation of the files from the find command running. I'm not sure why your original test failed even after the update. It's possible that test is no good due to creation of the files, or if you did an "ls -l" in the directory it would have filled the page cache and the test would have passed after that point. I will attach updated test scripts to this bug.
Created attachment 1101955 [details] t0_bz1252549_prep.sh
Created attachment 1101956 [details] t0_bz1252549_run.sh
Comment on attachment 1101955 [details] t0_bz1252549_prep.sh Run as follows: # ./t0_bz1252549_prep.sh 127.0.0.1 10000 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Prepping test for https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Creating directory /mnt/bz1252549-export adding /exports/bz1252549-export to /etc/exports creating /exports/bz1252549-export directory restarting nfs-server Thu Dec 3 15:13:47 EST 2015: Step 2. On NFS client: mount -t nfs -overs=3 127.0.0.1:/exports/bz1252549-export /mnt/bz1252549-export Creating files in /mnt/bz1252549-export/test/1252549 Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 52403200 2333696 50069504 5% /mnt/bz1252549-export
Comment on attachment 1101956 [details] t0_bz1252549_run.sh Run as follows: [root@core-aarch64-02 01478764]# ./t0_bz1252549_run.sh 127.0.0.1 10000 0 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Thu Dec 3 15:15:51 EST 2015: Step 1. On NFS client: tcpdump -q -i lo -w /tmp/tcpdump-12379-1252549.pcap -s 0 port 2049 and host 127.0.0.1 tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes Thu Dec 3 15:15:52 EST 2015: Step 2. On NFS client: skipping unmount /mnt/bz1252549-export Thu Dec 3 15:15:52 EST 2015: Step 3. On NFS client: skipping mount /mnt/bz1252549-export Thu Dec 3 15:15:52 EST 2015: Step 4. On NFS client: df /mnt/bz1252549-export/test Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 52403200 2333696 50069504 5% /mnt/bz1252549-export Thu Dec 3 15:15:52 EST 2015: Step 5. On NFS client: strace -c -o /tmp/test-1252549-12379-strace.txt find /mnt/bz1252549-export/test -name "*.pdf" > /tmp/test-1252549-12379-cmd-out.txt Thu Dec 3 15:15:53 EST 2015: Step 6. On NFS client: Check output files for fstatat, gentdents Found 10000 /tmp/test-1252549-12379-cmd-out.txt files Found 6731 fstatat calls in /tmp/test-1252549-12379-strace.txt Found 9 getdents calls in /tmp/test-1252549-12379-strace.txt Thu Dec 3 15:15:53 EST 2015: Step 7. On NFS client, kill tcpdump 13541 packets captured 27082 packets received by filter 0 packets dropped by kernel Thu Dec 3 15:15:53 EST 2015: Step 9. On NFS client, show summary of tcpdump. Running as user "root" and group "root". This could be dangerous. Running as user "root" and group "root". This could be dangerous. NFSv3 Call Count Min Avg Max Total GETATTR 6728 0.000027 0.000035 0.000397 0.234163 ACCESS 3 0.000034 0.000060 0.000101 0.000179 READDIR 9 0.000077 0.000262 0.000339 0.002358 READDIRPLUS 11 0.000076 0.000670 0.000772 0.007375 FSSTAT 2 0.000055 0.000057 0.000059 0.000114 summary 6753 0.000027 0.000036 0.000772 0.244189 Full strace file: System call usage summary for 64 bit mode: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.001837 0 6731 newfstatat 0.00 0.000000 0 19 fcntl 0.00 0.000000 0 2 2 ioctl 0.00 0.000000 0 2 statfs64 0.00 0.000000 0 1 fstatfs64 0.00 0.000000 0 1 1 faccessat 0.00 0.000000 0 1 fchdir 0.00 0.000000 0 20 6 openat 0.00 0.000000 0 21 close 0.00 0.000000 0 9 getdents64 0.00 0.000000 0 9 read 0.00 0.000000 0 8 write 0.00 0.000000 0 14 fstat 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 futex 0.00 0.000000 0 1 set_robust_list 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 37 brk 0.00 0.000000 0 3 munmap 0.00 0.000000 0 1 execve 0.00 0.000000 0 19 mmap 0.00 0.000000 0 9 mprotect ------ ----------- ----------- --------- --------- ---------------- 100.00 0.001837 6915 9 total TEST FAIL: on findutils-4.5.11-5.el7.aarch64 kernel-4.2.0-0.21.el7.aarch64 - excessive newfstatat system calls found
Comment on attachment 1101956 [details] t0_bz1252549_run.sh Example passing run with new findutils [root@core-aarch64-02 01478764]# ./t0_bz1252549_run.sh 127.0.0.1 10000 0Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Thu Dec 3 15:18:20 EST 2015: Step 1. On NFS client: tcpdump -q -i lo -w /tmp/tcpdump-12431-1252549.pcap -s 0 port 2049 and host 127.0.0.1 tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes Thu Dec 3 15:18:21 EST 2015: Step 2. On NFS client: skipping unmount /mnt/bz1252549-export Thu Dec 3 15:18:21 EST 2015: Step 3. On NFS client: skipping mount /mnt/bz1252549-export Thu Dec 3 15:18:21 EST 2015: Step 4. On NFS client: df /mnt/bz1252549-export/test Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 52403200 2339840 50063360 5% /mnt/bz1252549-export Thu Dec 3 15:18:21 EST 2015: Step 5. On NFS client: strace -c -o /tmp/test-1252549-12431-strace.txt find /mnt/bz1252549-export/test -name "*.pdf" > /tmp/test-1252549-12431-cmd-out.txt Thu Dec 3 15:18:21 EST 2015: Step 6. On NFS client: Check output files for fstatat, gentdents Found 10000 /tmp/test-1252549-12431-cmd-out.txt files Found 5 fstatat calls in /tmp/test-1252549-12431-strace.txt Found 9 getdents calls in /tmp/test-1252549-12431-strace.txt Thu Dec 3 15:18:21 EST 2015: Step 7. On NFS client, kill tcpdump 91 packets captured 182 packets received by filter 0 packets dropped by kernel Thu Dec 3 15:18:21 EST 2015: Step 9. On NFS client, show summary of tcpdump. Running as user "root" and group "root". This could be dangerous. Running as user "root" and group "root". This could be dangerous. NFSv3 Call Count Min Avg Max Total GETATTR 4 0.000040 0.000055 0.000080 0.000220 ACCESS 3 0.000033 0.000057 0.000098 0.000171 READDIR 9 0.000098 0.000271 0.000345 0.002442 READDIRPLUS 10 0.000627 0.000745 0.000818 0.007446 FSSTAT 2 0.000062 0.000080 0.000097 0.000159 summary 28 0.000033 0.000373 0.000818 0.010438 Full strace file: System call usage summary for 64 bit mode: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 19 fcntl 0.00 0.000000 0 2 2 ioctl 0.00 0.000000 0 2 statfs64 0.00 0.000000 0 1 fstatfs64 0.00 0.000000 0 1 1 faccessat 0.00 0.000000 0 1 fchdir 0.00 0.000000 0 20 6 openat 0.00 0.000000 0 21 close 0.00 0.000000 0 9 getdents64 0.00 0.000000 0 9 read 0.00 0.000000 0 8 write 0.00 0.000000 0 5 newfstatat 0.00 0.000000 0 14 fstat 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 futex 0.00 0.000000 0 1 set_robust_list 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 37 brk 0.00 0.000000 0 3 munmap 0.00 0.000000 0 1 execve 0.00 0.000000 0 19 mmap 0.00 0.000000 0 9 mprotect ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 189 9 total TEST PASS: on findutils-4.5.11-6.el7.aarch64 kernel-4.2.0-0.21.el7.aarch64 - did not find excessive newfstatat system calls
(In reply to Dave Wysochanski from comment #12) > I'm not sure why your original test failed even after the update. That is not what I am saying. The problem in my case was that I was not able to observe the excessive stat() calls with findutils-4.5.11-5.el7 either. I see you are testing on aarch64. Cannot the issue be specific to that platform? Could you please check with findutils-4.5.11-6.el7 that using -noleaf reintroduces the old inefficient behavior in your testing environment?
(In reply to Kamil Dudka from comment #19) > (In reply to Dave Wysochanski from comment #12) > > I'm not sure why your original test failed even after the update. > > That is not what I am saying. The problem in my case was that I was not > able to observe the excessive stat() calls with findutils-4.5.11-5.el7 > either. I see you are testing on aarch64. Cannot the issue be specific to > that platform? > No aarch64 has nothing to do with the problem / outcome. Did you try the scripts I uploaded in comments #16 and #17 on your own RHEL7.2 GA and the exact commandlines? You should see the same results. I just ran on an x86_64 system and got the same results.
(In reply to Dave Wysochanski from comment #20) > Did you try the scripts I uploaded in comments #16 and #17 on your own > RHEL7.2 GA and the exact commandlines? Yes, I did. Here is the output with findutils-4.5.11-5.el7.x86_64 and kernel- 3.10.0-327.el7.x86_64: [root@el7 bz1252549]# ./t0_bz1252549_prep.sh 127.0.0.1 10000 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Prepping test for https://bugzilla.redhat.com/show_bug.cgi?id=1252549 restarting nfs-server Tue Dec 8 12:34:46 CET 2015: Step 2. On NFS client: mount -t nfs -overs=3 127.0.0.1:/exports/bz1252549-export /mnt/bz1252549-export mount.nfs: /mnt/bz1252549-export is busy or already mounted Creating files in /mnt/bz1252549-export/test/1252549 Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 126931968 63222272 57238528 53% /mnt/bz1252549-export [root@el7 bz1252549]# ./t0_bz1252549_run.sh 127.0.0.1 10000 0 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Tue Dec 8 12:36:09 CET 2015: Step 1. On NFS client: tcpdump -q -i lo -w /tmp/tcpdump-22203-1252549.pcap -s 0 port 2049 and host 127.0.0.1 tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes Tue Dec 8 12:36:10 CET 2015: Step 2. On NFS client: skipping unmount /mnt/bz1252549-export Tue Dec 8 12:36:10 CET 2015: Step 3. On NFS client: skipping mount /mnt/bz1252549-export Tue Dec 8 12:36:10 CET 2015: Step 4. On NFS client: df /mnt/bz1252549-export/test Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 126931968 63222272 57238528 53% /mnt/bz1252549-export Tue Dec 8 12:36:10 CET 2015: Step 5. On NFS client: strace -c -o /tmp/test-1252549-22203-strace.txt find /mnt/bz1252549-export/test -name "*.pdf" > /tmp/test-1252549-22203-cmd-out.txt Tue Dec 8 12:36:10 CET 2015: Step 6. On NFS client: Check output files for fstatat, gentdents Found 10000 /tmp/test-1252549-22203-cmd-out.txt files Found 4 fstatat calls in /tmp/test-1252549-22203-strace.txt Found 4 getdents calls in /tmp/test-1252549-22203-strace.txt Tue Dec 8 12:36:10 CET 2015: Step 7. On NFS client, kill tcpdump 20 packets captured 40 packets received by filter 0 packets dropped by kernel Tue Dec 8 12:36:10 CET 2015: Step 9. On NFS client, show summary of tcpdump. Skipping pcap_nfsstat.sh - file not found Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 18.46 0.001613 56 29 mmap 14.09 0.001231 10 120 write 10.18 0.000890 56 16 mprotect 10.15 0.000887 222 4 getdents 10.07 0.000880 46 19 6 open 6.49 0.000567 26 22 close 5.62 0.000491 33 15 fstat 5.46 0.000477 43 11 read 4.35 0.000380 190 2 openat 3.31 0.000289 5 53 brk 2.16 0.000189 189 1 1 access 2.05 0.000179 36 5 munmap 1.75 0.000153 153 1 execve 1.00 0.000087 44 2 rt_sigaction 0.90 0.000079 40 2 2 statfs 0.76 0.000066 3 19 fcntl 0.58 0.000051 51 1 set_tid_address 0.49 0.000043 43 1 arch_prctl 0.47 0.000041 41 1 set_robust_list 0.45 0.000039 39 1 1 stat 0.45 0.000039 39 1 rt_sigprocmask 0.39 0.000034 34 1 uname 0.39 0.000034 34 1 getrlimit 0.00 0.000000 0 2 2 ioctl 0.00 0.000000 0 1 fchdir 0.00 0.000000 0 1 futex 0.00 0.000000 0 4 newfstatat ------ ----------- ----------- --------- --------- ---------------- 100.00 0.008739 336 12 total TEST PASS: on findutils-4.5.11-5.el7.x86_64 kernel-3.10.0-327.el7.x86_64 - did not find excessive newfstatat system calls Where did you get kernel-4.2.0-0.21.el7? There is no such build in brew...
(In reply to Kamil Dudka from comment #21) > (In reply to Dave Wysochanski from comment #20) > > Did you try the scripts I uploaded in comments #16 and #17 on your own > > RHEL7.2 GA and the exact commandlines? > > Yes, I did. Here is the output with findutils-4.5.11-5.el7.x86_64 and > kernel- > 3.10.0-327.el7.x86_64: > > [root@el7 bz1252549]# ./t0_bz1252549_prep.sh 127.0.0.1 10000 > Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 > Prepping test for https://bugzilla.redhat.com/show_bug.cgi?id=1252549 > restarting nfs-server > Tue Dec 8 12:34:46 CET 2015: Step 2. On NFS client: mount -t nfs -overs=3 > 127.0.0.1:/exports/bz1252549-export /mnt/bz1252549-export > mount.nfs: /mnt/bz1252549-export is busy or already mounted This indicates the mount point was already mounted so the test results may be invalid - i.e. it's impossible to know what has been done to the mount point and what state the caches are in. Please umount and try again. Regarding the kernel-4.2.0-0.21.el7, this is for the 7.2 release of Red Hat Enterprise Linux Server for ARM. It is in development preview right now. Regardless this does not matter as I can reproduce on a 7.2 x86_64 GA system and you should be able to as well. [root@rhel7u2-node1 ~]# systemctl start nfs-server [root@rhel7u2-node1 ~]# systemctl status nfs-server ● nfs-server.service - NFS server and services Loaded: loaded (/usr/lib/systemd/system/nfs-server.service; disabled; vendor preset: disabled) Active: active (exited) since Tue 2015-12-08 11:04:14 EST; 4s ago Process: 2431 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS (code=exited, status=0/SUCCESS) Process: 2430 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS) Main PID: 2431 (code=exited, status=0/SUCCESS) CGroup: /system.slice/nfs-server.service Dec 08 11:04:14 rhel7u2-node1.dwysocha.net systemd[1]: Starting NFS server and services... Dec 08 11:04:14 rhel7u2-node1.dwysocha.net systemd[1]: Started NFS server and services. [root@rhel7u2-node1 ~]# cd cases/01478764/ [root@rhel7u2-node1 01478764]# ./t0_bz1252549_prep.sh 127.0.0.1 10000 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Prepping test for https://bugzilla.redhat.com/show_bug.cgi?id=1252549 restarting nfs-server Tue Dec 8 11:04:41 EST 2015: Step 2. On NFS client: mount -t nfs -overs=3 127.0.0.1:/exports/bz1252549-export /mnt/bz1252549-export Creating files in /mnt/bz1252549-export/test/1252549 Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 8869888 3534976 5334912 40% /mnt/bz1252549-export [root@rhel7u2-node1 01478764]# ./t0_bz1252549_run.sh 127.0.0.1 10000 0 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Tue Dec 8 11:05:27 EST 2015: Step 1. On NFS client: tcpdump -q -i lo -w /tmp/tcpdump-12505-1252549.pcap -s 0 port 2049 and host 127.0.0.1 tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes Tue Dec 8 11:05:28 EST 2015: Step 2. On NFS client: skipping unmount /mnt/bz1252549-export Tue Dec 8 11:05:28 EST 2015: Step 3. On NFS client: skipping mount /mnt/bz1252549-export Tue Dec 8 11:05:28 EST 2015: Step 4. On NFS client: df /mnt/bz1252549-export/test Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 8869888 3534976 5334912 40% /mnt/bz1252549-export Tue Dec 8 11:05:28 EST 2015: Step 5. On NFS client: strace -c -o /tmp/test-1252549-12505-strace.txt find /mnt/bz1252549-export/test -name "*.pdf" > /tmp/test-1252549-12505-cmd-out.txt Tue Dec 8 11:05:29 EST 2015: Step 6. On NFS client: Check output files for fstatat, gentdents Found 10000 /tmp/test-1252549-12505-cmd-out.txt files Found 6436 fstatat calls in /tmp/test-1252549-12505-strace.txt Found 6 getdents calls in /tmp/test-1252549-12505-strace.txt Tue Dec 8 11:05:29 EST 2015: Step 7. On NFS client, kill tcpdump 13483 packets captured 26966 packets received by filter 0 packets dropped by kernel Tue Dec 8 11:05:29 EST 2015: Step 9. On NFS client, show summary of tcpdump. Running as user "root" and group "root". This could be dangerous. Running as user "root" and group "root". This could be dangerous. NFSv3 Call Count Min Avg Max Total GETATTR 6434 0.000029 0.000041 0.000581 0.263655 ACCESS 1 0.000128 0.000128 0.000128 0.000128 READDIR 127 0.000052 0.000091 0.000116 0.011520 READDIRPLUS 176 0.000064 0.000095 0.000801 0.016771 FSSTAT 2 0.000053 0.000076 0.000099 0.000152 summary 6740 0.000029 0.000043 0.000801 0.292226 Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 89.62 0.164860 26 6436 newfstatat 9.41 0.017319 2887 6 getdents 0.32 0.000596 5 120 write 0.20 0.000360 7 53 brk 0.08 0.000148 5 28 mmap 0.08 0.000143 72 2 openat 0.07 0.000123 7 18 6 open 0.05 0.000094 6 16 mprotect 0.03 0.000049 2 21 close 0.02 0.000044 44 1 fstatfs 0.02 0.000042 2 19 fcntl 0.02 0.000036 9 4 munmap 0.02 0.000034 2 14 fstat 0.02 0.000032 4 9 read 0.02 0.000031 16 2 statfs 0.00 0.000007 4 2 2 ioctl 0.00 0.000006 6 1 stat 0.00 0.000006 6 1 1 access 0.00 0.000004 2 2 rt_sigaction 0.00 0.000004 4 1 futex 0.00 0.000003 3 1 execve 0.00 0.000003 3 1 fchdir 0.00 0.000003 3 1 getrlimit 0.00 0.000003 3 1 arch_prctl 0.00 0.000003 3 1 set_tid_address 0.00 0.000002 2 1 rt_sigprocmask 0.00 0.000002 2 1 uname 0.00 0.000002 2 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.183959 6764 9 total TEST FAIL: on findutils-4.5.11-5.el7.x86_64 kernel-3.10.0-327.el7.x86_64 - excessive newfstatat system calls found [root@rhel7u2-node1 01478764]# yum localinstall findutils-4.5.11-6.el7.x86_64.rpm Loaded plugins: product-id, search-disabled-repos, subscription-manager Examining findutils-4.5.11-6.el7.x86_64.rpm: 1:findutils-4.5.11-6.el7.x86_64 Marking findutils-4.5.11-6.el7.x86_64.rpm as an update to 1:findutils-4.5.11-5.el7.x86_64 Resolving Dependencies --> Running transaction check ---> Package findutils.x86_64 1:4.5.11-5.el7 will be updated ---> Package findutils.x86_64 1:4.5.11-6.el7 will be an update --> Finished Dependency Resolution Dependencies Resolved ============================================================================================================================ Package Arch Version Repository Size ============================================================================================================================ Updating: findutils x86_64 1:4.5.11-6.el7 /findutils-4.5.11-6.el7.x86_64 1.8 M Transaction Summary ============================================================================================================================ Upgrade 1 Package Total size: 1.8 M Is this ok [y/d/N]: y Downloading packages: Running transaction check Running transaction test Transaction test succeeded Running transaction Updating : 1:findutils-4.5.11-6.el7.x86_64 1/2 Cleanup : 1:findutils-4.5.11-5.el7.x86_64 2/2 Verifying : 1:findutils-4.5.11-6.el7.x86_64 1/2 Verifying : 1:findutils-4.5.11-5.el7.x86_64 2/2 Updated: findutils.x86_64 1:4.5.11-6.el7 Complete! [root@rhel7u2-node1 01478764]# ./t0_bz1252549_run.sh 127.0.0.1 10000 0 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Tue Dec 8 11:06:30 EST 2015: Step 1. On NFS client: tcpdump -q -i lo -w /tmp/tcpdump-12597-1252549.pcap -s 0 port 2049 and host 127.0.0.1 tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes Tue Dec 8 11:06:31 EST 2015: Step 2. On NFS client: skipping unmount /mnt/bz1252549-export Tue Dec 8 11:06:31 EST 2015: Step 3. On NFS client: skipping mount /mnt/bz1252549-export Tue Dec 8 11:06:31 EST 2015: Step 4. On NFS client: df /mnt/bz1252549-export/test Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 8869888 3526144 5343744 40% /mnt/bz1252549-export Tue Dec 8 11:06:31 EST 2015: Step 5. On NFS client: strace -c -o /tmp/test-1252549-12597-strace.txt find /mnt/bz1252549-export/test -name "*.pdf" > /tmp/test-1252549-12597-cmd-out.txt Tue Dec 8 11:06:31 EST 2015: Step 6. On NFS client: Check output files for fstatat, gentdents Found 10000 /tmp/test-1252549-12597-cmd-out.txt files Found 4 fstatat calls in /tmp/test-1252549-12597-strace.txt Found 6 getdents calls in /tmp/test-1252549-12597-strace.txt Tue Dec 8 11:06:31 EST 2015: Step 7. On NFS client, kill tcpdump 625 packets captured 1250 packets received by filter 0 packets dropped by kernel Tue Dec 8 11:06:31 EST 2015: Step 9. On NFS client, show summary of tcpdump. Running as user "root" and group "root". This could be dangerous. Running as user "root" and group "root". This could be dangerous. NFSv3 Call Count Min Avg Max Total GETATTR 4 0.000045 0.000097 0.000216 0.000388 ACCESS 3 0.000042 0.000132 0.000300 0.000396 READDIR 127 0.000053 0.000092 0.000126 0.011723 READDIRPLUS 175 0.000078 0.000093 0.000121 0.016199 FSSTAT 2 0.000049 0.000082 0.000114 0.000163 summary 311 0.000042 0.000093 0.000300 0.028869 Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 97.42 0.017665 2944 6 getdents 0.63 0.000114 4 28 mmap 0.40 0.000072 5 16 mprotect 0.36 0.000066 1 120 write 0.33 0.000059 3 18 6 open 0.21 0.000038 19 2 openat 0.14 0.000025 1 21 close 0.13 0.000024 6 4 newfstatat 0.13 0.000023 3 9 read 0.10 0.000019 1 14 fstat 0.05 0.000009 0 53 brk 0.04 0.000007 7 1 1 access 0.03 0.000006 0 19 fcntl 0.02 0.000003 3 1 execve 0.01 0.000002 2 1 arch_prctl 0.00 0.000000 0 1 stat 0.00 0.000000 0 4 munmap 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 2 2 ioctl 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 fchdir 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 2 statfs 0.00 0.000000 0 1 fstatfs 0.00 0.000000 0 1 futex 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.018132 332 9 total TEST PASS: on findutils-4.5.11-6.el7.x86_64 kernel-3.10.0-327.el7.x86_64 - did not find excessive newfstatat system calls [root@rhel7u2-node1 01478764]# yum downgrade findutils Loaded plugins: product-id, search-disabled-repos, subscription-manager Resolving Dependencies --> Running transaction check ---> Package findutils.x86_64 1:4.5.11-5.el7 will be a downgrade ---> Package findutils.x86_64 1:4.5.11-6.el7 will be erased --> Finished Dependency Resolution Dependencies Resolved ============================================================================================================================ Package Arch Version Repository Size ============================================================================================================================ Downgrading: findutils x86_64 1:4.5.11-5.el7 rhel-7-server-rpms 559 k Transaction Summary ============================================================================================================================ Downgrade 1 Package Total download size: 559 k Is this ok [y/d/N]: y Downloading packages: findutils-4.5.11-5.el7.x86_64.rpm | 559 kB 00:00:01 Running transaction check Running transaction test Transaction test succeeded Running transaction Installing : 1:findutils-4.5.11-5.el7.x86_64 1/2 Cleanup : 1:findutils-4.5.11-6.el7.x86_64 2/2 Verifying : 1:findutils-4.5.11-5.el7.x86_64 1/2 Verifying : 1:findutils-4.5.11-6.el7.x86_64 2/2 Removed: findutils.x86_64 1:4.5.11-6.el7 Installed: findutils.x86_64 1:4.5.11-5.el7 Complete! [root@rhel7u2-node1 01478764]# ./t0_bz1252549_run.sh 127.0.0.1 10000 0 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Tue Dec 8 11:07:08 EST 2015: Step 1. On NFS client: tcpdump -q -i lo -w /tmp/tcpdump-12651-1252549.pcap -s 0 port 2049 and host 127.0.0.1 tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes Tue Dec 8 11:07:09 EST 2015: Step 2. On NFS client: skipping unmount /mnt/bz1252549-export Tue Dec 8 11:07:09 EST 2015: Step 3. On NFS client: skipping mount /mnt/bz1252549-export Tue Dec 8 11:07:09 EST 2015: Step 4. On NFS client: df /mnt/bz1252549-export/test Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 8869888 3528064 5341824 40% /mnt/bz1252549-export Tue Dec 8 11:07:09 EST 2015: Step 5. On NFS client: strace -c -o /tmp/test-1252549-12651-strace.txt find /mnt/bz1252549-export/test -name "*.pdf" > /tmp/test-1252549-12651-cmd-out.txt Tue Dec 8 11:07:10 EST 2015: Step 6. On NFS client: Check output files for fstatat, gentdents Found 10000 /tmp/test-1252549-12651-cmd-out.txt files Found 6436 fstatat calls in /tmp/test-1252549-12651-strace.txt Found 6 getdents calls in /tmp/test-1252549-12651-strace.txt Tue Dec 8 11:07:10 EST 2015: Step 7. On NFS client, kill tcpdump 12879 packets captured 25758 packets received by filter 0 packets dropped by kernel Tue Dec 8 11:07:10 EST 2015: Step 9. On NFS client, show summary of tcpdump. Running as user "root" and group "root". This could be dangerous. Running as user "root" and group "root". This could be dangerous. NFSv3 Call Count Min Avg Max Total GETATTR 6435 0.000036 0.000041 0.000215 0.265277 READDIRPLUS 1 0.000256 0.000256 0.000256 0.000256 FSSTAT 2 0.000050 0.000067 0.000084 0.000134 summary 6438 0.000036 0.000041 0.000256 0.265667 Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 98.51 0.107845 17 6436 newfstatat 0.79 0.000867 145 6 getdents 0.33 0.000361 7 53 brk 0.28 0.000304 3 120 write 0.02 0.000026 1 28 mmap 0.02 0.000020 1 16 mprotect 0.01 0.000016 8 2 openat 0.01 0.000013 1 18 6 open 0.01 0.000006 6 1 1 access 0.00 0.000005 0 14 fstat 0.00 0.000005 0 19 fcntl 0.00 0.000004 0 9 read 0.00 0.000003 1 4 munmap 0.00 0.000003 3 1 execve 0.00 0.000002 0 21 close 0.00 0.000000 0 1 stat 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 2 2 ioctl 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 fchdir 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 2 statfs 0.00 0.000000 0 1 fstatfs 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 1 futex 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.109480 6764 9 total TEST FAIL: on findutils-4.5.11-5.el7.x86_64 kernel-3.10.0-327.el7.x86_64 - excessive newfstatat system calls found
My guess is you probably did an 'ls' in the directory where the files are. If you do an 'ls' then this triggers NFS to do more expensive operations which obtains attributes, so the page cache is then filled with d_type. If you run the test with the remount option set to 1, it should fail on findutils-4.5.11-5.el7 and pass on findutils-4.5.11-6.el7 every time: # ./t0_bz1252549_run.sh 127.0.0.1 10000 1
(In reply to Dave Wysochanski from comment #22) > > [root@el7 bz1252549]# ./t0_bz1252549_prep.sh 127.0.0.1 10000 > > Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 > > Prepping test for https://bugzilla.redhat.com/show_bug.cgi?id=1252549 > > restarting nfs-server > > Tue Dec 8 12:34:46 CET 2015: Step 2. On NFS client: mount -t nfs -overs=3 > > 127.0.0.1:/exports/bz1252549-export /mnt/bz1252549-export > > mount.nfs: /mnt/bz1252549-export is busy or already mounted > > This indicates the mount point was already mounted so the test results may > be invalid - i.e. it's impossible to know what has been done to the mount > point and what state the caches are in. Please umount and try again. It was caused by repeated invocation of those scripts while trying to repeat the bug. I have restarted the VM to try it with fresh environment but it did not change anything: Last login: Tue Dec 8 12:25:18 2015 from gateway [kdudka@el7 ~]$ su - Password: Last login: Tue Dec 8 12:25:29 CET 2015 on pts/0 [root@el7 ~]# systemctl start nfs-server [root@el7 ~]# systemctl status nfs-server ● nfs-server.service - NFS server and services Loaded: loaded (/usr/lib/systemd/system/nfs-server.service; disabled; vendor preset: disabled) Active: active (exited) since Tue 2015-12-08 17:48:14 CET; 5s ago Process: 1858 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS (code=exited, status=0/SUCCESS) Process: 1855 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS) Main PID: 1858 (code=exited, status=0/SUCCESS) CGroup: /system.slice/nfs-server.service Dec 08 17:48:14 el7 systemd[1]: Starting NFS server and services... Dec 08 17:48:14 el7 systemd[1]: Started NFS server and services. [root@el7 ~]# cd /tmp/bz1252549/ [root@el7 bz1252549]# ./t0_bz1252549_prep.sh 127.0.0.1 10000 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Prepping test for https://bugzilla.redhat.com/show_bug.cgi?id=1252549 restarting nfs-server Tue Dec 8 17:48:47 CET 2015: Step 2. On NFS client: mount -t nfs -overs=3 127.0.0.1:/exports/bz1252549-export /mnt/bz1252549-export Creating files in /mnt/bz1252549-export/test/1252549 Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 126931968 63222272 57238528 53% /mnt/bz1252549-export [root@el7 bz1252549]# ./t0_bz1252549_run.sh 127.0.0.1 10000 0 Setting FIND_DIR = /mnt/bz1252549-export/test, FILE_COUNT = 10000 Testing https://bugzilla.redhat.com/show_bug.cgi?id=1252549 Tue Dec 8 17:50:07 CET 2015: Step 1. On NFS client: tcpdump -q -i lo -w /tmp/tcpdump-11927-1252549.pcap -s 0 port 2049 and host 127.0.0.1 tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes Tue Dec 8 17:50:08 CET 2015: Step 2. On NFS client: skipping unmount /mnt/bz1252549-export Tue Dec 8 17:50:08 CET 2015: Step 3. On NFS client: skipping mount /mnt/bz1252549-export Tue Dec 8 17:50:08 CET 2015: Step 4. On NFS client: df /mnt/bz1252549-export/test Filesystem 1K-blocks Used Available Use% Mounted on 127.0.0.1:/exports/bz1252549-export 126931968 63222272 57238528 53% /mnt/bz1252549-export Tue Dec 8 17:50:09 CET 2015: Step 5. On NFS client: strace -c -o /tmp/test-1252549-11927-strace.txt find /mnt/bz1252549-export/test -name "*.pdf" > /tmp/test-1252549-11927-cmd-out.txt Tue Dec 8 17:50:10 CET 2015: Step 6. On NFS client: Check output files for fstatat, gentdents Found 10000 /tmp/test-1252549-11927-cmd-out.txt files Found 4 fstatat calls in /tmp/test-1252549-11927-strace.txt Found 4 getdents calls in /tmp/test-1252549-11927-strace.txt Tue Dec 8 17:50:10 CET 2015: Step 7. On NFS client, kill tcpdump 872 packets captured 1992 packets received by filter 232 packets dropped by kernel Tue Dec 8 17:50:10 CET 2015: Step 9. On NFS client, show summary of tcpdump. Skipping pcap_nfsstat.sh - file not found Full strace file: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 94.16 0.219337 54834 4 getdents 3.11 0.007245 60 120 write 0.76 0.001765 33 53 brk 0.51 0.001179 54 22 close 0.29 0.000680 23 29 mmap 0.20 0.000470 25 19 6 open 0.17 0.000406 21 19 fcntl 0.17 0.000387 24 16 mprotect 0.13 0.000306 153 2 openat 0.12 0.000280 19 15 fstat 0.10 0.000244 22 11 read 0.07 0.000152 30 5 munmap 0.05 0.000111 28 4 newfstatat 0.02 0.000052 26 2 2 statfs 0.02 0.000043 22 2 2 ioctl 0.02 0.000038 19 2 rt_sigaction 0.01 0.000034 34 1 1 access 0.01 0.000028 28 1 fchdir 0.01 0.000025 25 1 1 stat 0.01 0.000022 22 1 execve 0.01 0.000021 21 1 getrlimit 0.01 0.000019 19 1 rt_sigprocmask 0.01 0.000019 19 1 arch_prctl 0.01 0.000018 18 1 uname 0.01 0.000018 18 1 futex 0.01 0.000018 18 1 set_tid_address 0.01 0.000017 17 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.232934 336 12 total TEST PASS: on findutils-4.5.11-5.el7.x86_64 kernel-3.10.0-327.el7.x86_64 - did not find excessive newfstatat system calls I can try it with a fresh installation of RHEL-7.2 to rule out any local changes I made to that VM. Did you try the -noleaf option on the updated findutils package? Did it work as expected?
(In reply to Kamil Dudka from comment #24) > I can try it with a fresh installation of RHEL-7.2 to rule out any local > changes I made to that VM. I did and it indeed helped me to reproduce the bug. So I checked what differs between those two machines and discovered that the fresh VM mounts NFS with size=262144,wsize=262144 whereas the old one with rsize=524288,wsize=524288. I was able to reproduce the bug also on the old VM after I changed the script to mount NFS explicitly with rsize=262144,wsize=262144. On the other hand, when I tried to mount NFS explicitly with rsize=524288,wsize=524288 on the fresh VM, those options were silently ignored. > Did you try the -noleaf option on the updated findutils package? I tried it and it reintroduces the bug as expected.
Ah ok - yeah mine had a much lower rsize/wsize. I should probably put that into the test case as that will definitely affect the results. # grep bz125 /proc/mounts 127.0.0.1:/exports/bz1252549-export /mnt/bz1252549-export nfs rw,relatime,vers=3,rsize=131072,wsize=131072,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=127.0.0.1,mountvers=3,mountport=20048,mountproto=udp,local_lock=none,addr=127.0.0.1 0 0
Created attachment 1103695 [details] updated prep script with explicit rsize/wsize so the test results are reliable
Created attachment 1103696 [details] updated run script with explicit rsize/wsize so the test results are reliable
Ok I don't fully understand this yet but here's what I'm seeing as far as the rsize/wsize. Actually it's the wsize which matters - the rsize doesn't seem to affect this. This doesn't make sense to me but I see the following. If I set wsize=524288 the getdents system call uses this value for the 'size' parameter. I would think it would use 'rsize' but apparently it does not. Or perhaps it's using some other parameter which is equivalent to wsize. In any case, the value of wsize affects the count given in getdents sytem call. Now the NFS client in the kernel turns on READDIRPLUS for the first 'getdents' call, then turns it off unless some other operation is done which gives an indication that attributes are needed. The reason it's turned off is so that operations such as a simple 'ls' which don't require attributes are not as expensive and are faster (reference discussion on d69ee9b NFS: Adapt readdirplus to application usage patterns). So for the first call to 'getdents' on an NFS directory, the d_type is filled into the page cache. And depending on the wsize value, the number of entries with valid d_type field varies. Then originally find saw the valid d_type and did not need to do further 'stat' calls. FWIW, I've confirmed with my original customer that indeed he's got directories with files only in leaf directories. So this leaf optimization seems to be something that would really help restore performance for him. Unfortunately he is on RHEL6 now and originally reported the perf regression when moving from RHEL5 to RHEL6. Unfortunately I've also confirmed on RHEL6 the rsize/wsize does not affect the test outcome. So probably this is something like the glibc issue Ben pointed out in https://bugzilla.redhat.com/show_bug.cgi?id=1248140#c35 However such a fix won't solve the problem completely, it will just make it less likely to get hit.
The gnulib's part of the patch proposed upstream: http://thread.gmane.org/gmane.comp.lib.gnulib.bugs/35539
upstream commit: http://git.savannah.gnu.org/cgit/gnulib.git/commit/?id=c97b8b90
fixed in findutils-4.5.15-2.fc24
fixed in findutils-4.5.16-1.fc23 fixed in findutils-4.5.14-6.fc22
Unfortunately, there is a bug report against Fedora revealing that the fix for this bug causes problems elsewhere: bug #1299169 The above mentioned upstream commit has been reverted: http://git.savannah.gnu.org/cgit/gnulib.git/commit/?id=85717b68
The current implementation of the leaf optimization in gnulib's FTS cannot be safely enabled for NFS. Assuming I have some environment to debug #1299169, I will try to implement a safer version of the leaf optimization upstream first. For RHEL-7 closing CANTFIX.