Browse Source

Additional info on slow blocks.

cl-refactor
Gav Wood 10 years ago
parent
commit
7f945041e8
  1. 4
      exp/main.cpp
  2. 16
      libdevcore/Common.h
  3. 8
      libdevcore/Worker.cpp
  4. 4
      libethcore/Miner.h
  5. 13
      libethereum/BlockChain.cpp
  6. 14
      libethereum/State.cpp

4
exp/main.cpp

@ -88,7 +88,7 @@ int main()
data.push_back(rlp(i)); data.push_back(rlp(i));
h256 ret; h256 ret;
DEV_TIMED(triedb) DEV_TIMED("triedb")
{ {
MemoryDB mdb; MemoryDB mdb;
GenericTrieDB<MemoryDB> t(&mdb); GenericTrieDB<MemoryDB> t(&mdb);
@ -99,7 +99,7 @@ int main()
ret = t.root(); ret = t.root();
} }
cdebug << ret; cdebug << ret;
DEV_TIMED(hash256) DEV_TIMED("hash256")
ret = orderedTrieRoot(data); ret = orderedTrieRoot(data);
cdebug << ret; cdebug << ret;
} }

16
libdevcore/Common.h

@ -193,12 +193,12 @@ private:
class TimerHelper class TimerHelper
{ {
public: public:
TimerHelper(char const* _id, unsigned _msReportWhenGreater = 0): m_t(std::chrono::high_resolution_clock::now()), m_id(_id), m_ms(_msReportWhenGreater) {} TimerHelper(std::string const& _id, unsigned _msReportWhenGreater = 0): m_t(std::chrono::high_resolution_clock::now()), m_id(_id), m_ms(_msReportWhenGreater) {}
~TimerHelper(); ~TimerHelper();
private: private:
std::chrono::high_resolution_clock::time_point m_t; std::chrono::high_resolution_clock::time_point m_t;
char const* m_id; std::string m_id;
unsigned m_ms; unsigned m_ms;
}; };
@ -215,20 +215,20 @@ private:
std::chrono::high_resolution_clock::time_point m_t; std::chrono::high_resolution_clock::time_point m_t;
}; };
#define DEV_TIMED(S) for (::std::pair<::dev::TimerHelper, bool> __eth_t(#S, true); __eth_t.second; __eth_t.second = false) #define DEV_TIMED(S) for (::std::pair<::dev::TimerHelper, bool> __eth_t(S, true); __eth_t.second; __eth_t.second = false)
#define DEV_TIMED_SCOPE(S) ::dev::TimerHelper __eth_t(S) #define DEV_TIMED_SCOPE(S) ::dev::TimerHelper __eth_t(S)
#if WIN32 #if WIN32
#define DEV_TIMED_FUNCTION DEV_TIMED_SCOPE(__FUNCSIG__) #define DEV_TIMED_FUNCTION DEV_TIMED_SCOPE(DEV_QUOTED(__FUNCSIG__))
#else #else
#define DEV_TIMED_FUNCTION DEV_TIMED_SCOPE(__PRETTY_FUNCTION__) #define DEV_TIMED_FUNCTION DEV_TIMED_SCOPE(DEV_QUOTED(__PRETTY_FUNCTION__))
#endif #endif
#define DEV_TIMED_ABOVE(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_ABOVE(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_ABOVE(S, MS) ::dev::TimerHelper __eth_t(S, MS) #define DEV_TIMED_SCOPE_ABOVE(S, MS) ::dev::TimerHelper __eth_t(S, MS)
#if WIN32 #if WIN32
#define DEV_TIMED_FUNCTION_ABOVE(MS) DEV_TIMED_SCOPE_ABOVE(__FUNCSIG__, MS) #define DEV_TIMED_FUNCTION_ABOVE(MS) DEV_TIMED_SCOPE_ABOVE(DEV_QUOTED(__FUNCSIG__), MS)
#else #else
#define DEV_TIMED_FUNCTION_ABOVE(MS) DEV_TIMED_SCOPE_ABOVE(__PRETTY_FUNCTION__, MS) #define DEV_TIMED_FUNCTION_ABOVE(MS) DEV_TIMED_SCOPE_ABOVE(DEV_QUOTED(__PRETTY_FUNCTION__), MS)
#endif #endif
enum class WithExisting: int enum class WithExisting: int

8
libdevcore/Worker.cpp

@ -65,14 +65,14 @@ void Worker::startWorking()
m_state.exchange(ex); m_state.exchange(ex);
// cnote << "Waiting until not Stopped..."; // cnote << "Waiting until not Stopped...";
DEV_TIMED_ABOVE(Worker stopping, 100) DEV_TIMED_ABOVE("Worker stopping", 100)
while (m_state == WorkerState::Stopped) while (m_state == WorkerState::Stopped)
this_thread::sleep_for(chrono::milliseconds(20)); this_thread::sleep_for(chrono::milliseconds(20));
} }
})); }));
// cnote << "Spawning" << m_name; // cnote << "Spawning" << m_name;
} }
DEV_TIMED_ABOVE(Start worker, 100) DEV_TIMED_ABOVE("Start worker", 100)
while (m_state == WorkerState::Starting) while (m_state == WorkerState::Starting)
this_thread::sleep_for(chrono::microseconds(20)); this_thread::sleep_for(chrono::microseconds(20));
} }
@ -85,7 +85,7 @@ void Worker::stopWorking()
WorkerState ex = WorkerState::Started; WorkerState ex = WorkerState::Started;
m_state.compare_exchange_strong(ex, WorkerState::Stopping); m_state.compare_exchange_strong(ex, WorkerState::Stopping);
DEV_TIMED_ABOVE(Stop worker, 100) DEV_TIMED_ABOVE("Stop worker", 100)
while (m_state != WorkerState::Stopped) while (m_state != WorkerState::Stopped)
this_thread::sleep_for(chrono::microseconds(20)); this_thread::sleep_for(chrono::microseconds(20));
} }
@ -99,7 +99,7 @@ void Worker::terminate()
{ {
m_state.exchange(WorkerState::Killing); m_state.exchange(WorkerState::Killing);
DEV_TIMED_ABOVE(Terminate worker, 100) DEV_TIMED_ABOVE("Terminate worker", 100)
m_work->join(); m_work->join();
m_work.reset(); m_work.reset();

4
libethcore/Miner.h

@ -107,9 +107,9 @@ public:
} }
if (!!_work) if (!!_work)
{ {
DEV_TIMED_ABOVE(pause, 250) DEV_TIMED_ABOVE("pause", 250)
pause(); pause();
DEV_TIMED_ABOVE(kickOff, 250) DEV_TIMED_ABOVE("kickOff", 250)
kickOff(); kickOff();
} }
else if (!_work && !!old) else if (!_work && !!old)

13
libethereum/BlockChain.cpp

@ -323,7 +323,7 @@ tuple<ImportRoute, bool, unsigned> BlockChain::sync(BlockQueue& _bq, OverlayDB c
{ {
// Nonce & uncle nonces already verified in verification thread at this point. // Nonce & uncle nonces already verified in verification thread at this point.
ImportRoute r; ImportRoute r;
DEV_TIMED_ABOVE(Block import, 500) DEV_TIMED_ABOVE("Block import", 500)
r = import(block.verified, _stateDB, ImportRequirements::Default & ~ImportRequirements::ValidNonce & ~ImportRequirements::CheckUncles); r = import(block.verified, _stateDB, ImportRequirements::Default & ~ImportRequirements::ValidNonce & ~ImportRequirements::CheckUncles);
fresh += r.liveBlocks; fresh += r.liveBlocks;
dead += r.deadBlocks; dead += r.deadBlocks;
@ -470,6 +470,9 @@ ImportRoute BlockChain::import(VerifiedBlockRef const& _block, OverlayDB const&
h256 newLastBlockHash = currentHash(); h256 newLastBlockHash = currentHash();
unsigned newLastBlockNumber = number(); unsigned newLastBlockNumber = number();
BlockLogBlooms blb;
BlockReceipts br;
u256 td; u256 td;
#if ETH_CATCH #if ETH_CATCH
try try
@ -480,8 +483,6 @@ ImportRoute BlockChain::import(VerifiedBlockRef const& _block, OverlayDB const&
State s(_db); State s(_db);
auto tdIncrease = s.enactOn(_block, *this, _ir); auto tdIncrease = s.enactOn(_block, *this, _ir);
BlockLogBlooms blb;
BlockReceipts br;
for (unsigned i = 0; i < s.pending().size(); ++i) for (unsigned i = 0; i < s.pending().size(); ++i)
{ {
blb.blooms.push_back(s.receipt(i).bloom()); blb.blooms.push_back(s.receipt(i).bloom());
@ -675,15 +676,17 @@ ImportRoute BlockChain::import(VerifiedBlockRef const& _block, OverlayDB const&
#if ETH_TIMED_IMPORTS #if ETH_TIMED_IMPORTS
checkBest = t.elapsed(); checkBest = t.elapsed();
if (total.elapsed() > 1.0) if (total.elapsed() > 0.5)
{ {
cnote << "SLOW IMPORT:" << _block.info.hash(); cnote << "SLOW IMPORT:" << _block.info.hash() << " #" << _block.info.number;
cnote << " Import took:" << total.elapsed(); cnote << " Import took:" << total.elapsed();
cnote << " preliminaryChecks:" << preliminaryChecks; cnote << " preliminaryChecks:" << preliminaryChecks;
cnote << " enactment:" << enactment; cnote << " enactment:" << enactment;
cnote << " collation:" << collation; cnote << " collation:" << collation;
cnote << " writing:" << writing; cnote << " writing:" << writing;
cnote << " checkBest:" << checkBest; cnote << " checkBest:" << checkBest;
cnote << " " << _block.transactions.size() << " transactions";
cnote << " " << _block.info.gasUsed << " gas used";
} }
#endif #endif

14
libethereum/State.cpp

@ -634,7 +634,7 @@ u256 State::enact(VerifiedBlockRef const& _block, BlockChain const& _bc, ImportR
// cnote << m_state; // cnote << m_state;
LastHashes lh; LastHashes lh;
DEV_TIMED_ABOVE(lastHashes, 500) DEV_TIMED_ABOVE("lastHashes", 500)
lh = _bc.lastHashes((unsigned)m_previousBlock.number); lh = _bc.lastHashes((unsigned)m_previousBlock.number);
RLP rlp(_block.block); RLP rlp(_block.block);
@ -643,7 +643,7 @@ u256 State::enact(VerifiedBlockRef const& _block, BlockChain const& _bc, ImportR
// All ok with the block generally. Play back the transactions now... // All ok with the block generally. Play back the transactions now...
unsigned i = 0; unsigned i = 0;
DEV_TIMED_ABOVE(txEcec, 500) DEV_TIMED_ABOVE("txExec", 500)
for (auto const& tr: _block.transactions) for (auto const& tr: _block.transactions)
{ {
try try
@ -664,7 +664,7 @@ u256 State::enact(VerifiedBlockRef const& _block, BlockChain const& _bc, ImportR
} }
h256 receiptsRoot; h256 receiptsRoot;
DEV_TIMED_ABOVE(receiptsRoot, 500) DEV_TIMED_ABOVE("receiptsRoot", 500)
receiptsRoot = orderedTrieRoot(receipts); receiptsRoot = orderedTrieRoot(receipts);
if (receiptsRoot != m_currentBlock.receiptsRoot) if (receiptsRoot != m_currentBlock.receiptsRoot)
@ -698,12 +698,12 @@ u256 State::enact(VerifiedBlockRef const& _block, BlockChain const& _bc, ImportR
vector<BlockInfo> rewarded; vector<BlockInfo> rewarded;
h256Hash excluded; h256Hash excluded;
DEV_TIMED_ABOVE(allKin, 500) DEV_TIMED_ABOVE("allKin", 500)
excluded = _bc.allKinFrom(m_currentBlock.parentHash, 6); excluded = _bc.allKinFrom(m_currentBlock.parentHash, 6);
excluded.insert(m_currentBlock.hash()); excluded.insert(m_currentBlock.hash());
unsigned ii = 0; unsigned ii = 0;
DEV_TIMED_ABOVE(uncleCheck, 500) DEV_TIMED_ABOVE("uncleCheck", 500)
for (auto const& i: rlp[2]) for (auto const& i: rlp[2])
{ {
try try
@ -752,11 +752,11 @@ u256 State::enact(VerifiedBlockRef const& _block, BlockChain const& _bc, ImportR
} }
} }
DEV_TIMED_ABOVE(applyRewards, 500) DEV_TIMED_ABOVE("applyRewards", 500)
applyRewards(rewarded); applyRewards(rewarded);
// Commit all cached state changes to the state trie. // Commit all cached state changes to the state trie.
DEV_TIMED_ABOVE(commit, 500) DEV_TIMED_ABOVE("commit", 500)
commit(); commit();
// Hash the state trie and check against the state_root hash in m_currentBlock. // Hash the state trie and check against the state_root hash in m_currentBlock.

Loading…
Cancel
Save