From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from sog-mx-1.v43.ch3.sourceforge.com ([172.29.43.191] helo=mx.sourceforge.net) by sfs-ml-4.v29.ch3.sourceforge.com with esmtp (Exim 4.76) (envelope-from ) id 1VQuW5-0001KS-Aw for bitcoin-development@lists.sourceforge.net; Tue, 01 Oct 2013 07:37:09 +0000 Received-SPF: neutral (sog-mx-1.v43.ch3.sourceforge.com: 74.220.216.66 is neither permitted nor denied by domain of trillion01.com) client-ip=74.220.216.66; envelope-from=olivier@trillion01.com; helo=oproxy4-pub.mail.unifiedlayer.com; Received: from oproxy4-pub.mail.unifiedlayer.com ([74.220.216.66]) by sog-mx-1.v43.ch3.sourceforge.com with smtp (Exim 4.76) id 1VQuW3-0000wK-Ee for bitcoin-development@lists.sourceforge.net; Tue, 01 Oct 2013 07:37:09 +0000 Received: (qmail 29465 invoked by uid 0); 1 Oct 2013 07:10:19 -0000 Received: from unknown (HELO box610.bluehost.com) (70.40.220.110) by oproxy4.mail.unifiedlayer.com with SMTP; 1 Oct 2013 07:10:19 -0000 Received: from [173.179.63.169] (port=41659 helo=[192.168.1.104]) by box610.bluehost.com with esmtpsa (TLSv1:RC4-SHA:128) (Exim 4.80) (envelope-from ) id 1VQu67-0001K2-KV; Tue, 01 Oct 2013 01:10:19 -0600 Message-ID: <1380611418.932.31.camel@Wailaba2> From: Olivier Langlois To: slush Date: Tue, 01 Oct 2013 03:10:18 -0400 In-Reply-To: <1380600219.932.21.camel@Wailaba2> References: <1380600219.932.21.camel@Wailaba2> Organization: Trillion01 Inc Content-Type: text/plain; charset="ISO-8859-1" X-Mailer: Evolution 3.8.5 Mime-Version: 1.0 Content-Transfer-Encoding: 7bit X-Identified-User: {5686:box610.bluehost.com:olivierl:trillion01.com} {sentby:smtp auth 173.179.63.169 authed with olivier@trillion01.com} X-Spam-Score: 0.7 (/) X-Spam-Report: Spam Filtering performed by mx.sourceforge.net. See http://spamassassin.org/tag/ for more details. 0.7 SPF_NEUTRAL SPF: sender does not match SPF record (neutral) X-Headers-End: 1VQuW3-0000wK-Ee Cc: "bitcoin-development@lists.sourceforge.net" Subject: Re: [Bitcoin-development] bitcoind stops responding X-BeenThere: bitcoin-development@lists.sourceforge.net X-Mailman-Version: 2.1.9 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 01 Oct 2013 07:37:09 -0000 > > Not sure yet exactly where the problem is but my current #1 suspect is: > > LOCK2(cs_main, pwalletMain->cs_wallet); > > with some kind of lock contention with the other threads. > I was right. It took more than 6 seconds to acquire the locks I did modify bitcoinrpc.cpp: namespace { struct timeval difftv( const struct timeval &tv1, const struct timeval &tv2 ) { struct timeval res; res.tv_sec = tv1.tv_sec - tv2.tv_sec; if (tv2.tv_usec > tv1.tv_usec) { res.tv_sec--; res.tv_usec = 1000000; } else res.tv_usec = 0; res.tv_usec += tv1.tv_usec; res.tv_usec -= tv2.tv_usec; return res; } void printExecTimes( const struct timeval &tv1, const struct timeval &tv2, const struct timeval &tv3 ) { struct timeval lockTime = difftv(tv2,tv1); struct timeval callTime = difftv(tv3,tv2); struct timeval totalTime = difftv(tv3,tv1); printf( "locktime : %ld.%06ld calltime : %ld.%06ld totaltime : % ld.%06ld\n", lockTime.tv_sec,lockTime.tv_usec,callTime.tv_sec,callTime.tv_usec, totalTime.tv_sec,totalTime.tv_usec); } } json_spirit::Value CRPCTable::execute(const std::string &strMethod, const json_spirit::Array ¶ms) const { // Find method const CRPCCommand *pcmd = tableRPC[strMethod]; if (!pcmd) throw JSONRPCError(RPC_METHOD_NOT_FOUND, "Method not found"); // Observe safe mode string strWarning = GetWarnings("rpc"); if (strWarning != "" && !GetBoolArg("-disablesafemode") && !pcmd->okSafeMode) throw JSONRPCError(RPC_FORBIDDEN_BY_SAFE_MODE, string("Safe mode: ") + strWarning); try { // Execute Value result; { if (pcmd->threadSafe) result = pcmd->actor(params, false); else { struct timeval tv1,tv2,tv3; gettimeofday(&tv1,NULL); { LOCK2(cs_main, pwalletMain->cs_wallet); gettimeofday(&tv2,NULL); result = pcmd->actor(params, false); } gettimeofday(&tv3,NULL); printExecTimes(tv1,tv2,tv3); } } return result; } catch (std::exception& e) { throw JSONRPCError(RPC_MISC_ERROR, e.what()); } } locktime : 0.000001 calltime : 0.000153 totaltime : 0.000154 locktime : 0.000000 calltime : 0.000011 totaltime : 0.000011 locktime : 0.000000 calltime : 0.000451 totaltime : 0.000451 locktime : 0.000000 calltime : 0.000313 totaltime : 0.000313 locktime : 0.000000 calltime : 0.000011 totaltime : 0.000011 locktime : 0.051574 calltime : 0.000377 totaltime : 0.051951 locktime : 0.000000 calltime : 0.000222 totaltime : 0.000222 locktime : 0.000000 calltime : 0.000011 totaltime : 0.000011 locktime : 0.121106 calltime : 0.000471 totaltime : 0.121577 locktime : 0.078093 calltime : 0.000451 totaltime : 0.078544 locktime : 0.101185 calltime : 0.000021 totaltime : 0.101206 locktime : 0.000000 calltime : 0.000476 totaltime : 0.000476 locktime : 0.000001 calltime : 0.000291 totaltime : 0.000292 locktime : 0.000000 calltime : 0.000017 totaltime : 0.000017 locktime : 0.003025 calltime : 0.000036 totaltime : 0.003061 locktime : 0.000000 calltime : 0.000383 totaltime : 0.000383 locktime : 0.000000 calltime : 0.000210 totaltime : 0.000210 locktime : 0.000000 calltime : 0.000016 totaltime : 0.000016 locktime : 0.000000 calltime : 0.000470 totaltime : 0.000470 locktime : 0.000000 calltime : 0.000295 totaltime : 0.000295 locktime : 0.000000 calltime : 0.000020 totaltime : 0.000020 locktime : 0.000001 calltime : 0.000385 totaltime : 0.000386 locktime : 0.000000 calltime : 0.000241 totaltime : 0.000241 locktime : 0.000000 calltime : 0.000017 totaltime : 0.000017 locktime : 0.000001 calltime : 0.000308 totaltime : 0.000309 locktime : 0.000000 calltime : 0.000164 totaltime : 0.000164 locktime : 0.000000 calltime : 0.000017 totaltime : 0.000017 locktime : 0.000000 calltime : 0.000376 totaltime : 0.000376 locktime : 0.000000 calltime : 0.000356 totaltime : 0.000356 locktime : 0.000000 calltime : 0.000021 totaltime : 0.000021 locktime : 0.000000 calltime : 0.000496 totaltime : 0.000496 locktime : 0.000001 calltime : 0.000201 totaltime : 0.000202 locktime : 0.000001 calltime : 0.000017 totaltime : 0.000018 locktime : 0.000000 calltime : 0.000301 totaltime : 0.000301 locktime : 0.000000 calltime : 0.000180 totaltime : 0.000180 locktime : 0.000000 calltime : 0.000016 totaltime : 0.000016 locktime : 0.000001 calltime : 0.000359 totaltime : 0.000360 locktime : 0.000000 calltime : 0.000265 totaltime : 0.000265 locktime : 0.000000 calltime : 0.000017 totaltime : 0.000017 locktime : 0.000001 calltime : 0.000488 totaltime : 0.000489 locktime : 0.000000 calltime : 0.000226 totaltime : 0.000226 locktime : 0.000000 calltime : 0.000025 totaltime : 0.000025 locktime : 0.000000 calltime : 0.000369 totaltime : 0.000369 locktime : 0.000000 calltime : 0.000262 totaltime : 0.000262 locktime : 0.000000 calltime : 0.000017 totaltime : 0.000017 locktime : 0.000000 calltime : 0.000459 totaltime : 0.000459 locktime : 0.000000 calltime : 0.000260 totaltime : 0.000260 locktime : 0.000000 calltime : 0.000017 totaltime : 0.000017 locktime : 0.000000 calltime : 0.000330 totaltime : 0.000330 locktime : 0.000000 calltime : 0.000223 totaltime : 0.000223 locktime : 0.000000 calltime : 0.000014 totaltime : 0.000014 locktime : 0.000001 calltime : 0.000449 totaltime : 0.000450 locktime : 0.000001 calltime : 0.000248 totaltime : 0.000249 locktime : 0.000000 calltime : 0.000017 totaltime : 0.000017 locktime : 0.000000 calltime : 0.000327 totaltime : 0.000327 locktime : 0.000000 calltime : 0.000196 totaltime : 0.000196 locktime : 0.000000 calltime : 0.000016 totaltime : 0.000016 locktime : 0.121170 calltime : 0.000408 totaltime : 0.121578 locktime : 0.004912 calltime : 0.000278 totaltime : 0.005190 locktime : 0.000000 calltime : 0.000016 totaltime : 0.000016 locktime : 5.996820 calltime : 0.000328 totaltime : 5.997148