On 2008/10/22 11:12, Max Kellermann <max@xxxxxxxxxxx> wrote:
> after I was able to fix http://lkml.org/lkml/2008/10/17/147, the
> server which was already upgraded to 2.6.27.2 still gets very high
> load. It is a web server with NFS file storage (NetApp), and while
> the others in the cluster (kernel 2.6.25) have a load of 1-3, 2.6.27.2
> gets 30-50.
>
> I did an oprofile, with the following results (server just started,
> load "only" 5-10):
>
> 87593 56.1116 (no location information) vmlinux
> vmlinux rpcauth_lookup_credcache
> 16037 10.2732 auth_generic.c:0 vmlinux
> vmlinux generic_match
> 6460 4.1382 (no location information) php4
> php4 (no symbols)
> 2478 1.5874 (no location information) libc-2.7.so
> libc-2.7.so (no symbols)
> [...]
>
> We havn't configured any special authentication method. It is a NFSv3
> over UDP mount, but the kernel has NFSv4 and therefore KRB5 enabled.
>
> Any ideas why rpcauth_lookup_credcache() goes overboard with CPU
> usage?
I have bisected the problem: 98a8e323 is the result ("SUNRPC: Add a
helper rpcauth_lookup_generic_cred()"). 5c691044 is ok.
See the attached oprofile annotation data for both commits. I guess
that the function rpcauth_lookup_credcache() is waiting for a spinlock
too often and too long. Trond, any idea?
Harry: added you to Cc because your problem sounds similar.
Max
/*
* Command line: opannotate -a -i rpcauth_lookup_credcache vmlinux
*
* Interpretation of command line:
* Output annotated assembly listing with samples
*
* CPU: P4 / Xeon with 2 hyper-threads, speed 2400 MHz (estimated)
* Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped) with a unit mask of 0x01 (mandatory) count 100000
*/
:
:/root/vmlinux: file format elf32-i386
:
:Disassembly of section .text.head:
:Disassembly of section .text:
:
c03f7074 <rpcauth_lookup_credcache>: /* rpcauth_lookup_credcache total: 905790 100.000 */
1525 0.1684 :c03f7074: push %ebp
140 0.0155 :c03f7075: mov %esp,%ebp
22 0.0024 :c03f7077: push %edi
81 0.0089 :c03f7078: push %esi
52 0.0057 :c03f7079: push %ebx
38 0.0042 :c03f707a: sub $0x1c,%esp
:c03f707d: mov %eax,0xffffffe0(%ebp)
156 0.0172 :c03f7080: mov %edx,0xffffffdc(%ebp)
67 0.0074 :c03f7083: mov %ecx,0xffffffd8(%ebp)
5 5.5e-04 :c03f7086: lea 0xffffffec(%ebp),%eax
21 0.0023 :c03f7089: mov %eax,0xffffffec(%ebp)
75 0.0083 :c03f708c: mov %eax,0xfffffff0(%ebp)
16 0.0018 :c03f708f: mov 0xffffffe0(%ebp),%eax
60 0.0066 :c03f7092: mov 0x1c(%eax),%eax
101 0.0112 :c03f7095: mov %eax,0xffffffe4(%ebp)
12 0.0013 :c03f7098: imul $0x9e370001,(%edx),%edx
273 0.0301 :c03f709e: shr $0x1c,%edx
38 0.0042 :c03f70a1: mov %edx,0xffffffe8(%ebp)
64 0.0071 :c03f70a4: mov (%eax,%edx,4),%esi
1254 0.1384 :c03f70a7: jmp c03f70ca <rpcauth_lookup_credcache+0x56>
620 0.0684 :c03f70a9: mov 0xffffffe4(%ebp),%eax
132 0.0146 :c03f70ac: add $0x40,%eax
20 0.0022 :c03f70af: call c0435d3e <_spin_lock>
4039 0.4459 :c03f70b4: testb $0x4,0x28(%esi)
34 0.0038 :c03f70b8: jne c03f70c2 <rpcauth_lookup_credcache+0x4e>
:c03f70ba: mov 0xffffffe4(%ebp),%ecx
:c03f70bd: incb 0x40(%ecx)
:c03f70c0: jmp c03f70c8 <rpcauth_lookup_credcache+0x54>
44 0.0049 :c03f70c2: lock incl 0x2c(%esi)
3854 0.4255 :c03f70c6: jmp c03f7147 <rpcauth_lookup_credcache+0xd3>
11816 1.3045 :c03f70c8: mov (%esi),%esi
5214 0.5756 :c03f70ca: test %esi,%esi
1082 0.1195 :c03f70cc: je c03f719e <rpcauth_lookup_credcache+0x12a>
22189 2.4497 :c03f70d2: mov (%esi),%eax
702721 77.5810 :c03f70d4: (bad)
:c03f70d6: inc %eax
43523 4.8050 :c03f70d7: add %cl,0x4d8b1c5e(%ebx)
:c03f70dd: fmuls 0xdc458bf2(%ecx)
3752 0.4142 :c03f70e3: call *0xc(%ebx)
22791 2.5161 :c03f70e6: test %eax,%eax
10130 1.1184 :c03f70e8: je c03f70c8 <rpcauth_lookup_credcache+0x54>
217 0.0240 :c03f70ea: jmp c03f70a9 <rpcauth_lookup_credcache+0x35>
:c03f70ec: mov 0xffffffe4(%ebp),%eax
:c03f70ef: add $0x40,%eax
:c03f70f2: call c0435d3e <_spin_lock>
4 4.4e-04 :c03f70f7: mov 0xffffffe8(%ebp),%edx
:c03f70fa: mov 0xffffffe4(%ebp),%ecx
:c03f70fd: mov (%ecx,%edx,4),%esi
:c03f7100: jmp c03f711e <rpcauth_lookup_credcache+0xaa>
:c03f7102: lock incl 0x2c(%esi)
:c03f7106: mov 0xfffffff0(%ebp),%ecx
:c03f7109: lea 0x8(%edi),%edx
:c03f710c: mov %edx,0xfffffff0(%ebp)
:c03f710f: lea 0xffffffec(%ebp),%eax
:c03f7112: mov %eax,0x8(%edi)
:c03f7115: mov %ecx,0x4(%edx)
:c03f7118: mov %edx,(%ecx)
:c03f711a: jmp c03f7147 <rpcauth_lookup_credcache+0xd3>
20 0.0022 :c03f711c: mov (%esi),%esi
:c03f711e: test %esi,%esi
:c03f7120: je c03f71c0 <rpcauth_lookup_credcache+0x14c>
19 0.0021 :c03f7126: mov (%esi),%eax
1279 0.1412 :c03f7128: (bad)
:c03f712a: inc %eax
59 0.0065 :c03f712b: add %cl,0x4d8b1c5e(%ebx)
:c03f7131: fmuls 0xdc458bf2(%ecx)
3 3.3e-04 :c03f7137: call *0xc(%ebx)
22 0.0024 :c03f713a: test %eax,%eax
18 0.0020 :c03f713c: je c03f711c <rpcauth_lookup_credcache+0xa8>
:c03f713e: jmp c03f7102 <rpcauth_lookup_credcache+0x8e>
:c03f7140: mov %edi,0x4(%eax)
:c03f7143: mov %edi,(%edx)
:c03f7145: mov %edi,%esi
14 0.0015 :c03f7147: mov 0xffffffe4(%ebp),%eax
11 0.0012 :c03f714a: incb 0x40(%eax)
76 0.0084 :c03f714d: testb $0x1,0x28(%esi)
109 0.0120 :c03f7151: je c03f7192 <rpcauth_lookup_credcache+0x11e>
:c03f7153: mov 0x1c(%esi),%eax
:c03f7156: mov 0x4(%eax),%ecx
:c03f7159: test %ecx,%ecx
:c03f715b: je c03f7192 <rpcauth_lookup_credcache+0x11e>
:c03f715d: testb $0x1,0xffffffd8(%ebp)
:c03f7161: jne c03f7192 <rpcauth_lookup_credcache+0x11e>
:c03f7163: mov %esi,%edx
:c03f7165: mov 0xffffffe0(%ebp),%eax
:c03f7168: call *%ecx
:c03f716a: mov %eax,%ebx
:c03f716c: test %eax,%eax
:c03f716e: jns c03f7192 <rpcauth_lookup_credcache+0x11e>
:c03f7170: mov %esi,%eax
:c03f7172: call c03f6caa <put_rpccred>
:c03f7177: mov %ebx,%esi
:c03f7179: jmp c03f7192 <rpcauth_lookup_credcache+0x11e>
:c03f717b: lea 0xfffffff8(%ebx),%eax
:c03f717e: mov (%ebx),%ecx
:c03f7180: mov 0x4(%ebx),%edx
:c03f7183: mov %edx,0x4(%ecx)
:c03f7186: mov %ecx,(%edx)
:c03f7188: mov %ebx,(%ebx)
:c03f718a: mov %ebx,0x4(%ebx)
:c03f718d: call c03f6caa <put_rpccred>
100 0.0110 :c03f7192: mov 0xffffffec(%ebp),%ebx
45 0.0050 :c03f7195: lea 0xffffffec(%ebp),%eax
5 5.5e-04 :c03f7198: cmp %eax,%ebx
49 0.0054 :c03f719a: jne c03f717b <rpcauth_lookup_credcache+0x107>
29 0.0032 :c03f719c: jmp c03f71e3 <rpcauth_lookup_credcache+0x16f>
1 1.1e-04 :c03f719e: mov 0xffffffe0(%ebp),%edx
:c03f71a1: mov 0x10(%edx),%ebx
2 2.2e-04 :c03f71a4: mov 0xffffffd8(%ebp),%ecx
:c03f71a7: mov 0xffffffdc(%ebp),%edx
:c03f71aa: mov 0xffffffe0(%ebp),%eax
:c03f71ad: call *0x18(%ebx)
:c03f71b0: mov %eax,%edi
:c03f71b2: mov %eax,%esi
:c03f71b4: cmp $0xfffff000,%eax
:c03f71b9: ja c03f71e3 <rpcauth_lookup_credcache+0x16f>
:c03f71bb: jmp c03f70ec <rpcauth_lookup_credcache+0x78>
:c03f71c0: lock btsl $0x2,0x28(%edi)
1 1.1e-04 :c03f71c6: mov 0xffffffe8(%ebp),%ecx
:c03f71c9: mov 0xffffffe4(%ebp),%eax
:c03f71cc: lea (%eax,%ecx,4),%edx
:c03f71cf: mov (%edx),%eax
:c03f71d1: mov %eax,(%edi)
:c03f71d3: mov %edx,0x4(%edi)
:c03f71d6: test %eax,%eax
:c03f71d8: jne c03f7140 <rpcauth_lookup_credcache+0xcc>
:c03f71de: jmp c03f7143 <rpcauth_lookup_credcache+0xcf>
58 0.0064 :c03f71e3: mov %esi,%eax
17 0.0019 :c03f71e5: add $0x1c,%esp
13 0.0014 :c03f71e8: pop %ebx
45 0.0050 :c03f71e9: pop %esi
17 0.0019 :c03f71ea: pop %edi
5 5.5e-04 :c03f71eb: pop %ebp
38 0.0042 :c03f71ec: ret
:Disassembly of section .init.text:
:Disassembly of section .altinstr_replacement:
:Disassembly of section .exit.text:
/*
* Command line: opannotate -a -i rpcauth_lookup_credcache vmlinux
*
* Interpretation of command line:
* Output annotated assembly listing with samples
*
* CPU: P4 / Xeon with 2 hyper-threads, speed 2400 MHz (estimated)
* Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped) with a unit mask of 0x01 (mandatory) count 100000
*/
:
:/root/vmlinux: file format elf32-i386
:
:Disassembly of section .text.head:
:Disassembly of section .text:
:
c03f7104 <rpcauth_lookup_credcache>: /* rpcauth_lookup_credcache total: 435 100.000 */
21 4.8276 :c03f7104: push %ebp
2 0.4598 :c03f7105: mov %esp,%ebp
:c03f7107: push %edi
:c03f7108: push %esi
1 0.2299 :c03f7109: push %ebx
:c03f710a: sub $0x1c,%esp
:c03f710d: mov %eax,0xffffffe0(%ebp)
1 0.2299 :c03f7110: mov %edx,0xffffffdc(%ebp)
:c03f7113: mov %ecx,0xffffffd8(%ebp)
:c03f7116: lea 0xffffffec(%ebp),%eax
1 0.2299 :c03f7119: mov %eax,0xffffffec(%ebp)
2 0.4598 :c03f711c: mov %eax,0xfffffff0(%ebp)
:c03f711f: mov 0xffffffe0(%ebp),%eax
3 0.6897 :c03f7122: mov 0x1c(%eax),%eax
3 0.6897 :c03f7125: mov %eax,0xffffffe4(%ebp)
:c03f7128: imul $0x9e370001,(%edx),%edx
4 0.9195 :c03f712e: shr $0x1c,%edx
2 0.4598 :c03f7131: mov %edx,0xffffffe8(%ebp)
2 0.4598 :c03f7134: mov (%eax,%edx,4),%esi
39 8.9655 :c03f7137: jmp c03f715a <rpcauth_lookup_credcache+0x56>
10 2.2989 :c03f7139: mov 0xffffffe4(%ebp),%eax
1 0.2299 :c03f713c: add $0x40,%eax
1 0.2299 :c03f713f: call c0435dce <_spin_lock>
134 30.8046 :c03f7144: testb $0x4,0x28(%esi)
2 0.4598 :c03f7148: jne c03f7152 <rpcauth_lookup_credcache+0x4e>
:c03f714a: mov 0xffffffe4(%ebp),%ecx
:c03f714d: incb 0x40(%ecx)
:c03f7150: jmp c03f7158 <rpcauth_lookup_credcache+0x54>
3 0.6897 :c03f7152: lock incl 0x2c(%esi)
110 25.2874 :c03f7156: jmp c03f71d7 <rpcauth_lookup_credcache+0xd3>
2 0.4598 :c03f7158: mov (%esi),%esi
6 1.3793 :c03f715a: test %esi,%esi
:c03f715c: je c03f722e <rpcauth_lookup_credcache+0x12a>
:c03f7162: mov (%esi),%eax
43 9.8851 :c03f7164: (bad)
:c03f7166: inc %eax
10 2.2989 :c03f7167: add %cl,0x4d8b1c5e(%ebx)
:c03f716d: fmuls 0xdc458bf2(%ecx)
:c03f7173: call *0xc(%ebx)
4 0.9195 :c03f7176: test %eax,%eax
6 1.3793 :c03f7178: je c03f7158 <rpcauth_lookup_credcache+0x54>
2 0.4598 :c03f717a: jmp c03f7139 <rpcauth_lookup_credcache+0x35>
:c03f717c: mov 0xffffffe4(%ebp),%eax
:c03f717f: add $0x40,%eax
:c03f7182: call c0435dce <_spin_lock>
:c03f7187: mov 0xffffffe8(%ebp),%edx
:c03f718a: mov 0xffffffe4(%ebp),%ecx
:c03f718d: mov (%ecx,%edx,4),%esi
:c03f7190: jmp c03f71ae <rpcauth_lookup_credcache+0xaa>
:c03f7192: lock incl 0x2c(%esi)
:c03f7196: mov 0xfffffff0(%ebp),%ecx
:c03f7199: lea 0x8(%edi),%edx
:c03f719c: mov %edx,0xfffffff0(%ebp)
:c03f719f: lea 0xffffffec(%ebp),%eax
:c03f71a2: mov %eax,0x8(%edi)
:c03f71a5: mov %ecx,0x4(%edx)
:c03f71a8: mov %edx,(%ecx)
:c03f71aa: jmp c03f71d7 <rpcauth_lookup_credcache+0xd3>
:c03f71ac: mov (%esi),%esi
:c03f71ae: test %esi,%esi
:c03f71b0: je c03f7250 <rpcauth_lookup_credcache+0x14c>
:c03f71b6: mov (%esi),%eax
:c03f71b8: (bad)
:c03f71ba: inc %eax
:c03f71bb: add %cl,0x4d8b1c5e(%ebx)
:c03f71c1: fmuls 0xdc458bf2(%ecx)
:c03f71c7: call *0xc(%ebx)
:c03f71ca: test %eax,%eax
:c03f71cc: je c03f71ac <rpcauth_lookup_credcache+0xa8>
:c03f71ce: jmp c03f7192 <rpcauth_lookup_credcache+0x8e>
:c03f71d0: mov %edi,0x4(%eax)
:c03f71d3: mov %edi,(%edx)
:c03f71d5: mov %edi,%esi
:c03f71d7: mov 0xffffffe4(%ebp),%eax
1 0.2299 :c03f71da: incb 0x40(%eax)
1 0.2299 :c03f71dd: testb $0x1,0x28(%esi)
2 0.4598 :c03f71e1: je c03f7222 <rpcauth_lookup_credcache+0x11e>
:c03f71e3: mov 0x1c(%esi),%eax
:c03f71e6: mov 0x4(%eax),%ecx
:c03f71e9: test %ecx,%ecx
:c03f71eb: je c03f7222 <rpcauth_lookup_credcache+0x11e>
:c03f71ed: testb $0x1,0xffffffd8(%ebp)
:c03f71f1: jne c03f7222 <rpcauth_lookup_credcache+0x11e>
:c03f71f3: mov %esi,%edx
:c03f71f5: mov 0xffffffe0(%ebp),%eax
:c03f71f8: call *%ecx
:c03f71fa: mov %eax,%ebx
:c03f71fc: test %eax,%eax
:c03f71fe: jns c03f7222 <rpcauth_lookup_credcache+0x11e>
:c03f7200: mov %esi,%eax
:c03f7202: call c03f6d3a <put_rpccred>
:c03f7207: mov %ebx,%esi
:c03f7209: jmp c03f7222 <rpcauth_lookup_credcache+0x11e>
:c03f720b: lea 0xfffffff8(%ebx),%eax
:c03f720e: mov (%ebx),%ecx
:c03f7210: mov 0x4(%ebx),%edx
:c03f7213: mov %edx,0x4(%ecx)
:c03f7216: mov %ecx,(%edx)
:c03f7218: mov %ebx,(%ebx)
:c03f721a: mov %ebx,0x4(%ebx)
:c03f721d: call c03f6d3a <put_rpccred>
2 0.4598 :c03f7222: mov 0xffffffec(%ebp),%ebx
2 0.4598 :c03f7225: lea 0xffffffec(%ebp),%eax
:c03f7228: cmp %eax,%ebx
1 0.2299 :c03f722a: jne c03f720b <rpcauth_lookup_credcache+0x107>
3 0.6897 :c03f722c: jmp c03f7273 <rpcauth_lookup_credcache+0x16f>
:c03f722e: mov 0xffffffe0(%ebp),%edx
:c03f7231: mov 0x10(%edx),%ebx
:c03f7234: mov 0xffffffd8(%ebp),%ecx
:c03f7237: mov 0xffffffdc(%ebp),%edx
:c03f723a: mov 0xffffffe0(%ebp),%eax
:c03f723d: call *0x18(%ebx)
:c03f7240: mov %eax,%edi
:c03f7242: mov %eax,%esi
:c03f7244: cmp $0xfffff000,%eax
:c03f7249: ja c03f7273 <rpcauth_lookup_credcache+0x16f>
:c03f724b: jmp c03f717c <rpcauth_lookup_credcache+0x78>
:c03f7250: lock btsl $0x2,0x28(%edi)
:c03f7256: mov 0xffffffe8(%ebp),%ecx
:c03f7259: mov 0xffffffe4(%ebp),%eax
:c03f725c: lea (%eax,%ecx,4),%edx
:c03f725f: mov (%edx),%eax
:c03f7261: mov %eax,(%edi)
:c03f7263: mov %edx,0x4(%edi)
:c03f7266: test %eax,%eax
:c03f7268: jne c03f71d0 <rpcauth_lookup_credcache+0xcc>
:c03f726e: jmp c03f71d3 <rpcauth_lookup_credcache+0xcf>
4 0.9195 :c03f7273: mov %esi,%eax
:c03f7275: add $0x1c,%esp
:c03f7278: pop %ebx
1 0.2299 :c03f7279: pop %esi
1 0.2299 :c03f727a: pop %edi
:c03f727b: pop %ebp
:c03f727c: ret
:Disassembly of section .init.text:
:Disassembly of section .altinstr_replacement:
:Disassembly of section .exit.text:
