[Bug 557760] rpciod taking 100% of cpu, box *almost* unusable

http://bugzilla.novell.com/show_bug.cgi?id=557760 http://bugzilla.novell.com/show_bug.cgi?id=557760#c14 Jon Nelson <jnelson-suse@jamponi.net> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEEDINFO |ASSIGNED Info Provider|jnelson-suse@jamponi.net | --- Comment #14 from Jon Nelson <jnelson-suse@jamponi.net> 2009-12-16 15:03:37 UTC --- The hardware is an R8169. On boot, this is what ethtool has to say: frank:~ # ethtool -k eth1 Offload parameters for eth1: Cannot get device flags: Operation not supported rx-checksumming: on tx-checksumming: off scatter-gather: off tcp segmentation offload: off udp fragmentation offload: off generic segmentation offload: off large receive offload: off frank:~ # So I change it: frank:~ # ethtool -K eth1 rx off Don't forget the (non-NFS) TCP rates gathered in comment 10: Raw TCP sends from this box: 111303.89kB/s -- 109MB/s for blasting TCP from the client to the server as fast as they can each send/receive. I don't think it's the hardware. ;-) jnelson@frank:~> dd if=/dev/zero of=/multimedia/foo bs=1k count=100000 100000+0 records in 100000+0 records out 102400000 bytes (102 MB) copied, 61.5018 s, 1.7 MB/s jnelson@frank:~> The ethtool change made no difference. I tried a tg3. Same exact problem/performance/whatever. I enabled a bit of rpc debugging. What I see are *sets* of loglines like this: Dec 16 08:59:48 frank kernel: [ 943.207724] RPC: write space: waking waiting task on xprt ffff88002c11d000 Dec 16 08:59:48 frank kernel: [ 943.207746] RPC: 4543 xprt_prepare_transmit Dec 16 08:59:48 frank kernel: [ 943.207749] RPC: 4543 xprt_transmit(131252) Dec 16 08:59:48 frank kernel: [ 943.207762] RPC: 4543 xmit complete Dec 16 08:59:48 frank kernel: [ 943.207765] RPC: 4544 xprt_prepare_transmit Dec 16 08:59:48 frank kernel: [ 943.207769] RPC: 4544 xprt_transmit(131252) Dec 16 08:59:49 frank kernel: [ 943.330798] RPC: 4505 xid 934fea59 complete (132 bytes received) Dec 16 08:59:49 frank kernel: [ 943.330920] RPC: 4505 release request ffff880013524fc0 Dec 16 08:59:49 frank kernel: [ 943.330933] RPC: 4546 reserved req ffff880013524fc0 xid 9c4fea59 Dec 16 08:59:49 frank kernel: [ 943.330947] RPC: 4546 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.330952] RPC: 4546 failed to lock transport ffff88002c11d000 Dec 16 08:59:49 frank kernel: [ 943.375795] RPC: write space: waking waiting task on xprt ffff88002c11d000 Dec 16 08:59:49 frank kernel: [ 943.375841] RPC: 4544 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.375846] RPC: 4544 xprt_transmit(131252) Dec 16 08:59:49 frank kernel: [ 943.375860] RPC: 4544 xmit complete Dec 16 08:59:49 frank kernel: [ 943.375875] RPC: 4545 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.375882] RPC: 4545 xprt_transmit(131252) Dec 16 08:59:49 frank kernel: [ 943.513595] RPC: 4506 xid 944fea59 complete (132 bytes received) Dec 16 08:59:49 frank kernel: [ 943.513727] RPC: 4506 release request ffff880013524e70 Dec 16 08:59:49 frank kernel: [ 943.513748] RPC: 4547 reserved req ffff880013524e70 xid 9d4fea59 Dec 16 08:59:49 frank kernel: [ 943.513754] RPC: 4547 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.513764] RPC: 4547 failed to lock transport ffff88002c11d000 Dec 16 08:59:49 frank kernel: [ 943.552714] RPC: write space: waking waiting task on xprt ffff88002c11d000 Dec 16 08:59:49 frank kernel: [ 943.552734] RPC: 4545 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.552737] RPC: 4545 xprt_transmit(131252) Dec 16 08:59:49 frank kernel: [ 943.552744] RPC: 4545 xmit complete Dec 16 08:59:49 frank kernel: [ 943.552754] RPC: 4546 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.552758] RPC: 4546 xprt_transmit(131252) Dec 16 08:59:49 frank kernel: [ 943.680157] RPC: 4507 xid 954fea59 complete (132 bytes received) Dec 16 08:59:49 frank kernel: [ 943.680247] RPC: 4507 release request ffff8800135247e0 Dec 16 08:59:49 frank kernel: [ 943.680265] RPC: 4548 reserved req ffff8800135247e0 xid 9e4fea59 Dec 16 08:59:49 frank kernel: [ 943.680270] RPC: 4548 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.680275] RPC: 4548 failed to lock transport ffff88002c11d000 Dec 16 08:59:49 frank kernel: [ 943.720442] RPC: write space: waking waiting task on xprt ffff88002c11d000 Dec 16 08:59:49 frank kernel: [ 943.720466] RPC: 4546 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.720469] RPC: 4546 xprt_transmit(131252) Dec 16 08:59:49 frank kernel: [ 943.720476] RPC: 4546 xmit complete Dec 16 08:59:49 frank kernel: [ 943.720485] RPC: 4547 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.720489] RPC: 4547 xprt_transmit(131252) Dec 16 08:59:49 frank kernel: [ 943.841025] RPC: 4508 xid 964fea59 complete (132 bytes received) Dec 16 08:59:49 frank kernel: [ 943.841216] RPC: 4508 release request ffff8800135242a0 Dec 16 08:59:49 frank kernel: [ 943.841229] RPC: 4549 reserved req ffff8800135242a0 xid 9f4fea59 Dec 16 08:59:49 frank kernel: [ 943.841243] RPC: 4549 xprt_prepare_transmit Dec 16 08:59:49 frank kernel: [ 943.841247] RPC: 4549 failed to lock transport ffff88002c11d000 when I set the rpc_debug level to 2: Dec 16 09:01:35 frank kernel: [ 1021.205749] RPC: 4681 call_status (status -11) Dec 16 09:01:35 frank kernel: [ 1021.205751] RPC: 4681 call_transmit (status 0) Dec 16 09:01:36 frank kernel: [ 1021.205754] RPC: 4681 rpc_xdr_encode (status 0) Dec 16 09:01:36 frank kernel: [ 1021.207315] RPC: 4675 call_status (status 132) Dec 16 09:01:36 frank kernel: [ 1021.207317] RPC: 4675 call_decode (status 132) Dec 16 09:01:36 frank kernel: [ 1021.207321] RPC: 4675 call_decode result 131072 Dec 16 09:01:36 frank kernel: [ 1021.207326] RPC: rpc_release_client(ffff88001a189e00) Dec 16 09:01:36 frank kernel: [ 1021.207337] RPC: 4691 call_reserveresult (status -11) Dec 16 09:01:36 frank kernel: [ 1021.207339] RPC: 4691 call_reserve (status 0) Dec 16 09:01:36 frank kernel: [ 1021.207341] RPC: 4691 call_reserveresult (status 0) Dec 16 09:01:36 frank kernel: [ 1021.207343] RPC: 4691 call_allocate (status 0) Dec 16 09:01:36 frank kernel: [ 1021.207345] RPC: 4691 call_bind (status 0) Dec 16 09:01:36 frank kernel: [ 1021.207347] RPC: 4691 call_connect xprt ffff88002c11d000 is connected Dec 16 09:01:36 frank kernel: [ 1021.207349] RPC: 4691 call_transmit (status 0) Dec 16 09:01:36 frank kernel: [ 1021.208135] RPC: 4681 call_status (status -11) Dec 16 09:01:36 frank kernel: [ 1021.208137] RPC: 4681 call_transmit (status 0) Dec 16 09:01:36 frank kernel: [ 1021.208152] RPC: 4682 call_status (status -11) Dec 16 09:01:36 frank kernel: [ 1021.208154] RPC: 4682 call_transmit (status 0) Dec 16 09:01:36 frank kernel: [ 1021.208165] RPC: 4682 rpc_xdr_encode (status 0) Dec 16 09:01:36 frank kernel: [ 1021.210237] RPC: 4676 call_status (status 132) Dec 16 09:01:36 frank kernel: [ 1021.210240] RPC: 4676 call_decode (status 132) Dec 16 09:01:36 frank kernel: [ 1021.210245] RPC: 4676 call_decode result 131072 Dec 16 09:01:36 frank kernel: [ 1021.210250] RPC: rpc_release_client(ffff88001a189e00) Dec 16 09:01:36 frank kernel: [ 1021.210256] RPC: 4682 call_status (status -11) Dec 16 09:01:36 frank kernel: [ 1021.210258] RPC: 4682 call_transmit (status 0) Dec 16 09:01:36 frank kernel: [ 1021.210272] RPC: 4692 call_reserveresult (status -11) Dec 16 09:01:36 frank kernel: [ 1021.210274] RPC: 4692 call_reserve (status 0) Dec 16 09:01:36 frank kernel: [ 1021.210276] RPC: 4692 call_reserveresult (status 0) Dec 16 09:01:36 frank kernel: [ 1021.210278] RPC: 4692 call_allocate (status 0) Dec 16 09:01:36 frank kernel: [ 1021.210280] RPC: 4692 call_bind (status 0) Dec 16 09:01:36 frank kernel: [ 1021.210282] RPC: 4692 call_connect xprt ffff88002c11d000 is connected Dec 16 09:01:36 frank kernel: [ 1021.210284] RPC: 4692 call_transmit (status 0) and when I really crank it up: Dec 16 09:03:15 frank kernel: [ 1054.434423] RPC: 5098 call_reserveresult (status -11) Dec 16 09:03:15 frank kernel: [ 1054.434427] RPC: 5098 call_reserve (status 0) Dec 16 09:03:15 frank kernel: [ 1054.434431] RPC: 5098 call_reserveresult (status 0) Dec 16 09:03:15 frank kernel: [ 1054.434435] RPC: 5098 call_allocate (status 0) Dec 16 09:03:15 frank kernel: [ 1054.434440] RPC: 5098 call_bind (status 0) Dec 16 09:03:15 frank kernel: [ 1054.434444] RPC: 5098 call_connect xprt ffff88002c11d000 is connected Dec 16 09:03:15 frank kernel: [ 1054.434448] RPC: 5098 call_transmit (status 0) Dec 16 09:03:15 frank kernel: [ 1054.434452] RPC: 5096 call_status (status -11) Dec 16 09:03:15 frank kernel: [ 1054.434456] RPC: 5096 call_transmit (status 0) Dec 16 09:03:15 frank kernel: [ 1054.434460] RPC: 5096 rpc_xdr_encode (status 0) Dec 16 09:03:15 frank kernel: [ 1054.437199] RPC: 5090 call_status (status 132) Dec 16 09:03:15 frank kernel: [ 1054.437204] RPC: 5090 call_decode (status 132) Dec 16 09:03:15 frank kernel: [ 1054.437210] RPC: 5090 call_decode result 131072 Dec 16 09:03:15 frank kernel: [ 1054.437219] RPC: rpc_release_client(ffff88001a189e00) Dec 16 09:03:15 frank kernel: [ 1054.437235] RPC: 5096 call_status (status -11) Dec 16 09:03:15 frank kernel: [ 1054.437239] RPC: 5096 call_transmit (status 0) Dec 16 09:03:15 frank kernel: [ 1054.437258] RPC: 5099 call_reserveresult (status -11) Dec 16 09:03:15 frank kernel: [ 1054.437262] RPC: 5099 call_reserve (status 0) Dec 16 09:03:15 frank kernel: [ 1054.437271] RPC: 5099 call_reserveresult (status 0) Dec 16 09:03:15 frank kernel: [ 1054.437275] RPC: 5099 call_allocate (status 0) Dec 16 09:03:15 frank kernel: [ 1054.437279] RPC: 5099 call_bind (status 0) Dec 16 09:03:15 frank kernel: [ 1054.437283] RPC: 5099 call_connect xprt ffff88002c11d000 is connected Dec 16 09:03:16 frank kernel: [ 1054.437294] RPC: 5099 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.437299] RPC: 5097 call_status (status -11) Dec 16 09:03:16 frank kernel: [ 1054.437303] RPC: 5097 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.437307] RPC: 5097 rpc_xdr_encode (status 0) Dec 16 09:03:16 frank kernel: [ 1054.439908] RPC: 5091 call_status (status 132) Dec 16 09:03:16 frank kernel: [ 1054.439912] RPC: 5091 call_decode (status 132) Dec 16 09:03:16 frank kernel: [ 1054.439919] RPC: 5091 call_decode result 131072 Dec 16 09:03:16 frank kernel: [ 1054.439927] RPC: rpc_release_client(ffff88001a189e00) Dec 16 09:03:16 frank kernel: [ 1054.439943] RPC: 5097 call_status (status -11) Dec 16 09:03:16 frank kernel: [ 1054.439947] RPC: 5097 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.439966] RPC: 5100 call_reserveresult (status -11) Dec 16 09:03:16 frank kernel: [ 1054.439970] RPC: 5100 call_reserve (status 0) Dec 16 09:03:16 frank kernel: [ 1054.439973] RPC: 5100 call_reserveresult (status 0) Dec 16 09:03:16 frank kernel: [ 1054.439982] RPC: 5100 call_allocate (status 0) Dec 16 09:03:16 frank kernel: [ 1054.439986] RPC: 5100 call_bind (status 0) Dec 16 09:03:16 frank kernel: [ 1054.439990] RPC: 5100 call_connect xprt ffff88002c11d000 is connected Dec 16 09:03:16 frank kernel: [ 1054.439995] RPC: 5100 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.440025] RPC: 5098 call_status (status -11) Dec 16 09:03:16 frank kernel: [ 1054.440028] RPC: 5098 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.440032] RPC: 5098 rpc_xdr_encode (status 0) Dec 16 09:03:16 frank kernel: [ 1054.442815] RPC: 5092 call_status (status 132) Dec 16 09:03:16 frank kernel: [ 1054.442820] RPC: 5092 call_decode (status 132) Dec 16 09:03:16 frank kernel: [ 1054.442829] RPC: 5092 call_decode result 131072 Dec 16 09:03:16 frank kernel: [ 1054.442840] RPC: rpc_release_client(ffff88001a189e00) Dec 16 09:03:16 frank kernel: [ 1054.442849] RPC: 5098 call_status (status -11) Dec 16 09:03:16 frank kernel: [ 1054.442853] RPC: 5098 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.442877] RPC: 5101 call_reserveresult (status -11) Dec 16 09:03:16 frank kernel: [ 1054.442885] RPC: 5101 call_reserveresult (status 0) Dec 16 09:03:16 frank kernel: [ 1054.442889] RPC: 5101 call_allocate (status 0) Dec 16 09:03:16 frank kernel: [ 1054.442899] RPC: 5101 call_bind (status 0) Dec 16 09:03:16 frank kernel: [ 1054.442903] RPC: 5101 call_connect xprt ffff88002c11d000 is connected Dec 16 09:03:16 frank kernel: [ 1054.442907] RPC: 5101 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.442911] RPC: 5099 call_status (status -11) Dec 16 09:03:16 frank kernel: [ 1054.442915] RPC: 5099 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.442925] RPC: 5099 rpc_xdr_encode (status 0) Dec 16 09:03:16 frank kernel: [ 1054.482089] RPC: 5099 call_status (status -11) Dec 16 09:03:16 frank kernel: [ 1054.482092] RPC: 5099 call_transmit (status 0) Dec 16 09:03:16 frank kernel: [ 1054.482100] RPC: 5100 call_status (status -11) Dec 16 09:03:16 frank kernel: [ 1054.482102] RPC: 5100 call_transmit (status 0) Dec 16 09:03:17 frank kernel: [ 1054.482104] RPC: 5100 rpc_xdr_encode (status 0) Dec 16 09:03:17 frank kernel: [ 1054.829555] RPC: 4849 call_status (status 132) Dec 16 09:03:17 frank kernel: [ 1054.829563] RPC: 4849 call_decode (status 132) Dec 16 09:03:17 frank kernel: [ 1054.829577] RPC: 4849 call_decode result 131072 Dec 16 09:03:17 frank kernel: [ 1054.829592] RPC: rpc_release_client(ffff88001a189e00) Dec 16 09:03:17 frank kernel: [ 1054.829603] RPC: 5102 call_reserveresult (status -11) Dec 16 09:03:17 frank kernel: [ 1054.829617] RPC: 5102 call_reserve (status 0) Dec 16 09:03:17 frank kernel: [ 1054.829622] RPC: 5102 call_reserveresult (status 0) Dec 16 09:03:17 frank kernel: [ 1054.829633] RPC: 5102 call_allocate (status 0) Dec 16 09:03:17 frank kernel: [ 1054.829638] RPC: 5102 call_bind (status 0) Dec 16 09:03:17 frank kernel: [ 1054.829643] RPC: 5102 call_connect xprt ffff88002c11d000 is connected Dec 16 09:03:17 frank kernel: [ 1054.829654] RPC: 5102 call_transmit (status 0) Dec 16 09:03:17 frank kernel: [ 1054.871559] RPC: 5100 call_status (status -11) Dec 16 09:03:17 frank kernel: [ 1054.871566] RPC: 5100 call_transmit (status 0) Dec 16 09:03:17 frank kernel: [ 1054.871593] RPC: 5101 call_status (status -11) Dec 16 09:03:17 frank kernel: [ 1054.871605] RPC: 5101 call_transmit (status 0) Dec 16 09:03:17 frank kernel: [ 1054.871610] RPC: 5101 rpc_xdr_encode (status 0) Dec 16 09:03:17 frank kernel: [ 1055.084218] RPC: 4850 call_status (status 132) Dec 16 09:03:17 frank kernel: [ 1055.084225] RPC: 4850 call_decode (status 132) Dec 16 09:03:17 frank kernel: [ 1055.084238] RPC: 4850 call_decode result 131072 Dec 16 09:03:17 frank kernel: [ 1055.084261] RPC: rpc_release_client(ffff88001a189e00) Dec 16 09:03:17 frank kernel: [ 1055.084278] RPC: 5103 call_reserveresult (status -11) Dec 16 09:03:17 frank kernel: [ 1055.084283] RPC: 5103 call_reserve (status 0) Dec 16 09:03:17 frank kernel: [ 1055.084288] RPC: 5103 call_reserveresult (status 0) Dec 16 09:03:17 frank kernel: [ 1055.084299] RPC: 5103 call_allocate (status 0) Dec 16 09:03:17 frank kernel: [ 1055.084304] RPC: 5103 call_bind (status 0) Dec 16 09:03:17 frank kernel: [ 1055.084309] RPC: 5103 call_connect xprt ffff88002c11d000 is connected Dec 16 09:03:17 frank kernel: [ 1055.084319] RPC: 5103 call_transmit (status 0) Note the timing. No lines have been altered or redacted. Hope this is useful. -- Configure bugmail: http://bugzilla.novell.com/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are on the CC list for the bug.