| Message ID | alpine.DEB.2.00.1208301339120.11149@cobra.newdream.net (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
This smells like it might be a DNS misconfiguration. Make sure you've got entries in your hosts files for whatever machines are involved. On Thu, Aug 30, 2012 at 01:39:36PM -0700, Sage Weil wrote: > What about this: > > diff --git a/src/client/Client.cc b/src/client/Client.cc > index 3333966..003e3f8 100644 > --- a/src/client/Client.cc > +++ b/src/client/Client.cc > @@ -294,6 +294,7 @@ int Client::init() > monclient->set_want_keys(CEPH_ENTITY_TYPE_MDS | CEPH_ENTITY_TYPE_OSD); > monclient->sub_want("mdsmap", 0, 0); > monclient->sub_want("osdmap", 0, CEPH_SUBSCRIBE_ONETIME); > + monclient->renew_subs(); > > // logger > PerfCountersBuilder plb(cct, "client", l_c_first, l_c_last); > > > If that doesn't do it, can you reproduce with 'debug client = 20' and > 'debug monc = 20'? > > Thanks! > sage > > > > On Thu, 30 Aug 2012, Noah Watkins wrote: > > > Here ya go: > > > > https://dl.dropbox.com/u/7899675/client.log > > https://dl.dropbox.com/u/7899675/mds.a.log > > https://dl.dropbox.com/u/7899675/mds.b.log > > https://dl.dropbox.com/u/7899675/mds.c.log > > > > - Noah > > > > On Thu, Aug 30, 2012 at 1:15 PM, Sage Weil <sage@inktank.com> wrote: > > > I see that Server::handle_client_session is calling mdlog->flush(), so > > > it's a bit odd. Can you generate a log with 'debug ms = 1' on the client > > > (and maybe mds) side? > > > > > > s > > > > > > On Thu, 30 Aug 2012, Noah Watkins wrote: > > > > > >> On Thu, Aug 30, 2012 at 1:06 PM, Gregory Farnum <greg@inktank.com> wrote: > > >> > On Thu, Aug 30, 2012 at 12:55 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: > > >> >> Using a tick interval of 1 drops the cost down to 3 seconds, but still > > >> >> a long time for running many unit tests that use fresh mounts. > > >> > > > >> > Are you using ceph-fuse or the kernel client? And how many of each daemon type? > > >> > > >> I'm using the C api, and there are 3 mon, 3 mds, 1 osd. > > >> > > >> > That said; I'm seeing broadly similar numbers ? with one of each > > >> > daemon (but otherwise the vstart defaults) "time sudo ceph-fuse mnt" > > >> > reports 3.1 seconds. > > >> > > >> > > > > > -- > To unsubscribe from this list: send the line "unsubscribe ceph-devel" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
No, Sage's one-liner should definitely handle it. We were just waiting for the monclient to tick before requesting updated subs. My question is how that changed — have mounts always taken ~3 seconds to go through and we just didn't notice, or did we change how the monclient handles subscription requests and didn't consider the implications? -Greg On Thu, Aug 30, 2012 at 1:46 PM, Mike Ryan <mike.ryan@inktank.com> wrote: > This smells like it might be a DNS misconfiguration. Make sure you've > got entries in your hosts files for whatever machines are involved. > > On Thu, Aug 30, 2012 at 01:39:36PM -0700, Sage Weil wrote: >> What about this: >> >> diff --git a/src/client/Client.cc b/src/client/Client.cc >> index 3333966..003e3f8 100644 >> --- a/src/client/Client.cc >> +++ b/src/client/Client.cc >> @@ -294,6 +294,7 @@ int Client::init() >> monclient->set_want_keys(CEPH_ENTITY_TYPE_MDS | CEPH_ENTITY_TYPE_OSD); >> monclient->sub_want("mdsmap", 0, 0); >> monclient->sub_want("osdmap", 0, CEPH_SUBSCRIBE_ONETIME); >> + monclient->renew_subs(); >> >> // logger >> PerfCountersBuilder plb(cct, "client", l_c_first, l_c_last); >> >> >> If that doesn't do it, can you reproduce with 'debug client = 20' and >> 'debug monc = 20'? >> >> Thanks! >> sage >> >> >> >> On Thu, 30 Aug 2012, Noah Watkins wrote: >> >> > Here ya go: >> > >> > https://dl.dropbox.com/u/7899675/client.log >> > https://dl.dropbox.com/u/7899675/mds.a.log >> > https://dl.dropbox.com/u/7899675/mds.b.log >> > https://dl.dropbox.com/u/7899675/mds.c.log >> > >> > - Noah >> > >> > On Thu, Aug 30, 2012 at 1:15 PM, Sage Weil <sage@inktank.com> wrote: >> > > I see that Server::handle_client_session is calling mdlog->flush(), so >> > > it's a bit odd. Can you generate a log with 'debug ms = 1' on the client >> > > (and maybe mds) side? >> > > >> > > s >> > > >> > > On Thu, 30 Aug 2012, Noah Watkins wrote: >> > > >> > >> On Thu, Aug 30, 2012 at 1:06 PM, Gregory Farnum <greg@inktank.com> wrote: >> > >> > On Thu, Aug 30, 2012 at 12:55 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: >> > >> >> Using a tick interval of 1 drops the cost down to 3 seconds, but still >> > >> >> a long time for running many unit tests that use fresh mounts. >> > >> > >> > >> > Are you using ceph-fuse or the kernel client? And how many of each daemon type? >> > >> >> > >> I'm using the C api, and there are 3 mon, 3 mds, 1 osd. >> > >> >> > >> > That said; I'm seeing broadly similar numbers ? with one of each >> > >> > daemon (but otherwise the vstart defaults) "time sudo ceph-fuse mnt" >> > >> > reports 3.1 seconds. >> > >> >> > >> >> > >> > >> -- >> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in >> the body of a message to majordomo@vger.kernel.org >> More majordomo info at http://vger.kernel.org/majordomo-info.html -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
It could be the order that monlcinet init happens changed.. or that we've just never noticed it being bad enough to fix. I have observed that mounts seem slow, but never looked into it and chaled it up to loadiness on my dev box running vstart (with a smattering of busy/apathy on top). sage On Thu, 30 Aug 2012, Gregory Farnum wrote: > No, Sage's one-liner should definitely handle it. We were just waiting > for the monclient to tick before requesting updated subs. > > My question is how that changed ? have mounts always taken ~3 seconds > to go through and we just didn't notice, or did we change how the > monclient handles subscription requests and didn't consider the > implications? > -Greg > > On Thu, Aug 30, 2012 at 1:46 PM, Mike Ryan <mike.ryan@inktank.com> wrote: > > This smells like it might be a DNS misconfiguration. Make sure you've > > got entries in your hosts files for whatever machines are involved. > > > > On Thu, Aug 30, 2012 at 01:39:36PM -0700, Sage Weil wrote: > >> What about this: > >> > >> diff --git a/src/client/Client.cc b/src/client/Client.cc > >> index 3333966..003e3f8 100644 > >> --- a/src/client/Client.cc > >> +++ b/src/client/Client.cc > >> @@ -294,6 +294,7 @@ int Client::init() > >> monclient->set_want_keys(CEPH_ENTITY_TYPE_MDS | CEPH_ENTITY_TYPE_OSD); > >> monclient->sub_want("mdsmap", 0, 0); > >> monclient->sub_want("osdmap", 0, CEPH_SUBSCRIBE_ONETIME); > >> + monclient->renew_subs(); > >> > >> // logger > >> PerfCountersBuilder plb(cct, "client", l_c_first, l_c_last); > >> > >> > >> If that doesn't do it, can you reproduce with 'debug client = 20' and > >> 'debug monc = 20'? > >> > >> Thanks! > >> sage > >> > >> > >> > >> On Thu, 30 Aug 2012, Noah Watkins wrote: > >> > >> > Here ya go: > >> > > >> > https://dl.dropbox.com/u/7899675/client.log > >> > https://dl.dropbox.com/u/7899675/mds.a.log > >> > https://dl.dropbox.com/u/7899675/mds.b.log > >> > https://dl.dropbox.com/u/7899675/mds.c.log > >> > > >> > - Noah > >> > > >> > On Thu, Aug 30, 2012 at 1:15 PM, Sage Weil <sage@inktank.com> wrote: > >> > > I see that Server::handle_client_session is calling mdlog->flush(), so > >> > > it's a bit odd. Can you generate a log with 'debug ms = 1' on the client > >> > > (and maybe mds) side? > >> > > > >> > > s > >> > > > >> > > On Thu, 30 Aug 2012, Noah Watkins wrote: > >> > > > >> > >> On Thu, Aug 30, 2012 at 1:06 PM, Gregory Farnum <greg@inktank.com> wrote: > >> > >> > On Thu, Aug 30, 2012 at 12:55 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: > >> > >> >> Using a tick interval of 1 drops the cost down to 3 seconds, but still > >> > >> >> a long time for running many unit tests that use fresh mounts. > >> > >> > > >> > >> > Are you using ceph-fuse or the kernel client? And how many of each daemon type? > >> > >> > >> > >> I'm using the C api, and there are 3 mon, 3 mds, 1 osd. > >> > >> > >> > >> > That said; I'm seeing broadly similar numbers ? with one of each > >> > >> > daemon (but otherwise the vstart defaults) "time sudo ceph-fuse mnt" > >> > >> > reports 3.1 seconds. > >> > >> > >> > >> > >> > > >> > > >> -- > >> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in > >> the body of a message to majordomo@vger.kernel.org > >> More majordomo info at http://vger.kernel.org/majordomo-info.html > > -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Ok, this patch sorta solves the problem. After a fresh restart of the daemons, the client hangs indefinitely (log urls attached for this case). If I kill the client and restart, I get a behavior similar to the original problem. Another client restart and everything is very fast. This easily reproducible. https://dl.dropbox.com/u/7899675/client.log https://dl.dropbox.com/u/7899675/mds.a.log https://dl.dropbox.com/u/7899675/mds.b.log https://dl.dropbox.com/u/7899675/mds.c.log - Noah On Thu, Aug 30, 2012 at 1:39 PM, Sage Weil <sage@inktank.com> wrote: > What about this: > > diff --git a/src/client/Client.cc b/src/client/Client.cc > index 3333966..003e3f8 100644 > --- a/src/client/Client.cc > +++ b/src/client/Client.cc > @@ -294,6 +294,7 @@ int Client::init() > monclient->set_want_keys(CEPH_ENTITY_TYPE_MDS | CEPH_ENTITY_TYPE_OSD); > monclient->sub_want("mdsmap", 0, 0); > monclient->sub_want("osdmap", 0, CEPH_SUBSCRIBE_ONETIME); > + monclient->renew_subs(); > > // logger > PerfCountersBuilder plb(cct, "client", l_c_first, l_c_last); > > > If that doesn't do it, can you reproduce with 'debug client = 20' and > 'debug monc = 20'? > > Thanks! > sage > > > > On Thu, 30 Aug 2012, Noah Watkins wrote: > >> Here ya go: >> >> https://dl.dropbox.com/u/7899675/client.log >> https://dl.dropbox.com/u/7899675/mds.a.log >> https://dl.dropbox.com/u/7899675/mds.b.log >> https://dl.dropbox.com/u/7899675/mds.c.log >> >> - Noah >> >> On Thu, Aug 30, 2012 at 1:15 PM, Sage Weil <sage@inktank.com> wrote: >> > I see that Server::handle_client_session is calling mdlog->flush(), so >> > it's a bit odd. Can you generate a log with 'debug ms = 1' on the client >> > (and maybe mds) side? >> > >> > s >> > >> > On Thu, 30 Aug 2012, Noah Watkins wrote: >> > >> >> On Thu, Aug 30, 2012 at 1:06 PM, Gregory Farnum <greg@inktank.com> wrote: >> >> > On Thu, Aug 30, 2012 at 12:55 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: >> >> >> Using a tick interval of 1 drops the cost down to 3 seconds, but still >> >> >> a long time for running many unit tests that use fresh mounts. >> >> > >> >> > Are you using ceph-fuse or the kernel client? And how many of each daemon type? >> >> >> >> I'm using the C api, and there are 3 mon, 3 mds, 1 osd. >> >> >> >> > That said; I'm seeing broadly similar numbers ? with one of each >> >> > daemon (but otherwise the vstart defaults) "time sudo ceph-fuse mnt" >> >> > reports 3.1 seconds. >> >> >> >> >> >> -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, Aug 30, 2012 at 3:10 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: > Ok, this patch sorta solves the problem. After a fresh restart of the > daemons, the client hangs indefinitely (log urls attached for this > case). If I kill the client and restart, I get a behavior similar to > the original problem. Another client restart and everything is very > fast. This easily reproducible. I'm not quite sure what scenario you're describing here — let's see if I understand correctly: 1) Working cluster. 2) Restart server daemons. 3) Client just hangs. :( 4) Restart client and it goes slow through the mount (once?). 5) Restart client again and everything goes fast from then on. Is that right? If it is, 3 might be caused by a client bug, but then 4 (and also maybe 3) is probably just caused by the MDS server going through reconnect and timing out its client connection. > https://dl.dropbox.com/u/7899675/client.log > https://dl.dropbox.com/u/7899675/mds.a.log > https://dl.dropbox.com/u/7899675/mds.b.log > https://dl.dropbox.com/u/7899675/mds.c.log > > - Noah > > On Thu, Aug 30, 2012 at 1:39 PM, Sage Weil <sage@inktank.com> wrote: >> What about this: >> >> diff --git a/src/client/Client.cc b/src/client/Client.cc >> index 3333966..003e3f8 100644 >> --- a/src/client/Client.cc >> +++ b/src/client/Client.cc >> @@ -294,6 +294,7 @@ int Client::init() >> monclient->set_want_keys(CEPH_ENTITY_TYPE_MDS | CEPH_ENTITY_TYPE_OSD); >> monclient->sub_want("mdsmap", 0, 0); >> monclient->sub_want("osdmap", 0, CEPH_SUBSCRIBE_ONETIME); >> + monclient->renew_subs(); >> >> // logger >> PerfCountersBuilder plb(cct, "client", l_c_first, l_c_last); >> >> >> If that doesn't do it, can you reproduce with 'debug client = 20' and >> 'debug monc = 20'? >> >> Thanks! >> sage >> >> >> >> On Thu, 30 Aug 2012, Noah Watkins wrote: >> >>> Here ya go: >>> >>> https://dl.dropbox.com/u/7899675/client.log >>> https://dl.dropbox.com/u/7899675/mds.a.log >>> https://dl.dropbox.com/u/7899675/mds.b.log >>> https://dl.dropbox.com/u/7899675/mds.c.log >>> >>> - Noah >>> >>> On Thu, Aug 30, 2012 at 1:15 PM, Sage Weil <sage@inktank.com> wrote: >>> > I see that Server::handle_client_session is calling mdlog->flush(), so >>> > it's a bit odd. Can you generate a log with 'debug ms = 1' on the client >>> > (and maybe mds) side? >>> > >>> > s >>> > >>> > On Thu, 30 Aug 2012, Noah Watkins wrote: >>> > >>> >> On Thu, Aug 30, 2012 at 1:06 PM, Gregory Farnum <greg@inktank.com> wrote: >>> >> > On Thu, Aug 30, 2012 at 12:55 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: >>> >> >> Using a tick interval of 1 drops the cost down to 3 seconds, but still >>> >> >> a long time for running many unit tests that use fresh mounts. >>> >> > >>> >> > Are you using ceph-fuse or the kernel client? And how many of each daemon type? >>> >> >>> >> I'm using the C api, and there are 3 mon, 3 mds, 1 osd. >>> >> >>> >> > That said; I'm seeing broadly similar numbers ? with one of each >>> >> > daemon (but otherwise the vstart defaults) "time sudo ceph-fuse mnt" >>> >> > reports 3.1 seconds. >>> >> >>> >> >>> >>> -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, Aug 30, 2012 at 3:17 PM, Gregory Farnum <greg@inktank.com> wrote: > On Thu, Aug 30, 2012 at 3:10 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: >> Ok, this patch sorta solves the problem. After a fresh restart of the >> daemons, the client hangs indefinitely (log urls attached for this >> case). If I kill the client and restart, I get a behavior similar to >> the original problem. Another client restart and everything is very >> fast. This easily reproducible. > > I'm not quite sure what scenario you're describing here — let's see if > I understand correctly: > 1) Working cluster. > 2) Restart server daemons. > 3) Client just hangs. :( > 4) Restart client and it goes slow through the mount (once?). > 5) Restart client again and everything goes fast from then on. Yeh, remove (4) -- there was some other fluke, I think. The following happens every time with the one line patch from Sage: 2) Restart daemons 3) Client hangs in mount 4) Restart client and everything runs very fast from now on. Without the patch, the client never hangs, but is consistently slow to mount. - Noah -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, 30 Aug 2012, Noah Watkins wrote: > On Thu, Aug 30, 2012 at 3:17 PM, Gregory Farnum <greg@inktank.com> wrote: > > On Thu, Aug 30, 2012 at 3:10 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: > >> Ok, this patch sorta solves the problem. After a fresh restart of the > >> daemons, the client hangs indefinitely (log urls attached for this > >> case). If I kill the client and restart, I get a behavior similar to > >> the original problem. Another client restart and everything is very > >> fast. This easily reproducible. > > > > I'm not quite sure what scenario you're describing here ? let's see if > > I understand correctly: > > 1) Working cluster. > > 2) Restart server daemons. > > 3) Client just hangs. :( > > 4) Restart client and it goes slow through the mount (once?). > > 5) Restart client again and everything goes fast from then on. > > Yeh, remove (4) -- there was some other fluke, I think. The following > happens every time with the one line patch from Sage: > > 2) Restart daemons > 3) Client hangs in mount > 4) Restart client and everything runs very fast from now on. > > Without the patch, the client never hangs, but is consistently slow to mount. I think this is just the mds reconnect delay; it's complete normal when the mds restarts and some of the clients also crashed that it has to wait for the full reconnect window to pass. I pushed the fix to master! sage -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, Aug 30, 2012 at 3:39 PM, Sage Weil <sage@inktank.com> wrote: > On Thu, 30 Aug 2012, Noah Watkins wrote: > > I think this is just the mds reconnect delay; it's complete normal when > the mds restarts and some of the clients also crashed that it has to wait > for the full reconnect window to pass. Are you talking about the clients running during the restart? In the case I'm describing I bring down all daemons and the client, before starting the cluster and re-running the test. - Noah -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, Aug 30, 2012 at 3:44 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: > On Thu, Aug 30, 2012 at 3:39 PM, Sage Weil <sage@inktank.com> wrote: >> On Thu, 30 Aug 2012, Noah Watkins wrote: >> >> I think this is just the mds reconnect delay; it's complete normal when >> the mds restarts and some of the clients also crashed that it has to wait >> for the full reconnect window to pass. > > Are you talking about the clients running during the restart? In the > case I'm describing I bring down all daemons and the client, before > starting the cluster and re-running the test. How long a hang have you observed? Since you brought down a client, the MDS needs to wait through a full time-out period before letting other people do things (it's giving the previous client a chance to claim some state). The default looks to be 45 seconds right now. But the patch shouldn't have changed that behavior in any way; so if it's actually different behavior in testing then we just broke...something else, somehow... -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
The delay is indefinite (I was killing it after >3 minutes). Interestingly, this "first mount" hang issue is not present after a restart of a fresh file system (./vstart.sh -n), but always occurs if I restart with an existing file system untouched (./stop.sh && ./vstart). - Noah On Thu, Aug 30, 2012 at 3:47 PM, Gregory Farnum <greg@inktank.com> wrote: > On Thu, Aug 30, 2012 at 3:44 PM, Noah Watkins <jayhawk@cs.ucsc.edu> wrote: >> On Thu, Aug 30, 2012 at 3:39 PM, Sage Weil <sage@inktank.com> wrote: >>> On Thu, 30 Aug 2012, Noah Watkins wrote: >>> >>> I think this is just the mds reconnect delay; it's complete normal when >>> the mds restarts and some of the clients also crashed that it has to wait >>> for the full reconnect window to pass. >> >> Are you talking about the clients running during the restart? In the >> case I'm describing I bring down all daemons and the client, before >> starting the cluster and re-running the test. > > How long a hang have you observed? Since you brought down a client, > the MDS needs to wait through a full time-out period before letting > other people do things (it's giving the previous client a chance to > claim some state). The default looks to be 45 seconds right now. > > But the patch shouldn't have changed that behavior in any way; so if > it's actually different behavior in testing then we just > broke...something else, somehow... -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/src/client/Client.cc b/src/client/Client.cc index 3333966..003e3f8 100644 --- a/src/client/Client.cc +++ b/src/client/Client.cc @@ -294,6 +294,7 @@ int Client::init() monclient->set_want_keys(CEPH_ENTITY_TYPE_MDS | CEPH_ENTITY_TYPE_OSD); monclient->sub_want("mdsmap", 0, 0); monclient->sub_want("osdmap", 0, CEPH_SUBSCRIBE_ONETIME); + monclient->renew_subs(); // logger PerfCountersBuilder plb(cct, "client", l_c_first, l_c_last);