On Fri, Mar 31, 2017 at 1:27 PM, Andras Pataki
<apat...@flatironinstitute.org> wrote:
> Hi John,
>
> It took a while but I believe now I have a reproducible test case for the
> capabilities being lost issue in CephFS I wrote about a couple of weeks ago.
> The quick summary of problem is that often processes hang using CephFS
> either for a while or sometimes indefinitely. The fuse client believes it
> is waiting for some caps which it does not get from the MDS.
>
> A quick summary of the setup: the whole system is on Jewel 10.2.6. We are
> using the fuse client on all nodes for the file system.
>
> The full test program is uploaded together with the verbose logs of all
> clients and the MDS (at log level 20) to
> http://voms.simonsfoundation.org:50013/GTrbrMWDHb9F7CampXyYt5Ensdjg47w/ceph-20170331/
> It essentially runs in a loop opening a file for read/write, reading from it
> and closing it. The read/write open is key, if open the file read-only, the
> problem doesn't happen:
>
> while (time(NULL) - t0 < INTERVAL) {
>
> int fd = open(FILENAME, O_RDWR);
> if (fd < 0) {
> printf("Could not open file '%s' for read/write", FILENAME);
> exit(1);
> }
>
> read(fd, buffer, 100);
>
> close(fd);
> count++;
> }
>
> With INTERVAL = 10 seconds, on one machine with a single process I get
> something like 30k opens per 10 seconds - an excellent result. When I run 3
> processes on 3 different nodes, I get a few (perhaps 4 or 5) opens per 10
> seconds per process. The particular case I collected logs for looks like
> this:
>
> apataki@worker1108:~/prg/ceph/test$ date; ssh worker1109
> ~/prg/ceph/test/timed_openrw_read < /dev/null & ssh worker1110
> ~/prg/ceph/test/timed_openrw_read < /dev/null & ssh worker1108
> ~/prg/ceph/test/timed_openrw_read < /dev/null &
> Fri Mar 31 07:33:04 EDT 2017
> [1] 53833
> [2] 53834
> [3] 53835
> apataki@worker1108:~/prg/ceph/test$ Number of repeats: 4
> Number of repeats: 3
> Number of repeats: 5
>
> [1] Done ssh worker1109
> ~/prg/ceph/test/timed_openrw_read < /dev/null
> [2]- Done ssh worker1110
> ~/prg/ceph/test/timed_openrw_read < /dev/null
> [3]+ Done ssh worker1108
> ~/prg/ceph/test/timed_openrw_read < /dev/null
> apataki@worker1108:~/prg/ceph/test$
>
> Looking at the client, it looks like there are 5 second pauses waiting for
> capabilities. It seems that it doesn't get a response, and perhaps at some
> frequency it polls back to find out what happened to its capabilities. Here
> is an example of such 5 second gaps from the client logs:
>
> 2017-03-31 07:33:05.010111 2aaab1a57700 10 client.3849178 waiting for caps
> need Fr want Fc
> 2017-03-31 07:33:05.464058 2aaaafd47700 20 client.3849178 trim_cache size 4
> max 16384
> 2017-03-31 07:33:06.464180 2aaaafd47700 20 client.3849178 trim_cache size 4
> max 16384
> 2017-03-31 07:33:07.464307 2aaaafd47700 20 client.3849178 trim_cache size 4
> max 16384
> 2017-03-31 07:33:08.464421 2aaaafd47700 20 client.3849178 trim_cache size 4
> max 16384
> 2017-03-31 07:33:09.464554 2aaaafd47700 20 client.3849178 trim_cache size 4
> max 16384
> 2017-03-31 07:33:10.464680 2aaaafd47700 10 client.3849178 check_caps on
> 100024a7b1d.head(faked_ino=0 ref=3 ll_ref=79894 cap_refs={1024=0,2048=0}
> open={3=1} mode=100664 size=23/4194304 mtime=2017-03-30 11:56:38.588478
> caps=pAsLsXsFr(0=pAsLsXsFr) objectset[100024a7b1d ts 0/0 objects 0
> dirty_or_tx 0] parents=0x55555f5d5340 0x55555f73ea00) wanted pAsxXsxFsxcrwb
> used - issued pAsLsXsFr revoking Fsc is_delayed=1
>
> The inode in question is 100024a7b1d which corresponds to the test file
> /mnt/ceph/users/apataki/test/TEST-READ.txt
> When I grep for this inode in the MDS logs, it also has a gap in the 7:33:05
> to 7:33:10 time. I've learned some about the caps by trying to reproduce
> the problem, but I'm afraid I don't understand enough of the MDS logic to
> see what the problem is there.
>
> The full logs are too large for the mailing list, so I've put them here:
> http://voms.simonsfoundation.org:50013/GTrbrMWDHb9F7CampXyYt5Ensdjg47w/ceph-20170331/
>
> Some help/advice with this would very much be appreciated. Thanks in
> advance!
Thanks for the reproducer -- I've tried this against master ceph with
several clients on one node and I'm seeing hundreds of repeats per 10
second interval, although my clients are all on the same node. I got
a similar result when setting the client to inject 10ms delays on
messages to simulate being remote. I ran it in a loop with three
clients several tens of times without seeing a hang.
I'm compiling jewel now to see if it has a different behaviour to
master (with the optimistic notion that we might have already fixed
the underlying cause...)
John
> Andras
>
>
>
>
> On 03/14/2017 12:55 PM, John Spray wrote:
>
> On Tue, Mar 14, 2017 at 2:10 PM, Andras Pataki
> <apat...@flatironinstitute.org> wrote:
>
> Hi John,
>
> I've checked the MDS session list, and the fuse client does appear on that
> with 'state' as 'open'. So both the fuse client and the MDS agree on an
> open connection.
>
> Attached is the log of the ceph fuse client at debug level 20. The MDS got
> restarted at 9:44:20, and it went through its startup, and was in an
> 'active' state in ceph -s by 9:45:20. As for the IP addresses in the logs,
> 10.128.128.110 is the MDS IP, the 10.128.128.1xy addresses are OSDs,
> 10.128.129.63 is the IP of the client the log is from.
>
> So it looks like the client is getting stuck waiting for some
> capabilities (the 7fff9c3f7700 thread in that log, which eventually
> completes a ll_write on inode 100024ebea8 after the MDS restart).
> Hard to say whether the MDS failed to send it the proper messages, or
> if the client somehow missed it.
>
> It would be useful to have equally verbose logs from the MDS side from
> earlier on, at the point that the client started trying to do the
> write. I wonder if you could see if your MDS+client can handle both
> being run at "debug mds = 20", "debug client = 20" respectively for a
> while, then when a client gets stuck, do the MDS restart, and follow
> back in the client log to work out which inode it was stuck on, then
> find log areas on the MDS side relating to that inode number.
>
> BTW I see this "FsUsage" stuff in your log, which I don't recognise
> from mainline Ceph, are you running something modified?
>
> John
>
>
> As per another suggestion, I've also tried kick_stale_sessions on the fuse
> client, which didn't help (I guess since it doesn't think the session is
> stale).
> Let me know if there is anything else I can do to help.
>
> Andras
>
>
>
> On 03/13/2017 06:08 PM, John Spray wrote:
>
> On Mon, Mar 13, 2017 at 8:15 PM, Andras Pataki
> <apat...@flatironinstitute.org> wrote:
>
> Dear Cephers,
>
> We're using the ceph file system with the fuse client, and lately some of
> our processes are getting stuck seemingly waiting for fuse operations.
> At
> the same time, the cluster is healthy, no slow requests, all OSDs up and
> running, and both the MDS and the fuse client think that there are no
> pending operations. The situation is semi-reproducible. When I run a
> various cluster jobs, some get stuck after a few hours of correct
> operation.
> The cluster is on ceph 10.2.5 and 10.2.6, the fuse clients are 10.2.6,
> but I
> have tried 10.2.5 and 10.2.3, all of which have the same issue. This is
> on
> CentOS (7.2 for the clients, 7.3 for the MDS/OSDs).
>
> Here are some details:
>
> The node with the stuck processes:
>
> [root@worker1070 ~]# ps -auxwww | grep 30519
> apataki 30519 39.8 0.9 8728064 5257588 ? Dl 12:11 60:50 ./Arepo
> param.txt 2 6
> [root@worker1070 ~]# cat /proc/30519/stack
> [<ffffffffa0a1d7bb>] fuse_file_aio_write+0xbb/0x340 [fuse]
> [<ffffffff811ddd3d>] do_sync_write+0x8d/0xd0
> [<ffffffff811de55d>] vfs_write+0xbd/0x1e0
> [<ffffffff811defff>] SyS_write+0x7f/0xe0
> [<ffffffff816458c9>] system_call_fastpath+0x16/0x1b
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> [root@worker1070 ~]# ps -auxwww | grep 30533
> apataki 30533 39.8 0.9 8795316 5261308 ? Sl 12:11 60:55 ./Arepo
> param.txt 2 6
> [root@worker1070 ~]# cat /proc/30533/stack
> [<ffffffffa0a12241>] wait_answer_interruptible+0x91/0xe0 [fuse]
> [<ffffffffa0a12653>] __fuse_request_send+0x253/0x2c0 [fuse]
> [<ffffffffa0a126d2>] fuse_request_send+0x12/0x20 [fuse]
> [<ffffffffa0a1b966>] fuse_send_write+0xd6/0x110 [fuse]
> [<ffffffffa0a1d45d>] fuse_perform_write+0x2ed/0x590 [fuse]
> [<ffffffffa0a1d9a1>] fuse_file_aio_write+0x2a1/0x340 [fuse]
> [<ffffffff811ddd3d>] do_sync_write+0x8d/0xd0
> [<ffffffff811de55d>] vfs_write+0xbd/0x1e0
> [<ffffffff811defff>] SyS_write+0x7f/0xe0
> [<ffffffff816458c9>] system_call_fastpath+0x16/0x1b
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> Presumably the second process is waiting on the first holding some lock
> ...
>
> The fuse client on the node:
>
> [root@worker1070 ~]# ceph daemon /var/run/ceph/ceph-client.admin.asok
> status
> {
> "metadata": {
> "ceph_sha1": "656b5b63ed7c43bd014bcafd81b001959d5f089f",
> "ceph_version": "ceph version 10.2.6
> (656b5b63ed7c43bd014bcafd81b001959d5f089f)",
> "entity_id": "admin",
> "hostname": "worker1070",
> "mount_point": "\/mnt\/ceph",
> "root": "\/"
> },
> "dentry_count": 40,
> "dentry_pinned_count": 23,
> "inode_count": 123,
> "mds_epoch": 19041,
> "osd_epoch": 462327,
> "osd_epoch_barrier": 462326
> }
>
> [root@worker1070 ~]# ceph daemon /var/run/ceph/ceph-client.admin.asok
> mds_sessions
> {
> "id": 3616543,
> "sessions": [
> {
> "mds": 0,
> "addr": "10.128.128.110:6800\/909443124",
> "seq": 338,
> "cap_gen": 0,
> "cap_ttl": "2017-03-13 14:47:37.575229",
> "last_cap_renew_request": "2017-03-13 14:46:37.575229",
> "cap_renew_seq": 12694,
> "num_caps": 713,
> "state": "open"
> }
> ],
> "mdsmap_epoch": 19041
> }
>
> [root@worker1070 ~]# ceph daemon /var/run/ceph/ceph-client.admin.asok
> mds_requests
> {}
>
>
> The overall cluster health and the MDS:
>
> [root@cephosd000 ~]# ceph -s
> cluster d7b33135-0940-4e48-8aa6-1d2026597c2f
> health HEALTH_WARN
> noscrub,nodeep-scrub,require_jewel_osds flag(s) set
> monmap e17: 3 mons at
>
> {hyperv029=10.4.36.179:6789/0,hyperv030=10.4.36.180:6789/0,hyperv031=10.4.36.181:6789/0}
> election epoch 29148, quorum 0,1,2
> hyperv029,hyperv030,hyperv031
> fsmap e19041: 1/1/1 up {0=cephosd000=up:active}
> osdmap e462328: 624 osds: 624 up, 624 in
> flags noscrub,nodeep-scrub,require_jewel_osds
> pgmap v44458747: 42496 pgs, 6 pools, 924 TB data, 272 Mobjects
> 2154 TB used, 1791 TB / 3946 TB avail
> 42496 active+clean
> client io 86911 kB/s rd, 556 MB/s wr, 227 op/s rd, 303 op/s wr
>
> [root@cephosd000 ~]# ceph daemon /var/run/ceph/ceph-mds.cephosd000.asok
> ops
> {
> "ops": [],
> "num_ops": 0
> }
>
>
> The odd thing is that if in this state I restart the MDS, the client
> process
> wakes up and proceeds with its work without any errors. As if a request
> was
> lost and somehow retransmitted/restarted when the MDS got restarted and
> the
> fuse layer reconnected to it.
>
> Interesting. A couple of ideas for more debugging:
>
> * Next time you go through this process of restarting the MDS while
> there is a stuck client, first increase the client's logging (ceph
> daemon <path to /var/run/ceph/ceph-<id>.asok> config set debug_client
> 20"). Then we should get a clear sense of exactly what's happening on
> the MDS restart that's enabling the client to proceed.
> * When inspecting the client's "mds_sessions" output, also check the
> "session ls" output on the MDS side to make sure the MDS and client
> both agree that it has an open session.
>
> John
>
> When I try to attach a gdb session to either of the client processes, gdb
> just hangs. However, right after the MDS restart gdb attaches to the
> process successfully, and shows that the getting stuck happened on
> closing
> of a file. In fact, it looks like both processes were trying to write to
> the same file opened with fopen("filename", "a") and close it:
>
> (gdb) where
> #0 0x00002aaaadc53abd in write () from /lib64/libc.so.6
> #1 0x00002aaaadbe2383 in _IO_new_file_write () from /lib64/libc.so.6
> #2 0x00002aaaadbe37ec in __GI__IO_do_write () from /lib64/libc.so.6
> #3 0x00002aaaadbe30e0 in __GI__IO_file_close_it () from /lib64/libc.so.6
> #4 0x00002aaaadbd7020 in fclose@@GLIBC_2.2.5 () from /lib64/libc.so.6
> ...
>
> It seems like the fuse client wasn't handling this case well, when two
> processes write to the same file and close it perhaps? This is just a
> speculation. Any ideas on how to proceed? Is there perhaps a known
> issue
> related to this?
>
> Thanks,
>
> Andras
> apat...@flatironinstitute.org
>
>
> _______________________________________________
> ceph-users mailing list
> ceph-users@lists.ceph.com
> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
>
>
_______________________________________________
ceph-users mailing list
ceph-users@lists.ceph.com
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
