merge bitcoin#25499: Use steady clock for all millis bench logging

This commit is contained in:
Kittywhiskers Van Gogh 2024-12-09 19:05:47 +00:00
parent 492654db49
commit e905ae0f4b
No known key found for this signature in database
GPG Key ID: 30CD0C065E5C4AAD
11 changed files with 29 additions and 30 deletions

View File

@ -188,11 +188,11 @@ std::optional<bilingual_str> LoadAddrman(const NetGroupManager& netgroupman, con
auto check_addrman = std::clamp<int32_t>(args.GetArg("-checkaddrman", DEFAULT_ADDRMAN_CONSISTENCY_CHECKS), 0, 1000000);
addrman = std::make_unique<AddrMan>(netgroupman, /*deterministic=*/false, /*consistency_check_ratio=*/check_addrman);
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
const auto path_addr{gArgs.GetDataDirNet() / "peers.dat"};
try {
DeserializeFileDB(path_addr, *addrman, CLIENT_VERSION);
LogPrintf("Loaded %i addresses from peers.dat %dms\n", addrman->Size(), GetTimeMillis() - nStart);
LogPrintf("Loaded %i addresses from peers.dat %dms\n", addrman->Size(), Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
} catch (const DbNotFoundError&) {
// Addrman can be in an inconsistent state after failure, reset it
addrman = std::make_unique<AddrMan>(netgroupman, /*deterministic=*/false, /*consistency_check_ratio=*/check_addrman);

View File

@ -31,12 +31,12 @@ void BanMan::LoadBanlist()
if (m_client_interface) m_client_interface->InitMessage(_("Loading banlist…").translated);
int64_t n_start = GetTimeMillis();
const auto start{SteadyClock::now()};
if (m_ban_db.Read(m_banned)) {
SweepBanned(); // sweep out unused entries
LogPrint(BCLog::NET, "Loaded %d banned node addresses/subnets %dms\n", m_banned.size(),
GetTimeMillis() - n_start);
Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
} else {
LogPrintf("Recreating the banlist database\n");
m_banned = {};
@ -58,13 +58,13 @@ void BanMan::DumpBanlist()
SetBannedSetDirty(false);
}
int64_t n_start = GetTimeMillis();
const auto start{SteadyClock::now()};
if (!m_ban_db.Write(banmap)) {
SetBannedSetDirty(true);
}
LogPrint(BCLog::NET, "Flushed %d banned node addresses/subnets to disk %dms\n", banmap.size(),
GetTimeMillis() - n_start);
Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
}
void BanMan::ClearBanned()

View File

@ -39,7 +39,7 @@ private:
{
// LOCK(objToSave.cs);
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
// serialize, checksum data up to that point, then append checksum
CDataStream ssObj(SER_DISK, CLIENT_VERSION);
@ -65,7 +65,7 @@ private:
}
fileout.fclose();
LogPrintf("Written info to %s %dms\n", strFilename, GetTimeMillis() - nStart);
LogPrintf("Written info to %s %dms\n", strFilename, Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
LogPrintf(" %s\n", objToSave.ToString());
return true;
@ -75,7 +75,7 @@ private:
{
//LOCK(objToLoad.cs);
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
// open input file, and associate with CAutoFile
FILE *file = fsbridge::fopen(pathDB, "rb");
CAutoFile filein(file, SER_DISK, CLIENT_VERSION);
@ -149,7 +149,7 @@ private:
return ReadResult::IncorrectFormat;
}
LogPrintf("Loaded info from %s %dms\n", strFilename, GetTimeMillis() - nStart);
LogPrintf("Loaded info from %s %dms\n", strFilename, Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
LogPrintf(" %s\n", objToLoad.ToString());
return ReadResult::Ok;
@ -193,11 +193,11 @@ public:
T tmpObjToLoad;
if (!Read(tmpObjToLoad)) return false;
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
LogPrintf("Writing info to %s...\n", strFilename);
const bool ret = CoreWrite(objToSave);
LogPrintf("%s dump finished %dms\n", strFilename, GetTimeMillis() - nStart);
LogPrintf("%s dump finished %dms\n", strFilename, Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
return ret;
}

View File

@ -1432,11 +1432,12 @@ void CGovernanceManager::AddCachedTriggers()
void CGovernanceManager::InitOnLoad()
{
LOCK(cs);
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
LogPrintf("Preparing masternode indexes and governance triggers...\n");
RebuildIndexes();
AddCachedTriggers();
LogPrintf("Masternode indexes and governance triggers prepared %dms\n", GetTimeMillis() - nStart);
LogPrintf("Masternode indexes and governance triggers prepared %dms\n",
Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
LogPrintf(" %s\n", ToString());
}

View File

@ -1865,7 +1865,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
do {
bool failed_verification = false;
const int64_t load_block_index_start_time = GetTimeMillis();
const auto load_block_index_start_time{SteadyClock::now()};
try {
LOCK(cs_main);
@ -2128,7 +2128,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
if (!failed_verification) {
fLoaded = true;
LogPrintf(" block index %15dms\n", GetTimeMillis() - load_block_index_start_time);
LogPrintf(" block index %15dms\n", Ticks<std::chrono::milliseconds>(SteadyClock::now() - load_block_index_start_time));
}
} while(false);

View File

@ -3100,12 +3100,12 @@ void CConnman::ThreadDNSAddressSeed()
void CConnman::DumpAddresses()
{
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
DumpPeerAddresses(::gArgs, addrman);
LogPrint(BCLog::NET, "Flushed %d addresses to peers.dat %dms\n",
addrman.Size(), GetTimeMillis() - nStart);
addrman.Size(), Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
}
void CConnman::ProcessAddrFetch()

View File

@ -908,13 +908,13 @@ void ThreadImport(ChainstateManager& chainman, CDeterministicMNManager& dmnman,
// and reduce further locking overhead for cs_main in other parts of code including GUI
LogPrintf("Filling coin cache with masternode UTXOs...\n");
LOCK(cs_main);
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
auto mnList = dmnman.GetListAtChainTip();
mnList.ForEachMN(false, [&](auto& dmn) {
Coin coin;
GetUTXOCoin(chainman.ActiveChainstate(), dmn.collateralOutpoint, coin);
});
LogPrintf("Filling coin cache with masternode UTXOs: done in %dms\n", GetTimeMillis() - nStart);
LogPrintf("Filling coin cache with masternode UTXOs: done in %dms\n", Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
}
if (mn_activeman != nullptr) {

View File

@ -28,8 +28,6 @@
#include <mutex>
#include <unordered_map>
using SteadyClock = std::chrono::steady_clock;
static Mutex g_rpc_warmup_mutex;
static std::atomic<bool> g_rpc_running{false};
static bool fRPCInWarmup GUARDED_BY(g_rpc_warmup_mutex) = true;

View File

@ -4603,7 +4603,7 @@ void CChainState::LoadExternalBlockFile(
// Either both should be specified (-reindex), or neither (-loadblock).
assert(!dbp == !blocks_with_unknown_parent);
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
int nLoaded = 0;
try {
@ -4739,7 +4739,7 @@ void CChainState::LoadExternalBlockFile(
} catch (const std::runtime_error& e) {
AbortNode(std::string("System error: ") + e.what());
}
LogPrintf("Loaded %i blocks from external file in %dms\n", nLoaded, GetTimeMillis() - nStart);
LogPrintf("Loaded %i blocks from external file in %dms\n", nLoaded, Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
}
void CChainState::CheckBlockIndex()

View File

@ -533,7 +533,7 @@ bool BerkeleyDatabase::Rewrite(const char* pszSkip)
void BerkeleyEnvironment::Flush(bool fShutdown)
{
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
// Flush log data to the actual data file on all files that are not in use
LogPrint(BCLog::WALLETDB, "BerkeleyEnvironment::Flush: [%s] Flush(%s)%s\n", strPath, fShutdown ? "true" : "false", fDbEnvInit ? "" : " database not started");
if (!fDbEnvInit)
@ -560,7 +560,7 @@ void BerkeleyEnvironment::Flush(bool fShutdown)
no_dbs_accessed = false;
}
}
LogPrint(BCLog::WALLETDB, "BerkeleyEnvironment::Flush: Flush(%s)%s took %15dms\n", fShutdown ? "true" : "false", fDbEnvInit ? "" : " database not started", GetTimeMillis() - nStart);
LogPrint(BCLog::WALLETDB, "BerkeleyEnvironment::Flush: Flush(%s)%s took %15dms\n", fShutdown ? "true" : "false", fDbEnvInit ? "" : " database not started", Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
if (fShutdown) {
char** listp;
if (no_dbs_accessed) {
@ -589,14 +589,14 @@ bool BerkeleyDatabase::PeriodicFlush()
if (m_refcount < 0) return false;
LogPrint(BCLog::WALLETDB, "Flushing %s\n", strFile);
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
// Flush wallet file so it's self contained
env->CloseDb(strFile);
env->CheckpointLSN(strFile);
m_refcount = -1;
LogPrint(BCLog::WALLETDB, "Flushed %s %dms\n", strFile, GetTimeMillis() - nStart);
LogPrint(BCLog::WALLETDB, "Flushed %s %dms\n", strFile, Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
return true;
}

View File

@ -4724,7 +4724,7 @@ std::shared_ptr<CWallet> CWallet::Create(interfaces::Chain* chain, interfaces::C
{
const std::string& walletFile = database->Filename();
int64_t nStart = GetTimeMillis();
const auto start{SteadyClock::now()};
// TODO: Can't use std::make_shared because we need a custom deleter but
// should be possible to use std::allocate_shared.
std::shared_ptr<CWallet> walletInstance(new CWallet(chain, coinjoin_loader, name, std::move(database)), ReleaseWallet);
@ -4970,7 +4970,7 @@ std::shared_ptr<CWallet> CWallet::Create(interfaces::Chain* chain, interfaces::C
walletInstance->m_confirm_target = gArgs.GetArg("-txconfirmtarget", DEFAULT_TX_CONFIRM_TARGET);
walletInstance->m_spend_zero_conf_change = gArgs.GetBoolArg("-spendzeroconfchange", DEFAULT_SPEND_ZEROCONF_CHANGE);
walletInstance->WalletLogPrintf("Wallet completed loading in %15dms\n", GetTimeMillis() - nStart);
walletInstance->WalletLogPrintf("Wallet completed loading in %15dms\n", Ticks<std::chrono::milliseconds>(SteadyClock::now() - start));
// Try to top up keypool. No-op if the wallet is locked.
walletInstance->TopUpKeyPool();