Ceph » CephFS

The direct cause of this is almost certainly an open fd limit coming from the OS, which you can probably work around by changing the ulimit or whatever.

The more interesting question is why on earth it has so many open sockets — it ought to be closing them down after they're idle for enough time.

I'll test out the ulimit as a workaround, and presumably to verify the open fd limit theory.

I checked all my client nodes and they don't seem to have any stuck client processes with open connections. If I dump up the logging level on the OSD will we be able to see the FDs, so we can correlate the log with the lsof output?

Err, dump up the level on the MDS...

Doesn't /proc tell you whether the fd is a socket or not? Or do you mean correlate activity?

In any case, all the Pipe debugging output includes the sd it's using — you'll probably want debug_ms 10 in order to get anything useful.

(Side note: while of course I want to debug this, restarting the MDS will presumably free up all those descriptors if necessary — and if not then this is either much weirder or not the kind of but I think it is.)

I had this thought that the set of FDs in the logs would be >> than the set shown in lsof, and that we'd want to cross-reference lsof from the log to figure out which class of socket was being left open. But maybe that's overkill :P

I'll do some investigation on this. We aren't under a time crunch or anything, but want to be able to keep MR jobs running continuously.

I bet #3630 is contributing here.

It might be contributing, but I believe the sockets should still be getting closed after a timeout period, right?

Is there anything I can do to get more information for this ticket?

To Greg's question, it seems as though the connections were not timing out. I'd toss out a rough estimate of about 45 minutes before I took down the MDS and they were still there.

can you reproduce with debug ms = 20 and debug mds = 20 ? those logs would be helpful

Would you like to logs up to the point that the MDS stops accepts connections, or just a snap shot after the FD list has grown large. For example, after a few rounds MR jobs with 256 map-tasks each (that have completed), I'm up to about 800 open sockets. Either is OK, the lots for the former will be enormous.

Log file fun. Here is the MDS log up until it stopped accepting connections.

http://piha.soe.ucsc.edu/ceph-mds.a.log.tar.gz

Here's some more info after investigating this a bit further.

Open socket counts by category after a fresh MDS reboot.

    378 REG
    180 FIFO
     90 IPv4
     54 CHR
     36 DIR
     18 unix

Open sockets after 1000 clean, mount/shutdown iterations.

1993964 sock
  42126 REG
  20060 FIFO
  10030 IPv4
   6018 CHR
   4012 DIR
   2006 unix

Driver program

int main(){
  struct ceph_mount_info *cmount;

  for (int i = 0; i < 1000; i++) {
    assert(ceph_create(&cmount, NULL) == 0);
    assert(ceph_conf_read_file(cmount, NULL) == 0);
    assert(ceph_mount(cmount, "/") == 0);

    assert(ceph_unmount(cmount) == 0);
    assert(ceph_release(cmount) == 0);
  }
}

Taking the diff between successive lsof output for 1, 2, ... mount attempts reveals the pattern. After one mount there are 20 threads each with an open socket:

ceph-mds  10361 10362 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10364 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10365 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10366 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10367 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10369 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10370 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10371 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10372 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10373 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10376 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10387 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10612 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10614 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10615 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10619 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10622 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10623 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10671 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10672 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol

After a second mount, each of the 20 threads have 2 open sockets, plus 2 new threads with two sockets.

ceph-mds  10361 10362 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10362 nwatkins   21u     sock                0,7       0t0   11657837 can't identify protocol
ceph-mds  10361 10364 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol
ceph-mds  10361 10364 nwatkins   21u     sock                0,7       0t0   11657837 can't identify protocol
ceph-mds  10361 10365 nwatkins   20u     sock                0,7       0t0   11657833 can't identify protocol

... clip ...

And so on. After 3 mounts, each of the previous 22 threads have 3 open sockets, plus 2 new threads with 3 open sockets.

Hmm, did we screw up our refactoring work so that replaced sockets are no longer actually closed? That might explain this behavior.

Although the high counts were because of double counting by lsof, the sockets still are not being closed. Without any active clients running, all the sockets created from previous mounts are still around after 30 minutes. I'm using the default settings.

Noah, do you want to try wip-mds-con?

Well hot damn. That branch seems to solve two problems. First, clients that do a clean unmount don't leave lots of FDs lingering in the MDS. Second, unclean mounts are now timing out the MDS-side sockets, after about 7 minutes. Is this mds_session_autoclose (defaulting to 5 minutes) ?

Err, "unclean mounts" = "exiting without unmounting"