* a full packet capture of a situation that causes this problem (358MB compressed)
* a corefile from the gluster/nfs process generated near the end of the test (10GB, compressible to 133MB or so)
Volume Name: gv0
Type: Distributed-Replicate
Volume ID: 52b830b4-f6b0-4103-b90b-ce665dfbafec
Status: Stopped
Number of Bricks: 8 x 2 = 16
Transport-type: tcp
Bricks:
Brick1: fearless1:/export/bricks/500117310007a6d8/glusterdata
Brick2: fearless2:/export/bricks/500117310007a674/glusterdata
Brick3: fearless1:/export/bricks/500117310007a714/glusterdata
Brick4: fearless2:/export/bricks/500117310007a684/glusterdata
Brick5: fearless1:/export/bricks/500117310007a7dc/glusterdata
Brick6: fearless2:/export/bricks/500117310007a694/glusterdata
Brick7: fearless1:/export/bricks/500117310007a7e4/glusterdata
Brick8: fearless2:/export/bricks/500117310007a720/glusterdata
Brick9: fearless1:/export/bricks/500117310007a7ec/glusterdata
Brick10: fearless2:/export/bricks/500117310007a74c/glusterdata
Brick11: fearless1:/export/bricks/500117310007a838/glusterdata
Brick12: fearless2:/export/bricks/500117310007a814/glusterdata
Brick13: fearless1:/export/bricks/500117310007a850/glusterdata
Brick14: fearless2:/export/bricks/500117310007a84c/glusterdata
Brick15: fearless1:/export/bricks/500117310007a858/glusterdata
Brick16: fearless2:/export/bricks/500117310007a8f8/glusterdata
Options Reconfigured:
diagnostics.count-fop-hits: on
diagnostics.latency-measurement: on
performance.nfs.io-threads: on
performance.client-io-threads: on
performance.io-cache: on
performance.write-behind-window-size: 4MB
performance.nfs.write-behind: on
nfs.ports-insecure: on
diagnostics.client-log-level: INFO
(gdb) print *this
$22 = {ops = 0x7f05d50d2580, listener = 0x0, private = 0x27b6d90, xl_private = 0x0, xl = 0x261ffb0, mydata = 0x27a70d0, lock = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0,
__kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}, refcount = 2, ctx = 0x25dd010, options = 0x7f05d70ba3c8,
name = 0x26215e0 "gv0-client-9", dnscache = 0x28fda50, buf = 0x0, init = 0x7f05d4ec5650 <init>, fini = 0x7f05d4ec6780 <fini>, reconfigure = 0x7f05d4ec56d0 <reconfigure>,
notify = 0x7f05d83f2bd0 <rpc_clnt_notify>, notify_data = 0x0, peerinfo = {sockaddr = {ss_family = 2, __ss_align = 0, __ss_padding = '\000' <repeats 111 times>}, sockaddr_len = 16,
identifier = "192.168.11.2:24037", '\000' <repeats 89 times>}, myinfo = {sockaddr = {ss_family = 2, __ss_align = 0, __ss_padding = '\000' <repeats 111 times>}, sockaddr_len = 16,
identifier = "192.168.11.1:933", '\000' <repeats 91 times>}, total_bytes_read = 134672272, total_bytes_write = 3678711, list = {next = 0x0, prev = 0x0}, bind_insecure = 0}
40 million oustanding frames at this point:
(gdb) print ((call_pool_t)this->ctx->pool)
$23 = {{all_frames = {next = 0x25f96c0, prev = 0x25f9620}, all_stacks = {next_call = 0x25f96c0, prev_call = 0x25f9620}}, cnt = 39705952, lock = 0, frame_mem_pool = 0x0, stack_mem_pool = 0x0}
gluster/nfs gets into a state (very quickly) where it's spending all of it's time spinning somewhere:
PID USER PRI NI VIRT RES SHR S CPU% MEM% TIME+ Command
26240 root 20 0 4287M 2062M 2736 R 1687 1.6 21:53.95 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26656 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:06.76 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26649 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:07.32 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26684 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:08.14 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26682 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:10.35 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26678 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:07.98 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26675 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:07.45 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26679 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:10.32 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26676 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:10.89 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26681 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:06.87 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26677 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:06.87 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26672 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:11.07 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26674 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:07.54 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26680 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:10.12 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26280 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:10.37 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26683 root 20 0 4287M 2062M 2736 R 99.0 1.6 1:08.90 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
26652 root 20 0 4287M 2062M 2736 R 98.0 1.6 1:09.92 /usr/local/glusterfs/sbin/glusterfs -s localhost --volfile-id gluster/nfs
6580 michael 20 0 111M 3112 1232 R 3.0 0.0 6:56.91 htop
1611 root 20 0 0 0 0 S 0.0 0.0 0:25.56 fio-wq/0
1647 root 20 0 0 0 0 S 0.0 0.0 0:21.33 fioa-scan
26228 root 20 0 1386M 57112 2172 S 0.0 0.0 0:09.38 /usr/local/glusterfs/sbin/glusterfsd -s localhost --volfile-id gv0.fearles
26267 root 20 0 1386M 57112 2172 S 0.0 0.0 0:01.46 /usr/local/glusterfs/sbin/glusterfsd -s localhost --volfile-id gv0.fearles
26646 root 20 0 1386M 57112 2172 S 0.0 0.0 0:00.59 /usr/local/glusterfs/sbin/glusterfsd -s localhost --volfile-id gv0.fearles
26671 root 20 0 1386M 57112 2172 S 0.0 0.0 0:00.57 /usr/local/glusterfs/sbin/glusterfsd -s localhost --volfile-id gv0.fearles
26685 root 20 0 1386M 57112 2172 S 0.0 0.0 0:00.46 /usr/local/glusterfs/sbin/glusterfsd -s localhost --volfile-id gv0.fearles
26686 root 20 0 1386M 57112 2172 S 0.0 0.0 0:00.25 /usr/local/glusterfs/sbin/glusterfsd -s localhost --volfile-id gv0.fearles
yet the disks are idle:
avg-cpu: %user %nice %system %iowait %steal %idle
18.41 0.00 0.26 0.00 0.00 81.33
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sdf 0.00 0.00 0.00 0.67 0.00 6.17 18.50 0.00 2.00 2.00 0.13
sdh 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda 0.00 0.00 0.00 0.33 0.00 1.33 8.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdc 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdg 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sde 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdd 0.00 0.00 0.00 0.67 0.00 6.17 18.50 0.00 2.00 2.00 0.13
sdi 0.00 0.00 0.00 0.33 0.00 1.33 8.00 0.00 0.00 0.00 0.00
dm-0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
fioa 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
and volume profile says that operations aren't being responded to:
NFS Server : localhost
----------------------
Cumulative Stats:
Block Size: 2b+ 8b+ 16b+
No. of Reads: 0 0 0
No. of Writes: 2 6 18
Block Size: 32b+ 64b+ 128b+
No. of Reads: 0 0 0
No. of Writes: 85 30 19
Block Size: 256b+ 512b+ 1024b+
No. of Reads: 0 23 18
No. of Writes: 81 28 54
Block Size: 2048b+ 4096b+ 8192b+
No. of Reads: 6 28 385676
No. of Writes: 21 16 7
Block Size: 16384b+ 32768b+ 65536b+
No. of Reads: 289 135 31300
No. of Writes: 235 0 0
%-latency Avg-latency Min-Latency Max-Latency No. of calls Fop
--------- ----------- ----------- ----------- ------------ ----
0.00 0.00 us 0.00 us 0.00 us 1 FORGET
0.00 0.00 us 0.00 us 0.00 us 81 RELEASE
0.00 671.00 us 671.00 us 671.00 us 1 UNLINK
0.00 151.88 us 139.00 us 166.00 us 8 OPEN
0.00 1622.00 us 1622.00 us 1622.00 us 1 RENAME
0.00 411.88 us 345.00 us 502.00 us 8 FSTAT
0.00 1515.50 us 549.00 us 3835.00 us 8 READDIRP
0.00 488.23 us 155.00 us 4467.00 us 30 LK
0.00 832.00 us 211.00 us 3206.00 us 119 SETATTR
0.00 167.32 us 115.00 us 5326.00 us 677 STATFS
0.00 11469.73 us 464.00 us 672289.00 us 74 CREATE
0.00 3335.09 us 60.00 us 3806186.00 us 1200 ACCESS
0.00 130144.47 us 235.00 us 26674232.00 us 256 LOOKUP
0.00 223278.53 us 5.00 us 5554879.00 us 602 WRITE
0.00 582000.45 us 51.00 us 75297085.00 us 278 FLUSH
0.01 129560.57 us 65.00 us 70316547.00 us 3446 STAT
99.98 8454338.20 us 99.00 us 115469515.00 us 417475 READ
Duration: 6021 seconds
Data Read: 5221816212 bytes
Data Written: 4168883 bytes
glusterfs really is taking a long time to respond:
rpc.xid == 0x8879128a
[2013-05-08 21:16:00.564817] T [rpcsvc.c:382:rpcsvc_request_create] 0-rpc-service: received rpc-message (XID: 0x8879128a, Ver: 2, Program: 100003, ProgVers: 3, Proc: 6) from rpc-transport (socket.nfs-server)
[2013-05-08 21:16:00.564860] D [nfs3-helpers.c:1757:nfs3_log_rw_call] 0-nfs-nfsv3: XID: 8879128a, READ: args: FH: exportid 52b830b4-f6b0-4103-b90b-ce665dfbafec, gfid 77c67b0a-57a1-4b56-a6dd-15899529facd, offset: 7456178176, count: 8192
[2013-05-08 21:16:03.161708] T [rpcsvc.c:382:rpcsvc_request_create] 0-rpc-service: received rpc-message (XID: 0x8879128a, Ver: 2, Program: 100003, ProgVers: 3, Proc: 6) from rpc-transport (socket.nfs-server)
[2013-05-08 21:16:03.161784] D [nfs3-helpers.c:1757:nfs3_log_rw_call] 0-nfs-nfsv3: XID: 8879128a, READ: args: FH: exportid 52b830b4-f6b0-4103-b90b-ce665dfbafec, gfid 77c67b0a-57a1-4b56-a6dd-15899529facd, offset: 7456178176, count: 8192
[2013-05-08 21:16:13.940617] T [rpcsvc.c:382:rpcsvc_request_create] 0-rpc-service: received rpc-message (XID: 0x8879128a, Ver: 2, Program: 100003, ProgVers: 3, Proc: 6) from rpc-transport (socket.nfs-server)
[2013-05-08 21:16:13.940662] D [nfs3-helpers.c:1757:nfs3_log_rw_call] 0-nfs-nfsv3: XID: 8879128a, READ: args: FH: exportid 52b830b4-f6b0-4103-b90b-ce665dfbafec, gfid 77c67b0a-57a1-4b56-a6dd-15899529facd, offset: 7456178176, count: 8192
[2013-05-08 21:16:41.028161] T [rpcsvc.c:382:rpcsvc_request_create] 0-rpc-service: received rpc-message (XID: 0x8879128a, Ver: 2, Program: 100003, ProgVers: 3, Proc: 6) from rpc-transport (socket.nfs-server)
[2013-05-08 21:16:41.028205] D [nfs3-helpers.c:1757:nfs3_log_rw_call] 0-nfs-nfsv3: XID: 8879128a, READ: args: FH: exportid 52b830b4-f6b0-4103-b90b-ce665dfbafec, gfid 77c67b0a-57a1-4b56-a6dd-15899529facd, offset: 7456178176, count: 8192
[2013-05-08 21:17:03.172976] D [nfs3-helpers.c:3421:nfs3_log_read_res] 0-nfs-nfsv3: XID: 8879128a, READ: NFS: 0(Call completed successfully.), POSIX: 0(Success), count: 8192, is_eof: 0, vector: count: 1, len: 8192
[2013-05-08 21:17:03.173042] T [rpcsvc.c:1087:rpcsvc_submit_generic] 0-rpc-service: submitted reply for rpc-message (XID: 0x8879128a, Program: NFS3, ProgVers: 3, Proc: 6) to rpc-transport (socket.nfs-server)
[2013-05-08 21:17:40.996580] D [nfs3-helpers.c:3421:nfs3_log_read_res] 0-nfs-nfsv3: XID: 8879128a, READ: NFS: 0(Call completed successfully.), POSIX: 0(Success), count: 8192, is_eof: 0, vector: count: 1, len: 8192
[2013-05-08 21:17:40.996628] T [rpcsvc.c:1087:rpcsvc_submit_generic] 0-rpc-service: submitted reply for rpc-message (XID: 0x8879128a, Program: NFS3, ProgVers: 3, Proc: 6) to rpc-transport (socket.nfs-server)
[2013-05-08 21:17:44.372915] T [rpcsvc.c:382:rpcsvc_request_create] 0-rpc-service: received rpc-message (XID: 0x8879128a, Ver: 2, Program: 100003, ProgVers: 3, Proc: 6) from rpc-transport (socket.nfs-server)
[2013-05-08 21:17:44.372956] D [nfs3-helpers.c:1757:nfs3_log_rw_call] 0-nfs-nfsv3: XID: 8879128a, READ: args: FH: exportid 52b830b4-f6b0-4103-b90b-ce665dfbafec, gfid 77c67b0a-57a1-4b56-a6dd-15899529facd, offset: 7456178176, count: 8192
[2013-05-08 21:18:12.439583] T [rpcsvc.c:382:rpcsvc_request_create] 0-rpc-service: received rpc-message (XID: 0x8879128a, Ver: 2, Program: 100003, ProgVers: 3, Proc: 6) from rpc-transport (socket.nfs-server)
[2013-05-08 21:18:12.439628] D [nfs3-helpers.c:1757:nfs3_log_rw_call] 0-nfs-nfsv3: XID: 8879128a, READ: args: FH: exportid 52b830b4-f6b0-4103-b90b-ce665dfbafec, gfid 77c67b0a-57a1-4b56-a6dd-15899529facd, offset: 7456178176, count: 8192
[2013-05-08 21:19:29.949901] D [nfs3-helpers.c:3421:nfs3_log_read_res] 0-nfs-nfsv3: XID: 8879128a, READ: NFS: 0(Call completed successfully.), POSIX: 0(Success), count: 8192, is_eof: 0, vector: count: 1, len: 8192
[2013-05-08 21:19:29.949953] T [rpcsvc.c:1087:rpcsvc_submit_generic] 0-rpc-service: submitted reply for rpc-message (XID: 0x8879128a, Program: NFS3, ProgVers: 3, Proc: 6) to rpc-transport (socket.nfs-server)
[2013-05-08 21:23:02.353017] D [nfs3-helpers.c:3421:nfs3_log_read_res] 0-nfs-nfsv3: XID: 8879128a, READ: NFS: 0(Call completed successfully.), POSIX: 0(Success), count: 8192, is_eof: 0, vector: count: 1, len: 8192
[2013-05-08 21:23:02.353066] T [rpcsvc.c:1087:rpcsvc_submit_generic] 0-rpc-service: submitted reply for rpc-message (XID: 0x8879128a, Program: NFS3, ProgVers: 3, Proc: 6) to rpc-transport (socket.nfs-server)
--
Michael Brown, Systems Consultant
Net Direct Inc.
☎: +1 519 883 1172 x5106
After a bit of load, I constantly find my gluster server getting
into a state where it seems to be unable to reply to NFS RPCs:
[2013-05-05 01:31:16.421507] E [rpcsvc.c:1080:rpcsvc_submit_generic] 0-rpc-service: failed to submit message (XID: 0x3705786983x, Program: NFS3, ProgVers: 3, Proc: 6) to rpc-transport (socket.nfs-server)
[2013-05-05 01:31:16.421528] E [nfs3.c:627:nfs3svc_submit_vector_reply] 0-nfs-nfsv3: Reply submission failed
http://pastie.org/7803022
Any idea what to do about it?
The NFS daemon also gets rather large - I suspect it's storing up
data for all these RPCs:
PID USER PRI NI VIRT RES SHR S CPU% MEM% TIME+
Command
30674 root 20 0 37.6G 37.3G 2288 R 99.0 29.6
5:29.88 /usr/local/glusterfs/sbin/glusterfs
I'm running 3.3.1 with a few patches:
https://github.com/Supermathie/glusterfs/tree/release-3.3-oracle
Workload is usually Oracle DNFS.
M.
--
Michael Brown | `One of the main causes of the fall of
Systems Consultant | the Roman Empire was that, lacking zero,
Net Direct Inc. | they had no way to indicate successful
☎: +1 519 883 1172 x5106 | termination of their C programs.' - Firth