From patchwork Tue Apr 2 19:16:28 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Jim Schutt X-Patchwork-Id: 2380161 Return-Path: X-Original-To: patchwork-ceph-devel@patchwork.kernel.org Delivered-To: patchwork-process-083081@patchwork1.kernel.org Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by patchwork1.kernel.org (Postfix) with ESMTP id E1B4B3FDDA for ; Tue, 2 Apr 2013 19:17:56 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932343Ab3DBTR4 (ORCPT ); Tue, 2 Apr 2013 15:17:56 -0400 Received: from sentry-two.sandia.gov ([132.175.109.14]:39340 "EHLO sentry-two.sandia.gov" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932283Ab3DBTRz (ORCPT ); Tue, 2 Apr 2013 15:17:55 -0400 X-WSS-ID: 0MKN6WT-0B-00L-02 X-M-MSG: Received: from interceptor2.sandia.gov (interceptor2.sandia.gov [132.175.109.18]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by sentry-two.sandia.gov (Postfix) with ESMTP id 1CCC9D2C25D; Tue, 2 Apr 2013 13:16:52 -0600 (MDT) Received: from sentry.sandia.gov (sentry.sandia.gov [132.175.109.21]) by interceptor2.sandia.gov (RSA Interceptor); Tue, 2 Apr 2013 13:16:52 -0600 Received: from [132.175.109.1] by sentry.sandia.gov with ESMTP (SMTP Relay 01 (Email Firewall v6.3.2)); Tue, 02 Apr 2013 13:16:29 -0600 X-Server-Uuid: AF72F651-81B1-4134-BA8C-A8E1A4E620FF Received: from mail.sandia.gov (exch01.sandia.gov [134.253.103.1] (may be forged)) by mailgate.sandia.gov (8.14.4/8.14.4) with ESMTP id r32JGTPr016214; Tue, 2 Apr 2013 13:16:29 -0600 Received: from [134.253.156.97] (134.253.95.171) by mail.sandia.gov ( 134.253.103.1) with Microsoft SMTP Server (TLS) id 14.2.342.3; Tue, 2 Apr 2013 13:16:28 -0600 Message-ID: <515B2E8C.5090001@sandia.gov> Date: Tue, 2 Apr 2013 13:16:28 -0600 From: "Jim Schutt" User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:17.0) Gecko/20130311 Thunderbird/17.0.3 MIME-Version: 1.0 To: "Joao Luis" cc: ceph-devel@vger.kernel.org Subject: Re: Trouble with paxos service for large PG count References: <5159F899.4090001@sandia.gov> <515AFC5F.4000705@inktank.com> <515B20F8.5060203@sandia.gov> In-Reply-To: X-TMWD-Spam-Summary: TS=20130402191630; ID=1; SEV=2.3.1; DFV=B2013022509; IFV=NA; AIF=B2013022509; RPD=5.03.0010; ENG=NA; RPDID=7374723D303030312E30413031303230322E35313542324538452E303042413A534346535441543838363133332C73733D312C6667733D30; CAT=NONE; CON=NONE; SIG=AAAAAAAAAAAAAAAAAAAAAAAAfQ== X-MMS-Spam-Filter-ID: B2013022509_5.03.0010 X-WSS-ID: 7D45F1072IW1310750-01-01 X-RSA-Inspected: yes X-RSA-Classifications: public X-RSA-Action: allow Sender: ceph-devel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: ceph-devel@vger.kernel.org On 04/02/2013 12:28 PM, Joao Luis wrote: > Right. I'll push a patch to bump that sort of output to 30 when I get home. Thanks - but FWIW, I don't think it's the root cause of my issue -- more below.... > > If you're willing, try reducing the paxos debug level to 0 and let us know > if those delays in the proposal go away. When I started debugging why I couldn't start new filesystems, several days ago, I wasn't using any debugging. It took me until last Friday to track the issue into paxos, which is when I turned on its debugging. Also, I've added the following bits of debug output: which produces this: 2013-04-02 13:04:22.311743 7ffff7fbe780 10 mon.cs31@0(leader).paxosservice(pgmap) propose_pending 2013-04-02 13:04:22.426810 7ffff7fbe780 10 mon.cs31@0(leader).paxosservice(pgmap) propose_pending - JSON formatting, encode took 0.000170 2013-04-02 13:04:22.426874 7ffff7fbe780 5 mon.cs31@0(leader).paxos(paxos active c 1..3) queue_proposal bl 19775198 bytes; ctx = 0x11e81f0 2013-04-02 13:04:22.426999 7ffff7fbe780 5 mon.cs31@0(leader).paxos(paxos preparing update c 1..3) propose_queued 4 19775198 bytes 2013-04-02 13:04:22.427003 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos preparing update c 1..3) propose_queued list_proposals 1 in queue: 2013-04-02 13:07:51.190312 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos preparing update c 1..3) begin for 4 19775198 bytes 2013-04-02 13:07:51.190860 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos updating c 1..3) begin - JSON formatting, debug_tx decode took 0.000002 2013-04-02 13:07:51.402134 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos updating c 1..3) begin - get_store()->apply_transaction took 0.211275 2013-04-02 13:07:51.402178 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos updating c 1..3) commit 4 2013-04-02 13:07:51.635113 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos active c 1..4) finish_queued_proposal finishing proposal 2013-04-02 13:07:51.635152 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos active c 1..4) finish_queued_proposal finish it (proposal = 0x1261340) 2013-04-02 13:07:51.635159 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos active c 1..4) finish_queued_proposal proposal took 209.208162 to finish 2013-04-02 13:07:51.635193 7ffff7fbe780 10 mon.cs31@0(leader).paxosservice(pgmap) _active I thought I was timing the same JSON formatting in propose_pending() and begin(), but they take much different amounts of time. I don't understand why yet..... Also, I just noticed the elapsed time between these two lines: 2013-04-02 13:04:22.427003 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos preparing update c 1..3) propose_queued list_proposals 1 in queue: 2013-04-02 13:07:51.190312 7ffff7fbe780 10 mon.cs31@0(leader).paxos(paxos preparing update c 1..3) begin for 4 19775198 bytes It accounts for nearly the whole of the delay that finish_queued_proposal() is reporting. Why did begin() take so long to start, I wonder ??? -- Jim > > -Joao --- 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/mon/Paxos.cc b/src/mon/Paxos.cc index bf3eb92..70a8b5d 100644 --- a/src/mon/Paxos.cc +++ b/src/mon/Paxos.cc @@ -494,6 +494,8 @@ void Paxos::begin(bufferlist& v) MonitorDBStore::Transaction t; t.put(get_name(), last_committed+1, new_value); + utime_t tstart = ceph_clock_now(g_ceph_context); + dout(30) << __func__ << " transaction dump:\n"; JSONFormatter f(true); t.dump(&f); @@ -506,7 +508,14 @@ void Paxos::begin(bufferlist& v) f.flush(*_dout); *_dout << dendl; + dout(10) << __func__ << " - JSON formatting, debug_tx decode took " + << ceph_clock_now(g_ceph_context) - tstart << dendl; + + tstart = ceph_clock_now(g_ceph_context); get_store()->apply_transaction(t); + dout(10) << __func__ << " - get_store()->apply_transaction took " + << ceph_clock_now(g_ceph_context) - tstart << dendl; + if (mon->get_quorum().size() == 1) { // we're alone, take it easy diff --git a/src/mon/PaxosService.cc b/src/mon/PaxosService.cc index a66c5ec..808ce62 100644 --- a/src/mon/PaxosService.cc +++ b/src/mon/PaxosService.cc @@ -158,6 +158,8 @@ void PaxosService::propose_pending() encode_pending(&t); have_pending = false; + utime_t tstart = ceph_clock_now(g_ceph_context); + dout(30) << __func__ << " transaction dump:\n"; JSONFormatter f(true); t.dump(&f); @@ -166,6 +168,9 @@ void PaxosService::propose_pending() t.encode(bl); + dout(10) << __func__ << " - JSON formatting, encode took " + << ceph_clock_now(g_ceph_context) - tstart << dendl; + // apply to paxos proposing.set(1); paxos->propose_new_value(bl, new C_Committed(this));