1252549 – leaf optimization cannot be enabled for a NFS file system

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1252549 - leaf optimization cannot be enabled for a NFS file system

Summary: leaf optimization cannot be enabled for a NFS file system

Keywords:
Status:	CLOSED CANTFIX
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	findutils
Sub Component:
Version:	7.2
Hardware:	All
OS:	Linux
Priority:	medium
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	Kamil Dudka
QA Contact:	BaseOS QE - Apps
Docs Contact:
URL:
Whiteboard:
Depends On:	1299169
Blocks:
TreeView+	depends on / blocked

Reported:	2015-08-11 16:25 UTC by Kamil Dudka
Modified:	2016-06-24 13:54 UTC (History)
CC List:	3 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:	883285
Environment:
Last Closed:	2016-06-24 13:50:39 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
[PATCH] enable leaf optimization for NFS (3.39 KB, patch) 2015-09-29 14:29 UTC, Kamil Dudka	no flags	Details \| Diff
[PATCH V2] enable leaf optimization for NFS (3.89 KB, patch) 2015-10-29 13:23 UTC, Kamil Dudka	no flags	Details \| Diff
t0_bz1252549_prep.sh (1.93 KB, text/plain) 2015-12-03 20:10 UTC, Dave Wysochanski	no flags	Details
t0_bz1252549_run.sh (4.35 KB, text/plain) 2015-12-03 20:10 UTC, Dave Wysochanski	no flags	Details
updated prep script with explicit rsize/wsize so the test results are reliable (1.98 KB, application/x-shellscript) 2015-12-08 19:54 UTC, Dave Wysochanski	no flags	Details
updated run script with explicit rsize/wsize so the test results are reliable (4.39 KB, application/x-shellscript) 2015-12-08 19:55 UTC, Dave Wysochanski	no flags	Details
Show Obsolete (3) View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Bugzilla	1236630	1	None	None	None	2021-01-20 06:05:38 UTC

Internal Links: 1236630

Description Kamil Dudka 2015-08-11 16:25:34 UTC

+++ 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.

Comment 1 Kamil Dudka 2015-09-29 14:29:32 UTC

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.

Comment 2 Kamil Dudka 2015-10-01 11:55:27 UTC

Dave, are you able to reproduce the slowdown on a RHEL-7 system?

Comment 3 Dave Wysochanski 2015-10-28 20:31:54 UTC

(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

Comment 4 Kamil Dudka 2015-10-29 12:59:59 UTC

(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.

Comment 5 Kamil Dudka 2015-10-29 13:23:18 UTC

Created attachment 1087477 [details]
[PATCH V2] enable leaf optimization for NFS

Comment 12 Dave Wysochanski 2015-12-03 19:22:35 UTC

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.

Comment 14 Dave Wysochanski 2015-12-03 20:10:28 UTC

Created attachment 1101955 [details]
t0_bz1252549_prep.sh

Comment 15 Dave Wysochanski 2015-12-03 20:10:46 UTC

Created attachment 1101956 [details]
t0_bz1252549_run.sh

Comment 16 Dave Wysochanski 2015-12-03 20:15:29 UTC

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 17 Dave Wysochanski 2015-12-03 20:16:25 UTC

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 18 Dave Wysochanski 2015-12-03 20:19:17 UTC

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

Comment 19 Kamil Dudka 2015-12-04 18:38:17 UTC

(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?

Comment 20 Dave Wysochanski 2015-12-07 18:57:10 UTC

(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.

Comment 21 Kamil Dudka 2015-12-08 11:38:38 UTC

(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...

Comment 22 Dave Wysochanski 2015-12-08 16:30:20 UTC

(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

Comment 23 Dave Wysochanski 2015-12-08 16:48:37 UTC

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

Comment 24 Kamil Dudka 2015-12-08 16:57:46 UTC

(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?

Comment 25 Kamil Dudka 2015-12-08 18:19:36 UTC

(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.

Comment 26 Dave Wysochanski 2015-12-08 19:45:40 UTC

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

Comment 27 Dave Wysochanski 2015-12-08 19:54:53 UTC

Created attachment 1103695 [details]
updated prep script with explicit rsize/wsize so the test results are reliable

Comment 28 Dave Wysochanski 2015-12-08 19:55:28 UTC

Created attachment 1103696 [details]
updated run script with explicit rsize/wsize so the test results are reliable

Comment 29 Dave Wysochanski 2015-12-08 22:34:09 UTC

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.

Comment 30 Kamil Dudka 2015-12-09 06:40:13 UTC

The gnulib's part of the patch proposed upstream:

http://thread.gmane.org/gmane.comp.lib.gnulib.bugs/35539

Comment 31 Kamil Dudka 2015-12-21 17:46:22 UTC

upstream commit:

http://git.savannah.gnu.org/cgit/gnulib.git/commit/?id=c97b8b90

Comment 32 Kamil Dudka 2015-12-21 18:11:40 UTC

fixed in findutils-4.5.15-2.fc24

Comment 33 Kamil Dudka 2015-12-29 00:15:11 UTC

fixed in findutils-4.5.16-1.fc23

fixed in findutils-4.5.14-6.fc22

Comment 34 Kamil Dudka 2016-01-19 14:41:54 UTC

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

Comment 35 Kamil Dudka 2016-06-24 13:50:39 UTC

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.

Note You need to log in before you can comment on or make changes to this bug.