System CPU increasing on idle 2.6.36

Possibly related to the flush-processes-taking-CPU issues I saw previously, I thought this was interesting. I found a log-crunching box that does all of its work via NFS and spends most of the day sleeping. It has been using a linearly-increasing amount of system time during the time where is sleeping. munin graph:

http://0x.ca/sim/ref/2.6.36/cpu_logcrunch_nfs.png

top shows:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 4767 root      20   0     0    0    0 S   16  0.0   2413:29 flush-0:69
22385 root      20   0     0    0    0 S   10  0.0   1320:23 flush-0:70

(rest idle)

perf top shows:

-------------------------------------------------------------------------------------------
PerfTop: 252 irqs/sec kernel:97.2% exact: 0.0% [1000Hz cycles], (all, 2 CPUs)
-------------------------------------------------------------------------------------------

samples pcnt function DSO
_______ _____ _______________________________ ___________

912.00 21.2% _raw_spin_lock [kernel]
592.00 13.8% nfs_writepages [kernel]
474.00 11.0% queue_io [kernel]
428.00 10.0% writeback_single_inode [kernel]
379.00 8.8% writeback_sb_inodes [kernel]
237.00 5.5% bit_waitqueue [kernel]
184.00 4.3% do_writepages [kernel]
169.00 3.9% __iget [kernel]
132.00 3.1% redirty_tail [kernel]
85.00 2.0% iput [kernel]
72.00 1.7% _atomic_dec_and_lock [kernel]
67.00 1.6% write_cache_pages [kernel]
63.00 1.5% port_inb [ipmi_si]
62.00 1.4% __mark_inode_dirty [kernel]
48.00 1.1% __wake_up_bit [kernel]
32.00 0.7% nfs_write_inode [kernel]
26.00 0.6% native_read_tsc [kernel]
25.00 0.6% radix_tree_gang_lookup_tag_slot [kernel]
25.00 0.6% schedule [kernel]
24.00 0.6% wake_up_bit [kernel]
20.00 0.5% apic_timer_interrupt [kernel]
19.00 0.4% ia32_syscall [kernel]
16.00 0.4% find_get_pages_tag [kernel]
15.00 0.3% _raw_spin_lock_irqsave [kernel]
15.00 0.3% load_balance [kernel]
13.00 0.3% ktime_get [kernel]
12.00 0.3% shrink_icache_memory [kernel]
11.00 0.3% semop libc-2.7.so
9.00 0.2% nfs_pageio_doio [kernel]
8.00 0.2% dso__find_symbol perf
8.00 0.2% down_read [kernel]
7.00 0.2% __switch_to [kernel]
7.00 0.2% __phys_addr [kernel]
7.00 0.2% nfs_pageio_init [kernel]
7.00 0.2% pagevec_lookup_tag [kernel]
7.00 0.2% _cond_resched [kernel]
7.00 0.2% up_read [kernel]
6.00 0.1% sched_clock_local [kernel]
5.00 0.1% rb_erase [kernel]
5.00 0.1% page_fault [kernel]

"tcpdump -i any -n port 2049" and "nfsstat" shows this work does not actually result in any NFS packets.

Known 2.6.36 issue? This did not occur on 2.6.35.4, according to the munin graphs. I'll try 2.6.37-rc an see if it changes.

Possibly a side effect of the fs/fs-writeback.c changes in 2.6.36? You do appear to be hitting a lot of spinlock contention, but I suspect that a lot of it is coming from writeback_sb_inodes, writeback_single_inode and queue_io, all of which seem unnaturally high on your stats above.

I don't see how you can be seeing no traffic on the wire. You are certainly hitting some page writeout (0.2% nfs_pageio_doio).

Quoted 5 lines · Trond Myklebust

Possibly a side effect of the fs/fs-writeback.c changes in 2.6.36? You do appear to be hitting a lot of spinlock contention, but I suspect that a lot of it is coming from writeback_sb_inodes, writeback_single_inode and queue_io, all of which seem unnaturally high on your stats above.

Quoted 2 lines

I don't see how you can be seeing no traffic on the wire. You are certainly hitting some page writeout (0.2% nfs_pageio_doio).

It really seems to not be doing anything. I ran nfsstat -Zcv for 5 minutes, and the only non-zero counters are rpc calls and authrefrsh, even though perf top shows similar profiles the whole time.

Quoted 10 lines · Simon Kirby

Quoted 7 lines · Trond Myklebust

Possibly a side effect of the fs/fs-writeback.c changes in 2.6.36? You do appear to be hitting a lot of spinlock contention, but I suspect that a lot of it is coming from writeback_sb_inodes, writeback_single_inode and queue_io, all of which seem unnaturally high on your stats above.

I don't see how you can be seeing no traffic on the wire. You are certainly hitting some page writeout (0.2% nfs_pageio_doio).

Quoted 3 lines

It really seems to not be doing anything. I ran nfsstat -Zcv for 5 minutes, and the only non-zero counters are rpc calls and authrefrsh, even though perf top shows similar profiles the whole time.

That sounds like a bug in nfsstat, then. As I said, your trace results definitely indicate that you are doing page writeout. I'd cross check using wireshark...

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Quoted 3 lines · Simon Kirby

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Ignore this; I was just confusing myself by having the leak fixes already applied. Otoh, I got this Oops while trying NFSv4. I'll check my merging again.

Do you have a git branch exposed with the "Allow the admin to turn off NFSv4 uid/gid mapping" patches applied?

Quoted 10 lines · Simon Kirby

Quoted 3 lines · Simon Kirby

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Ignore this; I was just confusing myself by having the leak fixes already applied. Otoh, I got this Oops while trying NFSv4. I'll check my merging again.

Quoted 2 lines

Do you have a git branch exposed with the "Allow the admin to turn off NFSv4 uid/gid mapping" patches applied?

Hm, the fixes were merged for -git4, and it seems to work fine there.

As for the nfs4 uid/gid mapping patch, it seems the server side support for this is still neded?

Quoted 15 lines · Simon Kirby

Quoted 12 lines · Simon Kirby

Quoted 3 lines · Simon Kirby

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Ignore this; I was just confusing myself by having the leak fixes already applied. Otoh, I got this Oops while trying NFSv4. I'll check my merging again.

Do you have a git branch exposed with the "Allow the admin to turn off NFSv4 uid/gid mapping" patches applied?

Quoted 4 lines

Hm, the fixes were merged for -git4, and it seems to work fine there.

As for the nfs4 uid/gid mapping patch, it seems the server side support for this is still neded?

I'm not convinced that this behavior should depend on the security flavor, so I'm assuming that something like steved's libnfsidmap patches should do the job.

Quoted 16 lines · J. Bruce Fields

Quoted 15 lines · Simon Kirby

Quoted 12 lines · Simon Kirby

Quoted 3 lines · Simon Kirby

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Ignore this; I was just confusing myself by having the leak fixes already applied. Otoh, I got this Oops while trying NFSv4. I'll check my merging again.

Do you have a git branch exposed with the "Allow the admin to turn off NFSv4 uid/gid mapping" patches applied?

Quoted 8 lines

Quoted 4 lines

Hm, the fixes were merged for -git4, and it seems to work fine there.

As for the nfs4 uid/gid mapping patch, it seems the server side support for this is still neded?

I'm not convinced that this behavior should depend on the security flavor, so I'm assuming that something like steved's libnfsidmap patches should do the job.

Don't assume.

Those patches do not fix the problem that if uid(name@server) != uid(name@client), then the client will be creating files with the 'wrong username' on the server.

In that case, everything from setuid applications through open(O_CREAT) to 'chown' will be broken because your authentication and authorisation models do not match up.

Quoted 26 lines · Trond Myklebust

Quoted 16 lines · J. Bruce Fields

Quoted 15 lines · Simon Kirby

Quoted 12 lines · Simon Kirby

Quoted 3 lines · Simon Kirby

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Ignore this; I was just confusing myself by having the leak fixes already applied. Otoh, I got this Oops while trying NFSv4. I'll check my merging again.

Do you have a git branch exposed with the "Allow the admin to turn off NFSv4 uid/gid mapping" patches applied?

Quoted 8 lines

Quoted 4 lines

Hm, the fixes were merged for -git4, and it seems to work fine there.

As for the nfs4 uid/gid mapping patch, it seems the server side support for this is still neded?

I'm not convinced that this behavior should depend on the security flavor, so I'm assuming that something like steved's libnfsidmap patches should do the job.

Quoted 5 lines

Don't assume.

Those patches do not fix the problem that if uid(name@server) != uid(name@client), then the client will be creating files with the 'wrong username' on the server.

I don't see any obviously correct solution in cases where the mapping disagrees between client and server sides, so prefer to stick to the NFSv3 behavior.

The only reason I see to do this anyway is to provide compatibility with NFSv3.

Quoted 3 lines

In that case, everything from setuid applications through open(O_CREAT) to 'chown' will be broken because your authentication and authorisation models do not match up.

Those are preexisting problems from NFSv3, and it's up to the administrator to fix them.

The best we can do is provide backwards-compatible behavior so that things that worked before continue working.

Quoted 44 lines · J. Bruce Fields

Quoted 26 lines · Trond Myklebust

Quoted 16 lines · J. Bruce Fields

Quoted 15 lines · Simon Kirby

Quoted 12 lines · Simon Kirby

Quoted 3 lines · Simon Kirby

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Ignore this; I was just confusing myself by having the leak fixes already applied. Otoh, I got this Oops while trying NFSv4. I'll check my merging again.

Do you have a git branch exposed with the "Allow the admin to turn off NFSv4 uid/gid mapping" patches applied?

Quoted 8 lines

Quoted 4 lines

Hm, the fixes were merged for -git4, and it seems to work fine there.

As for the nfs4 uid/gid mapping patch, it seems the server side support for this is still neded?

I'm not convinced that this behavior should depend on the security flavor, so I'm assuming that something like steved's libnfsidmap patches should do the job.

Quoted 5 lines

Don't assume.

Those patches do not fix the problem that if uid(name@server) != uid(name@client), then the client will be creating files with the 'wrong username' on the server.

I don't see any obviously correct solution in cases where the mapping disagrees between client and server sides, so prefer to stick to the NFSv3 behavior.

The only reason I see to do this anyway is to provide compatibility with NFSv3.

Quoted 3 lines

In that case, everything from setuid applications through open(O_CREAT) to 'chown' will be broken because your authentication and authorisation models do not match up.

Quoted 5 lines

Those are preexisting problems from NFSv3, and it's up to the administrator to fix them.

The best we can do is provide backwards-compatible behavior so that things that worked before continue working.

No. There are two cases here:

1) The user is authenticating using uids and gids (AUTH_SYS). In that case, the server is using those uids and gids to authorise user behaviour, and so file/directory creation/access/deletion/... will depend only on the numeric values of those uids and gids. It doesn't matter if the client belongs to a different domain, 'cos AUTH_SYS has no concept of a domain. It doesn't matter whether or mot there exists a name@domain mapping on the client, and server. Only the numbers matter. NFSv2 and NFSv3 got this case right, and NFSv4 got it wrong (or didn't consider it).

2) The user is authenticating using a principal name@DOMAIN. In this case, either there is a mapping between name@DOMAIN and a owner@domain +groupname@domain on the server, or there isn't. In the latter case, the server treats the principal as the anonymous user. In the former case, then if the client and server map owner@domain and groupname@domain to the same uid and gid, then it is safe to pass uids and gids back and forth. If they don't have identical mappings, then it is still safe to pass owner@domain and groupname@domain,

but passing uids and gids is now
wrong. NFSv4 gets this case right, but NFSv2/v3 get it wrong.

Trond

Signature · 6 lines

Trond Myklebust
Linux NFS client maintainer

NetApp
[email protected]
www.netapp.com

Quoted 63 lines · Trond Myklebust

Quoted 44 lines · J. Bruce Fields

Quoted 26 lines · Trond Myklebust

Quoted 16 lines · J. Bruce Fields

Quoted 15 lines · Simon Kirby

Quoted 12 lines · Simon Kirby

Quoted 3 lines · Simon Kirby

I'm just about to try
2.6.37-rc5-git3 on there plus your NFS fixes (which Linus seems to have half-merged and uploaded as -git3 but not pushed to his public git)

Ignore this; I was just confusing myself by having the leak fixes already applied. Otoh, I got this Oops while trying NFSv4. I'll check my merging again.

Do you have a git branch exposed with the "Allow the admin to turn off NFSv4 uid/gid mapping" patches applied?

Quoted 8 lines

Quoted 4 lines

Hm, the fixes were merged for -git4, and it seems to work fine there.

As for the nfs4 uid/gid mapping patch, it seems the server side support for this is still neded?

I'm not convinced that this behavior should depend on the security flavor, so I'm assuming that something like steved's libnfsidmap patches should do the job.

Quoted 5 lines

Don't assume.

Those patches do not fix the problem that if uid(name@server) != uid(name@client), then the client will be creating files with the 'wrong username' on the server.

I don't see any obviously correct solution in cases where the mapping disagrees between client and server sides, so prefer to stick to the NFSv3 behavior.

The only reason I see to do this anyway is to provide compatibility with NFSv3.

Quoted 3 lines

In that case, everything from setuid applications through open(O_CREAT) to 'chown' will be broken because your authentication and authorisation models do not match up.

Quoted 5 lines

Those are preexisting problems from NFSv3, and it's up to the administrator to fix them.

The best we can do is provide backwards-compatible behavior so that things that worked before continue working.

No. There are two cases here:

1) The user is authenticating using uids and gids (AUTH_SYS). In that case, the server is using those uids and gids to authorise user behaviour, and so file/directory creation/access/deletion/... will depend only on the numeric values of those uids and gids. It doesn't matter if the client belongs to a different domain, 'cos AUTH_SYS has no concept of a domain. It doesn't matter whether or mot there exists a name@domain mapping on the client, and server. Only the numbers matter. NFSv2 and NFSv3 got this case right, and NFSv4 got it wrong (or didn't consider it).

Quoted 8 lines

2) The user is authenticating using a principal name@DOMAIN. In this case, either there is a mapping between name@DOMAIN and a owner@domain +groupname@domain on the server, or there isn't. In the latter case, the server treats the principal as the anonymous user. In the former case, then if the client and server map owner@domain and groupname@domain to the same uid and gid, then it is safe to pass uids and gids back and forth. If they don't have identical mappings, then it is still safe to pass owner@domain and groupname@domain,

Not necessarily; for example, there could be just a one-off mapping between root/client@DOMAIN and root on the server. And that would be sufficient to do something like a dumb

cp -ax / /nfs

backup, where you're just saving/restoring id's using chown/stat.

I don't know if those sorts of cases are common. But they work under v3, and I don't see a reason to break them on upgrade to v4.

Certainly I don't see any motivation for going out of our way to break that case when an administrator explicitly requests numeric id's.

Quoted 24 lines · J. Bruce Fields

Quoted 10 lines · Trond Myklebust

1) The user is authenticating using uids and gids (AUTH_SYS). In that case, the server is using those uids and gids to authorise user behaviour, and so file/directory creation/access/deletion/... will depend only on the numeric values of those uids and gids. It doesn't matter if the client belongs to a different domain, 'cos AUTH_SYS has no concept of a domain. It doesn't matter whether or mot there exists a name@domain mapping on the client, and server. Only the numbers matter. NFSv2 and NFSv3 got this case right, and NFSv4 got it wrong (or didn't consider it).

Quoted 8 lines

2) The user is authenticating using a principal name@DOMAIN. In this case, either there is a mapping between name@DOMAIN and a owner@domain +groupname@domain on the server, or there isn't. In the latter case, the server treats the principal as the anonymous user. In the former case, then if the client and server map owner@domain and groupname@domain to the same uid and gid, then it is safe to pass uids and gids back and forth. If they don't have identical mappings, then it is still safe to pass owner@domain and groupname@domain,

Not necessarily; for example, there could be just a one-off mapping between root/client@DOMAIN and root on the server. And that would be sufficient to do something like a dumb

Quoted 6 lines

cp -ax / /nfs

backup, where you're just saving/restoring id's using chown/stat.

I don't know if those sorts of cases are common. But they work under v3, and I don't see a reason to break them on upgrade to v4.

See above. It's about fixing what is broken with NFSv3.

Quoted 2 lines

Certainly I don't see any motivation for going out of our way to break that case when an administrator explicitly requests numeric id's.

What do you mean by 'explicitly requests numeric ids'?

If you mean 'decides to use NFSv3' then that works today.

What is the point of bending over backwards to make NFSv4 bug-compatible with NFSv3?

If people want NFSv3 they can use it. You can even mount an NFSv3 partition while someone else is using NFSv4 on the same machine.

Could you give an example of a case in which all of the following are true?:
- the administrator explicitly requests numeric id's (for example by setting nfs4_disable_idmapping).
- numeric id's work as long as the client uses auth_sys.
- they no longer work if that same client switches to krb5.

Quoted 6 lines · J. Bruce Fields

Could you give an example of a case in which all of the following are true?:
- the administrator explicitly requests numeric id's (for example by setting nfs4_disable_idmapping).
- numeric id's work as long as the client uses auth_sys.
- they no longer work if that same client switches to krb5.

Trivially:

Server /etc/passwd maps trondmy to uid 1000
Client /etc/passwd maps trondmy to uid 500

Quoted 9 lines · Trond Myklebust

Quoted 6 lines · J. Bruce Fields

Could you give an example of a case in which all of the following are true?:
- the administrator explicitly requests numeric id's (for example by setting nfs4_disable_idmapping).
- numeric id's work as long as the client uses auth_sys.
- they no longer work if that same client switches to krb5.

Quoted 4 lines

Trivially:

Server /etc/passwd maps trondmy to uid 1000
Client /etc/passwd maps trondmy to uid 500

I understand that any problematic case would involve different name<->id mappings on the two sides.

What I don't understand--and apologies if I'm being dense!--is what sequence of operations exactly would work in this situation if we automatically switch idmapping based on auth flavor, and would not work without it.

Are you imagining a future client that is also able to switch auth flavors on the fly (say, based on whether a krb5 ticket exists or not), or just unmounting and remounting to change the security flavor?

Are you thinking of creating a file under one flavor and accessing it under another?

Quoted 23 lines · J. Bruce Fields

Quoted 9 lines · Trond Myklebust

Quoted 6 lines · J. Bruce Fields

Could you give an example of a case in which all of the following are true?:
- the administrator explicitly requests numeric id's (for example by setting nfs4_disable_idmapping).
- numeric id's work as long as the client uses auth_sys.
- they no longer work if that same client switches to krb5.

Quoted 4 lines

Trivially:

Server /etc/passwd maps trondmy to uid 1000
Client /etc/passwd maps trondmy to uid 500

I understand that any problematic case would involve different name<->id mappings on the two sides.

What I don't understand--and apologies if I'm being dense!--is what sequence of operations exactly would work in this situation if we automatically switch idmapping based on auth flavor, and would not work without it.

Quoted 6 lines

Are you imagining a future client that is also able to switch auth flavors on the fly (say, based on whether a krb5 ticket exists or not), or just unmounting and remounting to change the security flavor?

Are you thinking of creating a file under one flavor and accessing it under another?

Neither.

I'm quite happy to accept that my user may map to completely different identities on the server as I switch authentication schemes. Fixing that is indeed the administrator's problem.

I'm thinking of the simple case of creating a file, and then expecting to see that file appear labelled with the correct user id when I do 'ls -l'. That should work irrespectively of the authentication scheme that I choose.

In other words, if I authenticate as 'trond' on my client or to the kerberos server, then do

touch foo
ls -l foo

I should see a file that is owned by 'trond'.

Quoted 48 lines · Trond Myklebust

Quoted 23 lines · J. Bruce Fields

Quoted 9 lines · Trond Myklebust

Quoted 6 lines · J. Bruce Fields

Could you give an example of a case in which all of the following are true?:
- the administrator explicitly requests numeric id's (for example by setting nfs4_disable_idmapping).
- numeric id's work as long as the client uses auth_sys.
- they no longer work if that same client switches to krb5.

Quoted 4 lines

Trivially:

Server /etc/passwd maps trondmy to uid 1000
Client /etc/passwd maps trondmy to uid 500

I understand that any problematic case would involve different name<->id mappings on the two sides.

What I don't understand--and apologies if I'm being dense!--is what sequence of operations exactly would work in this situation if we automatically switch idmapping based on auth flavor, and would not work without it.

Quoted 6 lines

Are you imagining a future client that is also able to switch auth flavors on the fly (say, based on whether a krb5 ticket exists or not), or just unmounting and remounting to change the security flavor?

Are you thinking of creating a file under one flavor and accessing it under another?

Neither.

I'm quite happy to accept that my user may map to completely different identities on the server as I switch authentication schemes. Fixing that is indeed the administrator's problem.

I'm thinking of the simple case of creating a file, and then expecting to see that file appear labelled with the correct user id when I do 'ls -l'. That should work irrespectively of the authentication scheme that I choose.

In other words, if I authenticate as 'trond' on my client or to the kerberos server, then do

touch foo
ls -l foo

Quoted 1 line

I should see a file that is owned by 'trond'.

Thanks, understood; but then, this isn't about behavior that occurs when a user *changes* authentication flavors.

It's about what happens when someone sets nfs4_disable_idmapping but shouldn't have.

Quoted 49 lines · J. Bruce Fields

Quoted 48 lines · Trond Myklebust

Quoted 23 lines · J. Bruce Fields

Quoted 9 lines · Trond Myklebust

Quoted 6 lines · J. Bruce Fields

Could you give an example of a case in which all of the following are true?:
- the administrator explicitly requests numeric id's (for example by setting nfs4_disable_idmapping).
- numeric id's work as long as the client uses auth_sys.
- they no longer work if that same client switches to krb5.

Quoted 4 lines

Trivially:

Server /etc/passwd maps trondmy to uid 1000
Client /etc/passwd maps trondmy to uid 500

I understand that any problematic case would involve different name<->id mappings on the two sides.

What I don't understand--and apologies if I'm being dense!--is what sequence of operations exactly would work in this situation if we automatically switch idmapping based on auth flavor, and would not work without it.

Quoted 6 lines

Are you imagining a future client that is also able to switch auth flavors on the fly (say, based on whether a krb5 ticket exists or not), or just unmounting and remounting to change the security flavor?

Are you thinking of creating a file under one flavor and accessing it under another?

Neither.

I'm quite happy to accept that my user may map to completely different identities on the server as I switch authentication schemes. Fixing that is indeed the administrator's problem.

I'm thinking of the simple case of creating a file, and then expecting to see that file appear labelled with the correct user id when I do 'ls -l'. That should work irrespectively of the authentication scheme that I choose.

In other words, if I authenticate as 'trond' on my client or to the kerberos server, then do

touch foo
ls -l foo

Quoted 7 lines

Quoted 1 line

I should see a file that is owned by 'trond'.

Thanks, understood; but then, this isn't about behavior that occurs when a user *changes* authentication flavors.

It's about what happens when someone sets nfs4_disable_idmapping but shouldn't have.

In other words, to make sure I understand:

- Is this switching-on-auth flavor *just* there to protect confused administrators against themselves?
- Or is there some reasons someone who knew what they were doing would actually *need* that behavior?

Quoted 27 lines · J. Bruce Fields

Quoted 16 lines · J. Bruce Fields

Quoted 15 lines · Trond Myklebust

I'm quite happy to accept that my user may map to completely different identities on the server as I switch authentication schemes. Fixing that is indeed the administrator's problem.

I'm thinking of the simple case of creating a file, and then expecting to see that file appear labelled with the correct user id when I do 'ls -l'. That should work irrespectively of the authentication scheme that I choose.

In other words, if I authenticate as 'trond' on my client or to the kerberos server, then do

touch foo
ls -l foo

Quoted 7 lines

Quoted 1 line

I should see a file that is owned by 'trond'.

Thanks, understood; but then, this isn't about behavior that occurs when a user *changes* authentication flavors.

It's about what happens when someone sets nfs4_disable_idmapping but shouldn't have.

In other words, to make sure I understand:

Quoted 4 lines

- Is this switching-on-auth flavor *just* there to protect confused administrators against themselves?
- Or is there some reasons someone who knew what they were doing would actually *need* that behavior?

It is there to ensure that you can use different type of authentication when speaking to different servers, and still have it work without the administrator having to add special mount options.

As I've said before, the uid-on-the-wire behaviour only makes sense with AUTH_SYS. It adds no value when authenticating using principals, and will in many (most?) cases end up doing the wrong thing.

Trond

Signature · 6 lines

Trond Myklebust
Linux NFS client maintainer

NetApp
[email protected]
www.netapp.com

Quoted 65 lines · Simon Kirby

Possibly related to the flush-processes-taking-CPU issues I saw previously, I thought this was interesting. I found a log-crunching box that does all of its work via NFS and spends most of the day sleeping. It has been using a linearly-increasing amount of system time during the time where is sleeping. munin graph:

http://0x.ca/sim/ref/2.6.36/cpu_logcrunch_nfs.png

top shows:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 4767 root      20   0     0    0    0 S   16  0.0   2413:29 flush-0:69
22385 root      20   0     0    0    0 S   10  0.0   1320:23 flush-0:70

(rest idle)

perf top shows:

-------------------------------------------------------------------------------------------
PerfTop: 252 irqs/sec kernel:97.2% exact: 0.0% [1000Hz cycles], (all, 2 CPUs)
-------------------------------------------------------------------------------------------

samples pcnt function DSO
_______ _____ _______________________________ ___________

912.00 21.2% _raw_spin_lock [kernel]
592.00 13.8% nfs_writepages [kernel]
474.00 11.0% queue_io [kernel]
428.00 10.0% writeback_single_inode [kernel]
379.00 8.8% writeback_sb_inodes [kernel]
237.00 5.5% bit_waitqueue [kernel]
184.00 4.3% do_writepages [kernel]
169.00 3.9% __iget [kernel]
132.00 3.1% redirty_tail [kernel]
85.00 2.0% iput [kernel]
72.00 1.7% _atomic_dec_and_lock [kernel]
67.00 1.6% write_cache_pages [kernel]
63.00 1.5% port_inb [ipmi_si]
62.00 1.4% __mark_inode_dirty [kernel]
48.00 1.1% __wake_up_bit [kernel]
32.00 0.7% nfs_write_inode [kernel]
26.00 0.6% native_read_tsc [kernel]
25.00 0.6% radix_tree_gang_lookup_tag_slot [kernel]
25.00 0.6% schedule [kernel]
24.00 0.6% wake_up_bit [kernel]
20.00 0.5% apic_timer_interrupt [kernel]
19.00 0.4% ia32_syscall [kernel]
16.00 0.4% find_get_pages_tag [kernel]
15.00 0.3% _raw_spin_lock_irqsave [kernel]
15.00 0.3% load_balance [kernel]
13.00 0.3% ktime_get [kernel]
12.00 0.3% shrink_icache_memory [kernel]
11.00 0.3% semop libc-2.7.so
9.00 0.2% nfs_pageio_doio [kernel]
8.00 0.2% dso__find_symbol perf
8.00 0.2% down_read [kernel]
7.00 0.2% __switch_to [kernel]
7.00 0.2% __phys_addr [kernel]
7.00 0.2% nfs_pageio_init [kernel]
7.00 0.2% pagevec_lookup_tag [kernel]
7.00 0.2% _cond_resched [kernel]
7.00 0.2% up_read [kernel]
6.00 0.1% sched_clock_local [kernel]
5.00 0.1% rb_erase [kernel]
5.00 0.1% page_fault [kernel]

Quoted 5 lines

"tcpdump -i any -n port 2049" and "nfsstat" shows this work does not actually result in any NFS packets.

Known 2.6.36 issue? This did not occur on 2.6.35.4, according to the munin graphs. I'll try 2.6.37-rc an see if it changes.

Possibly a side effect of the fs/fs-writeback.c changes in 2.6.36? You do appear to be hitting a lot of spinlock contention, but I suspect that a lot of it is coming from writeback_sb_inodes, writeback_single_inode and queue_io, all of which seem unnaturally high on your stats above.

I don't see how you can be seeing no traffic on the wire. You are certainly hitting some page writeout (0.2% nfs_pageio_doio).

Cheers
Trond

Signature · 6 lines

Trond Myklebust
Linux NFS client maintainer

NetApp
[email protected]
www.netapp.com

Hello!

Following up on "System CPU increasing on idle 2.6.36", this issue is still happening even on 3.1-rc7. So, since it has been 9 months since I reported this, I figured I'd bisect this issue. The first bisection ended in an IPMI regression that looked like the problem, so I had to start again. Eventually, I got commit b80c3cb628f0ebc241b02e38dd028969fb8026a2 which made it into 2.6.34-rc4.

With this commit, system CPU keeps rising as the log crunch box runs (reads log files via NFS and spews out HTML files into NFS-mounted report directories). When it finishes the daily run, the system time stays non-zero and continues to be higher and higher after each run, until the box never completes a run within a day due to all of the wasted cycles.

Quoted 9 lines · Simon Kirby

Hello!

Following up on "System CPU increasing on idle 2.6.36", this issue is still happening even on 3.1-rc7. So, since it has been 9 months since I reported this, I figured I'd bisect this issue. The first bisection ended in an IPMI regression that looked like the problem, so I had to start again. Eventually, I got commit b80c3cb628f0ebc241b02e38dd028969fb8026a2 which made it into 2.6.34-rc4.

Quoted 5 lines

With this commit, system CPU keeps rising as the log crunch box runs (reads log files via NFS and spews out HTML files into NFS-mounted report directories). When it finishes the daily run, the system time stays non-zero and continues to be higher and higher after each run, until the box never completes a run within a day due to all of the wasted cycles.

So reverting that commit fixes the problem on 3.1-rc7?

As far as I can see, doing so should be safe thanks to commit 5547e8aac6f71505d621a612de2fca0dd988b439 (writeback: Update dirty flags in two steps) which fixes the original problem at the VFS level.

Quoted 16 lines · Trond Myklebust

Quoted 9 lines · Simon Kirby

Hello!

Following up on "System CPU increasing on idle 2.6.36", this issue is still happening even on 3.1-rc7. So, since it has been 9 months since I reported this, I figured I'd bisect this issue. The first bisection ended in an IPMI regression that looked like the problem, so I had to start again. Eventually, I got commit b80c3cb628f0ebc241b02e38dd028969fb8026a2 which made it into 2.6.34-rc4.

Quoted 5 lines

With this commit, system CPU keeps rising as the log crunch box runs (reads log files via NFS and spews out HTML files into NFS-mounted report directories). When it finishes the daily run, the system time stays non-zero and continues to be higher and higher after each run, until the box never completes a run within a day due to all of the wasted cycles.

Quoted 5 lines

So reverting that commit fixes the problem on 3.1-rc7?

As far as I can see, doing so should be safe thanks to commit 5547e8aac6f71505d621a612de2fca0dd988b439 (writeback: Update dirty flags in two steps) which fixes the original problem at the VFS level.

Hmm, I went to git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2, but for some reason git left the nfs_mark_request_dirty(req); line in nfs_writepage_setup(), even though the original commit had that. Is that OK or should I remove that as well?

Once that is sorted, I'll build it and let it run for a day and let you know. Thanks!

Quoted 29 lines · Simon Kirby

Quoted 16 lines · Trond Myklebust

Quoted 9 lines · Simon Kirby

Hello!

Following up on "System CPU increasing on idle 2.6.36", this issue is still happening even on 3.1-rc7. So, since it has been 9 months since I reported this, I figured I'd bisect this issue. The first bisection ended in an IPMI regression that looked like the problem, so I had to start again. Eventually, I got commit b80c3cb628f0ebc241b02e38dd028969fb8026a2 which made it into 2.6.34-rc4.

Quoted 5 lines

With this commit, system CPU keeps rising as the log crunch box runs (reads log files via NFS and spews out HTML files into NFS-mounted report directories). When it finishes the daily run, the system time stays non-zero and continues to be higher and higher after each run, until the box never completes a run within a day due to all of the wasted cycles.

Quoted 5 lines

So reverting that commit fixes the problem on 3.1-rc7?

As far as I can see, doing so should be safe thanks to commit 5547e8aac6f71505d621a612de2fca0dd988b439 (writeback: Update dirty flags in two steps) which fixes the original problem at the VFS level.

Hmm, I went to git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2, but for some reason git left the nfs_mark_request_dirty(req); line in nfs_writepage_setup(), even though the original commit had that. Is that OK or should I remove that as well?

Quoted 2 lines

Once that is sorted, I'll build it and let it run for a day and let you know. Thanks!

It shouldn't make any difference whether you leave it or remove it. The resulting second call to __set_page_dirty_nobuffers() will always be a no-op since the page will already be marked as dirty.

Quoted 33 lines · Trond Myklebust

Quoted 31 lines · Simon Kirby

Quoted 16 lines · Trond Myklebust

Quoted 9 lines · Simon Kirby

Hello!

Following up on "System CPU increasing on idle 2.6.36", this issue is still happening even on 3.1-rc7. So, since it has been 9 months since I reported this, I figured I'd bisect this issue. The first bisection ended in an IPMI regression that looked like the problem, so I had to start again. Eventually, I got commit b80c3cb628f0ebc241b02e38dd028969fb8026a2 which made it into 2.6.34-rc4.

Quoted 5 lines

With this commit, system CPU keeps rising as the log crunch box runs (reads log files via NFS and spews out HTML files into NFS-mounted report directories). When it finishes the daily run, the system time stays non-zero and continues to be higher and higher after each run, until the box never completes a run within a day due to all of the wasted cycles.

Quoted 5 lines

So reverting that commit fixes the problem on 3.1-rc7?

As far as I can see, doing so should be safe thanks to commit 5547e8aac6f71505d621a612de2fca0dd988b439 (writeback: Update dirty flags in two steps) which fixes the original problem at the VFS level.

Hmm, I went to git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2, but for some reason git left the nfs_mark_request_dirty(req); line in nfs_writepage_setup(), even though the original commit had that. Is that OK or should I remove that as well?

Once that is sorted, I'll build it and let it run for a day and let you know. Thanks!

Quoted 3 lines

It shouldn't make any difference whether you leave it or remove it. The resulting second call to __set_page_dirty_nobuffers() will always be a no-op since the page will already be marked as dirty.

Ok, confirmed, git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2 on 3.1-rc7 fixes the problem for me. Does this make sense, then, or do we need further investigation and/or testing?

-----Original Message-----
From: Simon Kirby [mailto:[email protected]]
Sent: Thursday, September 29, 2011 8:58 PM
To: Myklebust, Trond
Cc: [email protected]; [email protected]
Subject: Re: NFS client growing system CPU

Quoted 11 lines · Simon Kirby

Quoted 9 lines · Trond Myklebust

Quoted 8 lines · Simon Kirby

Quoted 6 lines · Trond Myklebust

Quoted 5 lines · Simon Kirby

Hello!

Following up on "System CPU increasing on idle 2.6.36", this issue is still happening even on 3.1-rc7. So, since it has been 9 months since I reported this, I figured I'd bisect

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

issue. The first bisection ended in an IPMI regression that looked like the problem, so I had to start again.

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

I got commit b80c3cb628f0ebc241b02e38dd028969fb8026a2 which made it into 2.6.34-rc4.

With this commit, system CPU keeps rising as the log crunch box runs (reads log files via NFS and spews out HTML files into NFS-mounted report directories). When it finishes the daily run, the system time stays non-zero and continues to

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

higher and higher after each run, until the box never

run within a day due to all of the wasted cycles.

Quoted 6 lines

Quoted 6 lines

Quoted 6 lines

Quoted 6 lines

So reverting that commit fixes the problem on 3.1-rc7?

As far as I can see, doing so should be safe thanks to commit 5547e8aac6f71505d621a612de2fca0dd988b439 (writeback: Update dirty flags in two steps) which fixes the original problem at

level.

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

Hmm, I went to git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2, but for some reason

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

left the nfs_mark_request_dirty(req); line in nfs_writepage_setup(), even though the original commit had that.

that OK or should I remove that as well?

Quoted 5 lines

Quoted 5 lines

Quoted 3 lines

Once that is sorted, I'll build it and let it run for a day and let you know. Thanks!

It shouldn't make any difference whether you leave it or remove

Quoted 4 lines

Quoted 2 lines

The resulting second call to __set_page_dirty_nobuffers() will always be a no-op since the page will already be marked as dirty.

Ok, confirmed, git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2

Quoted 1 line

3.1-rc7 fixes the problem for me. Does this make sense, then, or do

Quoted 1 line

need further investigation and/or testing?

Just to clear up what I said before, it seems that on plain 3.1-rc8, I

able to clear the endless CPU use in nfs_writepages by just running

am not sure when this changed, but I'm pretty sure that some versions between 2.6.34 and 3.1-rc used to not be affected by just "sync"

was paired with drop_caches. Maybe this makes the problem more obvious...

Quoted 7 lines

-----Original Message-----
From: Simon Kirby [mailto:[email protected]]
Sent: Thursday, September 29, 2011 8:58 PM
To: Myklebust, Trond
Cc: [email protected]; [email protected]
Subject: Re: NFS client growing system CPU

Quoted 13 lines

Quoted 11 lines · Simon Kirby

Quoted 9 lines · Trond Myklebust

Quoted 8 lines · Simon Kirby

Quoted 6 lines · Trond Myklebust

Quoted 5 lines · Simon Kirby

Hello!

Following up on "System CPU increasing on idle 2.6.36", this issue is still happening even on 3.1-rc7. So, since it has been 9 months since I reported this, I figured I'd bisect

this

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

issue. The first bisection ended in an IPMI regression that looked like the problem, so I had to start again.

Eventually,

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

I got commit b80c3cb628f0ebc241b02e38dd028969fb8026a2 which made it into 2.6.34-rc4.

With this commit, system CPU keeps rising as the log crunch box runs (reads log files via NFS and spews out HTML files into NFS-mounted report directories). When it finishes the daily run, the system time stays non-zero and continues to

be

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

higher and higher after each run, until the box never

completes a

Quoted 7 lines

run within a day due to all of the wasted cycles.

Quoted 6 lines

Quoted 6 lines

Quoted 6 lines

Quoted 6 lines

So reverting that commit fixes the problem on 3.1-rc7?

As far as I can see, doing so should be safe thanks to commit 5547e8aac6f71505d621a612de2fca0dd988b439 (writeback: Update dirty flags in two steps) which fixes the original problem at

the VFS

Quoted 4 lines

level.

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

Hmm, I went to git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2, but for some reason

git

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

left the nfs_mark_request_dirty(req); line in nfs_writepage_setup(), even though the original commit had that.

Is

Quoted 6 lines

that OK or should I remove that as well?

Quoted 5 lines

Quoted 5 lines

Quoted 3 lines

Once that is sorted, I'll build it and let it run for a day and let you know. Thanks!

It shouldn't make any difference whether you leave it or remove

it.

Quoted 4 lines

Quoted 4 lines

Quoted 2 lines

The resulting second call to __set_page_dirty_nobuffers() will always be a no-op since the page will already be marked as dirty.

Ok, confirmed, git revert b80c3cb628f0ebc241b02e38dd028969fb8026a2

on

Quoted 1 line

Quoted 1 line

3.1-rc7 fixes the problem for me. Does this make sense, then, or do

we

Quoted 3 lines

Quoted 1 line

need further investigation and/or testing?

Just to clear up what I said before, it seems that on plain 3.1-rc8, I

am actually

Quoted 1 line

able to clear the endless CPU use in nfs_writepages by just running

"sync". I

Quoted 2 lines

am not sure when this changed, but I'm pretty sure that some versions between 2.6.34 and 3.1-rc used to not be affected by just "sync"

unless it

Quoted 2 lines

was paired with drop_caches. Maybe this makes the problem more obvious...

Hi Simon,

I think you are just finding yourself cycling through the VFS writeback routines all the time because we dirty the inode for COMMIT at the same time as we dirty a new page. Usually, we want to wait until after the WRITE rpc call has completed, and so it was only the vfs race that forced us to write this workaround so that we can guarantee reliable fsync() behaviour.

My only concern at this point is to make sure that in reverting that patch, we haven't overlooked some other fsync() bug that this patch fixed. So far, it looks as if Dmitry's patch is sufficient to deal with any issues that I can see.

Possibly related to the flush-processes-taking-CPU issues I saw previously, I thought this was interesting. I found a log-crunching box that does all of its work via NFS and spends most of the day sleeping. It has been using a linearly-increasing amount of system time during the time where is sleeping. munin graph:

http://0x.ca/sim/ref/2.6.36/cpu_logcrunch_nfs.png
...
Known 2.6.36 issue? This did not occur on 2.6.35.4, according to the munin graphs. I'll try 2.6.37-rc an see if it changes.

Quoted 10 lines · Simon Kirby

Possibly related to the flush-processes-taking-CPU issues I saw previously, I thought this was interesting.  I found a log-crunching box that does all of its work via NFS and spends most of the day sleeping. It has been using a linearly-increasing amount of system time during the time where is sleeping.  munin graph:

http://0x.ca/sim/ref/2.6.36/cpu_logcrunch_nfs.png
...
Known 2.6.36 issue?  This did not occur on 2.6.35.4, according to the munin graphs.  I'll try 2.6.37-rc an see if it changes.

So, back on this topic,

It seems that system CPU from "flush" processes is still increasing during and after periods of NFS activity, even with 2.6.37-rc5-git4:

       http://0x.ca/sim/ref/2.6.37/cpu_nfs.png

Something is definitely going on while NFS is active, and then keeps happening in the idle periods.  top and perf top look the same as in 2.6.36.  No userland activity at all, but the kernel keeps doing stuff.

I could bisect this, but I have to wait a day for each build, unless I can come up with a way to reproduce it more quickly.  The mount points for which the flush processes are active are the two mount points where the logs are read from, rotated, compressed, and unlinked, and where the reports are written, running in parallel under an xargs -P 15.

I'm pretty sure the only syscalls that are reproducing this are read(), readdir(), lstat(), write(), rename(), unlink(), and close().  There's nothing special happening here...

Quoted 10 lines · Simon Kirby

Possibly related to the flush-processes-taking-CPU issues I saw previously, I thought this was interesting. I found a log-crunching box that does all of its work via NFS and spends most of the day sleeping. It has been using a linearly-increasing amount of system time during the time where is sleeping. munin graph:

http://0x.ca/sim/ref/2.6.36/cpu_logcrunch_nfs.png
...
Known 2.6.36 issue? This did not occur on 2.6.35.4, according to the munin graphs. I'll try 2.6.37-rc an see if it changes.

So, back on this topic,

It seems that system CPU from "flush" processes is still increasing during and after periods of NFS activity, even with 2.6.37-rc5-git4:

        http://0x.ca/sim/ref/2.6.37/cpu_nfs.png

Something is definitely going on while NFS is active, and then keeps happening in the idle periods. top and perf top look the same as in 2.6.36. No userland activity at all, but the kernel keeps doing stuff.

I could bisect this, but I have to wait a day for each build, unless I can come up with a way to reproduce it more quickly. The mount points for which the flush processes are active are the two mount points where the logs are read from, rotated, compressed, and unlinked, and where the reports are written, running in parallel under an xargs -P 15.

I'm pretty sure the only syscalls that are reproducing this are read(), readdir(), lstat(), write(), rename(), unlink(), and close(). There's nothing special happening here...

Quoted 30 lines · Simon Kirby

Quoted 10 lines · Simon Kirby

Possibly related to the flush-processes-taking-CPU issues I saw previously, I thought this was interesting.  I found a log-crunching box that does all of its work via NFS and spends most of the day sleeping. It has been using a linearly-increasing amount of system time during the time where is sleeping.  munin graph:

http://0x.ca/sim/ref/2.6.36/cpu_logcrunch_nfs.png
...
Known 2.6.36 issue?  This did not occur on 2.6.35.4, according to the munin graphs.  I'll try 2.6.37-rc an see if it changes.

So, back on this topic,

It seems that system CPU from "flush" processes is still increasing during and after periods of NFS activity, even with 2.6.37-rc5-git4:

        http://0x.ca/sim/ref/2.6.37/cpu_nfs.png

Something is definitely going on while NFS is active, and then keeps happening in the idle periods.  top and perf top look the same as in 2.6.36.  No userland activity at all, but the kernel keeps doing stuff.

I could bisect this, but I have to wait a day for each build, unless I can come up with a way to reproduce it more quickly.  The mount points for which the flush processes are active are the two mount points where the logs are read from, rotated, compressed, and unlinked, and where the reports are written, running in parallel under an xargs -P 15.

Quoted 3 lines

I'm pretty sure the only syscalls that are reproducing this are read(), readdir(), lstat(), write(), rename(), unlink(), and close().  There's nothing special happening here...

I've noticed nfs_inode_cache is ever-increasing as well with 2.6.37:

 OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME 2562514 2541520  99%    0.95K  78739       33   2519648K nfs_inode_cache 467200 285110  61%    0.02K   1825      256      7300K kmalloc-16 299397 242350  80%    0.19K  14257       21     57028K dentry 217434 131978  60%    0.55K   7767       28    124272K radix_tree_node 215232  81522  37%    0.06K   3363       64     13452K kmalloc-64 183027 136802  74%    0.10K   4693       39     18772K buffer_head 101120  71184  70%    0.03K    790      128      3160K kmalloc-32 79616  59713  75%    0.12K   2488       32      9952K kmalloc-128 66560  41257  61%    0.01K    130      512       520K kmalloc-8 42126  26650  63%    0.75K   2006       21     32096K ext3_inode_cache

http://0x.ca/sim/ref/2.6.37/inodes_nfs.png
http://0x.ca/sim/ref/2.6.37/cpu2_nfs.png

Perhaps I could bisect just fs/nfs changes between 2.6.35 and 2.6.36 to try to track this down without having to wait too long, unless somebody can see what is happening here.

Quoted 14 lines · Simon Kirby

I've noticed nfs_inode_cache is ever-increasing as well with 2.6.37:

?OBJS ACTIVE ?USE OBJ SIZE ?SLABS OBJ/SLAB CACHE SIZE NAME 2562514 2541520 ?99% ? ?0.95K ?78739 ? ? ? 33 ? 2519648K nfs_inode_cache 467200 285110 ?61% ? ?0.02K ? 1825 ? ? ?256 ? ? ?7300K kmalloc-16 299397 242350 ?80% ? ?0.19K ?14257 ? ? ? 21 ? ? 57028K dentry 217434 131978 ?60% ? ?0.55K ? 7767 ? ? ? 28 ? ?124272K radix_tree_node 215232 ?81522 ?37% ? ?0.06K ? 3363 ? ? ? 64 ? ? 13452K kmalloc-64 183027 136802 ?74% ? ?0.10K ? 4693 ? ? ? 39 ? ? 18772K buffer_head 101120 ?71184 ?70% ? ?0.03K ? ?790 ? ? ?128 ? ? ?3160K kmalloc-32 ?79616 ?59713 ?75% ? ?0.12K ? 2488 ? ? ? 32 ? ? ?9952K kmalloc-128 ?66560 ?41257 ?61% ? ?0.01K ? ?130 ? ? ?512 ? ? ? 520K kmalloc-8 ?42126 ?26650 ?63% ? ?0.75K ? 2006 ? ? ? 21 ? ? 32096K ext3_inode_cache

Quoted 6 lines

http://0x.ca/sim/ref/2.6.37/inodes_nfs.png
http://0x.ca/sim/ref/2.6.37/cpu2_nfs.png

Perhaps I could bisect just fs/nfs changes between 2.6.35 and 2.6.36 to try to track this down without having to wait too long, unless somebody can see what is happening here.

I'll get started bisecting too, since this is something of a show-stopper. Boxes that pre-2.6.36 would stay up for months at a time now have to be powercycled every couple of days (which is about how long it takes for this behavior to show up). This is across-the-board for about 50 boxes, ranging from 2.6.36 to 2.6.36.2.

Simon: It's probably irrelevant since these are kernel threads, but I'm curious what distro your boxes are running. Ours are Debian Lenny, i386, Dell Poweredge 850s. Just trying to figure out any commonalities. I'll get my boxes back on 2.6.36.2 and start watching nfs_inode_cache as well.

Quoted 29 lines · Mark Moseley

Quoted 14 lines · Simon Kirby

I've noticed nfs_inode_cache is ever-increasing as well with 2.6.37:

?OBJS ACTIVE ?USE OBJ SIZE ?SLABS OBJ/SLAB CACHE SIZE NAME 2562514 2541520 ?99% ? ?0.95K ?78739 ? ? ? 33 ? 2519648K nfs_inode_cache 467200 285110 ?61% ? ?0.02K ? 1825 ? ? ?256 ? ? ?7300K kmalloc-16 299397 242350 ?80% ? ?0.19K ?14257 ? ? ? 21 ? ? 57028K dentry 217434 131978 ?60% ? ?0.55K ? 7767 ? ? ? 28 ? ?124272K radix_tree_node 215232 ?81522 ?37% ? ?0.06K ? 3363 ? ? ? 64 ? ? 13452K kmalloc-64 183027 136802 ?74% ? ?0.10K ? 4693 ? ? ? 39 ? ? 18772K buffer_head 101120 ?71184 ?70% ? ?0.03K ? ?790 ? ? ?128 ? ? ?3160K kmalloc-32 ?79616 ?59713 ?75% ? ?0.12K ? 2488 ? ? ? 32 ? ? ?9952K kmalloc-128 ?66560 ?41257 ?61% ? ?0.01K ? ?130 ? ? ?512 ? ? ? 520K kmalloc-8 ?42126 ?26650 ?63% ? ?0.75K ? 2006 ? ? ? 21 ? ? 32096K ext3_inode_cache

Quoted 6 lines

http://0x.ca/sim/ref/2.6.37/inodes_nfs.png
http://0x.ca/sim/ref/2.6.37/cpu2_nfs.png

Perhaps I could bisect just fs/nfs changes between 2.6.35 and 2.6.36 to try to track this down without having to wait too long, unless somebody can see what is happening here.

I'll get started bisecting too, since this is something of a show-stopper. Boxes that pre-2.6.36 would stay up for months at a time now have to be powercycled every couple of days (which is about how long it takes for this behavior to show up). This is across-the-board for about 50 boxes, ranging from 2.6.36 to 2.6.36.2.

Quoted 5 lines

Simon: It's probably irrelevant since these are kernel threads, but I'm curious what distro your boxes are running. Ours are Debian Lenny, i386, Dell Poweredge 850s. Just trying to figure out any commonalities. I'll get my boxes back on 2.6.36.2 and start watching nfs_inode_cache as well.

Same distro, x86_64, similar servers.

I'm not sure if the two cases I am seeing are exactly the same problem, but on the log crunching boxes, system time seems proportional to nfs_inode_cache and nfs_inode_cache just keeps growing forever; however, if I stop the load and unmount the NFS mount points, all of the nfs_inode_cache objects do actually go away (after umount finishes).

It seems the shrinker callback might not be working as intended here.

On the shared server case, the crazy spinlock contention from all of the flusher processes happens suddenly and overloads the boxes for 10-15 minutes, and then everything recovers.  Over 21 of these boxes, they each have about 500k-700k nfs_inode_cache objects.  The log cruncher hit 3.3 million nfs_inode_cache objects before I unmounted.

Are your boxes repeating this behaviour at any predictable interval?

Quoted 47 lines · Simon Kirby

Quoted 29 lines · Mark Moseley

Quoted 14 lines · Simon Kirby

I've noticed nfs_inode_cache is ever-increasing as well with 2.6.37:

?OBJS ACTIVE ?USE OBJ SIZE ?SLABS OBJ/SLAB CACHE SIZE NAME 2562514 2541520 ?99% ? ?0.95K ?78739 ? ? ? 33 ? 2519648K nfs_inode_cache 467200 285110 ?61% ? ?0.02K ? 1825 ? ? ?256 ? ? ?7300K kmalloc-16 299397 242350 ?80% ? ?0.19K ?14257 ? ? ? 21 ? ? 57028K dentry 217434 131978 ?60% ? ?0.55K ? 7767 ? ? ? 28 ? ?124272K radix_tree_node 215232 ?81522 ?37% ? ?0.06K ? 3363 ? ? ? 64 ? ? 13452K kmalloc-64 183027 136802 ?74% ? ?0.10K ? 4693 ? ? ? 39 ? ? 18772K buffer_head 101120 ?71184 ?70% ? ?0.03K ? ?790 ? ? ?128 ? ? ?3160K kmalloc-32 ?79616 ?59713 ?75% ? ?0.12K ? 2488 ? ? ? 32 ? ? ?9952K kmalloc-128 ?66560 ?41257 ?61% ? ?0.01K ? ?130 ? ? ?512 ? ? ? 520K kmalloc-8 ?42126 ?26650 ?63% ? ?0.75K ? 2006 ? ? ? 21 ? ? 32096K ext3_inode_cache

Quoted 6 lines

http://0x.ca/sim/ref/2.6.37/inodes_nfs.png
http://0x.ca/sim/ref/2.6.37/cpu2_nfs.png

Perhaps I could bisect just fs/nfs changes between 2.6.35 and 2.6.36 to try to track this down without having to wait too long, unless somebody can see what is happening here.

I'll get started bisecting too, since this is something of a show-stopper. Boxes that pre-2.6.36 would stay up for months at a time now have to be powercycled every couple of days (which is about how long it takes for this behavior to show up). This is across-the-board for about 50 boxes, ranging from 2.6.36 to 2.6.36.2.

Quoted 5 lines

Simon: It's probably irrelevant since these are kernel threads, but I'm curious what distro your boxes are running. Ours are Debian Lenny, i386, Dell Poweredge 850s. Just trying to figure out any commonalities. I'll get my boxes back on 2.6.36.2 and start watching nfs_inode_cache as well.

Same distro, x86_64, similar servers.

I'm not sure if the two cases I am seeing are exactly the same problem, but on the log crunching boxes, system time seems proportional to nfs_inode_cache and nfs_inode_cache just keeps growing forever; however, if I stop the load and unmount the NFS mount points, all of the nfs_inode_cache objects do actually go away (after umount finishes).

It seems the shrinker callback might not be working as intended here.

Quoted 7 lines

On the shared server case, the crazy spinlock contention from all of the flusher processes happens suddenly and overloads the boxes for 10-15 minutes, and then everything recovers.  Over 21 of these boxes, they each have about 500k-700k nfs_inode_cache objects.  The log cruncher hit 3.3 million nfs_inode_cache objects before I unmounted.

Are your boxes repeating this behaviour at any predictable interval?

Simon:
My boxes definitely fall into the latter category, with spinlock regularly sitting at 60-80% CPU (according to 'perf top'). As far as predictability, not strictly, but it's typically after an uptime of 2-3 days. They take so long to get into this state that I've never seen the actual transition in person, just the after-effects of flush-0:xx gone crazy. These boxes have a number of other NFS mounts, but it's on the flush-0:xx's for the heavily written-to NFS mounts that are spinning wildly, which you'd expect to be the case. The infrequently written-to NFS servers' flush-0:xx isn't to be found in 'top' output.

I'd booted into older kernels after my initial reply, so I'm 14 hrs into booting a box back into 2.6.36.2 and another box into a double-bisected 2.6.35-2.6.36 kernel (my first bisect hit compile errors). Both are running normally but that fits with the pattern so far.

NFS Guys:
Anything else we can be digging up to help debug this? This is a pretty ugly issue.

Quoted 74 lines · Mark Moseley

Quoted 47 lines · Simon Kirby

Quoted 29 lines · Mark Moseley

Quoted 14 lines · Simon Kirby

I've noticed nfs_inode_cache is ever-increasing as well with 2.6.37:

?OBJS ACTIVE ?USE OBJ SIZE ?SLABS OBJ/SLAB CACHE SIZE NAME 2562514 2541520 ?99% ? ?0.95K ?78739 ? ? ? 33 ? 2519648K nfs_inode_cache 467200 285110 ?61% ? ?0.02K ? 1825 ? ? ?256 ? ? ?7300K kmalloc-16 299397 242350 ?80% ? ?0.19K ?14257 ? ? ? 21 ? ? 57028K dentry 217434 131978 ?60% ? ?0.55K ? 7767 ? ? ? 28 ? ?124272K radix_tree_node 215232 ?81522 ?37% ? ?0.06K ? 3363 ? ? ? 64 ? ? 13452K kmalloc-64 183027 136802 ?74% ? ?0.10K ? 4693 ? ? ? 39 ? ? 18772K buffer_head 101120 ?71184 ?70% ? ?0.03K ? ?790 ? ? ?128 ? ? ?3160K kmalloc-32 ?79616 ?59713 ?75% ? ?0.12K ? 2488 ? ? ? 32 ? ? ?9952K kmalloc-128 ?66560 ?41257 ?61% ? ?0.01K ? ?130 ? ? ?512 ? ? ? 520K kmalloc-8 ?42126 ?26650 ?63% ? ?0.75K ? 2006 ? ? ? 21 ? ? 32096K ext3_inode_cache

Quoted 6 lines

http://0x.ca/sim/ref/2.6.37/inodes_nfs.png
http://0x.ca/sim/ref/2.6.37/cpu2_nfs.png

Perhaps I could bisect just fs/nfs changes between 2.6.35 and 2.6.36 to try to track this down without having to wait too long, unless somebody can see what is happening here.

I'll get started bisecting too, since this is something of a show-stopper. Boxes that pre-2.6.36 would stay up for months at a time now have to be powercycled every couple of days (which is about how long it takes for this behavior to show up). This is across-the-board for about 50 boxes, ranging from 2.6.36 to 2.6.36.2.

Quoted 5 lines

Simon: It's probably irrelevant since these are kernel threads, but I'm curious what distro your boxes are running. Ours are Debian Lenny, i386, Dell Poweredge 850s. Just trying to figure out any commonalities. I'll get my boxes back on 2.6.36.2 and start watching nfs_inode_cache as well.

Same distro, x86_64, similar servers.

I'm not sure if the two cases I am seeing are exactly the same problem, but on the log crunching boxes, system time seems proportional to nfs_inode_cache and nfs_inode_cache just keeps growing forever; however, if I stop the load and unmount the NFS mount points, all of the nfs_inode_cache objects do actually go away (after umount finishes).

It seems the shrinker callback might not be working as intended here.

Quoted 7 lines

On the shared server case, the crazy spinlock contention from all of the flusher processes happens suddenly and overloads the boxes for 10-15 minutes, and then everything recovers.  Over 21 of these boxes, they each have about 500k-700k nfs_inode_cache objects.  The log cruncher hit 3.3 million nfs_inode_cache objects before I unmounted.

Are your boxes repeating this behaviour at any predictable interval?

Simon:
My boxes definitely fall into the latter category, with spinlock regularly sitting at 60-80% CPU (according to 'perf top'). As far as predictability, not strictly, but it's typically after an uptime of 2-3 days. They take so long to get into this state that I've never seen the actual transition in person, just the after-effects of flush-0:xx gone crazy. These boxes have a number of other NFS mounts, but it's on the flush-0:xx's for the heavily written-to NFS mounts that are spinning wildly, which you'd expect to be the case. The infrequently written-to NFS servers' flush-0:xx isn't to be found in 'top' output.

I'd booted into older kernels after my initial reply, so I'm 14 hrs into booting a box back into 2.6.36.2 and another box into a double-bisected 2.6.35-2.6.36 kernel (my first bisect hit compile errors). Both are running normally but that fits with the pattern so far.

Quoted 4 lines

NFS Guys:
Anything else we can be digging up to help debug this? This is a pretty ugly issue.

NOTE: NFS/Kernel guys: I've left the 2.6.36.2 box still thrashing about in case there's something you'd like me to look at.

Ok, both my 2.6.36.2 kernel box and my 2.6.35->2.6.36 bisect box (was bisected to ce7db282a3830f57f5b05ec48288c23a5c4d66d5 -- this is my first time doing bisect, so I'll preemptively apologize for doing anything silly) both went berserk within 15 mins of each other, after an uptime of around 63 hours for 2.6.36.2 and 65 hours for the bisected box. The 2.6.36.2 one is still running with all the various flush-0:xx threads spinning wildly. The bisected box just keeled over and died, but is back up now. The only kernel messages logged are just of the "task kworker/4:1:359 blocked for more than 120 seconds" variety, all with _raw_spin_lock_irq at the top of the stack trace.

Looking at slabinfo, specifically, this: stats=$(grep nfs_inode_cache /proc/slabinfo | awk '{ print $2, $3 }')
the active_objs and num_objs both increase to over a million (these boxes are delivering mail to NFS-mounted mailboxes, so that's perfectly reasonable). On both boxes, looking at sar, things start to go awry around 10am today EST. At that time on the 2.6.36.2 box, the NFS numbers look like this:

Fri Jan  7 09:58:00 2011: 1079433 1079650
Fri Jan  7 09:59:00 2011: 1079632 1080300
Fri Jan  7 10:00:00 2011: 1080196 1080300
Fri Jan  7 10:01:01 2011: 1080599 1080716
Fri Jan  7 10:02:01 2011: 1081074 1081288

on the bisected, like this:

Fri Jan  7 09:59:34 2011: 1162786 1165320
Fri Jan  7 10:00:34 2011: 1163301 1165320
Fri Jan  7 10:01:34 2011: 1164369 1165450
Fri Jan  7 10:02:35 2011: 1164179 1165450
Fri Jan  7 10:03:35 2011: 1165795 1166958

When the bisected box finally died, the last numbers were:

Fri Jan  7 10:40:33 2011: 1177156 1177202
Fri Jan  7 10:42:21 2011: 1177157 1177306
Fri Jan  7 10:44:55 2011: 1177201 1177324
Fri Jan  7 10:45:55 2011: 1177746 1177826

On the still-thrashing 2.6.36.2 box, the highwater mark is:

Fri Jan  7 10:23:30 2011: 1084020 1084070

and once things went awry, the active_objs started falling away and the number_objs has stayed at 1084070. Last numbers were:

Fri Jan  7 12:19:34 2011: 826623 1084070

The bisected box had reached 1mil entries (or more significantly 1048576 entries) by y'day evening. The 2.6.36.2 box hit that by 7am EST today. So in neither case was there a big spike in entries.

These boxes have identical workloads. They're not accessible from the net, so there's no chance of a DDoS or something. The significance of 10am EST could be either uptime-related (all these have gone down after 2-3 days) or just due to the to-be-expected early morning spike in mail flow.

Quoted 136 lines · Mark Moseley

Quoted 74 lines · Mark Moseley

Quoted 47 lines · Simon Kirby

Quoted 29 lines · Mark Moseley

Quoted 14 lines · Simon Kirby

I've noticed nfs_inode_cache is ever-increasing as well with 2.6.37:

?OBJS ACTIVE ?USE OBJ SIZE ?SLABS OBJ/SLAB CACHE SIZE NAME 2562514 2541520 ?99% ? ?0.95K ?78739 ? ? ? 33 ? 2519648K nfs_inode_cache 467200 285110 ?61% ? ?0.02K ? 1825 ? ? ?256 ? ? ?7300K kmalloc-16 299397 242350 ?80% ? ?0.19K ?14257 ? ? ? 21 ? ? 57028K dentry 217434 131978 ?60% ? ?0.55K ? 7767 ? ? ? 28 ? ?124272K radix_tree_node 215232 ?81522 ?37% ? ?0.06K ? 3363 ? ? ? 64 ? ? 13452K kmalloc-64 183027 136802 ?74% ? ?0.10K ? 4693 ? ? ? 39 ? ? 18772K buffer_head 101120 ?71184 ?70% ? ?0.03K ? ?790 ? ? ?128 ? ? ?3160K kmalloc-32 ?79616 ?59713 ?75% ? ?0.12K ? 2488 ? ? ? 32 ? ? ?9952K kmalloc-128 ?66560 ?41257 ?61% ? ?0.01K ? ?130 ? ? ?512 ? ? ? 520K kmalloc-8 ?42126 ?26650 ?63% ? ?0.75K ? 2006 ? ? ? 21 ? ? 32096K ext3_inode_cache

Quoted 6 lines

http://0x.ca/sim/ref/2.6.37/inodes_nfs.png
http://0x.ca/sim/ref/2.6.37/cpu2_nfs.png

Perhaps I could bisect just fs/nfs changes between 2.6.35 and 2.6.36 to try to track this down without having to wait too long, unless somebody can see what is happening here.

I'll get started bisecting too, since this is something of a show-stopper. Boxes that pre-2.6.36 would stay up for months at a time now have to be powercycled every couple of days (which is about how long it takes for this behavior to show up). This is across-the-board for about 50 boxes, ranging from 2.6.36 to 2.6.36.2.

Quoted 5 lines

Simon: It's probably irrelevant since these are kernel threads, but I'm curious what distro your boxes are running. Ours are Debian Lenny, i386, Dell Poweredge 850s. Just trying to figure out any commonalities. I'll get my boxes back on 2.6.36.2 and start watching nfs_inode_cache as well.

Same distro, x86_64, similar servers.

I'm not sure if the two cases I am seeing are exactly the same problem, but on the log crunching boxes, system time seems proportional to nfs_inode_cache and nfs_inode_cache just keeps growing forever; however, if I stop the load and unmount the NFS mount points, all of the nfs_inode_cache objects do actually go away (after umount finishes).

It seems the shrinker callback might not be working as intended here.

Quoted 7 lines

On the shared server case, the crazy spinlock contention from all of the flusher processes happens suddenly and overloads the boxes for 10-15 minutes, and then everything recovers.  Over 21 of these boxes, they each have about 500k-700k nfs_inode_cache objects.  The log cruncher hit 3.3 million nfs_inode_cache objects before I unmounted.

Are your boxes repeating this behaviour at any predictable interval?

Simon:
My boxes definitely fall into the latter category, with spinlock regularly sitting at 60-80% CPU (according to 'perf top'). As far as predictability, not strictly, but it's typically after an uptime of 2-3 days. They take so long to get into this state that I've never seen the actual transition in person, just the after-effects of flush-0:xx gone crazy. These boxes have a number of other NFS mounts, but it's on the flush-0:xx's for the heavily written-to NFS mounts that are spinning wildly, which you'd expect to be the case. The infrequently written-to NFS servers' flush-0:xx isn't to be found in 'top' output.

I'd booted into older kernels after my initial reply, so I'm 14 hrs into booting a box back into 2.6.36.2 and another box into a double-bisected 2.6.35-2.6.36 kernel (my first bisect hit compile errors). Both are running normally but that fits with the pattern so far.

Quoted 4 lines

NFS Guys:
Anything else we can be digging up to help debug this? This is a pretty ugly issue.

NOTE: NFS/Kernel guys: I've left the 2.6.36.2 box still thrashing about in case there's something you'd like me to look at.

Ok, both my 2.6.36.2 kernel box and my 2.6.35->2.6.36 bisect box (was bisected to ce7db282a3830f57f5b05ec48288c23a5c4d66d5 -- this is my first time doing bisect, so I'll preemptively apologize for doing anything silly) both went berserk within 15 mins of each other, after an uptime of around 63 hours for 2.6.36.2 and 65 hours for the bisected box. The 2.6.36.2 one is still running with all the various flush-0:xx threads spinning wildly. The bisected box just keeled over and died, but is back up now. The only kernel messages logged are just of the "task kworker/4:1:359 blocked for more than 120 seconds" variety, all with _raw_spin_lock_irq at the top of the stack trace.

Looking at slabinfo, specifically, this: stats=$(grep nfs_inode_cache /proc/slabinfo | awk '{ print $2, $3 }')
the active_objs and num_objs both increase to over a million (these boxes are delivering mail to NFS-mounted mailboxes, so that's perfectly reasonable). On both boxes, looking at sar, things start to go awry around 10am today EST. At that time on the 2.6.36.2 box, the NFS numbers look like this:

Fri Jan  7 09:58:00 2011: 1079433 1079650
Fri Jan  7 09:59:00 2011: 1079632 1080300
Fri Jan  7 10:00:00 2011: 1080196 1080300
Fri Jan  7 10:01:01 2011: 1080599 1080716
Fri Jan  7 10:02:01 2011: 1081074 1081288

on the bisected, like this:

Fri Jan  7 09:59:34 2011: 1162786 1165320
Fri Jan  7 10:00:34 2011: 1163301 1165320
Fri Jan  7 10:01:34 2011: 1164369 1165450
Fri Jan  7 10:02:35 2011: 1164179 1165450
Fri Jan  7 10:03:35 2011: 1165795 1166958

When the bisected box finally died, the last numbers were:

Fri Jan  7 10:40:33 2011: 1177156 1177202
Fri Jan  7 10:42:21 2011: 1177157 1177306
Fri Jan  7 10:44:55 2011: 1177201 1177324
Fri Jan  7 10:45:55 2011: 1177746 1177826

On the still-thrashing 2.6.36.2 box, the highwater mark is:

Fri Jan  7 10:23:30 2011: 1084020 1084070

and once things went awry, the active_objs started falling away and the number_objs has stayed at 1084070. Last numbers were:

Fri Jan  7 12:19:34 2011: 826623 1084070

The bisected box had reached 1mil entries (or more significantly 1048576 entries) by y'day evening. The 2.6.36.2 box hit that by 7am EST today. So in neither case was there a big spike in entries.

Quoted 6 lines

These boxes have identical workloads. They're not accessible from the net, so there's no chance of a DDoS or something. The significance of 10am EST could be either uptime-related (all these have gone down after 2-3 days) or just due to the to-be-expected early morning spike in mail flow.

Actually, I shouldn't say 'perfectly reasonable'. On other boxes in that pool, doing the same workload (but running 2.6.32.27), the number is more like:

117196 120756

after 9 days of uptime. So maybe 8 x that  isn't quite reasonable after only 2.5 days of uptime.

NOTE: NFS/Kernel guys: I've left the 2.6.36.2 box still thrashing about in case there's something you'd like me to look at.

Ok, both my 2.6.36.2 kernel box and my 2.6.35->2.6.36 bisect box (was bisected to ce7db282a3830f57f5b05ec48288c23a5c4d66d5 -- this is my first time doing bisect, so I'll preemptively apologize for doing

anything silly) both went berserk within 15 mins of each other, after an uptime of around 63 hours for 2.6.36.2 and 65 hours for the bisected box. The 2.6.36.2 one is still running with all the various flush-0:xx threads spinning wildly. The bisected box just keeled over and died, but is back up now. The only kernel messages logged are just of the "task kworker/4:1:359 blocked for more than 120 seconds" variety, all with _raw_spin_lock_irq at the top of the stack trace.

Looking at slabinfo, specifically, this: stats=$(grep nfs_inode_cache /proc/slabinfo | awk '{ print $2, $3 }')
the active_objs and num_objs both increase to over a million (these boxes are delivering mail to NFS-mounted mailboxes, so that's perfectly reasonable). On both boxes, looking at sar, things start to go awry around 10am today EST. At that time on the 2.6.36.2 box, the NFS numbers look like this:

Fri Jan  7 09:58:00 2011: 1079433 1079650
Fri Jan  7 09:59:00 2011: 1079632 1080300
Fri Jan  7 10:00:00 2011: 1080196 1080300
Fri Jan  7 10:01:01 2011: 1080599 1080716
Fri Jan  7 10:02:01 2011: 1081074 1081288

on the bisected, like this:

Fri Jan  7 09:59:34 2011: 1162786 1165320
Fri Jan  7 10:00:34 2011: 1163301 1165320
Fri Jan  7 10:01:34 2011: 1164369 1165450
Fri Jan  7 10:02:35 2011: 1164179 1165450
Fri Jan  7 10:03:35 2011: 1165795 1166958

When the bisected box finally died, the last numbers were:

Fri Jan  7 10:40:33 2011: 1177156 1177202
Fri Jan  7 10:42:21 2011: 1177157 1177306
Fri Jan  7 10:44:55 2011: 1177201 1177324
Fri Jan  7 10:45:55 2011: 1177746 1177826

Quoted 3 lines · Mark Moseley

NOTE: NFS/Kernel guys: I've left the 2.6.36.2 box still thrashing about in case there's something you'd like me to look at.

Quoted 3 lines

Ok, both my 2.6.36.2 kernel box and my 2.6.35->2.6.36 bisect box (was bisected to ce7db282a3830f57f5b05ec48288c23a5c4d66d5 -- this is my first time doing bisect, so I'll preemptively apologize for doing

That's a merge commit, so that doesn't sound right (it doesn't contain changes by itself).  How were you running the bisect?  Were you definitely seeing a good case since v2.6.35?  Could you post your "git bisect log" so I can see if I can follow it?

Yeah, I was seeing load proportional to these, but I don't think their growth is anything wrong.  It just seems to be something that is taking up CPU from flush proceses as they grow, and something which is causing a thundering herd of reclaim with lots of spinlock contention.

Hmmm.. I tried to see if drop_caches would clear nfs_inode_cache and thus the CPU usage.  The top of slabtop before doing anything:

 OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME 1256343 1221799  97%    0.95K  38071       33   1218272K nfs_inode_cache

# echo 2 > /proc/sys/vm/drop_caches

this took about 40 seconds to execute, and perf top showed this for pretty much the whole time:

            samples  pcnt function                 DSO _______ _____ ________________________ ___________

            1188.00 45.1% _raw_spin_lock           [kernel] 797.00 30.2% rpcauth_cache_shrinker   [kernel] 132.00  5.0% shrink_slab              [kernel] 60.00  2.3% queue_io                 [kernel] 59.00  2.2% _cond_resched            [kernel] 44.00  1.7% nfs_writepages           [kernel] 35.00  1.3% writeback_single_inode   [kernel] 34.00  1.3% writeback_sb_inodes      [kernel] 23.00  0.9% do_writepages            [kernel] 20.00  0.8% bit_waitqueue            [kernel] 15.00  0.6% redirty_tail             [kernel] 11.00  0.4% __iget                   [kernel] 11.00  0.4% __GI_strstr              libc-2.7.so

slabtop then showed:

 OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME 1256211 531720  42%    0.95K  38067       33   1218144K nfs_inode_cache

and this doesn't change further with drop_caches=3 or 1.  It's strange that most of them were freed, but not all...  We do actually have RPC_CREDCACHE_DEFAULT_HASHBITS set to 10 at build time, which might explain a bigger credcache and time to free that.  Did you change your auth_hashtable_size at all?  Anyway, even with all of that, system CPU doesn't change.

Ok, weird, Running "sync" actually caused "vmstat 1" to go from 25% CPU spikes every 5 seconds with nfs_writepages in the "perf top" every 5 seconds to being idle!  /proc/vmstat showed only nr_dirty 8 and nr_writeback 0 before I ran "sync".  Either that, or it was just good timing.

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa 0  0      0 6767892   9696  41088    0    0     5   180   15   70 62  7 29  1 0  0      0 6767892   9696  41088    0    0     0     0 1124 1978  0  0 100  0 0  0      0 6767892   9696  41088    0    0     0     0 1105 1967  0  0 100  0 0  0      0 6767892   9696  41088    0    0     0     0 1180 1984  0  2 98  0 2  0      0 6767892   9696  41088    0    0     0     0 2102 1968  0 22 78  0 0  0      0 6767768   9704  41084    0    0     0    52 1504 2022  0  8 91  1 0  0      0 6767768   9704  41084    0    0     0     0 1059 1965  0  0 100  0 0  0      0 6767768   9704  41088    0    0     0     0 1077 1982  0  0 100  0 0  0      0 6767768   9704  41088    0    0     0     0 1166 1972  1  2 97  0 0  0      0 6767768   9704  41088    0    0     0     0 1353 1990  0  6 94  0 0  0      0 6767644   9704  41100    0    0     0     0 2531 2050  0 27 72  0 0  0      0 6767644   9704  41100    0    0     0     0 1065 1974  0  0 100  0 1  0      0 6767644   9704  41100    0    0     0     0 1090 1967  0  0 100  0 0  0      0 6767644   9704  41100    0    0     0     0 1175 1971  0  2 98  0 0  0      0 6767644   9704  41100    0    0     0     0 1321 1967  0  6 94  0 1  0      0 6767644   9712  41100    0    0     0    52 1995 1995  0 18 81  1 0  0      0 6767644   9712  41100    0    0     0     0 1342 1964  0  6 94  0 0  0      0 6767644   9712  41100    0    0     0     0 1064 1974  0  0 100  0 0  0      0 6767644   9712  41100    0    0     0     0 1163 1968  0  2 98  0 0  0      0 6767644   9712  41100    0    0     0     0 1390 1976  1  6 94  0 0  0      0 6767768   9712  41112    0    0     0     0 1282 2018  0  1 99  0 0  0      0 6767768   9712  41112    0    0     0     0 2166 1972  0 24 76  0 0  0      0 6786260   9712  41112    0    0     0     0 1092 1989  0  0 100  0 0  0      0 6786260   9712  41112    0    0     0     0 1039 2003  0  2 98  0 0  0      0 6774588   9712  41112    0    0     0     0 1524 2015  3  9 89  0 0  1      0 6770124   9716  41112    0    0     0    48 1315 1990  3  0 87 11 1  0      0 6769628   9720  41112    0    0     0     4 2196 1966  0 20 79  0 0  0      0 6768364   9724  41108    0    0    36     0 1403 2031  1  5 94  1 0  0      0 6768388   9724  41144    0    0     0     0 1185 1969  0  2 98  0 0  0      0 6768388   9724  41144    0    0     0     0 1351 1975  0  6 94  0 0  0      0 6768140   9724  41156    0    0     0     0 1261 2020  0  1 99  0 0  0      0 6768140   9724  41156    0    0     0     0 1053 1973  0  0 100  0 1  0      0 6768140   9724  41156    0    0     0     0 2194 1971  1 26 73  0 0  0      0 6768140   9732  41148    0    0     0    52 1283 2088  0  4 96  0 2  0      0 6768140   9732  41156    0    0     0     0 1184 1965  0  2 98  0 0  0      0 6786368   9732  41156    0    0     0     0 1297 2000  0  4 97  0 0  0      0 6786384   9732  41156    0    0     0     0  998 1949  0  0 100  0 (stop vmstat 1, run sync, restart vmstat 1)
 1  0      0 6765304   9868  41736    0    0     0     0 1239 1967  0  0 100  0 0  0      0 6765304   9868  41736    0    0     0     0 1174 2035  0  0 100  0 0  0      0 6765304   9868  41736    0    0     0     0 1084 1976  0  0 100  0 1  0      0 6765172   9868  41736    0    0     0     0 1100 1975  0  0 100  0 0  0      0 6765304   9868  41760    0    0     0     0 1501 1997  1  1 98  0 0  0      0 6765304   9868  41760    0    0     0     0 1092 1964  0  0 100  0 1  0      0 6765304   9868  41760    0    0     0     0 1096 1963  0  0 100  0 0  0      0 6765304   9868  41760    0    0     0     0 1083 1967  0  0 100  0 0  0      0 6765304   9876  41752    0    0     0    76 1101 1980  0  0 99  1 0  0      0 6765304   9876  41760    0    0     0     4 1199 2097  0  2 98  0 0  0      0 6765304   9876  41760    0    0     0     0 1055 1964  0  0 100  0 0  0      0 6765304   9876  41760    0    0     0     0 1064 1977  0  0 100  0 0  0      0 6765304   9876  41760    0    0     0     0 1073 1968  0  0 100  0 0  0      0 6765304   9876  41760    0    0     0     0 1080 1976  0  0 100  0 0  0      0 6765156   9884  41772    0    0     0    20 1329 2034  1  1 98  1 0  0      0 6765180   9884  41780    0    0     0     0 1097 1971  0  1 99  0 0  0      0 6765180   9884  41780    0    0     0     0 1073 1960  0  0 100  0 0  0      0 6765180   9884  41780    0    0     0     0 1079 1976  0  0 100  0 0  0      0 6765172   9884  41780    0    0     0     0 1120 1980  0  0 100  0 0  0      0 6765180   9892  41772    0    0     0    60 1097 1982  0  0 100  0 0  0      0 6765180   9892  41780    0    0     0     0 1067 1969  0  0 100  0 0  0      0 6765180   9892  41780    0    0     0     0 1063 1973  0  0 100  0 0  0      0 6765180   9892  41780    0    0     0     0 1064 1969  0  1 100  0

Hmmm.  I'll watch it and see if it climbs back up again.  That would mean that for now, echo 2 > /proc/sys/vm/drop_caches ; sync is a workaround for the problem we're seeing with system CPU slowly creeping up since 2.6.36.  I have no idea if this affects the sudden flush process spinlock contention and attempted writeback without much progress during normal load, but it certainly changes things here.

http://0x.ca/sim/ref/2.6.37/cpu_after_drop_caches_2_and_sync.png