Hello,

Maybe it's related with this one: https://bugzilla.redhat.com/show_bug.cgi?id=688130

I'm trying run with "nordirplus". Until now, looks fine. Tomorrow during the load it's possible to confirm.

I don't know how exactly it's fixed in kernel.org.

There's another BZ related with my 3rd problem. Maybe close that one with duplicate of this one, because other problems that need to be backported.
https://bugzilla.redhat.com/show_bug.cgi?id=785830

Best regards

Ok. We are testing those cenarios:

2.6.32-71.29.1                              - Load +- 41
2.6.32-220.4.1 + patches above + nordirplus - Load +- 25
2.6.32-71                                   - Load +- 25

With nordirplus works fine. Do you need something else?

Best regards

Hello guys,

I testes another kernel 2.6.32-244.el6.x86_64 provided by RedHat support, and has the same problem with all others.

To make all things simple I tested only two kernels (2.6.32-71.29.1.el6.x86_64 and 2.6.32-244.el6.x86_64). I generated rpcdebug -m rpc -s all during 2 seconds and I'll add to BZ.

Looking at nfsstat during this period, something is really wrong. Look below:

* 2.6.32-71.29.1.el6.x86_64:
RPC:
	calls: 7365
	retrans: 0
	authrefrsh: 0
NFS3:
	null: 0
	getattr: 1426
	setattr: 126
	lookup: 973
	access: 1607
	readlink: 0
	read: 1790
	write: 72
	create: 7
	mkdir: 0
	symlink: 0
	mknod: 0
	remove: 119
	rmdir: 0
	rename: 49
	link: 85
	readdir: 660
	readdirplus: 390
	fsstat: 0
	fsinfo: 0
	pathconf: 0
	commit: 62

* 2.6.32-244.el6.x86_64:
RPC:
	calls: 15963
	retrans: 0
	authrefrsh: 15964
NFS3:
	null: 0
	getattr: 2187
	setattr: 44
	lookup: 636
	access: 1781
	readlink: 0
	read: 8394
	write: 54
	create: 6
	mkdir: 0
	symlink: 0
	mknod: 0
	remove: 71
	rmdir: 0
	rename: 56
	link: 42
	readdir: 0
	readdirplus: 2647
	fsstat: 0
	fsinfo: 0
	pathconf: 0
	commit: 46

The 2.6.32-244.el6.x86_64 server are running with 1/4 of users, comparated with another server.

Looking the nfsstat you can see a huge increase in 'authrefrsh' and that all requests of readdir is goning to readdirplus. Besides, the server with 1/4 of users are doing 2x more  calls.

Comparing rpcdebug, I found this:

* 2.6.32-71.29.1.el6.x86_64:
kernel: RPC: 34691 call_start nfs3 proc READDIRPLUS (sync)
kernel: RPC: 34691 call_reserve (status 0)
kernel: RPC: 34691 reserved req ffff8801b8173598 xid d54ee4ec
kernel: RPC: 34691 call_reserveresult (status 0)
kernel: RPC: 34691 call_allocate (status 0)
kernel: RPC: 34691 allocated buffer of size 572 at ffff88021efbb800

* 2.6.32-244.el6.x86_64:kernel: RPC: 17812 call_start nfs3 proc READDIRPLUS (sync)
kernel: RPC: 17812 call_reserve (status 0)
kernel: RPC: 17812 reserved req ffff8801b84681b0 xid 890edccb
kernel: RPC: 17812 call_reserveresult (status 0)
kernel: RPC: 17812 call_refresh (status 0)
kernel: RPC: 17812 refreshing UNIX cred ffff8803f0a3e900
kernel: RPC: 17812 call_refreshresult (status 0)
kernel: RPC: 17812 call_allocate (status 0)
kernel: RPC: 17812 allocated buffer of size 572 at ffff8801c8683000

I don't know why 'call_refresh' are calling after 'call_reserveresult', but on the old behaviour it's not happens.

Best regards

Created attachment 569511 [details]
rpcdebug -m rpc -s all on 2.6.32-71.29.1.el6.x86_64

Created attachment 569512 [details]
rpcdebug -m rpc -s all on 2.6.32-244.el6.x86_64

Using CentOS kernel 2.6.32-220.7.1.el6.x86_64 and I also see the authrefrsh count skyrocketing:

Client rpc stats:
calls      retrans    authrefrsh
105283279   0          105285429

Client nfs v3:
null         getattr      setattr      lookup       access       readlink     
0         0% 55955     0% 4901      0% 8735      0% 10309     0% 87        0% 
read         write        create       mkdir        symlink      mknod        
54463085 51% 50703785 48% 4352      0% 193       0% 176       0% 0         0% 
remove       rmdir        rename       link         readdir      readdirplus  
1136      0% 54        0% 264       0% 2         0% 0         0% 905       0% 
fsstat       fsinfo       pathconf     commit       
1965      0% 10        0% 5         0% 0         0% 

I'm working with large files (10s of GB) and in the middle of sequential reads and writes it stalls to a few KB/s. If I do an ls (from a separate terminal) of the directrory where those files are then the speed resumes to the nornal 100MB/s while ls itself is running for 3-4 minutes.

NFSv4 previously crashed the whole box, that's why I switched to NFS3.

I think the first thing that needs to happen here is to define this problem better. It looks like there are 3-4 different problem reports all
squashed together here. Some of those are likely already fixed in 6.3 kernels.

I'm really only interested in problems that are not already fixed in 6.3
kernels. What we probably need to have the reporters of this bug test some
very recent 6.3 kernels (especially those with the appropriate readdir and
other NFS fixes), and then restate the problems that you're seeing on top
of that.

For instance, Marcus said:

"I testes another kernel 2.6.32-244.el6.x86_64 provided by RedHat support, and
has the same problem with all others."

...what I'm not clear on is which problem you mean since you enumerated 3-4
different problems originally. He also said:

"Looking the nfsstat you can see a huge increase in 'authrefrsh' and that all
requests of readdir is goning to readdirplus."

I'm not sure we can call the authrefresh counter increasing a "problem". It
may just be an artefact of other changes in the RPC layer. IOW, it may be a 
possible symptom, but is not a problem in and of itself. In any case, it
does not indicate an increase in the number of RPC calls, but rather an
increase in the number of calls to refresh the credentials for making a new
RPC call. For anything but GSSAPI, that's basically just a set_bit call.

The change to use readdirplus more widely is also expected. A patch series
added to RHEL6.1 removed the readdir plus directory size limit. That may or
may not have a performance impact with your workload.

If you're experiencing performance issues, then it's critical that we
understand what is actually slow, preferably at the system call level. Only
with that info will we be able to make progress here. You'll also need to
help quantify the slowness. IOW, we need to understand what got slower and
how much slower it is. Without that, we can't quantify any possible performance
improvement that we might make.

Hello Jeff,

(In reply to comment #11)
> I think the first thing that needs to happen here is to define this problem
> better. It looks like there are 3-4 different problem reports all
> squashed together here. Some of those are likely already fixed in 6.3 kernels.
> 
> I'm really only interested in problems that are not already fixed in 6.3
> kernels. What we probably need to have the reporters of this bug test some
> very recent 6.3 kernels (especially those with the appropriate readdir and
> other NFS fixes), and then restate the problems that you're seeing on top
> of that.
> 
> For instance, Marcus said:
> 
> "I testes another kernel 2.6.32-244.el6.x86_64 provided by RedHat support, and
> has the same problem with all others."

Sure, I'll test the latest 6.3 kernel and describe better the problems. Can you provide the latest 6.3 kernel with perf rpm? With perf top I saw a number of calls that I can't see on the latest 6.1 kernel, like below:

   PerfTop:    3486 irqs/sec  kernel:74.6%  exact:  0.0% [1000Hz cycles],  (all, 12 CPUs)
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------                                                              

             samples  pcnt function                            DSO
             _______ _____ ___________________________________ _________________________________________________________________________________

             3346.00  5.2% __GI_vfprintf                       /lib64/libc-2.12.so                                                              
             2169.00  3.4% inflate                             /lib64/libz.so.1.2.3                                                             
             1610.00  2.5% nfs_permission                      /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/fs/nfs/nfs.ko                  
             1442.00  2.3% _IO_default_xsputn_internal         /lib64/libc-2.12.so                                                              
             1437.00  2.2% inflate_fast                        /lib64/libz.so.1.2.3                                                             
             1110.00  1.7% __GI_____strtoll_l_internal         /lib64/libc-2.12.so                                                              
              988.00  1.5% find_inode                          [kernel.kallsyms]                                                                
              922.00  1.4% rpc_wake_up_queued_task             /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/net/sunrpc/sunrpc.ko           
              913.00  1.4% _spin_lock                          [kernel.kallsyms]                                                                
              890.00  1.4% __d_lookup                          [kernel.kallsyms]                                                                
              850.00  1.3% TrrMailFolderGetNextMessage         /usr/lib/libtrrmail.so.3.5.1                                                     
              836.00  1.3% bnx2_poll_work                      /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/drivers/net/bnx2.ko            
              801.00  1.3% __memcpy                            [kernel.kallsyms]                                                                
              692.00  1.1% find_busiest_group                  [kernel.kallsyms]                                                                
              685.00  1.1% rpc_free_client                     /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/net/sunrpc/sunrpc.ko           
              663.00  1.0% find_next_bit                       [kernel.kallsyms]                                                                
              641.00  1.0% copy_user_generic_string            [kernel.kallsyms]                                                                
              610.00  1.0% clear_page_c                        [kernel.kallsyms]                                                                
              596.00  0.9% __strchr_sse2                       /lib64/libc-2.12.so                                                              
              570.00  0.9% generic_pkt_to_tuple                /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/net/netfilter/nf_conntrack.ko  
              541.00  0.8% _itoa_word                          /lib64/libc-2.12.so                                                              
              535.00  0.8% memcpy                              /lib64/libc-2.12.so                                                              
              485.00  0.8% __list_add                          [kernel.kallsyms]                                                                
              465.00  0.7% xs_udp_timer                        /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/net/sunrpc/sunrpc.ko           
              437.00  0.7% nf_conntrack_free                   /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/net/netfilter/nf_conntrack.ko  
              436.00  0.7% kmem_cache_alloc                    [kernel.kallsyms]                                                                
              429.00  0.7% inode_init_once                     [kernel.kallsyms]                                                                
              424.00  0.7% _int_malloc                         /lib64/libc-2.12.so                                                              
              423.00  0.7% kfree                               [kernel.kallsyms]                                                                
              419.00  0.7% nfs_post_op_update_inode            /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/fs/nfs/nfs.ko                  
              411.00  0.6% TrrMailLog                          /usr/lib/libtrrmail.so.3.5.1                                                     
              404.00  0.6% crc32                               /lib64/libz.so.1.2.3                                                             
              394.00  0.6% TrrMailMsgGetPath                   /usr/lib/libtrrmail.so.3.5.1                                                     
              392.00  0.6% nfs_cache_upcall                    /lib/modules/2.6.32-220.7.1.el6.x86_64/kernel/fs/nfs/nfs.ko

> 
> ...what I'm not clear on is which problem you mean since you enumerated 3-4
> different problems originally. He also said:
> 
> "Looking the nfsstat you can see a huge increase in 'authrefrsh' and that all
> requests of readdir is goning to readdirplus."
> 
> I'm not sure we can call the authrefresh counter increasing a "problem". It
> may just be an artefact of other changes in the RPC layer. IOW, it may be a 
> possible symptom, but is not a problem in and of itself. In any case, it
> does not indicate an increase in the number of RPC calls, but rather an
> increase in the number of calls to refresh the credentials for making a new
> RPC call. For anything but GSSAPI, that's basically just a set_bit call.

Looking the number of rpc calls seems that's nothing change. It's almost equal the number of 6.1 and 6.3 kernel.

> 
> The change to use readdirplus more widely is also expected. A patch series
> added to RHEL6.1 removed the readdir plus directory size limit. That may or
> may not have a performance impact with your workload.
> 
> If you're experiencing performance issues, then it's critical that we
> understand what is actually slow, preferably at the system call level. Only
> with that info will we be able to make progress here. You'll also need to
> help quantify the slowness. IOW, we need to understand what got slower and
> how much slower it is. Without that, we can't quantify any possible performance
> improvement that we might make.

I'll try to figure out with the latest kernel.

Thanks

(In reply to comment #12)

> Sure, I'll test the latest 6.3 kernel and describe better the problems. Can you
> provide the latest 6.3 kernel with perf rpm? With perf top I saw a number of
> calls that I can't see on the latest 6.1 kernel, like below:
> 

No, that will need to be done by the support person handling the support case.
Please ask them to give you the latest kernel possible so we can rule out any
fixes that are already slated for 6.3. As of today that would be -257.el6.

(In reply to comment #13)
> (In reply to comment #12)
> 
> > Sure, I'll test the latest 6.3 kernel and describe better the problems. Can you
> > provide the latest 6.3 kernel with perf rpm? With perf top I saw a number of
> > calls that I can't see on the latest 6.1 kernel, like below:
> > 
> 
> No, that will need to be done by the support person handling the support case.
> Please ask them to give you the latest kernel possible so we can rule out any
> fixes that are already slated for 6.3. As of today that would be -257.el6.

OK.

Any more word on this? Did the latest kernel help anything?

Development Management has reviewed and declined this request.
You may appeal this decision by reopening this request.

Hello Jeff,

During last two days I returned to this problem. I have found the problem.

It's related with the remove the limit to use READDIRPLUS (NFS: remove readdir plus limit). 

The fix below (NFS: Adapt readdirplus to application usage patterns) solve my problem, can you add on the default EL kernel?

http://git.kernel.org/?p=linux/kernel/git/stable/linux-stable.git;a=commitdiff;h=d69ee9b85541a69a1092f5da675bd23256dc62af

For all the other problems related on the beginning, all it's fixed until -279.11.1. 

Best regards

*** This bug has been marked as a duplicate of bug 819891 ***