Only report worker stuff when it's laggy.

Cleanups ETH_ -> DEV_

alethzero/MainWin.cpp

@@ -1371,6 +1371,8 @@ void Main::on_transactionQueue_currentItemChanged()
 			s << "<div>Log Bloom: " << receipt.bloom() << "</div>";
 		else
 			s << "<div>Log Bloom: <b><i>Uneventful</i></b></div>";
+		s << "<div>Gas Used: <b>" << receipt.gasUsed() << "</b></div>";
+		s << "<div>End State: <b>" << receipt.stateRoot().abridged() << "</b></div>";
 		auto r = receipt.rlp();
 		s << "<div>Receipt: " << toString(RLP(r)) << "</div>";
 		s << "<div>Receipt-Hex: " Span(Mono) << toHex(receipt.rlp()) << "</span></div>";
@@ -1564,6 +1566,8 @@ void Main::on_blocks_currentItemChanged()
 				s << "<div>Log Bloom: " << receipt.bloom() << "</div>";
 			else
 				s << "<div>Log Bloom: <b><i>Uneventful</i></b></div>";
+			s << "<div>Gas Used: <b>" << receipt.gasUsed() << "</b></div>";
+			s << "<div>End State: <b>" << receipt.stateRoot().abridged() << "</b></div>";
 			auto r = receipt.rlp();
 			s << "<div>Receipt: " << toString(RLP(r)) << "</div>";
 			s << "<div>Receipt-Hex: " Span(Mono) << toHex(receipt.rlp()) << "</span></div>";

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";
 }
 
 }

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,

libdevcore/Guards.h

@@ -81,9 +81,9 @@ using SpinGuard = std::lock_guard<SpinLock>;
  * 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<SpinLock>;
  * 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<SpinLock>;
  * @endcode
  */
 
-#define ETH_GUARDED(MUTEX) \
+#define DEV_GUARDED(MUTEX) \
 	for (GenericGuardBool<Guard, Mutex> __eth_l(MUTEX); __eth_l.b; __eth_l.b = false)
-#define ETH_READ_GUARDED(MUTEX) \
+#define DEV_READ_GUARDED(MUTEX) \
 	for (GenericGuardBool<ReadGuard, SharedMutex> __eth_l(MUTEX); __eth_l.b; __eth_l.b = false)
-#define ETH_WRITE_GUARDED(MUTEX) \
+#define DEV_WRITE_GUARDED(MUTEX) \
 	for (GenericGuardBool<WriteGuard, SharedMutex> __eth_l(MUTEX); __eth_l.b; __eth_l.b = false)
-#define ETH_RECURSIVE_GUARDED(MUTEX) \
+#define DEV_RECURSIVE_GUARDED(MUTEX) \
 	for (GenericGuardBool<RecursiveGuard, RecursiveMutex> __eth_l(MUTEX); __eth_l.b; __eth_l.b = false)
-#define ETH_UNGUARDED(MUTEX) \
+#define DEV_UNGUARDED(MUTEX) \
 	for (GenericUnguardBool<Mutex> __eth_l(MUTEX); __eth_l.b; __eth_l.b = false)
-#define ETH_READ_UNGUARDED(MUTEX) \
+#define DEV_READ_UNGUARDED(MUTEX) \
 	for (GenericUnguardSharedBool<SharedMutex> __eth_l(MUTEX); __eth_l.b; __eth_l.b = false)
-#define ETH_WRITE_UNGUARDED(MUTEX) \
+#define DEV_WRITE_UNGUARDED(MUTEX) \
 	for (GenericUnguardBool<SharedMutex> __eth_l(MUTEX); __eth_l.b; __eth_l.b = false)
 
 }

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();
 		}
 }

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;

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<ProofOfWork>(_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<unsigned> 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();

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<EthereumPeer> const& p: s.first)
 				for (auto const& b: blocks)
 				{

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<h256>();
-				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))

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();

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