monitor dispatch queue seems backed up?

monitor dispatch queue seems backed up?

[Jim Schutt]

Hi,

I'm continuing my testing of the master branch
(commit 1ed2d8c587) against 96 osds.

I'm having trouble getting a new filesystem to
start up.  FWIW this size filesystem starts up
in a minute or two at most under the stable branch.

I'm using the attached patch to log message
queue wait times.  I'm seeing excessive queuing times,
and the message dispatch queue is really backed up as
a result:

2011-03-04 10:03:47.144090 7fd7849ea940 -- 172.17.40.34:6789/0 dispatch_throttle_release 52 to dispatch throttler 104760196/104857600
2011-03-04 10:03:47.147846 7fd7849ea940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6812/28404 pipe(0x7fd768586d30 sd=73 pgs=89 cs=1 l=1).reader wants 52 from dispatch throttler 104760144/104857600
2011-03-04 10:03:47.250609 7fd77a6a6940 -- 172.17.40.34:6789/0 dispatch_throttle_release 53 to dispatch throttler 104760196/104857600
2011-03-04 10:03:47.254636 7fd77a6a6940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6818/26733 pipe(0x7fd7685870f0 sd=7 pgs=110 cs=1 l=1).reader wants 53 from dispatch throttler 104760143/104857600
2011-03-04 10:03:47.291575 7fd787b0d940 mon.an14@0(leader) e1 ms_dispatch existing session MonSession: osd78 172.17.40.31:6818/30346 is open for osd78 172.17.40.31:6818/30346
2011-03-04 10:03:47.327148 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_throttle_release 270286 to dispatch throttler 104760196/104857600
2011-03-04 10:03:47.327186 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_entry done with 0x2767540 que_et 694.609439 op_et 18.173758 tot_et 712.783197
2011-03-04 10:03:47.334681 7fd787b0d940 mon.an14@0(leader) e1 ms_dispatch existing session MonSession: osd22 172.17.40.23:6818/25413 is open for osd22 172.17.40.23:6818/25413
2011-03-04 10:03:47.340074 7fd779f9f940 -- 172.17.40.34:6789/0 >> 172.17.40.33:6815/10175 pipe(0x7fd7806f94e0 sd=53 pgs=29 cs=1 l=1).reader wants 22 from dispatch throttler 104705742/104857600
2011-03-04 10:03:47.340586 7fd779f9f940 -- 172.17.40.34:6789/0 >> 172.17.40.33:6815/10175 pipe(0x7fd7806f94e0 sd=53 pgs=29 cs=1 l=1).reader wants 215832 from dispatch throttler 104705764/104857600
2011-03-04 10:03:47.369077 7fd73fdfd940 -- 172.17.40.34:6789/0 dispatch_throttle_release 53 to dispatch throttler 104705764/104857600
2011-03-04 10:03:47.373492 7fd73fdfd940 -- 172.17.40.34:6789/0 >> 172.17.40.31:6821/30438 pipe(0x7fd76858a430 sd=75 pgs=93 cs=1 l=1).reader wants 53 from dispatch throttler 104705711/104857600
2011-03-04 10:03:47.379362 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_throttle_release 326202 to dispatch throttler 104705764/104857600
2011-03-04 10:03:47.379401 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_entry done with 0x7fd75d9d2cb0 que_et 714.277852 op_et 0.044714 tot_et 714.322566
2011-03-04 10:03:47.395951 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 22 from dispatch throttler 104644280/104857600
2011-03-04 10:03:47.396294 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644302/104857600
2011-03-04 10:03:47.396818 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644486/104857600
2011-03-04 10:03:47.397276 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644670/104857600
2011-03-04 10:03:47.397499 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644854/104857600
2011-03-04 10:03:47.397698 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104645038/104857600
2011-03-04 10:03:47.397954 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104645222/104857600


I'm still digging to see if I can isolate what's happening;
I've got full logs available on request, and can reproduce 
with more debugging as needed.

-- Jim

From 8eb5f27bdc3bee7ab8c7af58717fad9f313dca42 Mon Sep 17 00:00:00 2001
From: Jim Schutt <jaschut@sandia.gov>
Date: Thu, 24 Feb 2011 16:42:50 -0700
Subject: [PATCH] Refine debug printing for handling message dispatch.


Signed-off-by: Jim Schutt <jaschut@sandia.gov>
---
 src/msg/SimpleMessenger.cc |   17 ++++++++++++++---
 src/osd/OSD.cc             |    3 +++
 2 files changed, 17 insertions(+), 3 deletions(-)

diff --git a/src/msg/SimpleMessenger.cc b/src/msg/SimpleMessenger.cc
index 23e6b29..96e74e9 100644
--- a/src/msg/SimpleMessenger.cc
+++ b/src/msg/SimpleMessenger.cc
@@ -352,17 +352,26 @@ void SimpleMessenger::dispatch_entry()
 		  << " " << m->get_footer().data_crc << ")"
 		  << " " << m << " con " << m->get_connection()
 		  << dendl;
+	  utime_t recv_stamp = m->get_recv_stamp();
+	  utime_t disp_stamp = g_clock.now();
 	  ms_deliver_dispatch(m);
 
 	  dispatch_throttle_release(msize);
 
-	  dout(20) << "done calling dispatch on " << m << dendl;
+	  utime_t done_stamp = g_clock.now();
+	  dout(20) << "dispatch_entry done with " << m
+		   << " que_et " << disp_stamp - recv_stamp
+		   << " op_et " << done_stamp - disp_stamp
+		   << " tot_et " << done_stamp - recv_stamp << dendl;
 	}
       }
       dispatch_queue.lock.Lock();
     }
-    if (!dispatch_queue.stop)
+    if (!dispatch_queue.stop) {
+      dout(20) << " Waiting for new work on SimpleMessenger dispatch queue" << dendl;
       dispatch_queue.cond.Wait(dispatch_queue.lock); //wait for something to be put on queue
+      dout(20) << " Got new work on SimpleMessenger dispatch queue" << dendl;
+    }
   }
   dispatch_queue.lock.Unlock();
 
@@ -553,8 +562,10 @@ void SimpleMessenger::Pipe::queue_received(Message *m, int priority)
       dout(20) << "queue_received queuing pipe" << dendl;
       if (!queue_items.count(priority)) 
 	queue_items[priority] = new xlist<Pipe *>::item(this);
-      if (messenger->dispatch_queue.queued_pipes.empty())
+      if (messenger->dispatch_queue.queued_pipes.empty()) {
+	dout(20) << " Waking up SimpleMessenger dispatch queue" << dendl;
 	messenger->dispatch_queue.cond.Signal();
+      }
       messenger->dispatch_queue.queued_pipes[priority].push_back(queue_items[priority]);
     }
 
-- 
1.6.6

Re: monitor dispatch queue seems backed up?

[Sage Weil]

> Hi,
> 
> I'm continuing my testing of the master branch
> (commit 1ed2d8c587) against 96 osds.
> 
> I'm having trouble getting a new filesystem to
> start up.  FWIW this size filesystem starts up
> in a minute or two at most under the stable branch.

The main thing that's changed since then is the default number of PGs has 
gone up.  Can you try changing the osd_pg_bits to 6 in common/config.cc, 
rebuild, and re-mkcephfs, and see if that gives you behavior similar to 
stable?  (mkcephfs isn't currently letting you adjust that yet.)

I suspect this is just a problem with the size of the various pg map<>s on 
the monitor (they're O(log n) for most operations).

Thanks!
sage



On Fri, 4 Mar 2011, Jim Schutt wrote:

> I'm using the attached patch to log message
> queue wait times.  I'm seeing excessive queuing times,
> and the message dispatch queue is really backed up as
> a result:
> 
> 2011-03-04 10:03:47.144090 7fd7849ea940 -- 172.17.40.34:6789/0 dispatch_throttle_release 52 to dispatch throttler 104760196/104857600
> 2011-03-04 10:03:47.147846 7fd7849ea940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6812/28404 pipe(0x7fd768586d30 sd=73 pgs=89 cs=1 l=1).reader wants 52 from dispatch throttler 104760144/104857600
> 2011-03-04 10:03:47.250609 7fd77a6a6940 -- 172.17.40.34:6789/0 dispatch_throttle_release 53 to dispatch throttler 104760196/104857600
> 2011-03-04 10:03:47.254636 7fd77a6a6940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6818/26733 pipe(0x7fd7685870f0 sd=7 pgs=110 cs=1 l=1).reader wants 53 from dispatch throttler 104760143/104857600
> 2011-03-04 10:03:47.291575 7fd787b0d940 mon.an14@0(leader) e1 ms_dispatch existing session MonSession: osd78 172.17.40.31:6818/30346 is open for osd78 172.17.40.31:6818/30346
> 2011-03-04 10:03:47.327148 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_throttle_release 270286 to dispatch throttler 104760196/104857600
> 2011-03-04 10:03:47.327186 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_entry done with 0x2767540 que_et 694.609439 op_et 18.173758 tot_et 712.783197
> 2011-03-04 10:03:47.334681 7fd787b0d940 mon.an14@0(leader) e1 ms_dispatch existing session MonSession: osd22 172.17.40.23:6818/25413 is open for osd22 172.17.40.23:6818/25413
> 2011-03-04 10:03:47.340074 7fd779f9f940 -- 172.17.40.34:6789/0 >> 172.17.40.33:6815/10175 pipe(0x7fd7806f94e0 sd=53 pgs=29 cs=1 l=1).reader wants 22 from dispatch throttler 104705742/104857600
> 2011-03-04 10:03:47.340586 7fd779f9f940 -- 172.17.40.34:6789/0 >> 172.17.40.33:6815/10175 pipe(0x7fd7806f94e0 sd=53 pgs=29 cs=1 l=1).reader wants 215832 from dispatch throttler 104705764/104857600
> 2011-03-04 10:03:47.369077 7fd73fdfd940 -- 172.17.40.34:6789/0 dispatch_throttle_release 53 to dispatch throttler 104705764/104857600
> 2011-03-04 10:03:47.373492 7fd73fdfd940 -- 172.17.40.34:6789/0 >> 172.17.40.31:6821/30438 pipe(0x7fd76858a430 sd=75 pgs=93 cs=1 l=1).reader wants 53 from dispatch throttler 104705711/104857600
> 2011-03-04 10:03:47.379362 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_throttle_release 326202 to dispatch throttler 104705764/104857600
> 2011-03-04 10:03:47.379401 7fd787b0d940 -- 172.17.40.34:6789/0 dispatch_entry done with 0x7fd75d9d2cb0 que_et 714.277852 op_et 0.044714 tot_et 714.322566
> 2011-03-04 10:03:47.395951 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 22 from dispatch throttler 104644280/104857600
> 2011-03-04 10:03:47.396294 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644302/104857600
> 2011-03-04 10:03:47.396818 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644486/104857600
> 2011-03-04 10:03:47.397276 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644670/104857600
> 2011-03-04 10:03:47.397499 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104644854/104857600
> 2011-03-04 10:03:47.397698 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104645038/104857600
> 2011-03-04 10:03:47.397954 7fd77e0e0940 -- 172.17.40.34:6789/0 >> 172.17.40.29:6800/26109 pipe(0x7fd7806decb0 sd=41 pgs=30 cs=1 l=1).reader wants 184 from dispatch throttler 104645222/104857600
> 
> 
> I'm still digging to see if I can isolate what's happening;
> I've got full logs available on request, and can reproduce 
> with more debugging as needed.
> 
> -- Jim
> 
> >From 8eb5f27bdc3bee7ab8c7af58717fad9f313dca42 Mon Sep 17 00:00:00 2001
> From: Jim Schutt <jaschut@sandia.gov>
> Date: Thu, 24 Feb 2011 16:42:50 -0700
> Subject: [PATCH] Refine debug printing for handling message dispatch.
> 
> 
> Signed-off-by: Jim Schutt <jaschut@sandia.gov>
> ---
>  src/msg/SimpleMessenger.cc |   17 ++++++++++++++---
>  src/osd/OSD.cc             |    3 +++
>  2 files changed, 17 insertions(+), 3 deletions(-)
> 
> diff --git a/src/msg/SimpleMessenger.cc b/src/msg/SimpleMessenger.cc
> index 23e6b29..96e74e9 100644
> --- a/src/msg/SimpleMessenger.cc
> +++ b/src/msg/SimpleMessenger.cc
> @@ -352,17 +352,26 @@ void SimpleMessenger::dispatch_entry()
>  		  << " " << m->get_footer().data_crc << ")"
>  		  << " " << m << " con " << m->get_connection()
>  		  << dendl;
> +	  utime_t recv_stamp = m->get_recv_stamp();
> +	  utime_t disp_stamp = g_clock.now();
>  	  ms_deliver_dispatch(m);
>  
>  	  dispatch_throttle_release(msize);
>  
> -	  dout(20) << "done calling dispatch on " << m << dendl;
> +	  utime_t done_stamp = g_clock.now();
> +	  dout(20) << "dispatch_entry done with " << m
> +		   << " que_et " << disp_stamp - recv_stamp
> +		   << " op_et " << done_stamp - disp_stamp
> +		   << " tot_et " << done_stamp - recv_stamp << dendl;
>  	}
>        }
>        dispatch_queue.lock.Lock();
>      }
> -    if (!dispatch_queue.stop)
> +    if (!dispatch_queue.stop) {
> +      dout(20) << " Waiting for new work on SimpleMessenger dispatch queue" << dendl;
>        dispatch_queue.cond.Wait(dispatch_queue.lock); //wait for something to be put on queue
> +      dout(20) << " Got new work on SimpleMessenger dispatch queue" << dendl;
> +    }
>    }
>    dispatch_queue.lock.Unlock();
>  
> @@ -553,8 +562,10 @@ void SimpleMessenger::Pipe::queue_received(Message *m, int priority)
>        dout(20) << "queue_received queuing pipe" << dendl;
>        if (!queue_items.count(priority)) 
>  	queue_items[priority] = new xlist<Pipe *>::item(this);
> -      if (messenger->dispatch_queue.queued_pipes.empty())
> +      if (messenger->dispatch_queue.queued_pipes.empty()) {
> +	dout(20) << " Waking up SimpleMessenger dispatch queue" << dendl;
>  	messenger->dispatch_queue.cond.Signal();
> +      }
>        messenger->dispatch_queue.queued_pipes[priority].push_back(queue_items[priority]);
>      }
>  
> -- 
> 1.6.6
> 
> 
> 
> 
> --
> 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: monitor dispatch queue seems backed up?

[Gregory Farnum]

On Friday, March 4, 2011 at 11:48 AM, Sage Weil wrote:
Hi,
> > 
> > I'm continuing my testing of the master branch
> > (commit 1ed2d8c587) against 96 osds.
> > 
> > I'm having trouble getting a new filesystem to
> > start up. FWIW this size filesystem starts up
> > in a minute or two at most under the stable branch.
> 
> The main thing that's changed since then is the default number of PGs has 
> gone up. Can you try changing the osd_pg_bits to 6 in common/config.cc, 
> rebuild, and re-mkcephfs, and see if that gives you behavior similar to 
> stable? (mkcephfs isn't currently letting you adjust that yet.)

Hmmm, I believe that if you set the osd_pg_bits in your ceph.conf it should get picked up by mkcephfs. :) Otherwise there are command-line options, and I have checked to make sure they work!
-Greg

Re: monitor dispatch queue seems backed up?

[Jim Schutt]

On Fri, 2011-03-04 at 12:48 -0700, Sage Weil wrote:
> > Hi,
> > 
> > I'm continuing my testing of the master branch
> > (commit 1ed2d8c587) against 96 osds.
> > 
> > I'm having trouble getting a new filesystem to
> > start up.  FWIW this size filesystem starts up
> > in a minute or two at most under the stable branch.
> 
> The main thing that's changed since then is the default number of PGs has 
> gone up.  Can you try changing the osd_pg_bits to 6 in common/config.cc, 
> rebuild, and re-mkcephfs, and see if that gives you behavior similar to 
> stable?  (mkcephfs isn't currently letting you adjust that yet.)

Sure, I'll give that a try.

> 
> I suspect this is just a problem with the size of the various pg map<>s on 
> the monitor (they're O(log n) for most operations).

I'm also trying to understand why my OSDs each 
need a couple dozen (!!) attempts before they
successfully connect to the monitor.  I'm in
the process of adding some extra diagnostics to
try to understand that.

Here's an OSD trying to connect:

# grep "mon0 172.17.40.34:6789/0" osd.0.log
2011-03-04 13:26:10.305195 7f379ce6f6f0 -- 0.0.0.0:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x2882e00
2011-03-04 13:26:13.305439 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x2882e00
2011-03-04 13:26:16.306263 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0009c0
2011-03-04 13:26:19.306693 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0009c0
2011-03-04 13:26:22.307165 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0009c0
2011-03-04 13:26:25.307613 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:26:28.308048 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:26:31.308626 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:26:34.309116 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:26:37.309551 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:26:40.310086 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0018e0
2011-03-04 13:26:43.310503 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:26:46.311607 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:26:49.312136 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c001280
2011-03-04 13:26:52.312534 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:26:55.336440 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:26:58.336978 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:27:01.337520 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:27:04.337945 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:27:07.338422 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:27:10.338834 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0015c0
2011-03-04 13:27:13.339393 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:27:16.339835 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:27:19.340282 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0013e0
2011-03-04 13:27:22.340709 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0013e0
2011-03-04 13:27:25.341182 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c001990
2011-03-04 13:27:28.341811 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:27:31.342372 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:27:34.342988 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c000be0
2011-03-04 13:27:37.343417 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:27:40.343966 7f3791685940 -- 172.17.40.21:6800/15577 --> mon0 172.17.40.34:6789/0 -- auth(proto 0 26 bytes) v1 -- ?+0 0x7f378c0008c0
2011-03-04 13:27:42.319377 7f3792e88940 -- 172.17.40.21:6800/15577 <== mon0 172.17.40.34:6789/0 1 ==== auth_reply(proto 1 0 Success) v1 ==== 24+0+0 (2593404908 0 0) 0x28835d0 con 0x7f378c0010e0

And here's the monitor ignoring it:

# grep 172.17.40.21:6800/15577 mon.an14.log | grep "read tag"
2011-03-04 13:26:13.301708 7f139b32f940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=1 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:16.302376 7f139b32f940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=2 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:19.303064 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=3 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:22.303488 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=4 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:25.303905 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=5 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:28.304367 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=6 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:31.304902 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=7 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:34.305400 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=8 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:37.305907 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=9 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:40.306360 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=10 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:43.306810 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=11 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:46.307858 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=12 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:49.308389 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=13 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:52.308881 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=14 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:55.309297 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x2bf1510 sd=10 pgs=15 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:26:58.333247 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x382e3c0 sd=88 pgs=16 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:01.333766 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x382e3c0 sd=88 pgs=17 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:04.334205 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x382e3c0 sd=88 pgs=18 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:07.334666 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x382e300 sd=88 pgs=19 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:10.335170 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x382e300 sd=88 pgs=20 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:13.335651 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x382e300 sd=88 pgs=21 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:16.336085 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x382e300 sd=87 pgs=22 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:19.336573 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x31a5150 sd=87 pgs=23 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:22.336946 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x31a5150 sd=87 pgs=24 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:25.337460 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x31a5150 sd=87 pgs=25 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:28.338088 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x31a5150 sd=86 pgs=26 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:31.338575 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x31a5150 sd=86 pgs=27 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:34.339265 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x7f1397686430 sd=86 pgs=28 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:37.339681 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x7f1397686430 sd=86 pgs=29 cs=1 l=1).reader couldn't read tag, Success
2011-03-04 13:27:40.340234 7f1392ded940 -- 172.17.40.34:6789/0 >> 172.17.40.21:6800/15577 pipe(0x7f1397686430 sd=86 pgs=30 cs=1 l=1).reader couldn't read tag, Success

That doesn't seem right to me, and the 3 second intervals
here seem awfully suspicious, but so far I haven't been
able to catch the socket code in the act of misbehaving.

During this time the monitor is trying to send pg updates, 
but can't because it has no one to talk to - none of the
OSDs has connected.

-- Jim

> 
> Thanks!
> sage
> 
> 

Re: monitor dispatch queue seems backed up?

[Sage Weil]

On Fri, 4 Mar 2011, Gregory Farnum wrote:
> On Friday, March 4, 2011 at 11:48 AM, Sage Weil wrote:
> Hi,
> > > 
> > > I'm continuing my testing of the master branch
> > > (commit 1ed2d8c587) against 96 osds.
> > > 
> > > I'm having trouble getting a new filesystem to
> > > start up. FWIW this size filesystem starts up
> > > in a minute or two at most under the stable branch.
> > 
> > The main thing that's changed since then is the default number of PGs has 
> > gone up. Can you try changing the osd_pg_bits to 6 in common/config.cc, 
> > rebuild, and re-mkcephfs, and see if that gives you behavior similar to 
> > stable? (mkcephfs isn't currently letting you adjust that yet.)
> 
> Hmmm, I believe that if you set the osd_pg_bits in your ceph.conf it 
> should get picked up by mkcephfs. :) Otherwise there are command-line 
> options, and I have checked to make sure they work!

You're right, I goofed my test.  FBIFW osdmaptool currently reads the 
ceph.conf.  We'll fix this with the new mkcephfs so that the tool can stop 
doing that :)

sage

Re: monitor dispatch queue seems backed up?

[Yehuda Sadeh Weinraub]

On Fri, Mar 4, 2011 at 12:38 PM, Gregory Farnum
<gregory.farnum@dreamhost.com> wrote:
> On Friday, March 4, 2011 at 11:48 AM, Sage Weil wrote:
> Hi,
>> >
>> > I'm continuing my testing of the master branch
>> > (commit 1ed2d8c587) against 96 osds.
>> >
>> > I'm having trouble getting a new filesystem to
>> > start up. FWIW this size filesystem starts up
>> > in a minute or two at most under the stable branch.
>>
>> The main thing that's changed since then is the default number of PGs has
>> gone up. Can you try changing the osd_pg_bits to 6 in common/config.cc,
>> rebuild, and re-mkcephfs, and see if that gives you behavior similar to
>> stable? (mkcephfs isn't currently letting you adjust that yet.)
>
> Hmmm, I believe that if you set the osd_pg_bits in your ceph.conf it should get picked up by mkcephfs. :) Otherwise there are command-line options, and I have checked to make sure they work!

you mean 'osd pg bits' in the ceph.conf?

Re: monitor dispatch queue seems backed up?

[Gregory Farnum]

On Friday, March 4, 2011 at 12:53 PM, Yehuda Sadeh Weinraub wrote:

> you mean 'osd pg bits' in the ceph.conf?
> 
Sorry, yes.

Jim, that 3 second gap is a configurable timeout/retry period; I don't remember exactly where it's set up. I suspect this failed reads problem is some kind of fallout from the activity with SIGPIPE yesterday (and signals in general the last few days), but couldn't say for sure on my own...
-Greg

Re: monitor dispatch queue seems backed up?

[Jim Schutt]

On Fri, 2011-03-04 at 12:48 -0700, Sage Weil wrote:
> > Hi,
> > 
> > I'm continuing my testing of the master branch
> > (commit 1ed2d8c587) against 96 osds.
> > 
> > I'm having trouble getting a new filesystem to
> > start up.  FWIW this size filesystem starts up
> > in a minute or two at most under the stable branch.
> 
> The main thing that's changed since then is the default number of PGs has 
> gone up.  Can you try changing the osd_pg_bits to 6 in common/config.cc, 
> rebuild, and re-mkcephfs, and see if that gives you behavior similar to 
> stable?  (mkcephfs isn't currently letting you adjust that yet.)

OK, I tried osd_pg_bits = 6 as you suggested.

The startup behavior is much like stable, except my "ceph -w"
seems to have some trouble connecting - it often needs to 
try multiple times before it is successful.

Unfortunately, the behavior under my 64-client write
test is also much like stable - I'm still getting
osds wrongly marked down.

I didn't dig into it enough yet to see if this is due to 
the same type of mysterious delays as I was finding
on stable.

-- Jim

> 
> I suspect this is just a problem with the size of the various pg map<>s on 
> the monitor (they're O(log n) for most operations).
> 
> Thanks!
> sage
> 
> 

Re: monitor dispatch queue seems backed up?

[Sage Weil]

On Fri, 4 Mar 2011, Jim Schutt wrote:
> On Fri, 2011-03-04 at 12:48 -0700, Sage Weil wrote:
> > > Hi,
> > > 
> > > I'm continuing my testing of the master branch
> > > (commit 1ed2d8c587) against 96 osds.
> > > 
> > > I'm having trouble getting a new filesystem to
> > > start up.  FWIW this size filesystem starts up
> > > in a minute or two at most under the stable branch.
> > 
> > The main thing that's changed since then is the default number of PGs has 
> > gone up.  Can you try changing the osd_pg_bits to 6 in common/config.cc, 
> > rebuild, and re-mkcephfs, and see if that gives you behavior similar to 
> > stable?  (mkcephfs isn't currently letting you adjust that yet.)
> 
> OK, I tried osd_pg_bits = 6 as you suggested.
> 
> The startup behavior is much like stable, except my "ceph -w"
> seems to have some trouble connecting - it often needs to 
> try multiple times before it is successful.

Okay.  We'll have more nodes up next week so hopefully I'll be able to 
reproduce this behavior.

> Unfortunately, the behavior under my 64-client write
> test is also much like stable - I'm still getting
> osds wrongly marked down.
> 
> I didn't dig into it enough yet to see if this is due to 
> the same type of mysterious delays as I was finding
> on stable.

I just pushed something to master that sprinkles debug prints all through 
the heartbeat thread.  Let's try to figure out where it is blocking.

My worry is that this is all the VM's fault: we're writing data, hit the 
dirty page limit, and thereafter any memory allocations or writes block.  
I've been assuming that only the thread that does the write gets blocked, 
but it may be that the VM blocks all threads in the process, or that it is 
a memory allocation (in the heartbeat thread) that is hitting the limit 
(balance_dirty_pages() IIRC).  We may need to make sure the heartbeat 
thread uses preallocated/locked memory or something.. :(

Anyway, getting more detailed logs will tell us which thread(s) are 
blocking when.  

Thanks!
sage

Re: monitor dispatch queue seems backed up?

[Jim Schutt]

On Fri, 2011-03-04 at 16:56 -0700, Sage Weil wrote:
> On Fri, 4 Mar 2011, Jim Schutt wrote:
> > On Fri, 2011-03-04 at 12:48 -0700, Sage Weil wrote:
> > > > Hi,
> > > > 
> > > > I'm continuing my testing of the master branch
> > > > (commit 1ed2d8c587) against 96 osds.
> > > > 
> > > > I'm having trouble getting a new filesystem to
> > > > start up.  FWIW this size filesystem starts up
> > > > in a minute or two at most under the stable branch.
> > > 
> > > The main thing that's changed since then is the default number of PGs has 
> > > gone up.  Can you try changing the osd_pg_bits to 6 in common/config.cc, 
> > > rebuild, and re-mkcephfs, and see if that gives you behavior similar to 
> > > stable?  (mkcephfs isn't currently letting you adjust that yet.)
> > 
> > OK, I tried osd_pg_bits = 6 as you suggested.
> > 
> > The startup behavior is much like stable, except my "ceph -w"
> > seems to have some trouble connecting - it often needs to 
> > try multiple times before it is successful.
> 
> Okay.  We'll have more nodes up next week so hopefully I'll be able to 
> reproduce this behavior.
> 
> > Unfortunately, the behavior under my 64-client write
> > test is also much like stable - I'm still getting
> > osds wrongly marked down.
> > 
> > I didn't dig into it enough yet to see if this is due to 
> > the same type of mysterious delays as I was finding
> > on stable.
> 
> I just pushed something to master that sprinkles debug prints all through 
> the heartbeat thread.  Let's try to figure out where it is blocking.
> 
> My worry is that this is all the VM's fault: we're writing data, hit the 
> dirty page limit, and thereafter any memory allocations or writes block.  
> I've been assuming that only the thread that does the write gets blocked, 
> but it may be that the VM blocks all threads in the process, or that it is 
> a memory allocation (in the heartbeat thread) that is hitting the limit 
> (balance_dirty_pages() IIRC).  We may need to make sure the heartbeat 
> thread uses preallocated/locked memory or something.. :(
> 
> Anyway, getting more detailed logs will tell us which thread(s) are 
> blocking when.  

OK.  FWIW, when I was digging into this on stable, one
thing I noticed is that when processing of a heatbeat
message stalled, the time between when it was dequeued
from the dispatch queue and when processing finished
was full of Reader/Writer thread processing, with the
occasional journal commit.

I'll recreate with your debugging, and see if I get
a similar behavior.  In any event, I'll have the logs
available.


-- Jim

> 
> Thanks!
> sage
>