From 97f936d30ce16e9873eba437d6c3d0043f773afb Mon Sep 17 00:00:00 2001 From: Gav Wood Date: Thu, 7 May 2015 11:52:35 +0200 Subject: [PATCH] Only report worker stuff when it's laggy. Cleanups ETH_ -> DEV_ --- alethzero/MainWin.cpp | 4 +++ libdevcore/Common.cpp | 12 +++++++- libdevcore/Common.h | 16 +++++++++-- libdevcore/Guards.h | 20 ++++++------- libdevcore/Worker.cpp | 45 +++++++++++++++-------------- libethereum/BlockChain.cpp | 10 +++---- libethereum/Client.cpp | 56 ++++++++++++++++++------------------ libethereum/EthereumHost.cpp | 2 +- libethereum/EthereumPeer.cpp | 4 +-- libethereum/Farm.h | 2 +- libp2p/Host.cpp | 8 +++--- 11 files changed, 102 insertions(+), 77 deletions(-) diff --git a/alethzero/MainWin.cpp b/alethzero/MainWin.cpp index 62515f171..e5504cab2 100644 --- a/alethzero/MainWin.cpp +++ b/alethzero/MainWin.cpp @@ -1371,6 +1371,8 @@ void Main::on_transactionQueue_currentItemChanged() s << "
Log Bloom: " << receipt.bloom() << "
"; else s << "
Log Bloom: Uneventful
"; + s << "
Gas Used: " << receipt.gasUsed() << "
"; + s << "
End State: " << receipt.stateRoot().abridged() << "
"; auto r = receipt.rlp(); s << "
Receipt: " << toString(RLP(r)) << "
"; s << "
Receipt-Hex: " Span(Mono) << toHex(receipt.rlp()) << "
"; @@ -1564,6 +1566,8 @@ void Main::on_blocks_currentItemChanged() s << "
Log Bloom: " << receipt.bloom() << "
"; else s << "
Log Bloom: Uneventful
"; + s << "
Gas Used: " << receipt.gasUsed() << "
"; + s << "
End State: " << receipt.stateRoot().abridged() << "
"; auto r = receipt.rlp(); s << "
Receipt: " << toString(RLP(r)) << "
"; s << "
Receipt-Hex: " Span(Mono) << toHex(receipt.rlp()) << "
"; diff --git a/libdevcore/Common.cpp b/libdevcore/Common.cpp index 7b9d74155..be8152b55 100644 --- a/libdevcore/Common.cpp +++ b/libdevcore/Common.cpp @@ -36,9 +36,19 @@ void HasInvariants::checkInvariants() const BOOST_THROW_EXCEPTION(FailedInvariant()); } +struct TimerChannel: public LogChannel { static const char* name(); static const int verbosity = 0; }; + +#ifdef _WIN32 +const char* TimerChannel::name() { return EthRed " ! "; } +#else +const char* TimerChannel::name() { return EthRed " ⚡ "; } +#endif + TimerHelper::~TimerHelper() { - cdebug << "Timer" << id << t.elapsed() << "s"; + auto e = m_t.elapsed(); + if (!m_ms || e * 1000 > m_ms) + clog(TimerChannel) << m_id << e << "s"; } } diff --git a/libdevcore/Common.h b/libdevcore/Common.h index e5d746372..e0872b5d4 100644 --- a/libdevcore/Common.h +++ b/libdevcore/Common.h @@ -169,15 +169,17 @@ private: #define DEV_INVARIANT_CHECK (void)0; #endif +/// Simple scope-based timer helper. class TimerHelper { public: - TimerHelper(char const* _id): id(_id) {} + TimerHelper(char const* _id, unsigned _msReportWhenGreater = 0): m_id(_id), m_ms(_msReportWhenGreater) {} ~TimerHelper(); private: - boost::timer t; - char const* id; + boost::timer m_t; + char const* m_id; + unsigned m_ms; }; #define DEV_TIMED(S) for (::std::pair<::dev::TimerHelper, bool> __eth_t(#S, true); __eth_t.second; __eth_t.second = false) @@ -188,6 +190,14 @@ private: #define DEV_TIMED_FUNCTION DEV_TIMED_SCOPE(__PRETTY_FUNCTION__) #endif +#define DEV_TIMED_IF(S, MS) for (::std::pair<::dev::TimerHelper, bool> __eth_t(::dev::TimerHelper(#S, MS), true); __eth_t.second; __eth_t.second = false) +#define DEV_TIMED_SCOPE_IF(S) ::dev::TimerHelper __eth_t(S, MS) +#if WIN32 +#define DEV_TIMED_FUNCTION_IF(MS) DEV_TIMED_SCOPE_IF(__FUNCSIG__, MS) +#else +#define DEV_TIMED_FUNCTION_IF(MS) DEV_TIMED_SCOPE_IF(__PRETTY_FUNCTION__, MS) +#endif + enum class WithExisting: int { Trust = 0, diff --git a/libdevcore/Guards.h b/libdevcore/Guards.h index d060108ef..2d3eced32 100644 --- a/libdevcore/Guards.h +++ b/libdevcore/Guards.h @@ -81,9 +81,9 @@ using SpinGuard = std::lock_guard; * Mutex m; * unsigned d; * ... - * ETH_GUARDED(m) d = 1; + * ETH_(m) d = 1; * ... - * ETH_GUARDED(m) { for (auto d = 10; d > 0; --d) foo(d); d = 0; } + * ETH_(m) { for (auto d = 10; d > 0; --d) foo(d); d = 0; } * @endcode * * There are several variants of this basic mechanism for different Mutex types and Guards. @@ -95,7 +95,7 @@ using SpinGuard = std::lock_guard; * Mutex m; * int d; * ... - * ETH_GUARDED(m) + * ETH_(m) * { * for (auto d = 50; d > 25; --d) * foo(d); @@ -107,19 +107,19 @@ using SpinGuard = std::lock_guard; * @endcode */ -#define ETH_GUARDED(MUTEX) \ +#define DEV_GUARDED(MUTEX) \ for (GenericGuardBool __eth_l(MUTEX); __eth_l.b; __eth_l.b = false) -#define ETH_READ_GUARDED(MUTEX) \ +#define DEV_READ_GUARDED(MUTEX) \ for (GenericGuardBool __eth_l(MUTEX); __eth_l.b; __eth_l.b = false) -#define ETH_WRITE_GUARDED(MUTEX) \ +#define DEV_WRITE_GUARDED(MUTEX) \ for (GenericGuardBool __eth_l(MUTEX); __eth_l.b; __eth_l.b = false) -#define ETH_RECURSIVE_GUARDED(MUTEX) \ +#define DEV_RECURSIVE_GUARDED(MUTEX) \ for (GenericGuardBool __eth_l(MUTEX); __eth_l.b; __eth_l.b = false) -#define ETH_UNGUARDED(MUTEX) \ +#define DEV_UNGUARDED(MUTEX) \ for (GenericUnguardBool __eth_l(MUTEX); __eth_l.b; __eth_l.b = false) -#define ETH_READ_UNGUARDED(MUTEX) \ +#define DEV_READ_UNGUARDED(MUTEX) \ for (GenericUnguardSharedBool __eth_l(MUTEX); __eth_l.b; __eth_l.b = false) -#define ETH_WRITE_UNGUARDED(MUTEX) \ +#define DEV_WRITE_UNGUARDED(MUTEX) \ for (GenericUnguardBool __eth_l(MUTEX); __eth_l.b; __eth_l.b = false) } diff --git a/libdevcore/Worker.cpp b/libdevcore/Worker.cpp index a68c18958..7d790ccf6 100644 --- a/libdevcore/Worker.cpp +++ b/libdevcore/Worker.cpp @@ -29,7 +29,7 @@ using namespace dev; void Worker::startWorking() { - cnote << "startWorking for thread" << m_name; +// cnote << "startWorking for thread" << m_name; Guard l(x_work); if (m_work) { @@ -42,65 +42,66 @@ void Worker::startWorking() m_work.reset(new thread([&]() { setThreadName(m_name.c_str()); - cnote << "Thread begins"; +// cnote << "Thread begins"; while (m_state != WorkerState::Killing) { WorkerState ex = WorkerState::Starting; bool ok = m_state.compare_exchange_strong(ex, WorkerState::Started); - cnote << "Trying to set Started: Thread was" << (unsigned)ex << "; " << ok; +// cnote << "Trying to set Started: Thread was" << (unsigned)ex << "; " << ok; + (void)ok; startedWorking(); - cnote << "Entering work loop..."; +// cnote << "Entering work loop..."; workLoop(); - cnote << "Finishing up worker thread..."; +// cnote << "Finishing up worker thread..."; doneWorking(); // ex = WorkerState::Stopping; // m_state.compare_exchange_strong(ex, WorkerState::Stopped); ex = m_state.exchange(WorkerState::Stopped); - cnote << "State: Stopped: Thread was" << (unsigned)ex; +// cnote << "State: Stopped: Thread was" << (unsigned)ex; if (ex == WorkerState::Killing || ex == WorkerState::Starting) m_state.exchange(ex); - cnote << "Waiting until not Stopped..."; - while (m_state == WorkerState::Stopped) - this_thread::sleep_for(chrono::milliseconds(20)); +// cnote << "Waiting until not Stopped..."; + DEV_TIMED_IF(Worker stopping, 100) + while (m_state == WorkerState::Stopped) + this_thread::sleep_for(chrono::milliseconds(20)); } })); - cnote << "Spawning" << m_name; +// cnote << "Spawning" << m_name; } - cnote << "Waiting until Started..."; - while (m_state != WorkerState::Started) - this_thread::sleep_for(chrono::microseconds(20)); + DEV_TIMED_IF(Start worker, 100) + while (m_state != WorkerState::Started) + this_thread::sleep_for(chrono::microseconds(20)); } void Worker::stopWorking() { - cnote << "stopWorking for thread" << m_name; - ETH_GUARDED(x_work) + DEV_GUARDED(x_work) if (m_work) { - cnote << "Stopping" << m_name; WorkerState ex = WorkerState::Started; m_state.compare_exchange_strong(ex, WorkerState::Stopping); - cnote << "Waiting until Stopped..."; - while (m_state != WorkerState::Stopped) - this_thread::sleep_for(chrono::microseconds(20)); + DEV_TIMED_IF(Stop worker, 100) + while (m_state != WorkerState::Stopped) + this_thread::sleep_for(chrono::microseconds(20)); } } void Worker::terminate() { // cnote << "stopWorking for thread" << m_name; - ETH_GUARDED(x_work) + DEV_GUARDED(x_work) if (m_work) { - cnote << "Terminating" << m_name; m_state.exchange(WorkerState::Killing); - m_work->join(); + DEV_TIMED_IF(Terminate worker, 100) + m_work->join(); + m_work.reset(); } } diff --git a/libethereum/BlockChain.cpp b/libethereum/BlockChain.cpp index c7c8a23ac..192cff34c 100644 --- a/libethereum/BlockChain.cpp +++ b/libethereum/BlockChain.cpp @@ -486,7 +486,7 @@ ImportRoute BlockChain::import(bytes const& _block, OverlayDB const& _db, Import // This is safe in practice since the caches don't get flushed nearly often enough to be // done here. details(bi.parentHash); - ETH_WRITE_GUARDED(x_details) + DEV_WRITE_GUARDED(x_details) m_details[bi.parentHash].children.push_back(bi.hash()); #if ETH_TIMED_IMPORTS || !ETH_TRUE @@ -495,7 +495,7 @@ ImportRoute BlockChain::import(bytes const& _block, OverlayDB const& _db, Import #endif blocksBatch.Put(toSlice(bi.hash()), (ldb::Slice)ref(_block)); - ETH_READ_GUARDED(x_details) + DEV_READ_GUARDED(x_details) extrasBatch.Put(toSlice(bi.parentHash, ExtraDetails), (ldb::Slice)dev::ref(m_details[bi.parentHash].rlp())); extrasBatch.Put(toSlice(bi.hash(), ExtraDetails), (ldb::Slice)dev::ref(BlockDetails((unsigned)pd.number + 1, td, bi.parentHash, {}).rlp())); @@ -623,7 +623,7 @@ ImportRoute BlockChain::import(bytes const& _block, OverlayDB const& _db, Import m_blocksDB->Write(m_writeOptions, &blocksBatch); m_extrasDB->Write(m_writeOptions, &extrasBatch); - ETH_WRITE_GUARDED(x_lastBlockHash) + DEV_WRITE_GUARDED(x_lastBlockHash) { m_lastBlockHash = newLastBlockHash; m_lastBlockNumber = newLastBlockNumber; @@ -981,7 +981,7 @@ bool BlockChain::isKnown(h256 const& _hash) const if (_hash == m_genesisHash) return true; - ETH_READ_GUARDED(x_blocks) + DEV_READ_GUARDED(x_blocks) if (!m_blocks.count(_hash)) { string d; @@ -989,7 +989,7 @@ bool BlockChain::isKnown(h256 const& _hash) const if (d.empty()) return false; } - ETH_READ_GUARDED(x_details) + DEV_READ_GUARDED(x_details) if (!m_details.count(_hash)) { string d; diff --git a/libethereum/Client.cpp b/libethereum/Client.cpp index 394b0007e..01426527f 100644 --- a/libethereum/Client.cpp +++ b/libethereum/Client.cpp @@ -244,13 +244,13 @@ void Client::startedWorking() // TODO: currently it contains keys for *all* blocks. Make it remove old ones. cdebug << "startedWorking()"; - ETH_WRITE_GUARDED(x_preMine) + DEV_WRITE_GUARDED(x_preMine) m_preMine.sync(m_bc); - ETH_READ_GUARDED(x_preMine) + DEV_READ_GUARDED(x_preMine) { - ETH_WRITE_GUARDED(x_working) + DEV_WRITE_GUARDED(x_working) m_working = m_preMine; - ETH_WRITE_GUARDED(x_postMine) + DEV_WRITE_GUARDED(x_postMine) m_postMine = m_preMine; } } @@ -259,13 +259,13 @@ void Client::doneWorking() { // Synchronise the state according to the head of the block chain. // TODO: currently it contains keys for *all* blocks. Make it remove old ones. - ETH_WRITE_GUARDED(x_preMine) + DEV_WRITE_GUARDED(x_preMine) m_preMine.sync(m_bc); - ETH_READ_GUARDED(x_preMine) + DEV_READ_GUARDED(x_preMine) { - ETH_WRITE_GUARDED(x_working) + DEV_WRITE_GUARDED(x_working) m_working = m_preMine; - ETH_WRITE_GUARDED(x_postMine) + DEV_WRITE_GUARDED(x_postMine) m_postMine = m_preMine; } } @@ -309,7 +309,7 @@ void Client::killChain() void Client::clearPending() { h256Set changeds; - ETH_WRITE_GUARDED(x_postMine) + DEV_WRITE_GUARDED(x_postMine) { if (!m_postMine.pending().size()) return; @@ -317,7 +317,7 @@ void Client::clearPending() // appendFromNewPending(m_postMine.logBloom(i), changeds); changeds.insert(PendingChangedFilter); m_tq.clear(); - ETH_READ_GUARDED(x_preMine) + DEV_READ_GUARDED(x_preMine) m_postMine = m_preMine; } @@ -434,7 +434,7 @@ ExecutionResult Client::call(Address _dest, bytes const& _data, u256 _gas, u256 { State temp; // cdebug << "Nonce at " << toAddress(_secret) << " pre:" << m_preMine.transactionsFrom(toAddress(_secret)) << " post:" << m_postMine.transactionsFrom(toAddress(_secret)); - ETH_READ_GUARDED(x_postMine) + DEV_READ_GUARDED(x_postMine) temp = m_postMine; temp.addBalance(_from, _value + _gasPrice * _gas); Executive e(temp, LastHashes(), 0); @@ -461,13 +461,13 @@ ProofOfWork::WorkPackage Client::getWork() bool Client::submitWork(ProofOfWork::Solution const& _solution) { bytes newBlock; - DEV_TIMED(working) ETH_WRITE_GUARDED(x_working) + DEV_TIMED(working) DEV_WRITE_GUARDED(x_working) if (!m_working.completeMine(_solution)) return false; - ETH_READ_GUARDED(x_working) + DEV_READ_GUARDED(x_working) { - DEV_TIMED(post) ETH_WRITE_GUARDED(x_postMine) + DEV_TIMED(post) DEV_WRITE_GUARDED(x_postMine) m_postMine = m_working; newBlock = m_working.blockData(); } @@ -499,17 +499,17 @@ void Client::syncTransactionQueue() h256Set changeds; TransactionReceipts newPendingReceipts; - DEV_TIMED(working) ETH_WRITE_GUARDED(x_working) + DEV_TIMED(working) DEV_WRITE_GUARDED(x_working) tie(newPendingReceipts, m_syncTransactionQueue) = m_working.sync(m_bc, m_tq, *m_gp); if (newPendingReceipts.empty()) return; - ETH_READ_GUARDED(x_working) - DEV_TIMED(post) ETH_WRITE_GUARDED(x_postMine) + DEV_READ_GUARDED(x_working) + DEV_TIMED(post) DEV_WRITE_GUARDED(x_postMine) m_postMine = m_working; - ETH_READ_GUARDED(x_postMine) + DEV_READ_GUARDED(x_postMine) for (size_t i = 0; i < newPendingReceipts.size(); i++) appendFromNewPending(newPendingReceipts[i], changeds, m_postMine.pending()[i].sha3()); changeds.insert(PendingChangedFilter); @@ -561,7 +561,7 @@ void Client::onChainChanged(ImportRoute const& _ir) bool preChanged = false; State newPreMine; - ETH_READ_GUARDED(x_preMine) + DEV_READ_GUARDED(x_preMine) newPreMine = m_preMine; // TODO: use m_postMine to avoid re-evaluating our own blocks. @@ -572,11 +572,11 @@ void Client::onChainChanged(ImportRoute const& _ir) if (isMining()) cnote << "New block on chain."; - ETH_WRITE_GUARDED(x_preMine) + DEV_WRITE_GUARDED(x_preMine) m_preMine = newPreMine; - DEV_TIMED(working) ETH_WRITE_GUARDED(x_working) + DEV_TIMED(working) DEV_WRITE_GUARDED(x_working) m_working = newPreMine; - ETH_READ_GUARDED(x_postMine) + DEV_READ_GUARDED(x_postMine) for (auto const& t: m_postMine.pending()) { clog(ClientNote) << "Resubmitting post-mine transaction " << t; @@ -584,7 +584,7 @@ void Client::onChainChanged(ImportRoute const& _ir) if (ir != ImportResult::Success) onTransactionQueueReady(); } - ETH_READ_GUARDED(x_working) DEV_TIMED(post) ETH_WRITE_GUARDED(x_postMine) + DEV_READ_GUARDED(x_working) DEV_TIMED(post) DEV_WRITE_GUARDED(x_postMine) m_postMine = m_working; changeds.insert(PendingChangedFilter); @@ -609,11 +609,11 @@ void Client::onPostStateChanged() cnote << "Post state changed: Restarting mining..."; if (isMining() || remoteActive()) { - DEV_TIMED(working) ETH_WRITE_GUARDED(x_working) + DEV_TIMED(working) DEV_WRITE_GUARDED(x_working) m_working.commitToMine(m_bc); - ETH_READ_GUARDED(x_working) + DEV_READ_GUARDED(x_working) { - DEV_TIMED(post) ETH_WRITE_GUARDED(x_postMine) + DEV_TIMED(post) DEV_WRITE_GUARDED(x_postMine) m_postMine = m_working; m_miningInfo = m_postMine.info(); } @@ -694,7 +694,7 @@ void Client::checkWatchGarbage() { // watches garbage collection vector toUninstall; - ETH_GUARDED(x_filtersWatches) + DEV_GUARDED(x_filtersWatches) for (auto key: keysOf(m_watches)) if (m_watches[key].lastPoll != chrono::system_clock::time_point::max() && chrono::system_clock::now() - m_watches[key].lastPoll > chrono::seconds(20)) { @@ -733,7 +733,7 @@ eth::State Client::state(h256 _block) const eth::State Client::state(unsigned _txi) const { - ETH_READ_GUARDED(x_postMine) + DEV_READ_GUARDED(x_postMine) return m_postMine.fromPending(_txi); assert(false); return State(); diff --git a/libethereum/EthereumHost.cpp b/libethereum/EthereumHost.cpp index 34d5eb504..299984a16 100644 --- a/libethereum/EthereumHost.cpp +++ b/libethereum/EthereumHost.cpp @@ -253,7 +253,7 @@ void EthereumHost::maintainBlocks(h256 const& _currentHash) h256s blocks = get<0>(m_chain.treeRoute(m_latestBlockSent, _currentHash, false, false, true)); - auto s = randomSelection(25, [&](EthereumPeer* p){ ETH_GUARDED(p->x_knownBlocks) return !p->m_knownBlocks.count(_currentHash); return false; }); + auto s = randomSelection(25, [&](EthereumPeer* p){ DEV_GUARDED(p->x_knownBlocks) return !p->m_knownBlocks.count(_currentHash); return false; }); for (shared_ptr const& p: s.first) for (auto const& b: blocks) { diff --git a/libethereum/EthereumPeer.cpp b/libethereum/EthereumPeer.cpp index c550bd4f7..85bdf33e9 100644 --- a/libethereum/EthereumPeer.cpp +++ b/libethereum/EthereumPeer.cpp @@ -559,7 +559,7 @@ bool EthereumPeer::interpret(unsigned _id, RLP const& _r) default:; } - ETH_GUARDED(x_knownBlocks) + DEV_GUARDED(x_knownBlocks) m_knownBlocks.insert(h); } break; @@ -578,7 +578,7 @@ bool EthereumPeer::interpret(unsigned _id, RLP const& _r) { addRating(1); auto h = _r[i].toHash(); - ETH_GUARDED(x_knownBlocks) + DEV_GUARDED(x_knownBlocks) m_knownBlocks.insert(h); auto status = host()->m_bq.blockStatus(h); if (status == QueueStatus::Importing || status == QueueStatus::Ready || host()->m_chain.isKnown(h)) diff --git a/libethereum/Farm.h b/libethereum/Farm.h index fda9d64c3..9acb375ad 100644 --- a/libethereum/Farm.h +++ b/libethereum/Farm.h @@ -127,7 +127,7 @@ public: */ void resetMiningProgress() { - ETH_READ_GUARDED(x_minerWork) + DEV_READ_GUARDED(x_minerWork) for (auto const& i: m_miners) i->resetHashCount(); resetTimer(); diff --git a/libp2p/Host.cpp b/libp2p/Host.cpp index 17ae1a8f1..8ba04b0e7 100644 --- a/libp2p/Host.cpp +++ b/libp2p/Host.cpp @@ -176,7 +176,7 @@ void Host::startPeerSession(Public const& _id, RLP const& _rlp, RLPXFrameIO* _io { // session maybe ingress or egress so m_peers and node table entries may not exist shared_ptr p; - ETH_RECURSIVE_GUARDED(x_sessions) + DEV_RECURSIVE_GUARDED(x_sessions) { if (m_peers.count(_id)) p = m_peers[_id]; @@ -257,7 +257,7 @@ void Host::onNodeTableEvent(NodeId const& _n, NodeTableEventType const& _e) if (Node n = m_nodeTable->node(_n)) { shared_ptr p; - ETH_RECURSIVE_GUARDED(x_sessions) + DEV_RECURSIVE_GUARDED(x_sessions) { if (m_peers.count(_n)) { @@ -412,7 +412,7 @@ void Host::requirePeer(NodeId const& _n, NodeIPEndpoint const& _endpoint) { // create or update m_peers entry shared_ptr p; - ETH_RECURSIVE_GUARDED(x_sessions) + DEV_RECURSIVE_GUARDED(x_sessions) if (m_peers.count(_n)) { p = m_peers[_n]; @@ -579,7 +579,7 @@ void Host::run(boost::system::error_code const&) // todo: update peerSlotsAvailable() unsigned pendingCount = 0; - ETH_GUARDED(x_pendingNodeConns) + DEV_GUARDED(x_pendingNodeConns) pendingCount = m_pendingPeerConns.size(); int openSlots = m_idealPeerCount - peerCount() - pendingCount; if (openSlots > 0)