Skip to content

Commit

Permalink
Implement MilliTimer class and add basic timing logging to StakeMiner
Browse files Browse the repository at this point in the history 
This commit implements a nifty little timer class that can be used
as a local timer or instantiated as a global timer object with a
map of timers.

A single global timer instance g_timer is initialized in the timer.cpp
file with the "default" label. The StakeMiner timings use a new "miner"
label in the global timer to allow timings that span across mulitple
functions/methods.
  • Loading branch information
@jamescowens
jamescowens committed Dec 18, 2020
1 parent e8126d9 commit 73babf4
Show file tree
Hide file tree
Showing 4 changed files with 241 additions and 7 deletions.
69 changes: 67 additions & 2 deletions src/miner.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -550,6 +550,8 @@ bool CreateCoinStake( CBlock &blocknew, CKey &key,
vector<const CWalletTx*> &StakeInputs,
CWallet &wallet, CBlockIndex* pindexPrev )
{
bool log_timer = LogInstance().WillLogCategory(BCLog::LogFlags::MISC);

int64_t CoinWeight;
CBigNum StakeKernelHash;
CTxDB txdb("r");
Expand All @@ -575,6 +577,12 @@ bool CreateCoinStake( CBlock &blocknew, CKey &key,
return false;
}

if (log_timer)
{
LogPrintf("StakeMiner(): CreateCoinStake(): SelectCoinsForStaking: elapsed %" PRId64 "ms",
g_timer.GetElapsedTime("miner"));
}

LogPrint(BCLog::LogFlags::MINER, "CreateCoinStake: Staking nTime/16= %d Bits= %u",
txnew.nTime/16,blocknew.nBits);

Expand Down Expand Up @@ -691,6 +699,13 @@ bool CreateCoinStake( CBlock &blocknew, CKey &key,
g_miner_status.WeightMin=StakeWeightMin;
g_miner_status.WeightMax=StakeWeightMax;
g_miner_status.nLastCoinStakeSearchInterval= txnew.nTime;

if (log_timer)
{
LogPrintf("StakeMiner(): CreateCoinStake(): stake loop: elapsed %" PRId64 "ms",
g_timer.GetElapsedTime("miner"));
}

return false;
}

Expand Down Expand Up @@ -1249,7 +1264,10 @@ void StakeMiner(CWallet *pwallet)
//wait for next round
MilliSleep(nMinerSleep);

CBlockIndex* pindexPrev = pindexBest;
bool log_timer = LogInstance().WillLogCategory(BCLog::LogFlags::MISC);

g_timer.InitTimer("miner");

CBlock StakeBlock;

{
Expand All @@ -1271,7 +1289,18 @@ void StakeMiner(CWallet *pwallet)
continue;
}

if (log_timer)
{
LogPrintf("StakeMiner(): IsMiningAllowed: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}

LOCK(cs_main);
if (log_timer)
{
LogPrintf("StakeMiner(): lock cs_main: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}

CBlockIndex* pindexPrev = pindexBest;

// * Create a bare block
StakeBlock.nTime= GetAdjustedTime();
Expand All @@ -1285,10 +1314,26 @@ void StakeMiner(CWallet *pwallet)
CKey BlockKey;
vector<const CWalletTx*> StakeInputs;

if( !CreateCoinStake( StakeBlock, BlockKey, StakeInputs, *pwallet, pindexPrev ) )
if (log_timer)
{
LogPrintf("StakeMiner(): CreateCoinStake start: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}

if (!CreateCoinStake(StakeBlock, BlockKey, StakeInputs, *pwallet, pindexPrev))
{
if (log_timer)
{
LogPrintf("StakeMiner(): CreateCoinStake end: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}
continue;
}
StakeBlock.nTime= StakeTX.nTime;

if (log_timer)
{
LogPrintf("StakeMiner(): CreateCoinStake end: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}

// * create rest of the block. This needs to be moved to after CreateGridcoinReward,
// because stake output splitting needs to be done beforehand for size considerations.
if( !CreateRestOfTheBlock(StakeBlock,pindexPrev) )
Expand All @@ -1301,6 +1346,11 @@ void StakeMiner(CWallet *pwallet)
continue;
}

if (log_timer)
{
LogPrintf("StakeMiner(): CreateGridcoinReward: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}

LogPrintf("StakeMiner: added gridcoin reward to coinstake");

// * If argument is supplied desiring stake output splitting or side staking, then call SplitCoinStakeOutput.
Expand All @@ -1309,11 +1359,22 @@ void StakeMiner(CWallet *pwallet)

AddSuperblockContractOrVote(StakeBlock);

if (log_timer)
{
LogPrintf("StakeMiner(): AddSuperblockContractOrVote: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}


// * sign boinchash, coinstake, wholeblock
if (!SignStakeBlock(StakeBlock, BlockKey, StakeInputs, pwallet)) {
continue;
}

if (log_timer)
{
LogPrintf("StakeMiner(): SignStakeBlock: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}

LogPrintf("StakeMiner: signed boinchash, coinstake, wholeblock");

{
Expand All @@ -1338,6 +1399,10 @@ void StakeMiner(CWallet *pwallet)
g_miner_status.m_last_pos_tx_hash = StakeBlock.vtx[1].GetHash();
}

if (log_timer)
{
LogPrintf("StakeMiner(): ProcessBlock: elapsed %" PRId64 "ms", g_timer.GetElapsedTime("miner"));
}
} //end while(!fShutdown)
}

92 changes: 92 additions & 0 deletions src/util/time.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -69,6 +69,98 @@ int64_t GetSystemTimeInSeconds()
return GetTimeMicros()/1000000;
}

void MilliTimer::InitTimer(std::string label)
{
internal_timer timer;

timer.start_time = GetTimeMillis();
timer.checkpoint_time = timer.start_time;

LOCK(cs_timer_map_lock);

// the [] either creates a new timer with the label or replaces an existing one.
timer_map[label] = timer;
}

bool MilliTimer::DeleteTimer(std::string label)
{
bool delete_status = false;

LOCK(cs_timer_map_lock);

if (timer_map.find(label) != timer_map.end())
{
timer_map.erase(label);

delete_status = true;
}

return delete_status;
}

int64_t MilliTimer::GetElapsedTime(std::string label)
{
internal_timer internal_timer;
timer timer;

LOCK(cs_timer_map_lock);

try
{
// This will throw an exception if the entry specified by label doesn't exist.
internal_timer = timer_map.at(label);

int64_t current_time = GetTimeMillis();

timer.elapsed_time = GetTimeMillis() - internal_timer.start_time;

internal_timer.checkpoint_time = current_time;

//Because of the exception guard above the map entry can be updated with [].
timer_map[label] = internal_timer;
}
catch (std::out_of_range)
{
timer.elapsed_time = 0;
}

return timer.elapsed_time;
}

MilliTimer::timer MilliTimer::GetTimes(std::string label)
{
internal_timer internal_timer;
timer timer;

LOCK(cs_timer_map_lock);

try
{
// This will throw an internal exception if the entry specified by label doesn't exist.
internal_timer = timer_map.at(label);

int64_t current_time = GetTimeMillis();

timer.elapsed_time = current_time - internal_timer.start_time;
timer.time_since_last_check = current_time - internal_timer.checkpoint_time;

internal_timer.checkpoint_time = current_time;

//Because of the exception guard above the map entry can be updated with [].
timer_map[label] = internal_timer;
}
catch (std::out_of_range)
{
//Re-initialize timer if internal exception is thrown.
timer = {};
}

return timer;
}

// Create global timer instance.
MilliTimer g_timer;

void MilliSleep(int64_t n)
{

Expand Down
48 changes: 48 additions & 0 deletions src/util/time.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,9 @@
#include <stdint.h>
#include <string>
#include <chrono>
#include <unordered_map>

#include "sync.h"

/**
* Helper to count the seconds of a duration.
Expand Down Expand Up @@ -38,6 +41,51 @@ int64_t GetMockTime();

void MilliSleep(int64_t n);

/**
* @brief The MilliTimer class
*
* This is a small class that implements a stopwatch style timer. The class can be used locally (usually using
* the "default" label) or as a global map of timers.
*
*/
class MilliTimer
{
public:
MilliTimer()
{
InitTimer("default");
}

MilliTimer(std::string label)
{
InitTimer(label);
}

struct timer
{
int64_t elapsed_time = 0;
int64_t time_since_last_check = 0;
};

void InitTimer(std::string label);
bool DeleteTimer(std::string label);

int64_t GetElapsedTime(std::string label = "default");
timer GetTimes(std::string label = "default");
private:
CCriticalSection cs_timer_map_lock;

struct internal_timer
{
int64_t start_time = 0;
int64_t checkpoint_time = 0;
};

std::unordered_map<std::string, internal_timer> timer_map;
};

extern MilliTimer g_timer;

/** Return system time (or mocked time, if set) */
template <typename T>
T GetTime();
Expand Down
39 changes: 34 additions & 5 deletions src/wallet/wallet.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@
using namespace std;

extern bool fQtActive;
extern MilliTimer g_timer;

bool fConfChange;
unsigned int nDerivationMethodIndex;
Expand Down Expand Up @@ -1335,15 +1336,18 @@ void CWallet::AvailableCoins(vector<COutput>& vCoins, bool fOnlyConfirmed, const
}
}

// A lock must be taken on cs_main before calling this function.
void CWallet::AvailableCoinsForStaking(vector<COutput>& vCoins, unsigned int nSpendTime) const
{

vCoins.clear();
{
LOCK2(cs_main, cs_wallet);
for (map<uint256, CWalletTx>::const_iterator it = mapWallet.begin(); it != mapWallet.end(); ++it)
AssertLockHeld(cs_main);
LOCK(cs_wallet);

for (const auto& it : mapWallet)
{
const CWalletTx* pcoin = &(*it).second;
const CWalletTx* pcoin = &it.second;

// Filtering by tx timestamp instead of block timestamp may give false positives but never false negatives
if (pcoin->nTime + nStakeMinAge > nSpendTime)
Expand All @@ -1356,9 +1360,14 @@ void CWallet::AvailableCoinsForStaking(vector<COutput>& vCoins, unsigned int nSp
if (nDepth < 1)
continue;

for (unsigned int i = 0; i < pcoin->vout.size(); i++)
if (!(pcoin->IsSpent(i)) && (IsMine(pcoin->vout[i]) != ISMINE_NO) && pcoin->vout[i].nValue >= nMinimumInputValue && pcoin->vout[i].nValue > 0)
for (unsigned int i = 0; i < pcoin->vout.size(); ++i)
if (!(pcoin->IsSpent(i))
&& (IsMine(pcoin->vout[i]) != ISMINE_NO)
&& pcoin->vout[i].nValue >= nMinimumInputValue
&& pcoin->vout[i].nValue > 0)
{
vCoins.push_back(COutput(pcoin, i, nDepth));
}
}
}
}
Expand Down Expand Up @@ -1624,6 +1633,8 @@ bool CWallet::SelectCoins(int64_t nTargetValue, unsigned int nSpendTime, set<pai
bool CWallet::SelectCoinsForStaking(unsigned int nSpendTime, std::vector<pair<const CWalletTx*,unsigned int> >& vCoinsRet,
GRC::MinerStatus::ReasonNotStakingCategory& not_staking_error, bool fMiner) const
{
bool log_timer = LogInstance().WillLogCategory(BCLog::LogFlags::MISC);

int64_t BalanceToConsider = GetBalance();

// Check if we have a spendable balance
Expand Down Expand Up @@ -1651,6 +1662,12 @@ bool CWallet::SelectCoinsForStaking(unsigned int nSpendTime, std::vector<pair<co
vector<COutput> vCoins;
AvailableCoinsForStaking(vCoins, nSpendTime);

if (log_timer)
{
LogPrintf("CWallet::SelectCoinsForStaking(): AvailableCoinsForStaking(): elapsed %" PRId64 "ms",
g_timer.GetElapsedTime("miner"));
}

if (vCoins.empty())
{
if (fMiner)
Expand Down Expand Up @@ -1687,6 +1704,12 @@ bool CWallet::SelectCoinsForStaking(unsigned int nSpendTime, std::vector<pair<co
return false;
}

if (log_timer)
{
LogPrintf("CWallet::SelectCoinsForStaking(): select loop: elapsed %" PRId64 "ms",
g_timer.GetElapsedTime("miner"));
}

// Randomize the vector order to keep PoS truly a roll of dice in which utxo has a chance to stake first
if (fMiner)
{
Expand All @@ -1695,6 +1718,12 @@ bool CWallet::SelectCoinsForStaking(unsigned int nSpendTime, std::vector<pair<co
std::shuffle(vCoinsRet.begin(), vCoinsRet.end(), std::default_random_engine(seed));
}

if (log_timer)
{
LogPrintf("CWallet::SelectCoinsForStaking(): shuffle: elapsed %" PRId64 "ms",
g_timer.GetElapsedTime("miner"));
}

return true;
}

Expand Down

0 comments on commit 73babf4

Please sign in to comment.