CephFS mount delay

CephFS mount delay

[Noah Watkins]

I'm experiencing delays of around 4-5 seconds when mounting the cephfs
client. The setup is both client and servers are on a local machine
which is otherwise idle, with the stock ceph.conf generated from
./vstart.sh. Is this length of delay expected, or do I have some
configuration out of whack? I'm not sure its relevant, but I'm using
'admin' as the 'id' parameter to ceph_create.

Thanks,
Noah

Re: CephFS mount delay

[Sage Weil]

On Thu, 30 Aug 2012, Noah Watkins wrote:
> I'm experiencing delays of around 4-5 seconds when mounting the cephfs
> client. The setup is both client and servers are on a local machine
> which is otherwise idle, with the stock ceph.conf generated from
> ./vstart.sh. Is this length of delay expected, or do I have some
> configuration out of whack? I'm not sure its relevant, but I'm using
> 'admin' as the 'id' parameter to ceph_create.

That's not expected.  It may be that the mds isn't flushing the log after 
the client session event is queued.  What happens if you set 'mds tick 
interval = 1' (default is 5).  (Btw you can add random crap to vstart.sh's 
config with -o 'foo = bar'.)

sage

Re: CephFS mount delay

[Noah Watkins]

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.

-Noah

On Thu, Aug 30, 2012 at 12:35 PM, Sage Weil <sage@inktank.com> wrote:
> On Thu, 30 Aug 2012, Noah Watkins wrote:
>> I'm experiencing delays of around 4-5 seconds when mounting the cephfs
>> client. The setup is both client and servers are on a local machine
>> which is otherwise idle, with the stock ceph.conf generated from
>> ./vstart.sh. Is this length of delay expected, or do I have some
>> configuration out of whack? I'm not sure its relevant, but I'm using
>> 'admin' as the 'id' parameter to ceph_create.
>
> That's not expected.  It may be that the mds isn't flushing the log after
> the client session event is queued.  What happens if you set 'mds tick
> interval = 1' (default is 5).  (Btw you can add random crap to vstart.sh's
> config with -o 'foo = bar'.)
>
> sage

Re: CephFS mount delay

[Gregory Farnum]

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?

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

Re: CephFS mount delay

[Noah Watkins]

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

Re: CephFS mount delay

[Sage Weil]

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.
> 
> 

Re: CephFS mount delay

[Gregory Farnum]

It's not an MDS problem; it handles the client mount requests in at
most .2 seconds. I'm looking through the client log and I see:

2012-08-30 12:48:21.875546 7f8a6d1f3780 10 client.4105  target mds.0
not active, waiting for new mdsmap
2012-08-30 12:48:21.875771 7f8a68737710  1 -- 192.168.106.225:0/2716
<== mon.0 192.168.106.225:6789/0 5 ==== osd_map(5..5 src has 1..5) v3
==== 1376+0+0 (2208396468 0 0) 0x2e56a00 con 0x2e68640
2012-08-30 12:48:24.872889 7f8a67f36710  1 -- 192.168.106.225:0/2716
--> 192.168.106.225:6789/0 -- mon_subscribe({mdsmap=0+,monmap=2+}) v2
-- ?+0 0x2e65700 con 0x2e68640

So it looks like it's waiting for some internal tick before sending
off the MDSMap request to the monitor?
(Both the monitor and MDS logs indicate they're promptly satisfying
the client requests as soon as received, as well. So this is
definitely the issue.)
-Greg

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.
>>
>>

Re: CephFS mount delay

[Noah Watkins]

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.
>>
>>

Re: CephFS mount delay

[Sage Weil]

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.
> >>
> >>
> 
> 

Re: CephFS mount delay

[Mike Ryan]

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

Re: CephFS mount delay

[Gregory Farnum]

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

Re: CephFS mount delay

[Sage Weil]

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
> 
> 

Re: CephFS mount delay

[Noah Watkins]

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.
>> >>
>> >>
>>
>>

Re: CephFS mount delay

[Gregory Farnum]

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

Re: CephFS mount delay

[Noah Watkins]

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

Re: CephFS mount delay

[Sage Weil]

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

Re: CephFS mount delay

[Noah Watkins]

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

Re: CephFS mount delay

[Gregory Farnum]

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...

Re: CephFS mount delay

[Noah Watkins]

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...